Stress: suspend/resume failure after dozens iterations on Yorp #304

Activity

1. keqiaozhang

   added

   bugSomething isn't workingSomething isn't working

   P2Critical bugs or normal featuresCritical bugs or normal features

   br-cros

   GLKApplies to Gemini LakeApplies to Gemini Lake

   on Nov 19, 2018
2. keqiaozhang

   assigned

   ranj063

   on Nov 19, 2018
3. keqiaozhang commented on Nov 20, 2018

   

   keqiaozhang

   on Nov 20, 2018

   Last edited by keqiaozhang

   Author

   More actions

   Re-tested it with same commits, but got different error logs:
   Command line error output:

   Suspend   212 of 10000: sleep for  6 seconds... wake for 10 seconds...
   Suspend   213 of 10000: sleep for  5 seconds... wake for  6 seconds...
   Suspend   214 of 10000: sleep for 10 seconds... wake for  8 seconds...
   Suspend   215 of 10000: sleep for  9 seconds... wake for  5 seconds...
   Suspend   216 of 10000: sleep for  7 seconds... wake for 10 seconds...
   Suspend   217 of 10000: sleep for  9 seconds... wake for 10 seconds...
   Suspend   218 of 10000: sleep for  6 seconds...Suspend failed.
   
   powerd start/running, process 8208
   tlsdated start/running, process 8227
   
   Finished 218 iterations.
   Suspend_failures: 1
   Firmware log errors: 0
   s0ix errors: 0
   

   dmesg log:

   [ 4257.328510] sof-audio sof-audio: loading firmware
   [ 4257.328539] sof-audio sof-audio: Debug PCIR: 00000000 at  00000048
   [ 4257.328547] sof-audio sof-audio: Debug PCIW: 00000000 at  00000048
   [ 4257.328557] sof-audio sof-audio: Debug PCIR: 00000000 at  00000044
   [ 4257.328564] sof-audio sof-audio: Debug PCIW: 00000004 at  00000044
   [ 4257.328567] sof-audio sof-audio: booting DSP firmware
   [ 4257.328666] sof-audio sof-audio: period_bytes:0x480
   [ 4257.328668] sof-audio sof-audio: periods:227
   [ 4257.328732] sof-audio sof-audio: unstall/run core: core_mask = 1
   [ 4257.328735] sof-audio sof-audio: DSP core(s) enabled? 1 : core_mask 1
   [ 4260.520424] sof-audio sof-audio: error: load fw failed err: -62
   [ 4260.520434] sof-audio sof-audio: unknown ROM status value 02000012
   [ 4260.520441] sof-audio sof-audio: error: status = 0x00000000 panic = 0x00000000
   [ 4260.520448] sof-audio sof-audio: unknown ROM status value 02000012
   [ 4260.520454] sof-audio sof-audio: error: load fw failed err: -62
   [ 4260.520458] sof-audio sof-audio: error: failed to reset DSP
   [ 4260.520461] sof-audio sof-audio: error: failed to boot DSP firmware after resume -62
   [ 4261.522424] PM: Wakeup pending, aborting suspend
   [ 4261.522437] last active wakeup source: rtc_cmos
   [ 4261.522448] PM: suspend of devices aborted after 0.028 msecs
   [ 4261.522450] PM: Some devices failed to suspend, or early wake event detected
   [ 4261.522457] PM: resume of devices complete after 0.002 msecs
   [ 4264.528394] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
   [ 4264.528463] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
   [ 4264.528482] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 7:0
   [ 4264.530161] PM: Finishing wakeup.
   [ 4264.530163] OOM killer enabled.
   [ 4264.530165] Restarting tasks ... done.
   [ 4264.537532] PM: suspend exit
   [ 4264.931582] init: powerd main process (3206) killed by TERM signal
   [ 4264.937119] audit: type=1400 audit(1542619796.548:1110): avc:  granted  { execute } for  pid=8154 comm="init" name="dash" dev="mmcblk0p3" ino=65624 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
   [ 4264.949217] audit: type=1400 audit(1542619796.560:1111): avc:  granted  { execute } for  pid=8155 comm="init" name="dash" dev="mmcblk0p3" ino=65624 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
   [ 4265.211755] audit: type=1400 audit(1542619796.822:1112): avc:  granted  { execute } for  pid=8207 comm="init" name="dash" dev="mmcblk0p3" ino=65624 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
   [ 4265.212969] audit: type=1400 audit(1542619796.823:1113): avc:  granted  { execute } for  pid=8207 comm="minijail0" path="/sbin/minijail0" dev="mmcblk0p3" ino=16408 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_minijail_exec:s0 tclass=file
   [ 4265.214231] audit: type=1400 audit(1542619796.825:1114): avc:  granted  { execute } for  pid=8207 comm="minijail0" name="powerd" dev="mmcblk0p3" ino=117853 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
   [ 4265.215438] audit: type=1400 audit(1542619796.825:1115): avc:  granted  { execute } for  pid=8208 comm="minijail0" name="powerd" dev="mmcblk0p3" ino=117853 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
   [ 4265.336804] audit: type=1400 audit(1542619796.947:1116): avc:  granted  { execute } for  pid=8221 comm="init" name="dash" dev="mmcblk0p3" ino=65624 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
   [ 4265.339432] audit: type=1400 audit(1542619796.950:1117): avc:  granted  { execute } for  pid=8222 comm="init" name="dash" dev="mmcblk0p3" ino=65624 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
   [ 4265.345192] audit: type=1400 audit(1542619796.956:1118): avc:  granted  { execute } for  pid=8226 comm="init" name="dash" dev="mmcblk0p3" ino=65624 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
   [ 4265.348191] audit: type=1400 audit(1542619796.959:1119): avc:  granted  { execute } for  pid=8226 comm="minijail0" path="/sbin/minijail0" dev="mmcblk0p3" ino=16408 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_minijail_exec:s0 tclass=file
   [ 5139.757354] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
   [15073.750425] kauditd_printk_skb: 4 callbacks suppressed
   [15073.750427] audit: type=1400 audit(1542630606.738:1124): avc:  granted  { execute } for  pid=9603 comm="minijail0" path="/sbin/minijail0" dev="mmcblk0p3" ino=16408 scontext=u:r:cros_debugd_minijail:s0 tcontext=u:object_r:cros_minijail_exec:s0 tclass=file
   [18657.500472] wlan0: deauthenticated from 00:62:ec:e6:2f:5d (Reason: 103=<unknown>)
   [18657.516495] ------------[ cut here ]------------
   [18657.516505] Command STATISTICS_CMD: a command is already active!
   [18657.516561] WARNING: CPU: 0 PID: 583 at /mnt/host/source/src/third_party/kernel/v4.14/drivers/net/wireless/iwl7000/iwlwifi/pcie/tx.c:1871 iwl_trans_pcie_send_hcmd+0x5a9/0x5c6 [iwlwifi]
   [18657.516564] Modules linked in: ax88179_178a usbnet mii cmac rfcomm uinput snd_soc_sst_bxt_da7219_max98357a snd_soc_hdac_hdmi snd_soc_dmic lzo lzo_compress zram 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_seq_dummy snd_hda_ext_core snd_hda_codec snd_hwdep snd_seq snd_hda_core snd_seq_device snd_soc_max98357a acpi_als snd_soc_da7219 bridge stp llc ipt_MASQUERADE nf_nat_masquerade_ipv4 fuse xt_mark iio_trig_sysfs btusb btrtl btbcm btintel bluetooth ecdh_generic uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core cros_ec_sensors cros_ec_sensors_ring cros_ec_sensors_core industrialio_triggered_buffer kfifo_buf industrialio iwlmvm iwl7000_mac80211 iwlwifi cfg80211 joydev
   [18657.516630] CPU: 0 PID: 583 Comm: wpa_supplicant Not tainted 4.14.78 #15
   [18657.516632] Hardware name: Google Yorp/Yorp, BIOS Google_Yorp.10641.0.2018_05_03_1421 05/03/2018
   [18657.516634] task: ffff8b11f3aab800 task.stack: ffff9b53c1278000
   [18657.516641] RIP: 0010:iwl_trans_pcie_send_hcmd+0x5a9/0x5c6 [iwlwifi]
   [18657.516644] RSP: 0018:ffff9b53c127b788 EFLAGS: 00010246
   [18657.516646] RAX: 2e6341c404017500 RBX: ffffffffc03bf8e9 RCX: 2e6341c404017500
   [18657.516648] RDX: 0000000000000007 RSI: 0000000000000082 RDI: ffff8b11ffc15418
   [18657.516650] RBP: ffff9b53c127b7f8 R08: fffffffffffc1b9b R09: 00000000ffff0a00
   [18657.516652] R10: 0000000000000007 R11: ffffffffb26e1ef4 R12: ffff8b11f6240028
   [18657.516654] R13: ffff9b53c127b858 R14: ffff8b11fb3d30a0 R15: ffff8b11f513c000
   [18657.516656] FS:  0000786d48627700(0000) GS:ffff8b11ffc00000(0000) knlGS:0000000000000000
   [18657.516658] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
   [18657.516660] CR2: 00002e56d2930000 CR3: 0000000173b78000 CR4: 00000000003406f0
   [18657.516662] Call Trace:
   [18657.516674]  iwl_trans_send_cmd+0x73/0xc1 [iwlwifi]
   [18657.516686]  iwl_mvm_send_cmd+0x3a/0x77 [iwlmvm]
   [18657.516695]  iwl_mvm_request_statistics+0x69/0xb8 [iwlmvm]
   [18657.516704]  iwl_mvm_mac_get_survey+0x9d/0x143 [iwlmvm]
   [18657.516722]  ieee80211_dump_survey+0xe8/0x131 [iwl7000_mac80211]
   [18657.516739]  ? nl80211_prepare_wdev_dump+0xee/0x117 [cfg80211]
   [18657.516749]  nl80211_dump_survey+0x370/0x450 [cfg80211]
   [18657.516756]  ? __alloc_skb+0x93/0x1a8
   [18657.516759]  ? __kmalloc_reserve+0x2a/0x60
   [18657.516763]  genl_lock_dumpit+0x2c/0x3c
   [18657.516768]  netlink_dump+0x10f/0x245
   [18657.516771]  __netlink_dump_start+0x152/0x16a
   [18657.516774]  genl_rcv_msg+0x2f2/0x42d
   [18657.516777]  ? genl_rcv_msg+0x42d/0x42d
   [18657.516779]  ? genl_lock_start+0x3d/0x3d
   [18657.516781]  ? genl_lock_dumpit+0x3c/0x3c
   [18657.516784]  ? genl_unbind+0xa6/0xa6
   [18657.516786]  netlink_rcv_skb+0x7e/0xef
   [18657.516789]  genl_rcv+0x28/0x36
   [18657.516792]  netlink_unicast+0x144/0x1ac
   [18657.516795]  netlink_sendmsg+0x2fc/0x32e
   [18657.516800]  sock_sendmsg_nosec+0x18/0x25
   [18657.516804]  ___sys_sendmsg+0x1b8/0x244
   [18657.516809]  ? security_socket_sendmsg+0x43/0x56
   [18657.516812]  ? sock_sendmsg_nosec+0x18/0x25
   [18657.516815]  ? SyS_sendto+0x120/0x149
   [18657.516819]  ? __fget_light+0x2c/0x58
   [18657.516822]  __sys_sendmsg+0x52/0x8c
   [18657.516827]  do_syscall_64+0x6d/0x81
   [18657.516831]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
   [18657.516835] RIP: 0033:0x786d47ea4050
   [18657.516837] RSP: 002b:00007ffdab1a3958 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
   [18657.516840] RAX: ffffffffffffffda RBX: 000057489ea9a2c0 RCX: 0000786d47ea4050
   [18657.516842] RDX: 0000000000000000 RSI: 00007ffdab1a39a0 RDI: 0000000000000007
   [18657.516844] RBP: 00007ffdab1a3990 R08: fffffffffffdb750 R09: fffffffffffdb740
   [18657.516846] R10: fffffffffffdb730 R11: 0000000000000246 R12: 000057489ea9a2c0
   [18657.516848] R13: 000057489ea72110 R14: 00007ffdab1a39a0 R15: 000057489ea72110
   [18657.516850] Code: 5b 41 5c 41 5d 41 5e 41 5f 5d c3 41 8b 75 28 4c 89 e7 e8 0c 97 ff ff 48 89 c1 48 c7 c7 d7 fa 27 c0 31 c0 48 89 ce e8 a9 e8 26 f2 <0f> 0b 6a fb 5b eb b9 0f 0b 6a ea 5b eb b2 0f 0b 6a 92 5b e9 75 
   [18657.516884] ---[ end trace b69244d77dfba5e5 ]---
   

   dmesg.log
   logger-t.log
4. ranj063 commented on Nov 20, 2018

   

   ranj063

   on Nov 20, 2018

   Last edited by ranj063

   Collaborator

   More actions

   @keqiaozhang just confirming once more:
   The suspend stress test is during hdmi playback?
   If so, instead of using youtube for hdmi playback, can you please test local hdmi playback through the browser and disconnect the network when you run this test?

   I am asking because I see this error in the log:
   [15073.750425] kauditd_printk_skb: 4 callbacks suppressed
   [15073.750427] audit: type=1400 audit(1542630606.738:1124): avc: granted { execute } for pid=9603 comm="minijail0" path="/sbin/minijail0" dev="mmcblk0p3" ino=16408 scontext=u:r:cros_debugd_minijail:s0 tcontext=u:object_r:cros_minijail_exec:s0 tclass=file
   [18657.500472] wlan0: deauthenticated from 00:62:ec:e6:2f:5d (Reason: 103=)
   [18657.516495] ------------[ cut here ]------------
   [18657.516505] Command STATISTICS_CMD: a command is already active!
5. mengdonglin commented on Nov 24, 2018

   

   mengdonglin

   on Nov 24, 2018

   Last edited by mengdonglin

   More actions

   @keqiaozhang Could you paste the 3 repo branch and commit info, and accurate reproduce steps here? Could you reply Ranjani?
6. keqiaozhang commented on Nov 26, 2018

   

   keqiaozhang

   on Nov 26, 2018

   Author

   More actions

   @ranj063
   I have passed the first ~500 iterations of test under following condition:
   local HDMI playback through browser + disconnect the network.
   I will do more tests next.
7. ranj063 commented on Nov 26, 2018

   

   ranj063

   on Nov 26, 2018

   Collaborator

   More actions

   @keqiaozhang then is it ok to close this? I think the previous failure was likely due to network issues.
8. keqiaozhang commented on Nov 26, 2018

   

   keqiaozhang

   on Nov 26, 2018

   Author

   More actions

   @ranj063
   I'm doing more rounds of test to confirm it. if no errors, I will close it.
9. keqiaozhang commented on Nov 27, 2018

   

   keqiaozhang

   on Nov 27, 2018

   Author

   More actions

   @ranj063
   Confirmed that this issue is fixed after disconnecting the network.
   I did 5 rounds of tests, each round of test can pass ~500 iterations.
10. keqiaozhang

    closed this as completedon Nov 27, 2018
11. ranj063 commented on Nov 27, 2018

    

    ranj063

    on Nov 27, 2018

    Collaborator

    More actions

    Thanks @keqiaozhang
12. mengdonglin

    added

    verified

    on Nov 27, 2018
13. oder-chiou

    added a commit that references this issue on May 5, 2026

    selftests/bpf: Skip test when perf_event_open returns EOPNOTSUPP

    ...

    c186ed1