[BUG] [TGL] PM Gate IPC Failure and not able to enter into D0i3

[RDharageswari]

Describe the bug
Start WOV, while there are no active streams.
there will be transition D0i3->D0i0->D3, while this happens the PM_GATE IPC timesout

To Reproduce
The following script can repro the issue:
#!/bin/bash
for i in {1..4}
do
cras_test_client --set_hotword_model 15:0:en_all
cras_test_client --listen_for_hotword /home/root/wov.wav --duration_seconds 10 & pid=pidof cras_test_client
sleep 7
kill -9 $pid
sleep 5
done
Steps to reproduce the behavior: (e.g. list commands or actions used to reproduce the bug)

Reproduction Rate
Several iterations of “D0I3->D0->D3” will reproduce the issue, once in 5 times

Expected behavior
No IPC error

Impact
There is an IPC error after which no streams can be played

Environment
tgl-011-drop-stable

Screenshots or console output
[ 589.957238] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 100 dir 1 cmd 1
[ 589.957583] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[ 589.957586] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000
[ 589.957750] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000
[ 594.981933] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40080000
[ 594.982140] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40080000
[ 594.982143] sof-audio-pci 0000:00:1f.3: Current DSP power state: D0I3

[ 598.198506] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 100 dir 1 cmd 0
[ 598.198521] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40080000
[ 598.700217] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40080000 size 32
[ 598.700241] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 598.700491] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 598.700505] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[ 598.700509] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 598.700529] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 598.700532] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 598.700541] sof-audio-pci 0000:00:1f.3: error: PM_GATE ipc error -110
[ 598.700553] sof-audio-pci 0000:00:1f.3: failed to set requested target DSP state 0 substate 0
[ 598.700557] sof-audio-pci 0000:00:1f.3: error: resuming DSP -110
[ 598.700621] sof-audio-pci 0000:00:1f.3: error: trace IO error

[lgirdwood]

@RDharageswari what happens when we do

#!/bin/bash
for i in {1..4}
do
cras_test_client --set_hotword_model 15:0:en_all
cras_test_client --listen_for_hotword /home/root/wov.wav --duration_seconds 10 & pid=pidof cras_test_client
sleep 11
# at this point we have slept for 11 secs so client should have gracefully completed
done

I am wondering if kill -9 means we are having a different sequence at stream shutdown.

[RDharageswari]

Hi Liam,
cras_test_client --listen_for_hotword /home/root/wov.wav --duration_seconds 10
The above command works this way: Capture data for "10 duration_seconds" after the keyword is detected.
The intention of the above script is to get the power sequence right

[lgirdwood]

@RDharageswari ok got you, we are capturing for 10 seconds after keyword and not listening for 10 secs. One other thing that comes to mind here is what is the background noise with your test (given the difference in reproduction rates that everyone is seeing) ?

[RDharageswari]

Hi Liam,
there is no background noise here Liam.
Just the power transition causes this issue.
This issue is reproducible on RVP also

[cujomalainey]

I am wondering if kill -9 means we are having a different sequence at stream shutdown.

I can cause a DSP panic in a similar fashion with arecord so I don't think its the shutdown procedure.

for i in {0..100};
do timeout 5s arecord -D hw:0,100 -N -f s16_le -c 2 --buffer-size=384000 -r 16000 -d 1 /dev/null;
sleep 5;
done

[  523.195723] sof-audio-pci 0000:00:1f.3: error : DSP panic!
[  523.195750] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  523.195785] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  525.210427] sof-audio-pci 0000:00:1f.3: error: firmware boot failure
[  525.210454] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  525.210490] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  525.210493] sof-audio-pci 0000:00:1f.3: error: failed to boot DSP firmware after resume -5
[  525.714158] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40080000 size 32
[  525.714166] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  525.714189] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  525.714223] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005

That being said this method is a bit more involved to prevent CRAS from unloading the hotword model

[keyonjie]

Hi @slawblauciak @abonislawski @bkokoszx this is not reproduced with the master branch at my end, I spent some time to figure out it could be clock switching related, can you help to backport the upstream version of the WOVCRO and clock switching logic to see if the issue is resolved?

[abonislawski]

@keyonjie just try without commit 445d65f
this is the only difference

[mwasko]

@keyonjie just try without commit 445d65f
this is the only difference

As @abonislawski pointed out, the only significant difference is keeping HPRO clock requested while in D0. This change significantly reduce the LPRO-HPRO clock switch time and improve overall FW performance. It is possible that with this change applied a kernel-FW race condition was revealed.

@ranj063 @lrgirdwo can you analyze the kernel driver power flows and verify the DSP suspend/resume programming routines?