ADL - N : Resume failures with IPC causing suspend failures in stress tests

[sathyap-chrome]

We have multiple reports of suspend failures due to audio driver failing to suspend. This is due to unsuccessful resume in previous cycle.

Sharing the 2 scenarios where the failure seems to be either same or similar.

Scenario thesofproject/linux#1: Seen in local testing when we tried to repro the thesofproject/linux#3915 with debug enabled and ran suspend stess test. Here we found ipc errors while the FW load itself resumed fine.
log slice :
pipeline_ipc_fail.txt

Scenario thesofproject/linux#2: Seen in ODM reporting with a dozing script ( variation of suspend_stress_test with additonal parameters)
suspend_stress_test --count 15 --suspend_max 30 --suspend_min 28 --wake_max 10 --wake_min 5 --suspend_time_margin_min -1 --suspend_time_margin_max 30 --fw_errors_fatal --premature_wake_fatal --late_wake_fatal --record_dmesg_dir /var/log/suspend

Logs :
kernel_log_20221017.txt

Errors seen in scenario thesofproject/linux#1
0000:00:1f.3: ipc tx error for 0x30030000 (msg/reply size: 16/12): -22
0000:00:1f.3: sof_ipc3_route_setup: route DMIC1.IN -> BUF11.0 failed
0000:00:1f.3: sof_ipc3_set_up_all_pipelines: route set up failed
0000:00:1f.3: Failed to restore pipeline after resume -22
0000:00:1f.3: PM: pci_pm_resume+0x0/0xef returned -22 after 114680 usecs
0000:00:1f.3: PM: failed to resume async: error -22

Errors seen in scenario thesofproject/linux#2
0000:00:1f.3: ipc tx error for 0x30130000 (msg/reply size: 12/12): -22
0000:00:1f.3: Failed to restore pipeline after resume -22
0000:00:1f.3: PM: pci_pm_resume+0x0/0xef returned -22 after 113515 usecs
0000:00:1f.3: PM: failed to resume async: error -22
0000:00:1f.3: PM: calling pci_pm_suspend+0x0/0x1da @ 5476, parent: pci0000:00
0000:00:1f.3: ipc tx error for 0x30020000 (msg/reply size: 12/12): -19
0000:00:1f.3: failed to free widget DMIC1.IN
0000:00:1f.3: failed to tear down paused pipelines

[kv2019i]

Note on kernel version:

• kernel is Linux 5.15.73 plus chromeos patches (other log had Linux 5.15.73-12723-g849d83202f61 )
• FW is 2:0:0-1153b

[kv2019i]

The failures seem to be IPC timeouts with no reported DSP crash.

In the first log (pipeline_ipc_fail.txt) the first error is timeout on TRIG_STOP for DMIC pipeline:

2022-10-19T12:46:19.604815Z DEBUG kernel: [  153.584391] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 99 dir 1 cmd 1
2022-10-19T12:46:19.606803Z DEBUG kernel: [  153.585471] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x2024001e successful
2022-10-19T12:46:19.606823Z DEBUG kernel: [  153.585489] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
2022-10-19T12:46:50.377658Z DEBUG kernel: [  184.365905] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 99 dir 1 cmd 0
2022-10-19T12:46:50.377700Z DEBUG kernel: [  184.365935] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
2022-10-19T12:46:50.879621Z ERR kernel: [  184.867686] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60050000 (msg/reply size: 12/12)

The suspend is done with error on CTX_SAVE (as DSP in unresponsive), and there are further errors on next resume.

In the other log (kernel_log_20221017.txt), SOF dynamic debug log are not enabled, so there is less to see, but the first error is reported on resume. So this looks a bit different.

So far nothing wrong spotted in the kernel side logs (e.g. an invalid sequence).

[kv2019i]

Only similar bug (searched open and clossed, kernel + fw) is this one: #6185 .. but this happens with playback (so different direction) and a different use-case (multiple-pipeline-playback).

Given the kernel side flow looks ok, moving to firmware side.

[lgirdwood]

@sathyap-chrome do you have the FW log ? I would say we are broken at the resume time if we cant hookup a route to DMIC.

[lgirdwood]

@mwasko fyi - pls assign.

[sathyap-chrome]

@lgirdwood We dont have a clear reproduction scenario. FW trace wont help with suspend resume right ? ( since FW trace starts after DSP starts) - but will try how we can get it.

[lgirdwood]

@lgirdwood We dont have a clear reproduction scenario. FW trace wont help with suspend resume right ? ( since FW trace starts after DSP starts) - but will try how we can get it.

Sorry, I mean we need the log from part 1 - the resume that fails.

0000:00:1f.3: ipc tx error for 0x30030000 (msg/reply size: 16/12): -22
0000:00:1f.3: sof_ipc3_route_setup: route DMIC1.IN -> BUF11.0 failed
0000:00:1f.3: sof_ipc3_set_up_all_pipelines: route set up failed
0000:00:1f.3: Failed to restore pipeline after resume -22
0000:00:1f.3: PM: pci_pm_resume+0x0/0xef returned -22 after 114680 usecs
0000:00:1f.3: PM: failed to resume async: error -22

