sof
sof copied to clipboard
thesofproject
[BUG] 14_11_TestMuxSimpleStreamOperations SofIpcErrorResponseException occured
Describe the bug Bug was found in: 14_11_TestMuxSimpleStreamOperations8000Hz16b16b2ch 14_11_TestMuxSimpleStreamOperations16000Hz24b32b4ch 14_11_TestMuxSimpleStreamOperations24000Hz32b32b8ch 14_11_TestMuxSimpleStreamOperations48000Hz32b32b4ch
the content of the error: ERROR:Exception SofIpcErrorResponseException occurred at 'C:\work\_KK\cavs_scripts-py\utilities\ipc_driver.py':730 FW replied with error. Error code: -22 0x00000005 0x00000000 0x00004000
**Last working build: SOF_FW_MASTER_01.01.00.2602 hash: 6b650bd95fe003cc8f13715aa53feb293e629b70 **
Topology
pipe_plb
+----------------------+
| +-------+ +------+ |
| | Host1 |-->| Buff |----+
| +-------+ +------+ | | pipe_plb
+----------------------+ | +--------------------------------+
+---->+-----+ +------+ +-----+ | +------+
| | Mux |-->| Buff |-->| Dai |------->| SSPx |
pipe_plb +---->+-----+ +------+ +-----+ | +------+
+----------------------+ | +--------------------------------+ |
| +-------+ +------+ | | |
| | Host2 |-->| Buff |----+ |
| +-------+ +------+ | |
+----------------------+ |
|
|
pipe_cap |
+-------------------------------+ |
| +------+ +------+ +-----+ | +------+ |
| | Host |<--| Buff |<--| Dai |<----| SSPx |<--------------------------<
| +------+ +------+ +-----+ | +------+
+-------------------------------+
Description: "Muxing" two playback pipelines into one using Mux component. Loopback signal on external SSP connection. While pipelines are working pause and resume operation are done on playback stream.
To Reproduce Run tests with diagnostic driver 14_11_TestMuxSimpleStreamOperations8000Hz16b16b2ch 14_11_TestMuxSimpleStreamOperations16000Hz24b32b4ch 14_11_TestMuxSimpleStreamOperations24000Hz32b32b8ch 14_11_TestMuxSimpleStreamOperations48000Hz32b32b4ch
Reproduction Rate 100%
Environment
- Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- SOF BRANCH: main HASH: c5ac4a44b9cc1e8431852afcec9c13dfc0ad1257
- Name of the platform(s) on which the bug is observed.
- Platform: ICL RVP, WHL RVP, TGL RVP, APL RVP
- Test environment: BRANCH: master HASH: 87f66648e4e19d251077cd31486494bc668d3aaa
Screenshots or console output
[ 2080577.916667] ( 25.781250) c0 dai 3.7 src/audio/dai.c:963 WARN dai_copy(): nothing to copy
[ 2083390.885417] ( 2812.968750) c0 pipe 2.5 ....../pipeline-stream.c:263 pipe trigger cmd 9
[ 2083403.567708] ( 12.682292) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 2083411.927083] ( 8.359375) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 0 flags 0 start 0 period 1000
[ 2083424.322917] ( 12.395833) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 96524892 at 96524704
[ 2083433.567708] ( 9.244792) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 6 total_num_tasks 6
[ 2083499.427083] ( 65.859375) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 9
[ 2083513.541667] ( 14.114583) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 1
[ 2083521.848958] ( 8.307292) c0 mux 3.6 src/audio/component.c:62 comp_set_state(), state already set to 5
[ 2083546.119792] ( 24.270834) c0 dai 3.7 src/audio/dai.c:963 WARN dai_copy(): nothing to copy
[ 3085820.729167] ( 1002274.625000) c0 pipe 1.2 ....../pipeline-stream.c:263 pipe trigger cmd 2
[ 3085831.953125] ( 11.223958) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 2
[ 3085842.447917] ( 10.494792) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe080080 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 3085852.265625] ( 9.817708) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 5 total_num_tasks 5
[ 3087631.822917] ( 1779.557251) c0 pipe 2.5 ....../pipeline-stream.c:263 pipe trigger cmd 2
[ 3087643.046875] ( 11.223958) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 2
[ 3087654.322917] ( 11.276042) c0 dw-dma src/drivers/dw/dma.c:370 dw_dma_pause(): dma 0 channel 0 pause
[ 3087663.619792] ( 9.296875) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1084 ssp_trigger() cmd 2
[ 3087673.046875] ( 9.427083) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1075 ssp_pause(), TX
[ 3087683.984375] ( 10.937500) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 3087694.401042] ( 10.416667) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 4 total_num_tasks 4
[ 3087703.203125] ( 8.802083) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe0800c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 3087712.656250] ( 9.453125) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 3 total_num_tasks 3
[ 4090592.864583] ( 1002880.187500) c0 pipe 1.2 ....../pipeline-stream.c:263 pipe trigger cmd 10
[ 4090605.052083] ( 12.187500) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe080080 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4090613.411458] ( 8.359375) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 0 flags 0 start 0 period 1000
[ 4090626.119792] ( 12.708333) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 173632092 at 173601255
[ 4090635.338542] ( 9.218750) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 4 total_num_tasks 4
[ 4090645.078125] ( 9.739583) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe0800c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4090654.036458] ( 8.958333) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 1 flags 0 start 0 period 1000
[ 4090666.718750] ( 12.682292) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 173632092 at 173602785
[ 4090675.729167] ( 9.010417) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 5 total_num_tasks 5
[ 4091482.291667] ( 806.562500) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 10
[ 4091494.401042] ( 12.109375) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1084 ssp_trigger() cmd 10
[ 4091503.177083] ( 8.776042) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:876 ssp_pre_start()
[ 4091512.734375] ( 9.557292) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:969 ssp_early_start(): SSE set for SSP0
[ 4091523.906250] ( 11.171875) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 3
[ 4091535.755208] ( 11.848958) c0 dw-dma src/drivers/dw/dma.c:348 dw_dma_release(): dma 0 channel 0 release
[ 4091545.390625] ( 9.635417) c0 dw-dma src/drivers/dw/dma.c:407 dw_dma_stop(): dma 0 channel 0 stop
[ 4091556.093750] ( 10.703125) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1084 ssp_trigger() cmd 3
[ 4091565.703125] ( 9.609375) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:983 ssp_start()
[ 4094535.260417] ( 2969.557373) c0 pipe 2.5 ....../pipeline-stream.c:263 pipe trigger cmd 10
[ 4094547.708333] ( 12.447917) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4094556.067708] ( 8.359375) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 0 flags 0 start 0 period 1000
[ 4094568.593750] ( 12.526042) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 173785692 at 173752645
[ 4094577.864583] ( 9.270833) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 6 total_num_tasks 6
[ 4095496.901042] ( 919.036438) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 10
[ 4095505.572917] ( 8.671875) c0 mux 3.6 src/audio/component.c:124 ERROR comp_set_state(): wrong state = 5, COMP_TRIGGER_PRE_RELEASE
[ 4095514.401042] ( 8.828125) c0 pipe 2.5 ....../pipeline-stream.c:318 ERROR pipeline_trigger_run(): ret = -22, host->comp.id = 3, cmd = 10
[ 4095523.359375] ( 8.958333) c0 pipe 2.5 ..../pipeline-schedule.c:73 ERROR pipeline_task(): failed to trigger components: -22
[ 4095534.973958] ( 11.614583) c0 ll-schedule ./schedule/ll_schedule.c:115 task complete 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
Skipped 0 bytes after the last statement. Wrap possible, check the start of the output for later logs.
@wszypelt can you check with https://github.com/thesofproject/sof/pull/4715
@lgirdwood with #4715 unfortunately still the same error
ERROR:Exception SofIpcErrorResponseException occurred at 'C:\work\_KK\cavs_scripts-py\utilities\ipc_driver.py':730 FW replied with error. Error code: -22 0x00000005 0x00000000 0x00004000
[ 2064741.041667] ( 9.088542) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 4 total_num_tasks 4
[ 2064750.807292] ( 9.765625) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe0800c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 2064759.791667] ( 8.984375) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 1 flags 0 start 0 period 1000
[ 2064772.447917] ( 12.656250) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 95507495 at 95505229
[ 2064781.484375] ( 9.036458) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 5 total_num_tasks 5
[ 2064882.630208] ( 101.145836) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 9
[ 2064895.416667] ( 12.786458) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1093 ssp_trigger() cmd 9
[ 2064904.088542] ( 8.671875) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:885 ssp_pre_start()
[ 2064913.723958] ( 9.635417) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:978 ssp_early_start(): SSE set for SSP0
[ 2064929.192708] ( 15.468750) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 1
[ 2064944.713542] ( 15.520833) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1093 ssp_trigger() cmd 1
[ 2064954.427083] ( 9.713542) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:992 ssp_start()
[ 2064979.505208] ( 25.078125) c0 dai 3.7 src/audio/dai.c:963 WARN dai_copy(): nothing to copy
[ 2066771.041667] ( 1791.536499) c0 pipe 2.5 ....../pipeline-stream.c:263 pipe trigger cmd 9
[ 2066783.359375] ( 12.317708) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 2066791.770833] ( 8.411458) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 0 flags 0 start 0 period 1000
[ 2066804.557292] ( 12.786458) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 95584295 at 95583292
[ 2066813.645833] ( 9.088542) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 6 total_num_tasks 6
[ 2066896.927083] ( 83.281250) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 9
[ 2066911.484375] ( 14.557292) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 1
[ 2066919.739583] ( 8.255208) c0 mux 3.6 src/audio/component.c:62 comp_set_state(), state already set to 5
[ 2066944.270833] ( 24.531250) c0 dai 3.7 src/audio/dai.c:963 WARN dai_copy(): nothing to copy
[ 3068943.333333] ( 1001999.062500) c0 pipe 1.2 ....../pipeline-stream.c:263 pipe trigger cmd 2
[ 3068954.531250] ( 11.197917) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 2
[ 3068965.078125] ( 10.546875) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe080080 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 3068974.739583] ( 9.661458) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 5 total_num_tasks 5
[ 3070620.390625] ( 1645.651001) c0 pipe 2.5 ....../pipeline-stream.c:263 pipe trigger cmd 2
[ 3070631.380208] ( 10.989583) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 2
[ 3070642.578125] ( 11.197917) c0 dw-dma src/drivers/dw/dma.c:370 dw_dma_pause(): dma 0 channel 0 pause
[ 3070651.927083] ( 9.348958) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1093 ssp_trigger() cmd 2
[ 3070661.197917] ( 9.270833) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1084 ssp_pause(), TX
[ 3070672.005208] ( 10.807292) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 3070681.536458] ( 9.531250) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 4 total_num_tasks 4
[ 3070690.338542] ( 8.802083) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe0800c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 3070701.406250] ( 11.067708) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 3 total_num_tasks 3
[ 4072704.270833] ( 1002002.875000) c0 pipe 1.2 ....../pipeline-stream.c:263 pipe trigger cmd 10
[ 4072716.614583] ( 12.343750) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe080080 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4072724.973958] ( 8.359375) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 0 flags 0 start 0 period 1000
[ 4072738.020833] ( 13.046875) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 172614695 at 172611135
[ 4072747.161458] ( 9.140625) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 4 total_num_tasks 4
[ 4072756.979167] ( 9.817708) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe0800c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4072765.989583] ( 9.010417) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 1 flags 0 start 0 period 1000
[ 4072778.671875] ( 12.682292) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 172614695 at 172612668
[ 4072787.682292] ( 9.010417) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 5 total_num_tasks 5
[ 4072883.125000] ( 95.442711) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 10
[ 4072895.156250] ( 12.031250) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1093 ssp_trigger() cmd 10
[ 4072903.906250] ( 8.750000) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:885 ssp_pre_start()
[ 4072913.463542] ( 9.557292) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:978 ssp_early_start(): SSE set for SSP0
[ 4072924.583333] ( 11.119792) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 3
[ 4072936.302083] ( 11.718750) c0 dw-dma src/drivers/dw/dma.c:348 dw_dma_release(): dma 0 channel 0 release
[ 4072946.041667] ( 9.739583) c0 dw-dma src/drivers/dw/dma.c:407 dw_dma_stop(): dma 0 channel 0 stop
[ 4072956.848958] ( 10.807292) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1093 ssp_trigger() cmd 3
[ 4072966.328125] ( 9.479167) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:992 ssp_start()
[ 4075426.015625] ( 2459.687500) c0 pipe 2.5 ....../pipeline-stream.c:263 pipe trigger cmd 10
[ 4075438.489583] ( 12.473958) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4075447.083333] ( 8.593750) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 0 flags 0 start 0 period 1000
[ 4075459.843750] ( 12.760417) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 172729895 at 172715654
[ 4075469.088542] ( 9.244792) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 6 total_num_tasks 6
[ 4075894.739583] ( 425.651031) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 10
[ 4075903.437500] ( 8.697917) c0 mux 3.6 src/audio/component.c:124 ERROR comp_set_state(): wrong state = 5, COMP_TRIGGER_PRE_RELEASE
[ 4075912.395833] ( 8.958333) c0 pipe 2.5 ....../pipeline-stream.c:318 ERROR pipeline_trigger_run(): ret = -22, host->comp.id = 3, cmd = 10
[ 4075921.145833] ( 8.750000) c0 pipe 2.5 ..../pipeline-schedule.c:73 ERROR pipeline_task(): failed to trigger components: -22
[ 4075932.994792] ( 11.848958) c0 ll-schedule ./schedule/ll_schedule.c:115 task complete 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
Skipped 0 bytes after the last statement. Wrap possible, check the start of the output for later logs.
@wszypelt could you explain what these tests are - I don't see them in the list of PR QB tests? Are they new or are they only run manually, not as a part of CI? With this specific failure the fix might be rather simple, but I'd like to be able to re-test the fix?
@wszypelt are you able to check HEAD now with #4722 on top (one other fix is in head).
@lgirdwood Unfortunately #4722 doesn't fix this issue. Logs: ICL_14_11.zip
@lyakh Tests are from internal Intel repository. In CI we test quickly and don't run all tests from our scope.
Looks like MUX state transition is broken.
[ 3128629.010417] ( 8.151042) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe0800c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 3128636.796875] ( 7.786458) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 1 flags 0 start 0 period 1000
[ 3128648.463542] ( 11.666667) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 138502393 at 138496874
[ 3128655.546875] ( 7.083333) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 5 total_num_tasks 5
[ 3128845.156250] ( 189.609375) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 9
[ 3128857.864583] ( 12.708333) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1084 ssp_trigger() cmd 9
[ 3128866.822917] ( 8.958333) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:876 ssp_pre_start()
[ 3128876.354167] ( 9.531250) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:969 ssp_early_start(): SSE set for SSP0
[ 3128892.005208] ( 15.651042) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 1
[ 3128906.666667] ( 14.661458) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1084 ssp_trigger() cmd 1
[ 3128917.083333] ( 10.416667) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:983 ssp_start()
[ 3128942.812500] ( 25.729166) c0 dai 3.7 src/audio/dai.c:963 WARN dai_copy(): nothing to copy
[ 3130643.125000] ( 1700.312500) c0 pipe 2.5 ....../pipeline-stream.c:263 pipe trigger cmd 9
[ 3130655.651042] ( 12.526042) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 3130664.218750] ( 8.567708) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 0 flags 0 start 0 period 1000
[ 3130676.718750] ( 12.500000) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 138579193 at 138574756
[ 3130685.989583] ( 9.270833) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 6 total_num_tasks 6
[ 3130857.343750] ( 171.354172) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 9
[ 3130871.614583] ( 14.270833) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 1
[ 3130879.895833] ( 8.281250) c0 mux 3.6 src/audio/component.c:62 comp_set_state(), state already set to 5
[ 3130905.546875] ( 25.651041) c0 dai 3.7 src/audio/dai.c:963 WARN dai_copy(): nothing to copy
[ 4143022.500000] ( 1012116.937500) c0 pipe 1.2 ....../pipeline-stream.c:263 pipe trigger cmd 2
[ 4143033.776042] ( 11.276042) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 2
[ 4143044.140625] ( 10.364583) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe080080 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4143053.932292] ( 9.791667) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 5 total_num_tasks 5
[ 4144284.375000] ( 1230.442749) c0 pipe 2.5 ....../pipeline-stream.c:263 pipe trigger cmd 2
[ 4144295.520833] ( 11.145833) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 2
[ 4144306.744792] ( 11.223958) c0 dw-dma src/drivers/dw/dma.c:370 dw_dma_pause(): dma 0 channel 0 pause
[ 4144316.015625] ( 9.270833) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1084 ssp_trigger() cmd 2
[ 4144325.364583] ( 9.348958) c0 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1075 ssp_pause(), TX
[ 4144336.328125] ( 10.963542) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe080140 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4144346.822917] ( 10.494792) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 4 total_num_tasks 4
[ 4144355.703125] ( 8.880208) c0 ll-schedule ./schedule/ll_schedule.c:516 task cancel 0xbe0800c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 4144365.234375] ( 9.531250) c0 ll-schedule ./schedule/ll_schedule.c:336 num_tasks 3 total_num_tasks 3
[ 5157545.494792] ( 1013180.250000) c0 pipe 1.2 ....../pipeline-stream.c:263 pipe trigger cmd 10
[ 5157557.734375] ( 12.239583) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe080080 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 5157566.119792] ( 8.385417) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 0 flags 0 start 0 period 1000
[ 5157578.776042] ( 12.656250) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 216415993 at 216407794
[ 5157587.968750] ( 9.192708) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 4 total_num_tasks 4
[ 5157597.630208] ( 9.661458) c0 ll-schedule ./schedule/ll_schedule.c:390 task add 0xbe0800c0 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[ 5157606.666667] ( 9.036458) c0 ll-schedule ./schedule/ll_schedule.c:394 task params pri 1 flags 0 start 0 period 1000
[ 5157619.375000] ( 12.708333) c0 ll-schedule ./schedule/ll_schedule.c:306 new added task->start 216415993 at 216409323
[ 5157628.385417] ( 9.010417) c0 ll-schedule ./schedule/ll_schedule.c:309 num_tasks 5 total_num_tasks 5
[ 5157846.848958] ( 218.463547) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 10
[ 5157857.083333] ( 10.234375) c0 mux 3.6 src/audio/mux/mux.c:703 mux_trigger(), command = 3
[ 5157865.416667] ( 8.333333) c0 mux 3.6 src/audio/component.c:77 ERROR comp_set_state(): wrong state = 4, COMP_TRIGGER_RELEASE
[ 5157874.140625] ( 8.723958) c0 pipe 1.2 ....../pipeline-stream.c:348 ERROR pipeline_trigger(): ret = -22, host->comp.id = 0, cmd = 10
[ 5157882.734375] ( 8.593750) c0 pipe 1.2 ..../pipeline-schedule.c:73 ERROR pipeline_task(): failed to trigger components: -22
[ 5157893.671875] ( 10.937500) c0 ll-schedule ./schedule/ll_schedule.c:115 task complete 0xbe080080 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
