[APL][Random] 'ipc timed out for 0x30200000' after S3 without playback/capture. (5%)

[stevyan]

Summary:
'ipc timed out for 0x30200000' after S3 without playback/capture.
Note: Following ipc message id occurred for different attempt times: 0x30200000, 0x30030000, 0x50010000, 0x30010000 ...

To reproduce

1. sudo ./stress-s3.sh 100 0 0

Actual result
error: ipc timed out for 0x30200000 size 36

Reproduce rate: 5%

Test recipe
date: 2019-04-26
sof (master): 6a84b4e9
linux (topic/sof-dev): f7e9d4a
topology: sof-apl-pcm512x.tplg, sof-apl-nocodec.tplg

dmesg log

[  664.869840] sof-audio-pci 0000:00:0e.0: ipc tx: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[  664.870078] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[  664.870082] sof-audio-pci 0000:00:0e.0: ipc tx: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[  665.177549] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x30200000 size 36
[  665.177560] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  665.177603] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  665.177607] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  665.177615] sof-audio-pci 0000:00:0e.0: error: failed to load widget type 31 with ID: 5
[  665.177619] sof-audio-pci 0000:00:0e.0: error: failed to restore pipeline after resume -110
[  665.177642] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  665.177945] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  665.177969] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1010303 successful
[  665.177973] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1000303 successful
[  665.177977] sof-audio-pci 0000:00:0e.0: DSP core(s) enabled? 0 : core_mask 3
[  665.177998] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000010 at  00000044

ipc_30200000.log
ipc_error-slogger.log

[ranj063]

@stevyan would you be able to check if this PR thesofproject/sof#1343 fixes the problem on APL. I was able to run a 100 iterations stress test with nocodec with this.

[mengdonglin]

May relevant to #1254

[stevyan]

this error still can be observed after patched the PR thesofproject/sof#1343 on APL nocodec. Iterations target: 500 times, failed at the 213rd.

Test Recipe
date: 2019-04-29
sof (master): be1331aa ( + PR thesofproject/sof#1343)
linux (topic/sof-dev): af71673
topology: sof-apl-nocodec.tplg

dmesg log

[ 1224.449230] sof-audio-pci 0000:00:0e.0: ipc tx: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[ 1224.449318] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[ 1224.449326] sof-audio-pci 0000:00:0e.0: ipc tx: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[ 1224.752588] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x30200000 size 36
[ 1224.752599] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 1224.752642] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 1224.752647] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 1224.752656] sof-audio-pci 0000:00:0e.0: error: failed to load widget type 31 with ID: 31
[ 1224.752661] sof-audio-pci 0000:00:0e.0: error: failed to restore pipeline after resume -110
[ 1224.752688] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 1224.752906] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 1224.752921] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1010303 successful
[ 1224.752928] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1000303 successful
[ 1224.752936] sof-audio-pci 0000:00:0e.0: DSP core(s) enabled? 0 : core_mask 3
[ 1224.752950] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000010 at  00000044
[ 1224.796758] ACPI: Preparing to enter system sleep state S3
[ 1224.797410] PM: Saving platform NVS memory
[ 1224.797418] Disabling non-boot CPUs ...
[ 1224.799315] smpboot: CPU 1 is now offline
[ 1224.801682] smpboot: CPU 2 is now offline
[ 1224.803940] smpboot: CPU 3 is now offline

test_213_fail.log

[keyonjie]

hi @stevyan can you share your ./stress-s3.sh please, I want to duplicate it on my side.

[keyonjie]

btw, @stevyan can you paste the sof-logger error log(without -t) also for the error case?

[stevyan]

test script attached, e.g.: #sudo ./stress-s3.sh 500 0 0

stress-s3.sh

[keyonjie]

both the 2 failed log show we have ipc timeout at runtime resume, so I am curious if we can reproduce it once we disable runtime suspend:
echo on > /sys/bus/pci/devices/0000:00:0e.0/power/control

[keyonjie]

@stevyan after I disabled runtime suspend, I can't duplicate the issue with 2000 iteration finished.
@ranj063 looks there is some corner cases left in our runtime suspend/resume?

[ranj063]

@keyonjie there is aboslutely no difference in sequence between runtime suspend/resume and system suspend/resume in SOF. So I dont know how this test is helpful in identifying the problem

[keyonjie]

@keyonjie there is aboslutely no difference in sequence between runtime suspend/resume and system suspend/resume in SOF. So I dont know how this test is helpful in identifying the problem

I meant doing suspend at SOF runtime-suspended case:
to response to S3 enter command, we wake up it to the active status, and then suspend it.
The issue happens at this waking up.

[ranj063]

Yes, but what i meant was that waking up from runtime suspend or waking up from S3 are exactly the same in the SOF driver.

[Jiangxinx]

Daily test result: can still be reproduced on apl_up2_nocodec platform, the rate is 17/100.
By the way, I can't reproduce it on apl_up2_pcm512x platform within 100 times.

To reproduce

1. sudo ./stress-s3.sh 100 0 0

Test Recipe
sof (master): de5bba49
linux (topic/sof-dev): 1071743
topology: sof-apl-pcm512x.tplg, sof-apl-nocodec.tplg