[BUG] [CML] IPC timed out for 0x60040000: GLB_STREAM_MSG: TRIG_START on ubuntu 20.04

[ClarexZhou]

Describe the bug
IPC timed out for 0x60040000: GLB_STREAM_MSG: TRIG_START on ubuntu 20.04 with UCM2

Error not seen with ubuntu 18.04 with UCM1.

To Reproduce

1. System os is 20.04 (get from cdimage.ubuntu.com/ubuntu/daily-live/current)
2. UCM2 Sof soundwire alsa-ucm-conf#29 is used and pulseaudio is enabled.
3. Boot up system and check dmesg -w

Reproduction Rate
4/5

Expected behavior
Sof load successfully and no ipc timed out

Impact
IPC timed out message is shown. Runtime PM keeps active.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {fce7f93} release/sof-dev
   • SOF: {d7ad0c1} Master
2. Name of the topology file
   • Topology: sof-cml-rt711-rt1308-mono-rt715.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: CML-U laptop with RT711 RT1308 and RT715 in SDW mode

Dmesg

```` [ 4.784635] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790756 [ 4.788597] sof-audio-pci 0000:00:1f.3: pcm: open stream 1 dir 1 [ 4.788598] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes [ 4.788599] sof-audio-pci 0000:00:1f.3: period count 2 max 16 [ 4.788600] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes [ 4.788939] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG [ 4.789233] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 1 [ 4.789645] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG [ 4.789647] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 1 dir 1 [ 4.789649] sof-audio-pci 0000:00:1f.3: generating page table for 00000000e9984685 size 0xffc0 pages 16 [ 4.789653] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x340000 successful [ 4.789665] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful [ 4.789667] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0 [ 4.789668] sof-audio-pci 0000:00:1f.3: periods:4 [ 4.789676] sof-audio-pci 0000:00:1f.3: stream_tag 3 [ 4.789680] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS [ 4.789743] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful [ 4.792603] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS [ 4.792605] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790604 [ 4.792609] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START [ 4.794581] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START [ 4.797729] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 1 cmd 1 [ 4.798241] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2034001e successful [ 4.798245] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START [ 5.305810] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60040000 size 12 [ 5.305814] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context [ 5.305820] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005 [ 5.305895] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000 [ 5.305900] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000f87 rirb 00 [ 5.305901] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000 [ 5.305905] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003 [ 5.305906] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers [ 5.305908] Headset mic: ASoC: trigger FE cmd: 1 failed: -110 [ 5.305912] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 1 cmd 0 [ 5.305914] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP ````

sof logger error message

```` TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT [ 13206992.291667] ( 13206992.000000) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 128 uS 3075 ticks [ 13208401.197917] ( 1408.906250) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 127 uS 3051 ticks [ 13209806.406250] ( 1405.208374) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 124 uS 2980 ticks [ 13211217.968750] ( 1411.562500) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 129 uS 3102 ticks [ 13212627.239583] ( 1409.270874) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 127 uS 3058 ticks [ 13214031.145833] ( 1403.906250) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 123 uS 2955 ticks [ 13215440.833333] ( 1409.687500) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 127 uS 3066 ticks [ 13216837.083333] ( 1396.250000) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 117 uS 2808 ticks [ 13218255.989583] ( 1418.906250) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 135 uS 3243 ticks [ 13219660.572917] ( 1404.583374) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 123 uS 2968 ticks [ 13221071.354167] ( 1410.781250) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 128 uS 3087 ticks [ 13222479.479167] ( 1408.125000) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 126 uS 3036 ticks [ 13223883.697917] ( 1404.218750) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 123 uS 2962 ticks [ 13225292.864583] ( 1409.166626) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 127 uS 3055 ticks [ 13226689.635417] ( 1396.770874) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 117 uS 2818 ticks [ 13228090.937500] ( 1401.302124) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 121 uS 2905 ticks [ 13229502.812500] ( 1411.875000) c0 SCHEDULE_LL /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 129 uS 3108 ticks [ 13230914.687500] ( ````

dmesg.txt
sof_logger_error.txt
sof_logger_full.txt

[lgirdwood]

@mengdonglin @fkaczmar looks like we have a blocker for v1.5, pulseaudio has some updates in the latest ubuntu that is breaking FW. There are a few other issues related to this today.

[lgirdwood]

@ClarexZhou does this happen when pulseaudio is disabled ?

[kv2019i]

Disabling pulseaudio is worth a try definitely. It seems one start IPC just fails. There are multiple successful starts, but one of them fails:

[ 4.798245] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 5.305810] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60040000 size 12

In FW, only clear errors are these:

[ 13518802.135417] ( nan) c0 volume 5.19 src/audio/component.c:176 ERROR comp_set_state(): wrong state = 5, COMP_TRIGGER_RESET
[ 13519984.479167] ( 1182.343750) c0 eq-iir 5.20 ../audio/eq_iir/eq_iir.c:931 eq_iir_reset()
[ 13520008.437500] ( 23.958334) c0 eq-iir 5.20 src/audio/component.c:176 ERROR comp_set_state(): wrong state = 5, COMP_TRIGGER_RESET
[ 13521138.958333] ( 1130.520874) c0 dai 5.24 src/audio/component.c:176 ERROR comp_set_state(): wrong state = 5, COMP_TRIGGER_RESET

So I'd guess timing of the boot-up sequence has changed in Pulseaudio and it triggers a timing issue in FW (or kernel-FW communication).

[plbossart]

@ClarexZhou please update the UCM files, I pushed to the wrong tree :-(

I have no issues on Olympic when doing basic tests + suspend resume.

[slawblauciak]

@plbossart so this is a UCM issue?

[plbossart]

@plbossart so this is a UCM issue?

dunno, I couldn't reproduce this.

[YvonneYang2]

Checked newest ucm2 https://github.com/thesofproject/alsa-ucm-conf (commit: 4722f5b ) +PR#29 , issue is gone on cml-u

[YvonneYang2]

Close it since not issue not reproduced with latest sof-dev(commit:052e45d7) + master(commit:b4e8b1e) + ucm2 ( https://github.com/thesofproject/alsa-ucm-conf (commit: 4722f5b ) +PR#29 )