This may shed some light on the previous suspend (where we may not have shutdown cleanly).

[kv2019i]

@sathyap-chrome Would be good to have more samples of failing case logs. It would be curious to see if the problem is always:

1. TRIG_STOP fail on DMIC before suspend (ADSP hw potentially in undefined state)
2. suspend (ADSP powered off but not cleanly as we have CTX_SAVE error, hw potentially in undefined state)
3. resume
4. error in setting up path for dmic

The HW power-cycling should of course help, but we've had cases in the past where e.g. the DMA hw has had issues that cannot be recovered by the above flow. The rootcause would then be the TRIG_STOP on DMIC.

[kv2019i]

I was now able to reproduce once locally on a "Nereid" device. FYI @abonislawski as you have the same hw.

No FW logs yet, but below are kernel logs showing the IPC sequence of a working and non-working case. Reproduction is once per day for me now, so will spend some time looking at the logs and then planning what to try next. But FYI with others who have same hw, it is possible to trigger this bug with this setup.

The sequence of IPC messages kernel sends seems valid. Here the failure is not with DMIC, but rather the first IPC sent to tear down the DSP pipelines for suspend (COMP_FREE for SSP1.IN). E.g. this line pair (not the timestamp showing 2sec, first line is last message to set up the DSP, second is start of suspend):

2022-10-26T12:01:59.399869Z DEBUG kernel: [ 1811.337622] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40020000
2022-10-26T12:02:01.380028Z DEBUG kernel: [ 1813.465770] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000

FAIL case

2022-10-26T12:01:59.399860Z DEBUG kernel: [ 1811.336836] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T12:01:59.399863Z DEBUG kernel: [ 1811.337023] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T12:01:59.399865Z DEBUG kernel: [ 1811.337218] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T12:01:59.399868Z DEBUG kernel: [ 1811.337408] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T12:01:59.399869Z DEBUG kernel: [ 1811.337622] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40020000
2022-10-26T12:02:01.380028Z DEBUG kernel: [ 1813.465770] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000
2022-10-26T12:02:01.401225Z DEBUG kernel: [ 1813.479839] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.29.SSP1.IN freed
2022-10-26T12:02:01.449898Z DEBUG kernel: [ 1813.513956] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30020000
2022-10-26T12:02:01.962621Z ERR kernel: [ 1814.043734] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x30020000 (msg/reply size: 12/12)
2022-10-26T12:02:09.613173Z DEBUG kernel: [ 1821.701262] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40010000
2022-10-26T12:02:10.762189Z INFO kernel: [ 1822.845534] PM: suspend entry (s2idle)
2022-10-26T12:02:49.675106Z DEBUG kernel: [ 1823.028655] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30100000
2022-10-26T12:02:49.675109Z DEBUG kernel: [ 1823.028925] snd_sof:sof_widget_setup: sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.29.SSP1.IN setup complete
2022-10-26T12:02:49.675110Z DEBUG kernel: [ 1823.028938] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30010000
2022-10-26T12:02:49.675112Z DEBUG kernel: [ 1823.029582] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000
2022-10-26T12:02:49.675113Z DEBUG kernel: [ 1823.030063] snd_sof:sof_widget_setup: sof-audio-pci-intel-tgl 0000:00:1f.3: widget SSP1.IN setup complete

OK case:

2022-10-26T11:57:28.430481Z DEBUG kernel: [ 1540.333981] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430484Z DEBUG kernel: [ 1540.334174] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430518Z DEBUG kernel: [ 1540.334333] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430520Z DEBUG kernel: [ 1540.334522] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430523Z DEBUG kernel: [ 1540.334705] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430525Z DEBUG kernel: [ 1540.334869] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430528Z DEBUG kernel: [ 1540.335031] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430531Z DEBUG kernel: [ 1540.335222] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430533Z DEBUG kernel: [ 1540.335385] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430536Z DEBUG kernel: [ 1540.335590] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430538Z DEBUG kernel: [ 1540.335783] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30130000
2022-10-26T11:57:28.430539Z DEBUG kernel: [ 1540.335984] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40020000
2022-10-26T11:57:29.994080Z DEBUG kernel: [ 1542.070562] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000
2022-10-26T11:57:32.035186Z DEBUG kernel: [ 1544.120273] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.29.SSP1.IN freed
2022-10-26T11:57:32.245961Z DEBUG kernel: [ 1544.323824] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30020000
2022-10-26T11:57:32.586207Z DEBUG kernel: [ 1544.662649] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget SSP1.IN freed
2022-10-26T11:57:32.630703Z DEBUG kernel: [ 1544.706783] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30110000
2022-10-26T11:57:32.676550Z DEBUG kernel: [ 1544.752087] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget PIPELINE.12.DMIC1.IN freed
2022-10-26T11:57:32.699443Z DEBUG kernel: [ 1544.774999] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30210000
2022-10-26T11:57:32.722328Z DEBUG kernel: [ 1544.797890] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget BUF12.2 freed
2022-10-26T11:57:32.744949Z DEBUG kernel: [ 1544.820776] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30210000
2022-10-26T11:57:32.791439Z DEBUG kernel: [ 1544.867276] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget BUF12.1 freed