powerd blocked on Chrome's suspend delay after closing samus device's lid |
||
Issue descriptionGoogle Chrome 57.0.2987.146 (Official Build) (64-bit) Platform 9202.64.0 (Official Build) stable-channel samus I closed the lid to try to suspend, but the machine just sat there for about ten seconds with the lightbar on. I eventually gave up and opened the lid. I filed a feedback report at http://feedback/#/Report/58316368953. Looking at powerd.LATEST, session_manager and shill reported readiness for their suspend delays but Chrome didn't: --- [0418/184219:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 63045633 (chrome) of 5000 ms on behalf of :1.7 ... [0418/184220:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 63045634 (shill) of 19500 ms on behalf of :1.11 ... [0418/184228:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 63045635 (session_manager) of 1000 ms on behalf of :1.5 ... [0422/090058:INFO:daemon.cc(507)] Lid closed ... [0422/090058:INFO:state_controller.cc(899)] Ready to perform lid-closed action (suspend) [0422/090058:INFO:suspender.cc(397)] Starting request 63045645 [0422/090058:INFO:daemon.cc(596)] Reading wakeup count from /sys/power/wakeup_count [0422/090058:INFO:daemon.cc(600)] Read wakeup count 44401 ... [0422/090058:INFO:suspend_delay_controller.cc(139)] Announcing suspend request 63045645 with 3 pending delay(s) and 0 outstanding delay(s) from previous request [0422/090058:INFO:suspend_delay_controller.cc(88)] Got notification that delay 63045635 (session_manager) is ready for suspend request 63045645 from :1.5 [0422/090058:INFO:suspend_delay_controller.cc(88)] Got notification that delay 63045634 (shill) is ready for suspend request 63045645 from :1.11 ... [0422/090112:INFO:daemon.cc(516)] Lid opened [0422/090112:INFO:suspender.cc(359)] Aborting request in response to user activity [0422/090112:INFO:suspender.cc(424)] Finishing request 63045645 unsuccessfully --- I assume that powerd would've given up and suspended eventually -- I think it just uses the max of the requested delays, and shill asks for 19.5 seconds. :-/ I don't see any obvious problems in the Chrome user log. The lock screen was shown successfully and reported to session_manager. Eric, is it easy for you to check if this was caused by something on the ARC side?
,
May 1 2017
Seems like the chrome suspend delay should be expiring first, right? Since the suspend delay for ARC pretty much moved from session_manager to chrome, I wouldn't be surprised that this is ARC related. However, the ActivityManager-Sleep wakelock shouldn't be held for very long if you're not using any apps. Did you have anything open at the time? Since the machine is corp-enrolled I assume you can't flash a version of Android with the ArcPowerManagerService DEBUG flag turned on... that's where all the logs that would be helpful here come from, sadly :/ We could change it from DEBUG/Slog.d to Slog.i to gather more information about this.
,
May 1 2017
Per in-person discussion just now: powerd just takes the max of all the timeouts and sets an alarm using that, so it's expected given the current implementation that we're waiting for the 19.5-second shill delay even though it's Chrome being slow. The timeouts are only intended as a failsafe so we don't stay awake forever. I'm not (intentionally) running anything on the Android side. This happens every time I close the lid (I haven't rebooted the device yet, I don't think). I'll probably a) try running an Android app to double-check that ActivityManager isn't wedged, and then b) reboot to see if it continues happening.
,
May 2 2017
Also per in-person discussion: running an Android app might actually hide this behavior. If the problem is that ArcPowerManagerService is waiting for the release of the ActivityManager-Sleep wake lock, and this lock is only taken when there are apps that might have to do work in their onPause callbacks, we might never observe the lock getting released since it wouldn't have been taken in the first place. On the bright side, if this does happen when you run an Android app pre-suspend, we can be pretty sure that this is the cause of the problem...
,
May 3 2017
I tried running a few Android apps (Play Store, Docs) before suspending and still saw the issue. Then I rebooted, and I continue to see the issue.
,
May 4 2017
I'll try to reproduce this on some devices I have lying around that I can put my own images on. I'm not sure there's much more that can be gleaned from a verified mode device :(
,
May 12 2017
Just noticed the same problem on a stable-channel kevin device at the same version.
,
Feb 1 2018
For issue 803727 , I checked in https://crrev.com/c/877321 to make Chrome log additional details when the timeout is hit, so we should be able to debug this more easily if it happens again. |
||
►
Sign in to add a comment |
||
Comment 1 by derat@chromium.org
, Apr 22 2017