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

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

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): 6a84b4e
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

@stevyan

@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.

May relevant to #1254

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): be1331a ( + 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

@stevyan

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

@stevyan

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

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

stress-s3.sh

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

@stevyan

@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?

@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

@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.

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.

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

sudo ./stress-s3.sh 100 0 0

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

Can you share the config for kernel? I'm getting different error message altogether for this (log attached). This happens always on first iteration of stress-s3.sh

Recipe

Kernel
1071743

FW and TPLG
thesofproject/sof@de5bba4
sof-apl-nocodec.tplg

Reproduction steps

sudo ./stress-s3.sh 100 0 0

Logs and files

test_1_fail.log

Three more observations:

Sometimes during an S3 stress test the whole system hangs, requiring a hard reset
In about 20-40% of the cases when an IPC timeout occurs, the logger returns an empty trace
Even in "normal" cases, when upon an IPC timeout a trace can be retrieved, it is often incomplete. But this might have a logical explanation, related to the IPC timeout itself

Traces seem to be corrupted sometimes:

    0      2          IPC             51784.895833         4.218750 of/src/ipc/handler.c:1028   ipc: pipe 23 -> complete
    0      2         PIPE 4.23        51805.885417        20.989584 src/audio/pipeline.c:188    pipeline_complete()
    0      2          IRQ             51809.895833         4.010417 f/src/lib/irqdebug.c:33     IRQ #0: 0x8
    0      2          IRQ             51812.239583         2.343750 f/src/lib/irqdebug.c:33     IRQ #1: 0x3
    0      2          IPC             51814.583333         2.343750 ers/intel/cavs/ipc.c:197    IPC complete: 16777215

where the last line should print the return code from ipc_cmd() for the pipeline-completion IPC, which can only return 0 or a negative error code.

@lgirdwood

I'm looking for new ideas. I see the following:

The system is preparing to suspend
For this the sound card is (runtime-) woken up
The driver performs the DSP initialisation, including sending a topology to it
Sending the topology involves a strictly serialised repeating "sending of IPC -> waiting for reply" sequence
At some point one of IPC replies fails to arrive, which means there is no interrupt and the interrupt registers don't show any bits set, when checked after the timeout expiration (@lgirdwood that's an answer to your question)
The DSP log looks either completely or "almost" completely normal: it receives the last IPC and sends a reply.

To me this looks like the hardware is failing to execute the IPC transfer from the DSP to the host. This also seems to be an intermittent failure, because if it is ignored, after it communication with the DSP is possible again. What is the procedure for debugging such cases? I've been told we don't have JTAG access to the DSP, maybe only to the SoC. I'm not sure if we have any GPIOs or other pins available to toggle them from both the DSP and thee host side to check them with a scope. Maybe we could write some data in the mailbox from the DSP side to check it from the host side? E.g. after each received and answered IPC start a periodic task, writing an IPC counter and a repeat counter into the mailbox and then check them on the host side when the timeout expires...

I'm trying to exchange some data over the DSP-to-host mailbox, using e.g.

	mailbox_dspbox_write(0x250, &cnt, sizeof(cnt));

on the DSP side and

	sof_mailbox_read(sdev, 0x250, &cnt, sizeof(cnt));

on the host side, but not getting the expected result...

@lyakh

@lyakh
Yes, every time you will get DSP reset after a suspend/resume. And we will power off the DSP so everything in memory window is gone. If you would like to have some count, make it in some register. There are few registers that are not using, or you can just use some bits of the register.

@xiulipan

@xiulipan I'm not trying to keep the counter across suspends, I'm trying to send it from the DSP to the host. Can I use registers for that too without disturbing the IPC? Which ones?

@lgirdwood

For the record: following @lgirdwood 's idea to switch over from MSI to "legacy" interrupt mode didn't fix the problem.

update: mailbox is working now.

500 iterations - check. I think I've fixed it, expect a patch soon.

please keep the test running while cooking your patch. last year we did 10k iterations to truly prove it's gone :)

fixed by #943

@lyakh

@lyakh It seems we have a patch for this in FW now thesofproject/sof#1441

fixed by #943

close

Navigation Menu

Repository navigation

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

Recipe

Reproduction steps

Logs and files

19 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

ranj063 commented on Apr 29, 2019

mengdonglin commented on Apr 29, 2019

stevyan commented on Apr 29, 2019

keyonjie commented on Apr 29, 2019

keyonjie commented on Apr 29, 2019

stevyan commented on Apr 29, 2019

keyonjie commented on Apr 29, 2019

keyonjie commented on Apr 30, 2019

ranj063 commented on Apr 30, 2019

keyonjie commented on Apr 30, 2019

ranj063 commented on Apr 30, 2019

Jiangxinx commented on May 6, 2019

wwittbrx commented on May 6, 2019

Recipe

Reproduction steps

Logs and files

19 remaining items

lyakh commented on May 10, 2019

lyakh commented on May 11, 2019

lyakh commented on May 13, 2019

lyakh commented on May 13, 2019

xiulipan commented on May 13, 2019

lyakh commented on May 14, 2019

lyakh commented on May 14, 2019

lyakh commented on May 14, 2019

lyakh commented on May 14, 2019

wenqingfu commented on May 14, 2019

lyakh commented on May 15, 2019

xiulipan commented on May 15, 2019

wenqingfu commented on May 22, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions