Skip to content

IPC error occurs during suspend/resume on APL #611

Closed

Description

@markyang

Summary:
Error message occurs on UP2 with pcm512x during the suspend/resume test.

dmesg:

[ 8060.313612] PM: suspend entry (deep)
[ 8060.313616] PM: Syncing filesystems ... done.
[ 8060.314373] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 8060.316209] OOM killer disabled.
[ 8060.316210] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 8060.317378] Suspending console(s) (use no_console_suspend to debug)
[ 8060.449370] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 5
[ 8060.449404] sof-audio sof-audio: ipc tx: 0x60000000: GLB_STREAM_MSG: unknown type
[ 8060.449533] sof-audio sof-audio: error: ipc error for 0x60000000 size 0xc
[ 8060.449550]  Port5: ASoC: trigger FE failed -22
[ 8060.449581] sof-audio sof-audio: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 8060.449788] sof-audio sof-audio: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 8060.471503] sof-audio sof-audio: DSP core(s) enabled? 0 : core_mask 3
[ 8060.471537] sof-audio sof-audio: Debug PCIR: 00000000 at  00000044
[ 8060.471546] sof-audio-pci 0000:00:0e.0: Turning i915 HDAC power off
[ 8060.509647] ACPI: Preparing to enter system sleep state S3

Test steps:

  1. aplay -Dhw:0,0 -c2 -fS16_LE -vv -i ~/Music/California_Dreaming_48k_24bit.wav
  2. sudo ./stress_pm_S3.sh
#!/bin/bash

set -e

ITERATIONS=1000
COUNTER=0

while [ $COUNTER -lt $ITERATIONS ]; do
	echo "Test $COUNTER"
	dmesg -C
	SUSPEND_TIME=$(($RANDOM%5+5))
	echo “System will suspend after $SUSPEND_TIME seconds ...”
	sleep $SUSPEND_TIME
	WAKE_TIME=$(($RANDOM%5+5))
	echo "system will resume after $WAKE_TIME seconds ..."
	rtcwake -m mem -s $WAKE_TIME
	unset ERROR
	ERROR=$(dmesg | grep sof-audio | grep -v "failed" | grep "error")
	if [ ! -z "$ERROR" ]
	then
		dmesg > test_${COUNTER}_fail.log
		echo "Suspend/resume failed, see test_${COUNTER}_fail.log for details"
		exit 1
	else
		echo "Test $COUNTER success"
	fi

	dmesg > test_${COUNTER}_pass.log
	let COUNTER+=1
done

Test env:
sof master: 43081af
sof tool: c702844
kernel sof-dev: 6a976e1
tplg: sof-apl-pcm512x.tplg-c7028444

Log:
logger-apl.log
test_0_fail.log

