HDA with deep-buffer: IPC error on pause_release after suspend-resume

[plbossart]

kernel changes for deep-buffer support: #3146
topology changes for deep-buffer support thesofproject/sof#4611

use two terminals
terminal1:

aplay -Dhw:0,0 -c2 -r48000 -fS16_LE -i /dev/zero
Playing raw data '/dev/zero' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

press space to trigger pause_push

terminal 2:

rtcwake -m mem -s 2

terminal 1:
press space to trigger pause_release

=== PAUSE ===                                                             Suspended. Trying resume. Failed. Restarting stream. aplay: suspend:1714: suspend: prepare error: No such device

Dmesg log
dmesg.log

[   43.918829] PM: suspend entry (s2idle)
[   43.918882] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   43.918913] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   43.919500] Filesystems sync: 0.000 seconds
[   43.925106] Freezing user space processes ... (elapsed 0.001 seconds) done.
[   43.926937] OOM killer disabled.
[   43.926938] Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
[   43.927843] printk: Suspending console(s) (use no_console_suspend to debug)
[   43.928714] wlp85s0: deauthenticating from f4:f5:e8:6b:45:bb by local choice (Reason: 3=DEAUTH_LEAVING)
[   43.943977] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget PIPELINE.30.HDA0.OUT is still in use: count 4
[   43.943980] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget BUF30.1 is still in use: count 1
[   43.943981] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget BUF30.0 is still in use: count 1
[   43.943982] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget PGA30.0 is still in use: count 1
[   43.943983] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget PCM0P is still in use: count 1
[   43.943984] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget BUF1.1 is still in use: count 1
[   43.943986] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget BUF1.0 is still in use: count 1
[   43.943987] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget PIPELINE.1.HDA0.OUT is still in use: count 5
[   43.943988] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget HDA0.OUT is still in use: count 2
[   43.943989] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget PGA1.0 is still in use: count 1
[   43.943990] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_tear_down_pipelines: widget MIXER1.0 is still in use: count 1
[   43.944511] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x20140000 successful
[   43.944521] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[   43.944670] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[   43.944690] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x9010f0f successful
[   43.945208] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
[   43.945210] sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[   43.945243] sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000010 at  00000044
[   43.945247] sof-audio-pci-intel-tgl 0000:00:1f.3: Turning i915 HDAC power 0
[   43.945249] sof-audio-pci-intel-tgl 0000:00:1f.3: Current DSP power state: D3

[   52.894346] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[   52.894541] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx error for 0x80010000 (msg/reply size: 216/12): -19
[   52.894551] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed resetting DAI config for HDA0.OUT
[   52.894571] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[   52.894798] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx error for 0x80010000 (msg/reply size: 216/12): -19
[   52.894810] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed setting DAI config for HDA0.OUT
[   52.894816] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_dai_prepare on Analog CPU DAI: -19
[   52.894822]  Analog Playback and Capture: ASoC: soc_pcm_prepare() failed (-19)
[   52.894828]  HDA Analog: ASoC: dpcm_be_dai_prepare() failed (-19)
[   52.894833]  HDA Analog: ASoC: dpcm_fe_dai_prepare() failed (-19)
[   52.895001] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: free stream 0 dir 0
[   52.895012] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30020000: GLB_TPLG_MSG: COMP_FREE
[   52.895114] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx error for 0x30020000 (msg/reply size: 12/12): -19
[   52.895122] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to free widget PCM0P
[   52.895131] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
[   52.895140] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
[   52.895144] sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[   52.895154] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30210000: GLB_TPLG_MSG: BUFFER_FREE
[   53.401640] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x30210000 (msg/reply size: 12/12)
[   53.401655] sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[   53.401659] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[   53.401670] sof-audio-pci-intel-tgl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[   53.401677] sof-audio-pci-intel-tgl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   53.401694] sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000000
[   53.401699] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[   53.401703] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[   53.401718] sof-audio-pci-intel-tgl 0000:00:1f.3: unknown ROM status value ffffffff
[   53.401759] sof-audio-pci-intel-tgl 0000:00:1f.3: invalid header size 0xffffffff. FW oops is bogus
[   53.401763] sof-audio-pci-intel-tgl 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[   53.401768] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[   53.401775] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to free widget BUF30.0

[plbossart]

topology used for reference:

[plbossart]

same issue with 'standard' topic/sof-dev kernel branch
6a95ae1 fixup! ASoC: SOF: handle paused streams during system suspend

and
topology changes for deep-buffer support thesofproject/sof#4611

My money is on the FE-BE trickery to allocate the stream in non-coupled mode. That is probably broken for the case with 2 FEs and 1 BE.

[plbossart]

It seems that the behavior is different with the latest firmware from thesofproject/sof#4611, not just the topology changes. No IPC error is seen, in contrast to with the released 1.8 firmware.

However I still see an xrun when monkey testing paused, at some point both streams stop with "aplay: pcm_write:2117: write error: Input/output error"

[plbossart]

To be more precise, with the latest firmware and topology from thesofproject/sof#4611, I see an xrun with the following sequence using 3 xterms and SSH.

a) terminal 1: aplay -Dhw:0,0 -c2 -r48000 -fS16_LE -i /dev/zero, press space for pause
b) terminal 2: aplay -Dhw:0,31 -c2 -r48000 -fS16_LE -i /dev/zero, press space for pause
c) terminal 3: rtcwake -m mem -s 2
d) terminal 2: press space -> pause_release
e) terminal 1: press space -> pause_release -> xrun on terminal 1 and terminal 2

Edit: d) and e) CANNOT be interchanged, it's when the pause-release happens in the reverse order that the xrun happens.

[plbossart]

Annotated dmesg log shows we don't handle the PAUSE_RELEASE well after the suspend-resume cycle: it's handled as a START. We probably need the same concept as for SoundWire where we track the paused state... @ranj063 FYI

dmesg.log

[plbossart]

retried today on UpExtreme, same unbalanced widget count @ranj063

dmesg.log

kernel 97a3289f2f0c [HACK] add trace to show widgets are not released....
firmware 71d5d3cf4 topology1: sof-hda-generic: add deep-buffer pipeline for analog playback

[plbossart]

On another laptop with 1.8 signed firmware and static pipelines I have a different error with the IPC DAI_CONFIG

dmesg.log