TIMESTAMP (us) DELTA C# COMPONENT LOCATION CONTENT ktime=229.366s @ 2021-08-20 21:53:04 +0800 +08 [ 532929.926740] ( 0.000000) c1 pipe 4.24 ....../pipeline-params.c:221 pipe params stream_tag 2 channels 4 sample_valid_bytes 4 sample_container_bytes 4 [ 274.010406] ( 274.010406) c1 igo-nr 4.20 ../audio/igo_nr/igo_nr.c:381 igo_nr_params() [ 288.749989] ( 14.739583) c1 igo-nr 4.20 ../audio/igo_nr/igo_nr.c:423 igo_nr_params(), sample rate = 48000 [ 303.489571] ( 14.739583) c1 dai 4.23 src/audio/dai.c:357 dai_data_config() dai type = 2 index = 0 dd 0x9e275300 [ 310.677071] ( 7.187500) c1 dai 4.23 src/audio/dai.c:376 config->dmic.fifo_bits = 32 config->dmic.num_pdm_active = 2 [ 622.604142] ( 311.927063) c1 dai 4.23 src/audio/dai.c:509 dai_capture_params() src_dev = 0 stream_id = 0 src_width = 4 dest_width = 4 [ 630.260392] ( 7.656250) c1 dai 4.23 src/audio/dai.c:515 dai_capture_params() fifo 0x10008 [ 648.229141] ( 17.968750) c1 pipe 4.24 ....../pipeline-params.c:303 pipe prepare [ 989.374961] ( 341.145813) c1 igo-nr 4.20 ../audio/igo_nr/igo_nr.c:679 igo_nr_set_igo_params() [ 996.510377] ( 7.135417) c1 igo-nr 4.20 ../audio/igo_nr/igo_nr.c:683 New config detected. [ 1729.062431] ( 732.552063) c1 igo-nr 4.20 ../audio/igo_nr/igo_nr.c:262 set_capture_func(), SOF_IPC_FRAME_S32_LE [ 2064.635335] ( 335.572906) c1 dai 4.23 src/audio/dai.c:821 dai_prepare() [ 2072.135334] ( 7.500000) c1 dai 4.23 src/audio/dai.c:769 dai_config_prepare(), channel = 0 [ 2079.062417] ( 6.927083) c1 dw-dma src/drivers/dw/dma.c:191 dw_dma_channel_get(): dma 1 request channel 0 [ 2087.760334] ( 8.697916) c1 dai 4.23 src/audio/dai.c:786 dai_config(): new configured dma channel index 1 [ 4461.197739] ( 2373.437500) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 4474.739406] ( 13.541666) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() [ 4490.885238] ( 16.145832) c1 pipe 4.24 ....../pipeline-stream.c:184 pipe trigger cmd 1 [ 4520.156070] ( 29.270832) c1 igo-nr 4.20 ../audio/igo_nr/igo_nr.c:798 igo_nr_trigger(), command = 1 [ 4552.447736] ( 32.291664) c1 dmic-dai 2.0 ....../intel/dmic/dmic.c:1288 dmic_start(), dmic->fifo_a [ 4560.416485] ( 7.968750) c1 dmic-dai 2.0 ....../intel/dmic/dmic.c:1323 dmic_start(), mic_a = 1, mic_b = 1, fir_a = 1, fir_b = 1 [ 4568.906068] ( 8.489583) c1 dmic-dai 2.0 ....../intel/dmic/dmic.c:1323 dmic_start(), mic_a = 1, mic_b = 1, fir_a = 1, fir_b = 1 [ 4579.166485] ( 10.260416) c1 ll-schedule ./schedule/ll_schedule.c:413 task add 0x9e265388 dmic-work <59c87728-d8f9-42f6-b89d-5870a87b0e1e> [ 4585.833151] ( 6.666667) c1 ll-schedule ./schedule/ll_schedule.c:417 task params pri 4 flags 0 start 1000 period 1000 [ 4614.947733] ( 29.114582) c1 ll-schedule /schedule/timer_domain.c:191 timer_domain_register domain->type 1 domain->clk 4 domain->ticks_per_ms 38400 period 1000 [ 4632.031066] ( 17.083332) c1 ll-schedule ./schedule/ll_schedule.c:329 new added task->start 10326073 at 10321147 [ 4638.020649] ( 5.989583) c1 ll-schedule ./schedule/ll_schedule.c:332 num_tasks 1 total_num_tasks 4 [ 4644.895649] ( 6.875000) c1 dmic-dai 2.0 ....../intel/dmic/dmic.c:1397 dmic_start(), dmic_active_fifos_mask = 0x1 [ 4659.062315] ( 14.166666) c1 ll-schedule ./schedule/ll_schedule.c:413 task add 0xbe2d0300 pipe-task [ 4665.260231] ( 6.197917) c1 ll-schedule ./schedule/ll_schedule.c:417 task params pri 0 flags 0 start 0 period 16000 [ 4678.749814] ( 13.489583) c1 ll-schedule ./schedule/ll_schedule.c:329 new added task->start 10326073 at 10322045 [ 4684.739397] ( 5.989583) c1 ll-schedule ./schedule/ll_schedule.c:332 num_tasks 2 total_num_tasks 5 [ 4992.603968] ( 307.864563) c1 host 4.19 src/audio/host.c:377 no bytes to copy, 0 avail in buffer, 24576 free in DMA [ 409278.264987] ( 404285.656250) c1 ll-schedule ./schedule/ll_schedule.c:125 task complete 0x9e265388 dmic-work <59c87728-d8f9-42f6-b89d-5870a87b0e1e> [ 409286.025403] ( 7.760417) c1 ll-schedule ./schedule/ll_schedule.c:128 num_tasks 1 total_num_tasks 4 [ 14089784.023456] ( 13680498.000000) c0 pipe 11.68 ....../pipeline-stream.c:184 pipe trigger cmd 0 [ 14089798.606788] ( 14.583333) c0 demux 11.64 src/audio/mux/mux.c:705 mux_trigger(), command = 0 [ 14089808.763038] ( 10.156250) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:841 ssp_trigger() cmd 0 [ 14089906.158867] ( 97.395828) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:800 ssp_stop(), RX stop [ 14089915.898450] ( 9.739583) c0 dw-dma src/drivers/dw/dma.c:407 dw_dma_stop(): dma 1 channel 0 stop [ 14089929.648450] ( 13.749999) c0 ll-schedule ./schedule/ll_schedule.c:539 task cancel 0xbe2d0240 pipe-task [ 14089938.658866] ( 9.010416) c0 ll-schedule ./schedule/ll_schedule.c:359 num_tasks 2 total_num_tasks 3 [ 14090130.481775] ( 191.822906) c0 pipe 11.68 ......./pipeline-graph.c:383 pipe reset [ 14090185.429690] ( 54.947914) c0 demux 11.64 src/audio/mux/mux.c:624 mux_reset() [ 14090193.033856] ( 7.604167) c0 dai 11.67 src/audio/dai.c:870 dai_reset() [ 14090200.273439] ( 7.239583) c0 dw-dma src/drivers/dw/dma.c:254 dw_dma_channel_put(): dma 1 channel 0 put [ 14090968.190075] ( 767.916626) c0 Maxim DSM 1.1 ../smart_amp_maxim_dsm.c:327 WARN [DSM] Feed Forward buffer overflow. (w_ptr : 52 + 236 > 192) [ 14216198.758016] ( 125230.570312) c0 pipe 1.6 ....../pipeline-stream.c:184 pipe trigger cmd 0 [ 14216223.133015] ( 24.374998) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:841 ssp_trigger() cmd 0 [ 14218213.549602] ( 1990.416626) c0 wait src/lib/wait.c:46 ERROR ewt [ 14218219.591269] ( 6.041667) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:58 WARN ssp_empty_tx_fifo() warning: timeout [ 14218226.987102] ( 7.395833) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:810 ssp_stop(), TX stop [ 14218234.435018] ( 7.447917) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:817 ssp_stop(), SSP port disabled [ 14218242.039184] ( 7.604167) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:704 releasing BCLK/MCLK clocks for SSP1... [ 14218253.862101] ( 11.822916) c0 dw-dma src/drivers/dw/dma.c:407 dw_dma_stop(): dma 0 channel 0 stop [ 14218267.716267] ( 13.854166) c0 ll-schedule ./schedule/ll_schedule.c:539 task cancel 0xbe2d0180 pipe-task [ 14218276.310016] ( 8.593750) c0 ll-schedule ./schedule/ll_schedule.c:359 num_tasks 1 total_num_tasks 2 [ 14219319.278725] ( 1042.968750) c0 pipe 1.6 ......./pipeline-graph.c:383 pipe reset [ 14219375.320389] ( 56.041664) c0 dai 1.5 src/audio/dai.c:870 dai_reset() [ 14219382.351639] ( 7.031250) c0 dw-dma src/drivers/dw/dma.c:254 dw_dma_channel_put(): dma 0 channel 0 put [ 14221878.601540] ( 2496.250000) c0 dai src/lib/dai.c:164 dai_get type 1 index 0 new sref 3 [ 14221887.820290] ( 9.218750) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:172 ssp_set_config(), config->format = 0x4001 [ 14221911.570289] ( 23.750000) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:599 ssp_set_config(), sscr0 = 0xc1d0003f, sscr1 = 0xd0700000, ssto = 0x00000000, sspsp = 0x2200000 [ 14221918.289038] ( 6.718750) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:601 ssp_set_config(), sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000, ssioc = 0x00000020 [ 14221924.382788] ( 6.093750) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:603 ssp_set_config(), ssrsa = 0x00000003, sstsa = 0x00000003 [ 14221931.830705] ( 7.447917) c0 dai src/lib/dai.c:188 dai_put type 1 index 0 new sref 2 [ 14221945.632787] ( 13.802083) c0 dai 2.11 src/audio/dai.c:706 dai_config() dai type = 1 index = 0 dd 0x9e275100 [ 14221965.632787] ( 20.000000) c0 dai 3.17 src/audio/dai.c:706 dai_config() dai type = 1 index = 0 dd 0x9e275200 [ 14232517.611534] ( 10551.978516) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 14232535.267783] ( 17.656250) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() [ 14233007.455264] ( 472.187469) c0 pipe 2.12 ....../pipeline-params.c:217 pipe params dir 0 frame_fmt 0 buffer_fmt 0 rate 48000 [ 14233014.434431] ( 6.979167) c0 pipe 2.12 ....../pipeline-params.c:221 pipe params stream_tag 1 channels 2 sample_valid_bytes 2 sample_container_bytes 2 [ 14233217.663589] ( 203.229156) c0 dai 2.11 src/audio/dai.c:357 dai_data_config() dai type = 1 index = 0 dd 0x9e275100 [ 14233376.726083] ( 159.062500) c0 dai 2.11 src/audio/dai.c:442 dai_playback_params() dest_dev = 2 stream_id = 0 src_width = 4 dest_width = 4 [ 14233383.548999] ( 6.822917) c0 dai 2.11 src/audio/dai.c:448 dai_playback_params() fifo 0x77010 [ 14233399.173999] ( 15.624999) c0 pipe 2.12 ....../pipeline-params.c:303 pipe prepare [ 14233452.663580] ( 53.489582) c0 dai 2.11 src/audio/dai.c:821 dai_prepare() [ 14233459.590663] ( 6.927083) c0 dai 2.11 src/audio/dai.c:769 dai_config_prepare(), channel = 0 [ 14233466.153163] ( 6.562500) c0 dw-dma src/drivers/dw/dma.c:191 dw_dma_channel_get(): dma 1 request channel 0 [ 14233473.809413] ( 7.656250) c0 dai 2.11 src/audio/dai.c:786 dai_config(): new configured dma channel index 0 [ 14284725.421959] ( 51251.613281) c0 pipe 2.12 ....../pipeline-stream.c:184 pipe trigger cmd 1 [ 14284765.682374] ( 40.260414) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:841 ssp_trigger() cmd 1 [ 14284773.651124] ( 7.968750) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:630 ssp_pre_start() [ 14284782.921957] ( 9.270833) c0 mn ./drivers/intel/ssp/mn.c:258 mclk_rate 24576000, mclk_source_clock 0 [ 14284788.963623] ( 6.041667) c0 mn ./drivers/intel/ssp/mn.c:220 mclk_id 0 mdivr_val 1 [ 14284798.182373] ( 9.218750) c0 mn ./drivers/intel/ssp/mn.c:320 find_mn for freq 24576000 bclk 3072000 [ 14284805.369873] ( 7.187500) c0 mn ./drivers/intel/ssp/mn.c:617 bclk_rate 3072000, *out_scr_div 8, m 1, n 1 [ 14284812.401123] ( 7.031250) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:686 ssp_set_config(), sscr0 = 0xc1d0077f [ 14284819.328206] ( 6.927083) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:758 ssp_start() [ 14284936.099034] ( 116.770828) c0 ll-schedule ./schedule/ll_schedule.c:413 task add 0xbe2d01c0 pipe-task [ 14284942.869867] ( 6.770833) c0 ll-schedule ./schedule/ll_schedule.c:417 task params pri 0 flags 0 start 0 period 1000 [ 14284957.765700] ( 14.895833) c0 ll-schedule ./schedule/ll_schedule.c:329 new added task->start 284540473 at 284503412 [ 14284963.807367] ( 6.041667) c0 ll-schedule ./schedule/ll_schedule.c:332 num_tasks 2 total_num_tasks 3 [ 14296512.140241] ( 11548.333008) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 14296529.327740] ( 17.187500) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() [ 14296546.098573] ( 16.770832) c1 pipe 4.24 ....../pipeline-stream.c:184 pipe trigger cmd 0 [ 14296569.796489] ( 23.697916) c1 igo-nr 4.20 ../audio/igo_nr/igo_nr.c:798 igo_nr_trigger(), command = 0 [ 14296585.213155] ( 15.416666) c1 dmic-dai 2.0 ....../intel/dmic/dmic.c:1431 dmic_stop(), dmic_active_fifos_mask = 0x1 [ 14296596.931904] ( 11.718750) c1 ll-schedule ./schedule/ll_schedule.c:539 task cancel 0x9e265388 dmic-work <59c87728-d8f9-42f6-b89d-5870a87b0e1e> [ 14296605.577737] ( 8.645833) c1 dw-dma src/drivers/dw/dma.c:407 dw_dma_stop(): dma 1 channel 1 stop [ 14296622.140237] ( 16.562500) c1 ll-schedule ./schedule/ll_schedule.c:539 task cancel 0xbe2d0300 pipe-task [ 14296634.067319] ( 11.927083) c1 ll-schedule /schedule/timer_domain.c:210 timer_domain_unregister domain->type 1 domain->clk 4 [ 14296656.879819] ( 22.812500) c1 ll-schedule ./schedule/ll_schedule.c:359 num_tasks 0 total_num_tasks 2 [ 14297111.098551] ( 454.218719) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 14297123.077717] ( 11.979166) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() [ 14297138.233966] ( 15.156249) c1 pipe 4.24 ......./pipeline-graph.c:383 pipe reset [ 14297227.140213] ( 88.906250) c1 igo-nr 4.20 ../audio/igo_nr/igo_nr.c:786 igo_nr_reset() [ 14297238.806879] ( 11.666666) c1 dai 4.23 src/audio/dai.c:870 dai_reset() [ 14297246.202712] ( 7.395833) c1 dw-dma src/drivers/dw/dma.c:254 dw_dma_channel_put(): dma 1 channel 1 put [ 14321100.680931] ( 23854.478516) c0 dai src/lib/dai.c:164 dai_get type 1 index 0 new sref 3 [ 14321109.535097] ( 8.854166) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:167 ssp_set_config(): playback/capture active. Ignore config [ 14321116.774680] ( 7.239583) c0 dai src/lib/dai.c:188 dai_put type 1 index 0 new sref 2 [ 14321130.524679] ( 13.749999) c0 dai 2.11 src/audio/dai.c:706 dai_config() dai type = 1 index = 0 dd 0x9e275100 [ 14321136.722596] ( 6.197917) c0 dai 2.11 src/audio/dai.c:710 dai_config(): Component is in active state. Ignore config [ 14321145.785095] ( 9.062500) c0 dai 3.17 src/audio/dai.c:706 dai_config() dai type = 1 index = 0 dd 0x9e275200 [ 14321193.545510] ( 47.760414) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 14321206.410093] ( 12.864583) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() [ 14321641.670492] ( 435.260406) c0 pipe 3.18 ....../pipeline-params.c:217 pipe params dir 1 frame_fmt 0 buffer_fmt 0 rate 48000 [ 14321648.753825] ( 7.083333) c0 pipe 3.18 ....../pipeline-params.c:221 pipe params stream_tag 1 channels 2 sample_valid_bytes 2 sample_container_bytes 2 [ 14321854.378817] ( 205.624985) c0 dai 3.17 src/audio/dai.c:357 dai_data_config() dai type = 1 index = 0 dd 0x9e275200 [ 14322016.774644] ( 162.395828) c0 dai 3.17 src/audio/dai.c:509 dai_capture_params() src_dev = 3 stream_id = 0 src_width = 4 dest_width = 4 [ 14322023.545477] ( 6.770833) c0 dai 3.17 src/audio/dai.c:515 dai_capture_params() fifo 0x77010 [ 14322038.701727] ( 15.156249) c0 pipe 3.18 ....../pipeline-params.c:303 pipe prepare [ 14322091.930891] ( 53.229164) c0 dai 3.17 src/audio/dai.c:821 dai_prepare() [ 14322098.805891] ( 6.875000) c0 dai 3.17 src/audio/dai.c:769 dai_config_prepare(), channel = 0 [ 14322105.264224] ( 6.458333) c0 dw-dma src/drivers/dw/dma.c:191 dw_dma_channel_get(): dma 0 request channel 0 [ 14322113.180890] ( 7.916667) c0 dai 3.17 src/audio/dai.c:786 dai_config(): new configured dma channel index 0 [ 14327310.576517] ( 5197.395508) c0 pipe 3.18 ....../pipeline-stream.c:184 pipe trigger cmd 1 [ 14327342.764016] ( 32.187500) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:841 ssp_trigger() cmd 1 [ 14327350.680682] ( 7.916667) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:630 ssp_pre_start() [ 14327358.493182] ( 7.812500) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:758 ssp_start() [ 14327456.253595] ( 97.760414) c0 ll-schedule ./schedule/ll_schedule.c:413 task add 0xbe2d02c0 pipe-task [ 14327462.764011] ( 6.510417) c0 ll-schedule ./schedule/ll_schedule.c:417 task params pri 0 flags 0 start 0 period 1000 [ 14327477.868177] ( 15.104166) c0 ll-schedule ./schedule/ll_schedule.c:329 new added task->start 285346873 at 285319800 [ 14327483.909844] ( 6.041667) c0 ll-schedule ./schedule/ll_schedule.c:332 num_tasks 3 total_num_tasks 3 Found valid LDC address after skipping 24 bytes (one line uses 20 + 0 to 16 bytes) --- negative DELTA = -14544909.057 us: wrap, IPC_TRACE, other? --- [ 315504.779130] ( 0.000000) c0 memory src/lib/alloc.c:1118 count 8 free 8 [ 6.197916] ( 6.197917) c0 memory src/lib/alloc.c:1115 block 2 base 0xbe2a8000 size 1024 [ 12.135416] ( 5.937500) c0 memory src/lib/alloc.c:1118 count 4 free 4 [ 18.489583] ( 6.354167) c0 memory src/lib/alloc.c:1105 heap: 0xbe2b6000 size 12288 blocks 3 caps 0x65 [ 24.531249] ( 6.041667) c0 memory src/lib/alloc.c:1107 used 0 free 12288 [ 30.677082] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 0 base 0xbe2b6000 size 64 [ 36.770832] ( 6.093750) c0 memory src/lib/alloc.c:1118 count 64 free 64 [ 42.864582] ( 6.093750) c0 memory src/lib/alloc.c:1115 block 1 base 0xbe2b7000 size 512 [ 49.010415] ( 6.145833) c0 memory src/lib/alloc.c:1118 count 8 free 8 [ 55.156248] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 2 base 0xbe2b8000 size 1024 [ 61.249998] ( 6.093750) c0 memory src/lib/alloc.c:1118 count 4 free 4 [ 67.552081] ( 6.302083) c0 memory src/lib/alloc.c:1105 heap: 0xbe2c6000 size 12288 blocks 3 caps 0x65 [ 73.697914] ( 6.145833) c0 memory src/lib/alloc.c:1107 used 0 free 12288 [ 79.895830] ( 6.197917) c0 memory src/lib/alloc.c:1115 block 0 base 0xbe2c6000 size 64 [ 85.937497] ( 6.041667) c0 memory src/lib/alloc.c:1118 count 64 free 64 [ 92.135413] ( 6.197917) c0 memory src/lib/alloc.c:1115 block 1 base 0xbe2c7000 size 512 [ 98.229163] ( 6.093750) c0 memory src/lib/alloc.c:1118 count 8 free 8 [ 104.374996] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 2 base 0xbe2c8000 size 1024 [ 110.572912] ( 6.197917) c0 memory src/lib/alloc.c:1118 count 4 free 4 [ 116.562495] ( 5.989583) c0 memory src/lib/alloc.c:1135 heap: buffer status [ 122.604162] ( 6.041667) c0 memory src/lib/alloc.c:1105 heap: 0xbe145d40 size 1048576 blocks 1 caps 0x71 [ 129.010412] ( 6.406250) c0 memory src/lib/alloc.c:1107 used 206080 free 842496 [ 135.156245] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 0 base 0xbe145d40 size 256 [ 141.354161] ( 6.197917) c0 memory src/lib/alloc.c:1118 count 4096 free 3291 [ 147.656244] ( 6.302083) c0 memory src/lib/alloc.c:1105 heap: 0xbe801800 size 59392 blocks 1 caps 0x69 [ 153.802077] ( 6.145833) c0 memory src/lib/alloc.c:1107 used 0 free 59392 [ 159.947910] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 0 base 0xbe801800 size 384 [ 166.041660] ( 6.093750) c0 memory src/lib/alloc.c:1118 count 154 free 154 [ 171.979160] ( 5.937500) c0 memory src/lib/alloc.c:1137 heap: runtime status [ 178.124993] ( 6.145833) c0 memory src/lib/alloc.c:1105 heap: 0xbe2d0000 size 65536 blocks 7 caps 0x45 [ 184.270826] ( 6.145833) c0 memory src/lib/alloc.c:1107 used 24064 free 41472 [ 190.520826] ( 6.250000) c0 memory src/lib/alloc.c:1115 block 0 base 0xbe2d0000 size 64 [ 196.458326] ( 5.937500) c0 memory src/lib/alloc.c:1118 count 128 free 124 [ 202.760409] ( 6.302083) c0 memory src/lib/alloc.c:1115 block 1 base 0xbe2d2000 size 128 [ 208.697908] ( 5.937500) c0 memory src/lib/alloc.c:1118 count 128 free 92 [ 214.843741] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 2 base 0xbe2d6000 size 256 [ 220.781241] ( 5.937500) c0 memory src/lib/alloc.c:1118 count 96 free 45 [ 226.927074] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 3 base 0xbe2dc000 size 512 [ 232.968741] ( 6.041667) c0 memory src/lib/alloc.c:1118 count 8 free 8 [ 239.114574] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 4 base 0xbe2dd000 size 1024 [ 245.156240] ( 6.041667) c0 memory src/lib/alloc.c:1118 count 4 free 4 [ 251.302073] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 5 base 0xbe2de000 size 2048 [ 257.343740] ( 6.041667) c0 memory src/lib/alloc.c:1118 count 2 free 1 [ 263.489573] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 6 base 0xbe2df000 size 4096 [ 269.531239] ( 6.041667) c0 memory src/lib/alloc.c:1118 count 1 free 0 [ 275.416656] ( 5.885417) c0 memory src/lib/alloc.c:1140 heap: runtime shared status [ 281.406239] ( 5.989583) c0 memory src/lib/alloc.c:1105 heap: 0x9e25d000 size 262144 blocks 5 caps 0x65 [ 287.552072] ( 6.145833) c0 memory src/lib/alloc.c:1107 used 22272 free 239872 [ 293.697905] ( 6.145833) c0 memory src/lib/alloc.c:1115 block 0 base 0x9e25d000 size 64 [ 299.635405] ( 5.937500) c0 memory src/lib/alloc.c:1118 count 512 free 346 [ 305.729155] ( 6.093750) c0 memory src/lib/alloc.c:1115 block 1 base 0x9e265000 size 128 [ 311.770821] ( 6.041667) c0 memory src/lib/alloc.c:1118 count 512 free 489 [ 359.114569] ( 47.343750) c0 memory src/lib/alloc.c:1115 block 2 base 0x9e275000 size 256 [ 365.208319] ( 6.093750) c0 memory src/lib/alloc.c:1118 count 384 free 368 [ 371.302069] ( 6.093750) c0 memory src/lib/alloc.c:1115 block 3 base 0x9e28d000 size 512 [ 377.395818] ( 6.093750) c0 memory src/lib/alloc.c:1118 count 32 free 25 [ 383.489568] ( 6.093750) c0 memory src/lib/alloc.c:1115 block 4 base 0x9e291000 size 1024 [ 389.635401] ( 6.145833) c0 memory src/lib/alloc.c:1118 count 16 free 15 [ 395.572901] ( 5.937500) c0 memory src/lib/alloc.c:1142 heap: system shared status [ 401.614567] ( 6.041667) c0 memory src/lib/alloc.c:1105 heap: 0x9e29d000 size 5376 blocks 0 caps 0x45 [ 407.708317] ( 6.093750) c0 memory src/lib/alloc.c:1107 used 3200 free 2176 [ 809.010385] ( 401.302063) c0 pipe 10.62 ......./pipeline-graph.c:300 pipeline complete, clock freq 400000000Hz [ 1132.656205] ( 323.645813) c0 pipe 9.56 ......./pipeline-graph.c:300 pipeline complete, clock freq 400000000Hz [ 1484.947858] ( 352.291656) c0 pipe 8.48 ......./pipeline-graph.c:300 pipeline complete, clock freq 400000000Hz [ 1797.031179] ( 312.083313) c0 pipe 7.42 ......./pipeline-graph.c:300 pipeline complete, clock freq 400000000Hz [ 2099.062417] ( 302.031250) c0 pipe 6.36 ......./pipeline-graph.c:300 pipeline complete, clock freq 400000000Hz [ 2415.989487] ( 316.927063) c0 pipe 5.30 ......./pipeline-graph.c:300 pipeline complete, clock freq 400000000Hz [ 2660.572811] ( 244.583328) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 2672.187394] ( 11.614583) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() --- negative DELTA = -34494.582 us: wrap, IPC_TRACE, other? --- [ 283682.384561] ( 0.000000) c1 pipe 4.24 src/ipc/helper-ipc3.c:802 buffer new size 0x480 id 536847296.73731 flags 0x5d5063 Found valid LDC address after skipping 12 bytes (one line uses 20 + 0 to 16 bytes) [ 35095.519439] ( 35095.519531) c0 pipe 2.12 ......./pipeline-graph.c:300 pipeline complete, clock freq 400000000Hz [ 35316.248597] ( 220.729156) c0 pipe 1.6 ......./pipeline-graph.c:300 pipeline complete, clock freq 400000000Hz [ 35612.342335] ( 296.093750) c0 demux 11.64 src/audio/mux/mux.c:343 mux_cmd() cmd = 0x00000066 [ 35618.956918] ( 6.614583) c0 demux 11.64 src/audio/mux/mux.c:284 mux_ctrl_set_cmd(), cdata->cmd = 0x00000003 [ 35625.154834] ( 6.197917) c0 demux 11.64 src/audio/mux/mux.c:100 mux_set_values() [ 36308.279807] ( 683.125000) c0 selector 10.58 ..../selector/selector.c:322 selector_cmd() [ 36314.946474] ( 6.666667) c0 selector 10.58 ..../selector/selector.c:251 selector_ctrl_set_data(), SOF_CTRL_CMD_BINARY [ 38100.050569] ( 1785.104126) c0 pga 9.50 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 0, value = 65536 [ 38107.810986] ( 7.760417) c0 pga 9.50 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 1, value = 65536 [ 38708.904712] ( 601.093750) c0 pga 8.44 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 0, value = 65536 [ 38716.717212] ( 7.812500) c0 pga 8.44 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 1, value = 65536 [ 39380.467185] ( 663.750000) c0 pga 7.38 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 0, value = 65536 [ 39388.279685] ( 7.812500) c0 pga 7.38 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 1, value = 65536 [ 40056.144242] ( 667.864563) c0 pga 6.32 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 0, value = 65536 [ 40064.477575] ( 8.333333) c0 pga 6.32 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 1, value = 65536 [ 40769.060880] ( 704.583313) c0 pga 5.26 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 0, value = 65536 [ 40777.290046] ( 8.229166) c0 pga 5.26 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 1, value = 65536 [ 41473.748352] ( 696.458313) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY Found valid LDC address after skipping 12 bytes (one line uses 20 + 0 to 16 bytes) --- negative DELTA = -38468.436 us: wrap, IPC_TRACE, other? --- [ 286687.696941] ( 0.000000) c0 unknown ......./pipeline-graph.c:113 pipeline new pipe_id 8 priority 0 [ 361.249986] ( 361.250000) c0 component src/ipc/helper-ipc3.c:264 comp new pga type 57347 id 6261791.0 Found valid LDC address after skipping 12 bytes (one line uses 20 + 0 to 16 bytes) [ 39455.519266] ( 39094.269531) c0 pga 3.14 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 1, value = 65536 [ 40098.487990] ( 642.968750) c0 pga 2.8 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 0, value = 65536 [ 40106.560906] ( 8.072916) c0 pga 2.8 ../audio/volume/volume.c:560 volume_ctrl_set_cmd(), channel = 1, value = 65536 [ 76096.090726] ( 35989.531250) c0 ipc src/ipc/handler-ipc3.c:605 ipc: pm -> restore [ 78898.226032] ( 2802.135254) c0 dai src/lib/dai.c:164 dai_get type 1 index 1 new sref 3 [ 78907.444781] ( 9.218750) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:172 ssp_set_config(), config->format = 0x4005 [ 78932.132280] ( 24.687498) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:599 ssp_set_config(), sscr0 = 0xc7d0003f, sscr1 = 0xd0700000, ssto = 0x00000000, sspsp = 0x10004 [ 78938.434363] ( 6.302083) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:601 ssp_set_config(), sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000, ssioc = 0x00000020 [ 78944.476030] ( 6.041667) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:603 ssp_set_config(), ssrsa = 0x000000ff, sstsa = 0x0000000f [ 78951.507279] ( 7.031250) c0 dai src/lib/dai.c:188 dai_put type 1 index 1 new sref 2 [ 78962.236446] ( 10.729166) c0 dai 1.5 src/audio/dai.c:706 dai_config() dai type = 1 index = 1 dd 0x9e275000 [ 79009.423944] ( 47.187500) c0 dai 11.67 src/audio/dai.c:706 dai_config() dai type = 1 index = 1 dd 0x9e275900 [ 79032.809360] ( 23.385416) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 79044.684359] ( 11.875000) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() [ 79612.705170] ( 568.020813) c0 pipe 1.6 ....../pipeline-params.c:217 pipe params dir 0 frame_fmt 0 buffer_fmt 0 rate 48000 [ 79619.684336] ( 6.979167) c0 pipe 1.6 ....../pipeline-params.c:221 pipe params stream_tag 1 channels 2 sample_valid_bytes 2 sample_container_bytes 2 [ 79826.871828] ( 207.187485) c0 dai 1.5 src/audio/dai.c:357 dai_data_config() dai type = 1 index = 1 dd 0x9e275000 [ 79989.996821] ( 163.125000) c0 dai 1.5 src/audio/dai.c:442 dai_playback_params() dest_dev = 4 stream_id = 0 src_width = 4 dest_width = 4 [ 79997.132238] ( 7.135417) c0 dai 1.5 src/audio/dai.c:448 dai_playback_params() fifo 0x77210 [ 80012.184321] ( 15.052083) c0 pipe 1.6 ....../pipeline-params.c:303 pipe prepare [ 80185.621814] ( 173.437500) c0 dai 1.5 src/audio/dai.c:821 dai_prepare() [ 80192.288480] ( 6.666667) c0 dai 1.5 src/audio/dai.c:769 dai_config_prepare(), channel = 0 [ 80198.590563] ( 6.302083) c0 dw-dma src/drivers/dw/dma.c:191 dw_dma_channel_get(): dma 0 request channel 0 [ 80206.663480] ( 8.072916) c0 dai 1.5 src/audio/dai.c:786 dai_config(): new configured dma channel index 0 [ 82181.923818] ( 1975.260376) c0 pipe 1.6 ....../pipeline-stream.c:184 pipe trigger cmd 1 [ 82297.652980] ( 115.729164) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:841 ssp_trigger() cmd 1 [ 82306.038396] ( 8.385416) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:630 ssp_pre_start() [ 82315.621729] ( 9.583333) c0 mn ./drivers/intel/ssp/mn.c:258 mclk_rate 24576000, mclk_source_clock 0 [ 82321.871729] ( 6.250000) c0 mn ./drivers/intel/ssp/mn.c:220 mclk_id 0 mdivr_val 1 [ 82331.194645] ( 9.322916) c0 mn ./drivers/intel/ssp/mn.c:320 find_mn for freq 24576000 bclk 12288000 [ 82338.850895] ( 7.656250) c0 mn ./drivers/intel/ssp/mn.c:617 bclk_rate 12288000, *out_scr_div 2, m 1, n 1 [ 82346.038395] ( 7.187500) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:686 ssp_set_config(), sscr0 = 0xc7d0017f [ 82352.861311] ( 6.822917) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:758 ssp_start() [ 82452.548807] ( 99.687492) c0 ll-schedule ./schedule/ll_schedule.c:413 task add 0xbe2d0180 pipe-task [ 82458.902973] ( 6.354167) c0 ll-schedule ./schedule/ll_schedule.c:417 task params pri 0 flags 0 start 0 period 1000 [ 82474.007139] ( 15.104166) c0 ll-schedule ./schedule/ll_schedule.c:329 new added task->start 7100473 at 7087864 [ 82479.944639] ( 5.937500) c0 ll-schedule ./schedule/ll_schedule.c:332 num_tasks 2 total_num_tasks 2 [ 216630.512225] ( 134150.562500) c0 dai src/lib/dai.c:164 dai_get type 1 index 1 new sref 3 [ 216639.783058] ( 9.270833) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:167 ssp_set_config(): playback/capture active. Ignore config [ 216646.762225] ( 6.979167) c0 dai src/lib/dai.c:188 dai_put type 1 index 1 new sref 2 [ 216657.230974] ( 10.468750) c0 dai 1.5 src/audio/dai.c:706 dai_config() dai type = 1 index = 1 dd 0x9e275000 [ 216663.376807] ( 6.145833) c0 dai 1.5 src/audio/dai.c:710 dai_config(): Component is in active state. Ignore config [ 216702.699722] ( 39.322914) c0 dai 11.67 src/audio/dai.c:706 dai_config() dai type = 1 index = 1 dd 0x9e275900 [ 216726.033055] ( 23.333332) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 216737.751804] ( 11.718750) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() [ 217618.845519] ( 881.093689) c0 pipe 11.68 ....../pipeline-params.c:217 pipe params dir 1 frame_fmt 0 buffer_fmt 0 rate 48000 [ 217626.137186] ( 7.291667) c0 pipe 11.68 ....../pipeline-params.c:221 pipe params stream_tag 1 channels 2 sample_valid_bytes 2 sample_container_bytes 2 [ 217825.512178] ( 199.374985) c0 demux 11.64 src/audio/mux/mux.c:265 mux_params() [ 217842.335094] ( 16.822916) c0 dai 11.67 src/audio/dai.c:357 dai_data_config() dai type = 1 index = 1 dd 0x9e275900 [ 218016.970503] ( 174.635406) c0 dai 11.67 src/audio/dai.c:509 dai_capture_params() src_dev = 5 stream_id = 0 src_width = 4 dest_width = 4 [ 218023.793420] ( 6.822917) c0 dai 11.67 src/audio/dai.c:515 dai_capture_params() fifo 0x77210 [ 218038.949669] ( 15.156249) c0 pipe 11.68 ....../pipeline-params.c:303 pipe prepare [ 218072.543418] ( 33.593750) c0 demux 11.64 src/audio/mux/mux.c:649 mux_prepare() [ 218098.533000] ( 25.989582) c0 dai 11.67 src/audio/dai.c:821 dai_prepare() [ 218105.772583] ( 7.239583) c0 dai 11.67 src/audio/dai.c:769 dai_config_prepare(), channel = 0 [ 218111.970500] ( 6.197917) c0 dw-dma src/drivers/dw/dma.c:191 dw_dma_channel_get(): dma 1 request channel 0 [ 218119.939249] ( 7.968750) c0 dai 11.67 src/audio/dai.c:786 dai_config(): new configured dma channel index 0 [ 220040.876673] ( 1920.937378) c0 pipe 11.68 ....../pipeline-stream.c:184 pipe trigger cmd 1 [ 220114.730837] ( 73.854164) c0 demux 11.64 src/audio/mux/mux.c:705 mux_trigger(), command = 1 [ 220134.210003] ( 19.479166) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:841 ssp_trigger() cmd 1 [ 220142.074586] ( 7.864583) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:630 ssp_pre_start() [ 220149.574585] ( 7.500000) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:758 ssp_start() [ 220247.543331] ( 97.968742) c0 ll-schedule ./schedule/ll_schedule.c:413 task add 0xbe2d0240 pipe-task [ 220254.001665] ( 6.458333) c0 ll-schedule ./schedule/ll_schedule.c:417 task params pri 0 flags 0 start 0 period 1000 [ 220269.522497] ( 15.520833) c0 ll-schedule ./schedule/ll_schedule.c:329 new added task->start 9750073 at 9733538 [ 220275.459997] ( 5.937500) c0 ll-schedule ./schedule/ll_schedule.c:332 num_tasks 3 total_num_tasks 3 [ 221224.105793] ( 948.645813) c0 Maxim DSM 1.1 ../smart_amp_maxim_dsm.c:752 WARN [DSM] feedback frame size zero warning. [ 221230.772459] ( 6.666667) c0 buffer 1.4 src/audio/buffer.c:242 comp_update_buffer_consume(), no bytes to consume, source->comp.id = 64, source->comp.type = 18, sink->comp.id = 1, sink->comp.type = 21 [ 221237.855792] ( 7.083333) c0 Maxim DSM 1.1 ../smart_amp_maxim_dsm.c:692 WARN [DSM] feed forward frame size zero warning. [ 221244.157875] ( 6.302083) c0 buffer 1.2 src/audio/buffer.c:242 comp_update_buffer_consume(), no bytes to consume, source->comp.id = 0, source->comp.type = 1, sink->comp.id = 1, sink->comp.type = 21 [ 221250.407875] ( 6.250000) c0 buffer 1.3 src/audio/buffer.c:202 comp_update_buffer_produce(), no bytes to produce, source->comp.id = 1, source->comp.type = 21, sink->comp.id = 5, sink->comp.type = 2 [ 246204.208967] ( 24953.800781) c1 idc ......./intel/cavs/idc.c:58 idc_irq_handler(), IPC_IDCTFC_BUSY [ 246215.979800] ( 11.770833) c1 idc ......./intel/cavs/idc.c:165 idc_do_cmd() [ 246235.458965] ( 19.479166) c1 pipe 4.24 ....../pipeline-params.c:217 pipe params dir 1 frame_fmt 2 buffer_fmt 0 rate 48000 Skipped 12 bytes after the last statement. Potential mailbox wrap, check the start of the output for later logs.