Activity

  1. added
    enhancementNew feature or request
    APLApplies to Apollolake platform
    on Nov 22, 2018
  2. added
    bugSomething isn't working as expected
    and removed
    enhancementNew feature or request
    on Nov 24, 2018
  3. mengdonglin commented on Nov 24, 2018

    @mengdonglin
    Collaborator

    @markyang Please share more information here:

    • attach the test script ./stress_pm_S3.sh
    • How many iterations will trigger the error message
    • confirm if system can resume from S3 and audio can resume successfully and playback can still work?
  4. markyang commented on Nov 26, 2018

    @markyang
    Author

    @mengdonglin

    • attach the test script ./stress_pm_S3.sh
      -- The scripts was already attached after step 2.
    • How many iterations will trigger the error message
      -- The error message was triggered at the first time.
    • confirm if system can resume from S3 and audio can resume successfully and playback can still work?
      -- system can resume from S3 and playback can work. but 'pcm_write' error will occur, I will attach the log.
  5. markyang commented on Nov 27, 2018

    @markyang
    Author

    A new bug(#637) was created to following the 'pcm_write' error.

  6. changed the title [-]Error message occurs during suspend/resume[/-] [+]IPC error occurs during suspend/resume on APL[/+] on Nov 30, 2018
  7. markyang commented on Dec 20, 2018

    @markyang
    Author

    Summary:
    The ipc error(error: ipc error for 0x60000000 size 0xc) also exists after the first time resume, but this is only a print issue, the functionality is OK, we can lower the priority.

    Test env:
    sof master: da9ab07
    kernel sof-dev: cfcd569
    tplg: sof-apl-pcm512x.tplg

  8. lgirdwood commented on Dec 20, 2018

    @lgirdwood
    Member

    @mengdonglin looks like a duplicate, can we mark and close ?

  9. mengdonglin commented on Dec 25, 2018

    @mengdonglin
    Collaborator

    @lgirdwood thesofproject/linux#370 is more complicate than this.
    May we keep it open until The ipc error(error: ipc error for 0x60000000 size 0xc) is fixed on APL?

  10. libinyang commented on Jan 5, 2019

    @libinyang
    Contributor

    As this issue doesn't block any function test cases, I suggest we set it as P3 and put it in low priority. What's your opinion? @mengdonglin @markyang

  11. markyang commented on Jan 7, 2019

    @markyang
    Author
  12. lgirdwood commented on Jan 8, 2019

    @lgirdwood
    Member

    @markyang can you check this again with latest kernel/FW. There have been some fixes in this area. Thanks.

  13. markyang commented on Jan 14, 2019

    @markyang
    Author

    @lgirdwood Audio can be resumed, but the ipc error(ipc error for 0x60000000 size 0xc) still exists with the latest build on APL with PCM512x.

    dmesg:

    [ 9767.839782] OOM killer disabled.
    [ 9767.839784] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
    [ 9767.840991] printk: Suspending console(s) (use no_console_suspend to debug)
    [ 9767.848392] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 5
    [ 9767.848412] sof-audio sof-audio: ipc tx: 0x60000000: GLB_STREAM_MSG: unknown type
    [ 9767.848488] sof-audio sof-audio: error: ipc error for 0x60000000 size 0xc
    [ 9767.848497]  Port5: ASoC: trigger FE failed -22
    [ 9767.848517] sof-audio sof-audio: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
    [ 9767.848623] sof-audio sof-audio: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
    [ 9767.848630] r8169 0000:03:00.0 enp3s0: Link is Down
    [ 9767.848697] sof-audio sof-audio: FW Poll Status: reg=0x1010303 successful
    [ 9767.848707] sof-audio sof-audio: FW Poll Status: reg=0x303 successful
    [ 9767.848712] sof-audio sof-audio: DSP core(s) enabled? 0 : core_mask 3
    [ 9767.848740] sof-audio sof-audio: Debug PCIR: 00000010 at  00000044
    [ 9767.848747] sof-audio-pci 0000:00:0e.0: Turning i915 HDAC power off
    [ 9767.980696] ------------[ cut here ]------------
    [ 9767.980699] Power well 2 on.
    [ 9767.980746] WARNING: CPU: 0 PID: 3271 at drivers/gpu/drm/i915/intel_runtime_pm.c:483 bxt_enable_dc9+0xf2/0x120
    [ 9767.980749] Modules linked in: snd_soc_sst_bxt_pcm512x snd_soc_hdac_hdmi snd_soc_dmic x86_pkg_temp_thermal sof_pci_dev snd_sof_intel_hda_common snd_sof_intel_hda snd_sof_intel_byt snd_sof_nocodec snd_sof_xtensa_dsp snd_sof snd_soc_acpi_intel_match snd_soc_acpi snd_hda_ext_core intel_lpss_pci snd_hda_core intel_lpss mfd_core snd_soc_wm8804_i2c snd_soc_pcm512x_i2c snd_soc_wm8804 snd_soc_pcm512x snd_soc_core snd_pcm efivarfs mmc_block sdhci_pci cqhci sdhci xhci_pci xhci_hcd
    [ 9767.980800] CPU: 0 PID: 3271 Comm: kworker/u8:6 Not tainted 4.20.0-daily-20190114 #1
    [ 9767.980803] Hardware name: AAEON UP-APL01/UP-APL01, BIOS UPA1AM36 04/10/2018
    [ 9767.980813] Workqueue: events_unbound async_run_entry_fn
    [ 9767.980821] RIP: 0010:bxt_enable_dc9+0xf2/0x120
    [ 9767.980826] Code: 6e b6 ff 0f 0b e9 69 ff ff ff 80 3d 46 6e 02 01 00 0f 85 79 ff ff ff 48 c7 c7 9c 51 a5 9a c6 05 32 6e 02 01 01 e8 de 6d b6 ff <0f> 0b e9 5f ff ff ff 80 3d 1e 6e 02 01 00 0f 85 5f ff ff ff 48 c7
    [ 9767.980830] RSP: 0018:ffff9acb81f6bdc8 EFLAGS: 00010286
    [ 9767.980834] RAX: 0000000000000000 RBX: ffff8f08f81f0000 RCX: 0000000000000006
    [ 9767.980838] RDX: 0000000000000007 RSI: 0000000000000082 RDI: ffff8f08fba15410
    [ 9767.980841] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000020280
    [ 9767.980844] R10: 0000000000000000 R11: 000000000003ed44 R12: ffff8f08fa4cd800
    [ 9767.980847] R13: 0000000000000000 R14: 0000000000000002 R15: ffffffff9aa7424e
    [ 9767.980851] FS:  0000000000000000(0000) GS:ffff8f08fba00000(0000) knlGS:0000000000000000
    [ 9767.980855] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [ 9767.980858] CR2: 000055d10b790860 CR3: 0000000162c0a000 CR4: 00000000003406f0
    [ 9767.980860] Call Trace:
    [ 9767.980875]  i915_drm_suspend_late+0xe9/0xf0
    [ 9767.980885]  ? pci_pm_poweroff_late+0x30/0x30
    [ 9767.980892]  dpm_run_callback+0x3b/0x150
    [ 9767.980899]  __device_suspend_late+0xd6/0x1a0
    [ 9767.980905]  async_suspend_late+0x15/0x90
    [ 9767.980912]  async_run_entry_fn+0x32/0xe0
    [ 9767.980920]  process_one_work+0x1e3/0x3d0
    [ 9767.980927]  worker_thread+0x28/0x3c0
    [ 9767.980933]  ? set_worker_desc+0xb0/0xb0
    [ 9767.980937]  kthread+0x10e/0x130
    [ 9767.980943]  ? kthread_park+0x80/0x80
    [ 9767.980951]  ret_from_fork+0x35/0x40
    [ 9767.980957] ---[ end trace 92df81f48b0d9126 ]---
    [ 9768.019015] ACPI: Preparing to enter system sleep state S3
    [ 9768.019654] PM: Saving platform NVS memory
    [ 9768.019662] Disabling non-boot CPUs ...
    [ 9768.026375] IRQ 123: no longer affine to CPU1
    [ 9768.027439] smpboot: CPU 1 is now offline
    [ 9768.034360] IRQ 120: no longer affine to CPU2
    [ 9768.035458] smpboot: CPU 2 is now offline
    [ 9768.050413] IRQ 122: no longer affine to CPU3
    [ 9768.051477] smpboot: CPU 3 is now offline
    [ 9768.054472] ACPI: Low-level resume complete
    [ 9768.054633] PM: Restoring platform NVS memory
    [ 9768.055526] Enabling non-boot CPUs ...
    [ 9768.055588] x86: Booting SMP configuration:
    [ 9768.055591] smpboot: Booting Node 0 Processor 1 APIC 0x2
    [ 9768.056856]  cache: parent cpu1 should not be sleeping
    [ 9768.057108] CPU1 is up
    [ 9768.057145] smpboot: Booting Node 0 Processor 2 APIC 0x4
    [ 9768.058558]  cache: parent cpu2 should not be sleeping
    [ 9768.058875] CPU2 is up
    [ 9768.058922] smpboot: Booting Node 0 Processor 3 APIC 0x6
    [ 9768.060560]  cache: parent cpu3 should not be sleeping
    [ 9768.061037] CPU3 is up
    [ 9768.064234] ACPI: Waking up from system sleep state S3
    [ 9768.116138] hpet1: lost 4813 rtc interrupts
    [ 9768.120414] sof-audio-pci 0000:00:0e.0: Turning i915 HDAC power on
    [ 9768.120422] sof-audio sof-audio: Debug PCIR: 00000000 at  00000044
    [ 9768.120425] sof-audio sof-audio: Debug PCIR: 00000040 at  00000048
    [ 9768.120429] sof-audio sof-audio: Debug PCIW: 00000000 at  00000048
    [ 9768.123738] sof-audio sof-audio: Debug PCIR: 00000000 at  00000048
    [ 9768.123742] sof-audio sof-audio: Debug PCIW: 00000040 at  00000048
    [ 9768.123754] sof-audio sof-audio: Debug PCIR: 00000040 at  00000048
    [ 9768.123757] sof-audio sof-audio: Debug PCIW: 00000000 at  00000048
    [ 9768.123761] sof-audio sof-audio: Debug PCIR: 00000000 at  00000048
    [ 9768.123764] sof-audio sof-audio: Debug PCIW: 00000040 at  00000048
    [ 9768.123777] sof-audio sof-audio: loading firmware
    [ 9768.123786] sof-audio sof-audio: Debug PCIR: 00000002 at  00000048
    [ 9768.123789] sof-audio sof-audio: Debug PCIW: 00000000 at  00000048
    [ 9768.123793] sof-audio sof-audio: Debug PCIR: 00000000 at  00000044
    [ 9768.123796] sof-audio sof-audio: Debug PCIW: 00000004 at  00000044
    [ 9768.123797] sof-audio sof-audio: booting DSP firmware
    [ 9768.123951] sof-audio sof-audio: period_bytes:0x0
    [ 9768.123952] sof-audio sof-audio: periods:1
    [ 9768.124797] sof-audio sof-audio: FW Poll Status: reg=0x3030303 successful
    [ 9768.124802] sof-audio sof-audio: FW Poll Status: reg=0x3030302 successful
    [ 9768.124805] sof-audio sof-audio: unstall/run core: core_mask = 1
    [ 9768.124809] sof-audio sof-audio: DSP core(s) enabled? 1 : core_mask 1
    [ 9768.125786] sof-audio sof-audio: FW Poll Status: reg=0x40000000 successful
    [ 9768.126804] sof-audio sof-audio: FW Poll Status: reg=0x1010202 successful
    [ 9768.126925] sof-audio sof-audio: error: rx list empty but received 0x4200
    [ 9768.126927] sof-audio sof-audio: error: can't find message header 0x1004200
    [ 9768.142823] sof-audio sof-audio: FW Poll Status: reg=0x5000001 successful
    [ 9768.162874] sof-audio sof-audio: FW Poll Status: reg=0x5 successful
    [ 9768.162878] sof-audio sof-audio: Firmware download successful, booting...
    [ 9768.175820] sof-audio sof-audio: ipc rx: 0x70000000: FW_READY
    [ 9768.175823] sof-audio sof-audio: ipc: DSP is ready 0x70000000 offset 0x81000
    [ 9768.175824] sof-audio sof-audio: booting DSP firmware completed
    [ 9768.175828] sof-audio sof-audio: ipc rx done: 0x70000000: FW_READY
    [ 9768.175877] sof-audio sof-audio: firmware boot complete
    [ 9768.175883] sof-audio sof-audio: Debug PCIR: 00000000 at  00000048
    [ 9768.175887] sof-audio sof-audio: Debug PCIW: 00000002 at  00000048
    [ 9768.175891] sof-audio sof-audio: Debug PCIR: 00000004 at  00000044
    [ 9768.175894] sof-audio sof-audio: Debug PCIW: 00000000 at  00000044
    [ 9768.175911] sof-audio sof-audio: period_bytes:0x0
    

    Test steps:

    1. aplay -Dhw:0,0 -c2 -fS16_LE -vv -i music.wav
    2. sudo rtcwake -m mem -s 2
    

    Test env:
    sof master: 872cefe
    kernel sof-dev: 2ac82ee
    tplg: sof-apl-pcm512x.tplg

  14. lgirdwood commented on Jan 14, 2019

    @lgirdwood
    Member

    @markyang This is a FW crash that's not being detected by the driver. I've added a kernel issue

    thesofproject/linux#537

    [ 9768.126925] sof-audio sof-audio: error: rx list empty but received 0x4200
    [ 9768.126927] sof-audio sof-audio: error: can't find message header 0x1004200
    
  15. mengdonglin commented on Mar 29, 2019

    @mengdonglin
    Collaborator

    @stevyan @Jiangxinx Please check the latest status

  16. Jiangxinx commented on Mar 29, 2019

    @Jiangxinx
    Contributor

    Not reproduce on daily test.
    Step:
    1.aplay -Dhw:0,0 -fS16_LE -c2 -r48000 /dev/zero& sudo ~/test/stress-s3.sh 50 1 1

    Env:
    sof master: 742f83b
    kernel sof-dev: e29122d
    tplg: sof-apl-pcm512x.tplg

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Labels

APLApplies to Apollolake platformP2Critical bugs or normal featuresbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions