thesofproject
[BUG][IPC4] enabling volume and mixer in cavs-nocodec tplg causes some IPC errors
Describe the bug Yesterday, we enabled the volume and mixer in cavs-nocodec tplg:https://github.com/thesofproject/sof/commit/5594ad3512830feaa478677718036ffabf51a454
This will cause some IPC errors on IPC4-NOCODEC platforms. Inner test ID:16105
Both IPC4 tester and SOF IPC4-Zephyr firmware have same issues. It can be triggered with some different cases like:
check-playback-50rounds.sh,check-signal-stop-start-playback-50.sh,multiple-pause-resume-50.sh .etc.
DMESG
[ 1662.311935] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc4 set pipeline 0 state 3
[ 1662.311938] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x13000003|0x0: GLB_SET_PIPELINE_STATE
[ 1662.312140] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[ 1662.312203] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x13000003|0x0: GLB_SET_PIPELINE_STATE
[ 1662.312209] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc4 set pipeline 0 state 4
[ 1662.312212] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x13000004|0x0: GLB_SET_PIPELINE_STATE
[ 1662.312558] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000007|0x0: GLB_SET_PIPELINE_STATE
[ 1662.312562] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 7 - Unsupported operation requested
[ 1662.312596] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x13000004|0x0
[ 1662.312603] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set state 4 for pipeline 1
[ 1662.312606] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -22
[ 1662.312610] kernel: Port0: ASoC: trigger FE cmd: 1 failed: -22
[ 1662.312614] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[ 1662.312636] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x140000 successful
[ 1662.312658] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc4 set pipeline 0 state 2
[ 2171.879716] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[ 2171.879734] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc4 set pipeline 0 state 3
[ 2171.879743] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x13000003|0x0: GLB_SET_PIPELINE_STATE
[ 2171.890255] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000006|0x0: GLB_SET_PIPELINE_STATE
[ 2171.890261] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 6 - Unknown error while processing the request
[ 2171.890298] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x13000003|0x0
[ 2171.890309] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to pause pipeline 1
[ 2171.890335] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x20140000 successful
[ 2171.890362] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -22
[ 2171.890369] kernel: Port0: ASoC: trigger FE cmd: 0 failed: -22
MTRACE
[ 0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7c000 initialized
[ 0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7d000 initialized
*** Booting Zephyr OS build v3.2.0-rc1-2-g0956647aaf6b ***
[ 0.000000] <inf> main: SOF on intel_adsp_cavs25
[ 0.000000] <inf> power: pm_runtime_enable_dsp dsp_d0_sref 1
[ 0.000000] <inf> ll_schedule: dma_single_chan_domain_init(): num_dma 2, clk 4
[ 0.000000] <wrn> ll_schedule: zephyr_ll_scheduler_init(): unsupported domain 2
[ 0.000000] <inf> ipc: ipc_init()
[ 0.000000] <inf> idc: idc_init()
[ 0.000000] <inf> dma_trace: dma_trace_init_complete()
[ 0.000000] <inf> hda_dma: hda-dmac :4 -> probe
[ 0.000000] <inf> dma: dma_get() ID 4 sref = 1 busy channels 0
[ 0.000000] <inf> main: SOF initialized
[ 0.000000] <wrn> ll_schedule: zephyr_ll_scheduler_init(): unsupported domain 2
[ 0.000000] <inf> idc: idc_init()
[ 0.001000] <inf> ipc: rx : 0xc4000000|0x31400008
[ 0.001000] <wrn> basefw: returning success for Set SYSTEM_TIME without handling it
[ 0.001000] <inf> ipc: rx : 0xc4000000|0x3060004c
[ 0.002000] <inf> ipc: rx : 0x91000007|0x0
[ 0.002000] <inf> pipe: pipeline new pipe_id 0 priority 0
[ 0.002000] <inf> ipc: rx : 0xc0000004|0x15
[ 0.002000] <inf> ipc: buffer new size 0x180 id 0.0 flags 0x0
[ 0.002000] <inf> hda_dma: hda-dmac :5 -> probe
[ 0.002000] <inf> dma: dma_get() ID 5 sref = 1 busy channels 0
[ 0.002000] <inf> pipe: connect buffer 0 as sink
[ 0.003000] <inf> ipc: rx : 0xc0000006|0x10
[ 0.003000] <inf> module_adapter: module_init() start
[ 0.003000] <inf> module_adapter: module_init() done
[ 0.003000] <inf> ipc: rx : 0xc4000006|0x30000018
[ 0.003000] <inf> ipc: rx : 0xc0000002|0xa
[ 0.004000] <inf> ipc: rx : 0x91010006|0x0
[ 0.004000] <inf> pipe: pipeline new pipe_id 1 priority 0
[ 0.004000] <inf> ipc: rx : 0xc0000003|0x1000a
[ 0.004000] <inf> ipc: rx : 0xc0010006|0x10010
[ 0.004000] <inf> module_adapter: module_init() start
[ 0.004000] <inf> module_adapter: module_init() done
[ 0.004000] <inf> ipc: rx : 0xc4010006|0x30000018
[ 0.005000] <inf> ipc: rx : 0xc0010004|0x10029
[ 0.005000] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[ 0.005000] <inf> power: en_ssp_power index 0
[ 0.005000] <inf> power: en_ssp_power I2SLCTL 00000101
[ 0.005000] <inf> dai: dai_get type 1 index 0 new sref 1
[ 0.005000] <inf> dma: dma_get() ID 0 sref = 1 busy channels 0
[ 0.005000] <inf> ipc: dai_config() dai type = 1 index = 0 dd 0x9e089140
[ 0.005000] <inf> ssp_dai: ssp_set_config(), sscr0 = 0xc1d0077f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2200000
[ 0.005000] <inf> ssp_dai: ssp_set_config(), sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000
[ 0.005000] <err> ssp_dai: ssp_set_config(), ssioc = 0x00000020, ssrsa = 0x00000003, sstsa = 0x00000003
[ 0.005000] <inf> pipe: connect buffer 0 as source
[ 0.005000] <inf> ipc: rx : 0xc5000004|0x6
[ 0.005000] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[ 0.005000] <inf> pipe: connect buffer 0 as sink
[ 0.005000] <inf> pipe: connect buffer 0 as source
[ 0.006000] <inf> ipc: rx : 0xc5000006|0x2
[ 0.006000] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[ 0.006000] <inf> pipe: connect buffer 0 as sink
[ 0.006000] <inf> pipe: connect buffer 0 as source
[ 0.006000] <inf> ipc: rx : 0xc5000002|0x3
[ 0.006000] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[ 0.006000] <inf> pipe: connect buffer 0 as sink
[ 0.006000] <inf> pipe: connect buffer 0 as source
[ 0.006000] <inf> ipc: rx : 0xc5000003|0x10006
[ 0.006000] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[ 0.006000] <inf> pipe: connect buffer 0 as sink
[ 0.006000] <inf> pipe: connect buffer 0 as source
[ 0.006000] <inf> ipc: rx : 0xc5010006|0x10004
[ 0.006000] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[ 0.006000] <inf> pipe: connect buffer 0 as sink
[ 0.006000[ 0.860000] <inf> ipc: rx : 0x93000003|0x0
[ 0.860000] <inf> pipe: pipe trigger cmd 2
[ 0.861000] <err> copier: failed to find dai comp or sink pipeline not running.
[ 0.861000] <inf> ll_schedule: task complete 0xbe08b180 0x20240U
[ 0.861000] <inf> ll_schedule: num_tasks 2 total_num_tasks 2
[ 0.861000] <inf> ipc: rx : 0x93000002|0x0
[ 0.861000] <inf> pipe: pipe trigger cmd 0
[ 0.861000] <err> copier: failed to find dai comp or sink pipeline not running.
[ 0.861000] <inf> pipe: pipe reset
[ 0.862000] <inf> ipc: rx : 0x93010003|0x0
[ 0.862000] <inf> pipe: pipe trigger cmd 2
[ 0.862000] <inf> dw_dma: dw_dma_pause(): dma 0 channel 0 pause
[ 0.862000] <inf> ssp_dai: ssp_trigger() cmd 2
[ 0.862000] <inf> ssp_dai: ssp_pause(), TX
[ 0.862000] <inf> ll_schedule: task complete 0xbe08bc00 0x20240U
[ 0.862000] <inf> ll_schedule: num_tasks 1 total_num_tasks 1
[ 0.862000] <inf> ll_schedule: zephyr_domain_unregister domain->type 1 domain->clk 4
[ 0.862000] <inf> ipc: rx : 0x93010002|0x0
[ 0.862000] <inf> pipe: pipe trigger cmd 0
[ 0.862000] <inf> ssp_dai: ssp_trigger() cmd 0
[ 0.862000] <inf> ssp_dai: ssp_stop(), TX stop
[ 0.862000] <inf> dw_dma: dw_dma_stop(): dma 0 channel 0 stop
[ 0.862000] <inf> pipe: pipe reset
[ 0.862000] <inf> dai_comp: dai_reset()
[ 0.862000] <inf> dw_dma: dw_dma_stop(): dma 0 channel 0 stop
[ 0.862000] <inf> dw_dma: dw_dma_channel_put(): dma 0 channel 0 put
[ 1.000000] <inf> ipc: rx : 0x93000003|0x0
[ 1.001000] <inf> ipc: rx : 0x93000004|0x0
[ 1.001000] <inf> pipe: pipe prepare
[ 1.001000] <inf> pipe: pipe trigger cmd 7
[ 1.001000] <inf> ll_schedule: task add 0xbe08b180 0x20240U priority 0 flags 0x0
[ 1.001000] <inf> ll_schedule: zephyr_domain_register domain->type 1 domain->clk 4 domain->ticks_per_ms 38400 period 1000
[ 1.001000] <err> copier: failed to find dai comp or sink pipeline not running.
[ 1.001000] <err> copier: failed to find dai comp or sink pipeline not running.
[ 1.001000] <inf> host: no bytes to copy, 384 free in buffer, 0 available in DMA
[ 1.001000] <inf> ipc: rx : 0x93010003|0x0
[ 1.002000] <inf> ipc: rx : 0x93010004|0x0
[ 1.002000] <inf> ipc: dai_data_config() dai type = 1 index = 0 dd 0x9e089140
[ 1.002000] <inf> dai_comp: dai_playback_params() dest_dev = 2 stream_id = 0 src_width = 4 dest_width = 4
[ 1.002000] <inf> dai_comp: dai_playback_params() fifo 0x77010
[ 1.002000] <inf> pipe: pipe prepare
[ 1.002000] <inf> dai_comp: dai_prepare()
[ 1.002000] <inf> dai_comp: dai_config_prepare(), channel = 0
[ 1.002000] <inf> dw_dma: dw_dma_channel_get(): dma 0 request channel 0
[ 1.002000] <inf> dai_comp: dai_config_prepare(): new configured dma channel index 0
[ 1.002000] <inf> pipe: pipe trigger cmd 7
[ 1.002000] <inf> ll_schedule: task add 0xbe08bc00 0x20240U priority 0 flags 0x0
[ 1.003000] <inf> ssp_dai: ssp_trigger() cmd 7
[ 1.003000] <inf> ssp_dai: ssp_pre_start()
[ 1.003000] <inf> ssp_dai: ssp_trigger() cmd 1
[ 1.003000] <inf> ssp_dai: ssp_start()
[ 1.003000] <err> mixer: No source info
[ 1.003000] <err> pipe: pipeline_copy(): ret = -22, start->comp.id = 262145, dir = 1
[ 1.003000] <err> pipe: pipeline_task(): xrun recovery failed! pipeline is stopped.
[ 1.003000] <inf> ll_schedule: task complete 0xbe08bc00 0x20240U
[ 1.003000] <inf> ll_schedule: num_tasks 2 total_num_tasks 2
[ 1.004000] <err> mixer: No source info
[ 1.004000] <err> pipe: pipeline_copy(): ret = -22, start->comp.id = 131072, dir = 1
[ 1.004000] <err> pipe: pipeline_task(): xrun recovery failed! pipeline is stopped.
[ 1.004000] <inf> ll_schedule: task complete 0xbe08b180 0x20240U
[ 1.004000] <inf> ll_schedule: num_tasks 1 total_num_tasks 1
[ 1.004000] <inf> ll_schedule: zephyr_domain_unregister domain->type 1 domain->clk 4
[ 3.572000] <inf> ipc: rx : 0x93000003|0x0
[ 3.572000] <inf> pipe: pipe trigger cmd 2
[ 3.583000] <err> ipc: failed to wait schedule thread
[ 3.583000] <err> ipc: ipc4: failed to send delayed reply
[ 3.583000] <inf> ipc: rx : 0x93000003|0x0
[ 3.583000] <inf> pipe: pipe trigger cmd 2
[ 3.593000] <err> ipc: failed to wait schedule thread
[ 3.593000] <err> ipc: ipc4: failed to send delayed reply
[ 3.594000] <inf> ipc: rx : 0xc6000004|0x6
[ 3.594000] <wrn> ipc: ignoring unbinding of src 40000 and dst 60000
[ 3.594000] <inf> ipc: rx : 0xc6000006|0x2
[ 3.594000] <wrn> ipc: ignoring unbinding of src 60000 and dst 20000
[ 3.594000] <inf> ipc: rx : 0xc6000002|0x3
[ 3.594000] <inf> ipc: rx : 0x92000000|0x0
[ 3.595000] <inf> pipe: disconnect buffer 0 as sink
[ 3.595000] <inf> pipe: disconnect buffer 0 as source
[ 3.595000] <err> ipc: ipc_comp_free(): comp id: 262144 state is 5 cannot be freed
[ 3.595000] <err> ipc: ipc_pipeline_free(): module free () failed
[ 3.595000] <err> ipc: ipc4: 0 failed err 12
[ 3.595000] <inf> ipc: rx : 0xc6000003|0x10006
[ 3.595000] <wrn> ipc: ignoring unbinding of src 30000 and dst 60001
[ 3.595000] <inf> ipc: rx : 0xc6010006|0x10004
[ 3.595000] <wrn> ipc: ignoring unbinding of src 60001 and dst 40001
[ 3.595000] <inf> ipc: rx : 0x92010000|0x0
[ 3.595000] <inf> pipe: disconnect buffer 0 as sink
[ 3.595000] <inf> pipe: disconnect buffer 0 as source
[ 3.595000] <err> ipc: ipc_comp_free(): comp id: 196608 state is 5 cannot be freed
[ 3.595000] <err> ipc: ipc_pipeline_free(): module free () failed
[ 3.595000] <err> ipc: ipc4: 0 failed err 12
[ 4.625000] <inf> ipc: rx : 0x91000007|0x0
[ 4.625000] <err> ipc: ipc: pipeline id is already taken, pipe_desc->instance_id = 0
[ 4.625000] <err> ipc: ipc4: 0 failed err 9
[ 4.626000] <inf> ipc: rx : 0x93000003|0x0
[ 4.626000] <inf> pipe: pipe trigger cmd 2
[ 4.637000] <err> ipc: failed to wait schedule thread
[ 4.637000] <err> ipc: ipc4: failed to send delayed reply
[ 4.637000] <inf> ipc: rx : 0x93000003|0x0
[ 4.637000] <inf> pipe: pipe trigger cmd 2
[ 4.647000] <err> ipc: failed to wait schedule thread
[ 4.647000] <err> ipc: ipc4: failed to send delayed reply
[ 5.148000] <inf> ipc: rx : 0x93000003|0x0
[ 5.148000] <inf> pipe: pipe trigger cmd 2
[ 5.159000] <err> ipc: failed to wait schedule thread
[ 5.159000] <err> ipc: ipc4: failed to send delayed reply
[ 6.182000] <inf> ipc: rx : 0x91000007|0x0
[ 6.182000] <err> ipc: ipc: pipeline id is already taken, pipe_desc->instance_id = 0
[ 6.182000] <err> ipc: ipc4: 0 failed err 9
[ 6.183000] <inf> ipc: rx : 0x93000003|0x0
[ 6.183000] <inf> pipe: pipe trigger cmd 2
[ 6.193000] <err> ipc: failed to wait schedule thread
[ 6.193000] <err> ipc: ipc4: failed to send delayed reply
[ 6.194000] <inf> ipc: rx : 0x93000003|0x0
[ 6.194000] <inf> pipe: pipe trigger cmd 2
[ 6.204000] <err> ipc: failed to wait schedule thread
[ 6.204000] <err> ipc: ipc4: failed to send delayed reply
[ 6.708000] <inf> ipc: rx : 0x93000003|0x0
[ 6.708000] <inf> pipe: pipe trigger cmd 2
[ 6.719000] <err> ipc: failed to wait schedule thread
[ 6.719000] <err> ipc: ipc4: failed to send delayed replTerminate
To Reproduce TPLG=/lib/firmware/intel/avs-tplg/cavs-tgl-nocodec.tplg MODEL=TGLU_RVP_NOCODEC_IPC4ZPH ~/sof-test/test-case/check-playback.sh -d 1 -l 1 -r 50
Reproduction Rate almost 100%
Environment Kernel Branch: topic/sof-dev Kernel Commit: f048bf5646cc
SOF Branch: main SOF Commit: 5594ad351283
Zephyr Commit: v3.2.0-rc1-2-g0956647aaf6b
TPLG: cavs-tgl-nocodec.tplg
@RanderWang I think it's something more complicated. To me any pipeline with mixer cannot handle a Ctrl-Z suspend and check-signal-stop-start.sh fails 100%. We've debugged this with @lyakh and this is completely reproducible.
We can see driver sends SOF_IPC4_PIPE_RESET and the mixin_mixout component erases state in its mixout_reset.
When driver resumes the pipeline with SOF_IPC4_PIPE_PAUSED followed by SOF_IPC4_PIPE_RUNNING, processing will fail as there at code to reinitialize is only in mixout_bind().
I cannot see how the mixin_mixout has ever handled this case. @ranj063 @ujfalusi given driver works with our reference testbench, the driver flow is assumed to be correct here (for IPC4)?
We can see driver sends SOF_IPC4_PIPE_RESET and the mixin_mixout component erases state in its mixout_reset.
@kv2019i https://github.com/thesofproject/sof/pull/6414/commits/eb521650fdfe838b0c92014a11d9834b93b69dd0 should fix it, waiting for CI...
@kv2019i eb52165 should fix it, waiting for CI...
@lyakh , that added memset() inside mixout_bind() will create problems: mixout can be connected to multiple mixins so every new bind will erase source info created for previous mixin bind. It's just enough to remove clearing from _reset().
Actually, I see there is one more problem in mixout_unbind() in
/* mixout -> new sink */
if (dev->ipc_config.id == src_id) {
mixed_data_info->mixed_frames = 0;
memset(mixed_data_info->source_info, 0, sizeof(mixed_data_info->source_info));
} else { /* new mixin -> mixout */
...
If mixout and component on its sink are unbinded and then binded again, source info will be erased on unbind and never re-created as there was no new mixin<->mixout bind. This could be fixed by just clearing mixed_data_info->mixed_frames = 0; and resetting consumed_yet_not_produced_frames = 0; for every mixin in source info but preserving mixin pointers in source info table.
@kv2019i eb52165 should fix it, waiting for CI...
@lyakh , that added memset() inside mixout_bind() will create problems: mixout can be connected to multiple mixins so every new bind will erase source info created for previous mixin bind. It's just enough to remove clearing from _reset().
@serhiy-katsyuba-intel Right, thanks, I've removed that.
Actually, I see there is one more problem in mixout_unbind() in
/* mixout -> new sink */ if (dev->ipc_config.id == src_id) { mixed_data_info->mixed_frames = 0; memset(mixed_data_info->source_info, 0, sizeof(mixed_data_info->source_info)); } else { /* new mixin -> mixout */ ...If mixout and component on its sink are unbinded and then binded again, source info will be erased on unbind and never re-created as there was no new mixin<->mixout bind. This could be fixed by just clearing mixed_data_info->mixed_frames = 0; and resetting consumed_yet_not_produced_frames = 0; for every mixin in source info but preserving mixin pointers in source info table.
Could you make a PR? I'm not sure I have a good way to test this
Could you make a PR? I'm not sure I have a good way to test this
OK. For both problems (reset and unbind) or just for second (unbind)? I do not see your pull-request for reset fix (that commit you mentioned seems does not belong to any pull-request).
The PR submitted: https://github.com/thesofproject/sof/pull/6433
Confirmed that this issue has been fixed by https://github.com/thesofproject/sof/pull/6433.