[BUG][CML] ipc timeout when playing via speaker pipeline

[aiChaoSONG]

Describe the bug
aplay via speaker pipeline, first you will see io error in the terminal, check dmesg, you will see ipc timeout error.

To Reproduce

1. reboot
2. run aplay -Dhw:0,5 -f dat -i -vvv -c 2 ./somewave.wav

Reproduction Rate
100%

Impact
function abnormal

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: sof-dev {0cf356c}
   • SOF: master {dbb70c8}
2. Name of the topology file
   • Topology: {sof-cml-rt1011-rt5682.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {ASUS CML Chromebook with rt5682 and rt1011 codec}

[   42.891340] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   42.891556] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   42.891562] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790528
[   42.897729] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 5 dir 0 cmd 1
[   42.898199] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
[   42.898205] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   42.911412] sof-audio-pci 0000:00:1f.3: error : DSP panic!
[   42.911417] sof-audio-pci 0000:00:1f.3: panic: dsp_oops_offset 788480 offset 788480
[   42.911420] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   42.911498] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xbe00897c trace 0x00004000
[   42.911500] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   43.401263] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60040000 size 12
[   43.401270] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   43.401279] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   43.401369] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xbe00897c trace 0x00004000
[   43.401379] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[   43.401382] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   43.401389] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   43.401392] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   43.401398]  Speakers: ASoC: trigger FE cmd: 1 failed: -110
[   43.401407] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 5 dir 0 cmd 0
[   43.401412] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[   43.905256] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[   43.905263] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   43.905274] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   43.905367] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xbe00897c trace 0x00004000
[   43.905378] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[   43.905382] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   43.905390] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   43.905394] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   43.905411] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[   43.905418]  Speakers: ASoC: trigger FE cmd: 0 failed: -110
[   44.513339] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[   44.513348] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   45.017272] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[   45.017280] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   45.017295] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   45.017387] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xbe00897c trace 0x00004000
[   45.017399] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[   45.017402] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   45.017415] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   45.017418] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   45.017496] sof-audio-pci 0000:00:1f.3: pcm: close stream 5 dir 0

speaker_ipc_timeout_soferror.log
speaker_ipc_timeout_dmesg.log
speaker_ipc_timeout_softrace.log

[sathyap-chrome]

@aiChaoSONG Thanks. We need fix for this at high priority as customer release for 008 is blocked on this.

cc @mengdonglin @keyonjie

[keyonjie]

Looks the dw-dma channel enable fails, see this:
"Channel enable = 0."
Hi @tlauda can you please help to take a look into this?

    0      2          DAI 7.38    182357041.875000        13.906250      src/audio/dai.c:494 	dai_comp_trigger(), command = 1
    0      2          DAI 7.38    182357054.791667        12.916667      src/audio/dai.c:505 	dai_comp_trigger(), START
    0      2          SSP         182357252.968750       198.177078 ers/intel/cavs/ssp.c:877 	ssp_trigger() cmd 1
    0      2          SSP         182357267.291667        14.322917 ers/intel/cavs/ssp.c:806 	ssp_start()
    0      2          DMA         182369944.947917     12677.656250 src/drivers/dw/dma.c:1044	dw_dma_free_data_size() size is 0! Channel enable = 0.
    0      2       BUFFER         182369967.135417        22.187500   src/audio/buffer.c:126 

[wwittbrx]

I cannot reproduce this issue with the following recipe (cml-008-drop):

PLATFORM: CML HATCH
OS: UBUNTU 19.04
FW: f7dfd05 sof-cml-rt5682-max98357a.m4
KERNEL: 5d67c4b + PR1383 + 169c659

Could you check if this is true on your side as well? I would strongly recommend switching to CML 008 as it is much more stable, with multiple fixes.

[keyonjie]

I cannot reproduce this issue with the following recipe (cml-008-drop):

PLATFORM: CML HATCH
OS: UBUNTU 19.04
FW: f7dfd05 sof-cml-rt5682-max98357a.m4
KERNEL: 5d67c4b + PR1383 + 169c659

