Repository navigation
suspend/resume failure after several cycles on Yorp #243
Description
This issue is more like a regression, we can do suspend/resume more than hundreds of times before. but it's easy to fail now(less then 10 times).
How to reproduce:
sudo suspend_stress_test
First error is (appears more than once)
[ 84.999092] call GOOG0004:00+ returned 0 after 1161 usecs
[ 84.999192] calling 0000:00:0e.0+ @ 3334, parent: pci0000:00, cb: snd_sof_suspend_late [snd_sof]
[ 84.999263] sof-audio sof-audio: tag 1 not opened!
[ 84.999334] sof-audio sof-audio: ipc tx: 0x40010000
[ 84.999795] sof-audio sof-audio: ipc tx succeeded: 0x40010000
[ 85.021391] sof-audio sof-audio: DSP core(s) enabled? 0 : core_mask 3
[ 85.021432] sof-audio sof-audio: Debug PCIR: 00000000 at 00000044
[ 85.021494] WARNING: CPU: 1 PID: 3334 at /mnt/host/source/src/third_party/kernel/v4.14/sound/hda/hdac_component.c:85 snd_hdac_display_power+0x9c/0xa7 [snd_hda_core]
[ 85.021499] Modules linked in: uinput snd_soc_sst_bxt_da7219_max98357a snd_soc_hdac_hdmi sof_pci_dev snd_sof_intel_hda_common snd_soc_hdac_hda snd_sof_intel_hda snd_sof_intel_byt snd_sof snd_sof_xtensa_dsp snd_soc_acpi_intel_match snd_soc_acpi snd_hda_ext_core snd_hda_codec snd_hwdep snd_hda_core snd_soc_max98357a acpi_als snd_soc_da7219 lzo lzo_compress zram bridge stp llc snd_seq_dummy snd_seq snd_seq_device ipt_MASQUERADE nf_nat_masquerade_ipv4 xt_mark fuse btusb btrtl btbcm btintel bluetooth uvcvideo ecdh_generic videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core iio_trig_sysfs cros_ec_sensors_ring cros_ec_sensors cros_ec_sensors_core industrialio_triggered_buffer kfifo_buf industrialio iwlmvm iwl7000_mac80211 iwlwifi cfg80211 ax88179_178a usbnet mii joydev
[ 85.021599] CPU: 1 PID: 3334 Comm: cat Tainted: G W 4.14.78 #7
[ 85.021600] Hardware name: Google Yorp/Yorp, BIOS Google_Yorp.10641.0.2018_05_03_1421 05/03/2018
[ 85.021602] task: ffff90b0878f0000 task.stack: ffffa1c2418bc000
[ 85.021605] RIP: 0010:snd_hdac_display_power+0x9c/0xa7 [snd_hda_core]
[ 85.021606] RSP: 0018:ffffa1c2418bfbc8 EFLAGS: 00010246
[ 85.021607] RAX: ffff90b08cb21b68 RBX: ffffffffffffffed RCX: 0000000000000000
[ 85.021608] RDX: 3c2350ec3984ba00 RSI: 0000000000000000 RDI: ffff90b08cbcc828
[ 85.021609] RBP: ffffa1c2418bfbd8 R08: 0000000000000000 R09: ffffffff8b4f9253
[ 85.021610] R10: 0000000000081020 R11: ffffffff8a521d00 R12: ffff90b08cbcc308
[ 85.021611] R13: ffff90b08b16e4c0 R14: ffff90b08cbcc828 R15: ffff90b08cbcc028
[ 85.021612] FS: 00007dec6cd9c800(0000) GS:ffff90b0bfd00000(0000) knlGS:0000000000000000
[ 85.021613] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 85.021614] CR2: 00005719e4c20b20 CR3: 000000014a722000 CR4: 00000000003406e0
[ 85.021615] Call Trace:
[ 85.021626] hda_dsp_suspend+0x2c/0x63 [snd_sof_intel_hda_common]
[ 85.021632] sof_suspend+0x10d/0x13f [snd_sof]
[ 85.021636] ? snd_sof_suspend+0xd/0xd [snd_sof]
[ 85.021641] dpm_run_callback+0x48/0x83
[ 85.021644] __device_suspend_late+0x1c6/0x249
[ 85.021646] dpm_suspend_late+0xc6/0x1e2
[ 85.021651] suspend_devices_and_enter+0x130/0x5e1
[ 85.021653] pm_suspend+0x2b1/0x306
[ 85.021656] state_store+0xa7/0xd2
[ 85.021660] kernfs_fop_write+0xf4/0x14c
[ 85.021664] __vfs_write+0x47/0xf0
[ 85.021668] ? inode_security+0x17/0x1e
[ 85.021670] ? selinux_file_permission+0x60/0xb0
[ 85.021672] vfs_write+0xaf/0xf2
[ 85.021674] SyS_write+0x53/0x9b
[ 85.021676] do_syscall_64+0x6d/0x81
[ 85.021681] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[ 85.021683] RIP: 0033:0x7dec6c83a3b0
[ 85.021706] RSP: 002b:00007fff683b2b78 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 85.021708] RAX: ffffffffffffffda RBX: 00007dec6cd7b000 RCX: 00007dec6c83a3b0
[ 85.021708] RDX: 0000000000000006 RSI: 00007dec6cd7b000 RDI: 0000000000000001
[ 85.021709] RBP: 00007fff683b2ba0 R08: ffffffffffffffff R09: 0000000000000000
[ 85.021710] R10: 0000000000001000 R11: 0000000000000246 R12: 0000000000000006
[ 85.021711] R13: 0000000000020000 R14: 00007dec6cd7b000 R15: 0000000000000001
[ 85.021712] Code: 74 29 31 db ff c9 41 89 8e d0 04 00 00 75 15 48 8b 48 08 4c 8b 59 10 4d 85 db 74 08 48 8b 38 e8 75 13 44 ca 89 d8 5b 41 5e 5d c3 <0f> 0b 41 8b 8e d0 04 00 00 eb cc 0f 1f 44 00 00 55 48 89 e5 41
[ 85.021742] ---[ end trace 1fd98ce707897907 ]---
Then several rx list empty errors like
[ 112.854673] sof-audio sof-audio: ipc tx succeeded: 0x30010000
[ 112.854683] sof-audio sof-audio: error: rx list empty but received 0x0
[ 112.854689] sof-audio sof-audio: error: can't find message header 0x30010000
[ 112.854710] sof-audio sof-audio: ipc rx: 0x90020000
Then finally FW crashes.
dmesg error：
[ 112.860691] sof-audio sof-audio: ipc tx succeeded: 0x30030000
[ 112.860701] sof-audio sof-audio: error: rx list empty but received 0x0
[ 112.860704] sof-audio sof-audio: error: can't find message header 0x30030000
[ 112.860725] sof-audio sof-audio: ipc rx: 0x90020000
[ 112.860741] sof-audio sof-audio: ipc rx done: 0x90020000
[ 112.860759] sof-audio sof-audio: ipc tx: 0x30030000
[ 112.860864] sof-audio sof-audio: ipc tx succeeded: 0x30030000
[ 112.860880] sof-audio sof-audio: ipc tx: 0x30030000
[ 112.860988] sof-audio sof-audio: ipc tx succeeded: 0x30030000
[ 112.861004] sof-audio sof-audio: ipc tx: 0x30030000
[ 112.861115] sof-audio sof-audio: ipc tx succeeded: 0x30030000
[ 112.861134] sof-audio sof-audio: ipc tx: 0x30030000
[ 112.861250] sof-audio sof-audio: ipc tx succeeded: 0x30030000
[ 112.861450] sof-audio sof-audio: ipc tx: 0x80010000
[ 112.861608] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 112.861629] sof-audio sof-audio: ipc tx: 0x80010000
[ 112.861778] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 112.861800] sof-audio sof-audio: ipc tx: 0x80010000
[ 112.861944] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 112.861965] sof-audio sof-audio: ipc tx: 0x80010000
[ 112.862370] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 112.862392] sof-audio sof-audio: ipc tx: 0x80010000
[ 112.862484] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 112.862506] sof-audio sof-audio: ipc tx: 0x80010000
[ 112.862591] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 112.862614] sof-audio sof-audio: ipc tx: 0x80010000
[ 112.862677] sof-audio sof-audio: ipc rx: 0x90020000
[ 112.862693] sof-audio sof-audio: ipc rx done: 0x90020000
[ 112.901011] sof-audio sof-audio: ipc rx: 0x90020000
[ 112.901032] sof-audio sof-audio: ipc rx done: 0x90020000
[ 112.940775] sof-audio sof-audio: ipc rx: 0x90020000
[ 112.940798] sof-audio sof-audio: ipc rx done: 0x90020000
[ 112.980767] sof-audio sof-audio: ipc rx: 0x90020000
[ 112.980790] sof-audio sof-audio: ipc rx done: 0x90020000
[ 113.020730] sof-audio sof-audio: ipc rx: 0x90020000
[ 113.020750] sof-audio sof-audio: ipc rx done: 0x90020000
[ 113.060848] sof-audio sof-audio: ipc rx: 0x90020000
[ 113.060869] sof-audio sof-audio: ipc rx done: 0x90020000
[ 113.100912] sof-audio sof-audio: ipc rx: 0x90020000
[ 113.100935] sof-audio sof-audio: ipc rx done: 0x90020000
[ 113.140939] sof-audio sof-audio: ipc rx: 0x90020000
[ 113.140959] sof-audio sof-audio: ipc rx done: 0x90020000
[ 113.169426] sof-audio sof-audio: error: ipc timed out for 0x80010000 size 0x48
[ 113.169444] sof-audio sof-audio: status: fw entered - code 00000005
[ 113.169593] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[ 113.169614] sof-audio sof-audio: error: waking up any trace sleepers
[ 113.169630] sof-audio sof-audio: error: failed to set dai config for iDisp3
[ 113.169633] sof-audio sof-audio: error: failed to restore pipeline after resume -110
[ 113.169651] sof-audio sof-audio: pcm: open stream 0 dir 0
[ 113.169653] sof-audio sof-audio: error: pcm open failed to resume -16
[ 113.169657] sof-audio sof-audio: ASoC: can't open component sof-audio: -16
[ 113.169661] Speakers: ASoC: failed to start FE -16
[ 113.180841] sof-audio sof-audio: ipc rx: 0x90020000
Trace log:
0 2 WAIT 63395601.666667 4.270833 ../../src/include/sof/wait.h:73 WFE
0 2 WAIT 63396592.916667 991.250000 ../../src/include/sof/wait.h:76 WFX
0 2 PIPE 63396597.395833 4.479167 schedule.c:368 sch
0 2 WAIT 63396601.666667 4.270833 ../../src/include/sof/wait.h:73 WFE
0 2 IPC 63396742.656250 140.989578 apl-ipc.c:65 IRQ
0 2 IPC 63396746.458333 3.802083 apl-ipc.c:72 Nms
0 1 IPC 63396749.947917 3.489583 apl-ipc.c:82 Pen
0 2 IPC 63396753.072917 3.125000 apl-ipc.c:92 Rpy
0 2 WAIT 63396758.906250 5.833333 ../../src/include/sof/wait.h:76 WFX
0 2 IPC 63396764.114583 5.208333 apl-ipc.c:172 Msg
0 2 PIPE 63396768.020833 3.906250 schedule.c:368 sch
Tested with:
soft-master:4ac9248f
sof-master:43da16
kernel-debug/cros-v4.14-rebase: 90eee4
Activity
lgirdwood commentedon Nov 2, 2018
Pasting from @markyang thesofproject/sof#522 (comment)
@ranj063 It looks like the driver is also sending PCM_PARAMS twice during this stress test too.
lgirdwood commentedon Nov 2, 2018
@keqiaozhang I've updated your initial post to include all the relevant logs. Please always double check that there is nothing important in the logs prior to the FW crash
keyonjie commentedon Nov 7, 2018
the issue should be a regression for code rebasing, @ranj063 found that a patch need to be redone.
after redone, this issue is fixed for me. @ranj063 can you help change cros branch please.
ranj063 commentedon Nov 7, 2018
@keyonjie yes, I will update the topic/cros branch tomorrow. I need to sync with @plbossart before I update it.
keqiaozhang commentedon Nov 13, 2018
@ranj063
This issue is fixed on your kernel branch-cros-sof-v4.14-rebase.
I will close this issue once you rebase it to google release branch(thesofproject/linux/tree/topic/cros-sof-v4.14).
kernel driver- ranja063-cros-sof-v4.14-rebase:a38231
sof-master:1607737
soft-master:2cd668c
keqiaozhang commentedon Nov 16, 2018
This issue is fixed, now suspend/resume can pass ~100 iterations.
But the criterion form chrome is 500 iterations. so we still have gap there.
I will keep this issue open until we meet this criterion.
[-]suspend/resume failure after several cycles on Yorp[/-][+]suspend/resume failure after ~100 iterations on Yorp[/+]ranj063 commentedon Nov 16, 2018
@keqiaozhang can we please get the log when it fails? It is impossible to debug without it. Thanks!
keqiaozhang commentedon Nov 20, 2018
Let's track the gap to meet Chrome request for 500 iterations in #304
[-]suspend/resume failure after ~100 iterations on Yorp[/-][+]suspend/resume failure after several cycles on Yorp[/+]Use Option::Map
selftests/bpf: Add mprog API tests for BPF tcx opts
selftests/bpf: Add various more tcx test cases
x86/ftrace: Relocate %rip-relative percpu refs in dynamic trampolines