Could you check if this is true on your side as well? I would strongly recommend switching to CML 008 as it is much more stable, with multiple fixes.

@wwittbrx we all hope to switch :), but unfortunately we can't, we have to figure out the fixes and back port them to 007.

[lgirdwood]

@keyonjie why cant you work on master ? @wenqingfu fyi.

[aiChaoSONG]

@wwittbrx this issue exist both on master and 008, please use helios to test and fix, this issue only exist on helios, not hatch.

[sathyap-chrome]

This issue was only seen from 008 on Helios. This issue is blocking our upgrade to 008.
On 007 this is not seen

[wwittbrx]

@sathyap-chrome
I suspect that the problem here is with topology file you are using.
Please try the following recipe:

Coreboot: ChromeOS-firmware-R79-12607.38.0
ChromeOS: ChromeOS-test-R79-12607.38.0-hatch
Platform: Helios
Topology: Same as the one included in OS image
Kernel: Same as the one included in OS image (Linux localhost 4.19.79-07513-g939160fe46cd #1 SMP PREEMPT Sat Nov 23 23:55:51)
FW: f7dfd05 (cml-008-drop-stable)

The key step here is to leave the default topology file. Do not upgrade topology to the one found in cml-008-drop-stable. This should enable normal speaker playback.

This should be the output of dmesg after boot:
[ 5.366153] sof-audio-pci 0000:00:1f.3: Firmware info: version 1:1:0-f7dfd
[ 5.366157] sof-audio-pci 0000:00:1f.3: Firmware: ABI 3:12:0 Kernel ABI 3:8:0
[ 5.366159] sof-audio-pci 0000:00:1f.3: warn: FW ABI is more recent than kernel
[ 5.366928] sof-audio-pci 0000:00:1f.3: firmware boot complete
[ 5.845559] cml_rt1011_rt5682 cml_rt1011_rt5682: info: override FE DAI link SSP0-Codec
[ 5.845563] cml_rt1011_rt5682 cml_rt1011_rt5682: info: override FE DAI link dmic01
[ 5.845564] cml_rt1011_rt5682 cml_rt1011_rt5682: info: override FE DAI link dmic16k
[ 5.845565] cml_rt1011_rt5682 cml_rt1011_rt5682: info: override FE DAI link iDisp1
[ 5.845566] cml_rt1011_rt5682 cml_rt1011_rt5682: info: override FE DAI link iDisp2
[ 5.845567] cml_rt1011_rt5682 cml_rt1011_rt5682: info: override FE DAI link iDisp3
[ 5.845568] cml_rt1011_rt5682 cml_rt1011_rt5682: info: override FE DAI link SSP1-Codec
[ 5.845884] sof-audio-pci 0000:00:1f.3: Topology: ABI 3:9:0 Kernel ABI 3:8:0

[sathyap-chrome]

@wwittbrx Thanks for this triage. But we dont have any changes on 008 specifically.
Actually i made changes for 007 after posting fix on master.

If the same m4 file is built with 008, are you seeing playback errors ?

[wwittbrx]

With topology built with cml-008-drop-stable the speaker playback does not work (aplay seems hanged).

https://github.com/thesofproject/sof/blob/cml-008-drop-stable/tools/topology/sof-cml-rt1011-rt5682.m4

From what I understand the topology included in ChromeOS image is made with cml-007-drop-stable + PR #1948

The difference between these files at a glance is:
in cml-008
PIPELINE_PCM_ADD(sof/pipe-volume-playback.m4,
7, 5, 2, s32le,
1000, 0, 0,
48000, 48000, 48000)

in cml-007
PIPELINE_PCM_ADD(sof/pipe-volume-playback.m4,
7, 5, 2, s32le,
48, 1000, 0, 0)

I'm not very familiar with topology changes, but it seems that the version in cml-008 is incompatible with our ChromeOS recipe. I hope someone can share more details on this.

Edit: I did not attach logs here because kernel included in ChromeOS image has disabled traces. I will build kernel with logs support tommorow and update this with exact errors for cml-008 topology. Sorry for inconvenience.

Edit 2: Promised logs for cml-008 topology failure:
speaker_fail.log