+avi for power management

+mark, +jeremy

"Kernel: Response from Google Chrome He timed out"

Looks like the kernel is trying to ask the helper process if it's OK to sleep, and the sandbox is blocking a response?

Hi Stephan,

Thanks for the report and detailed repro steps!

I'm unable to reproduce this on an MBP running 10.7.4 and Chrome 21.0.1171.0.

Can you please try the following:
* Launch chrome with the --no-sandbox flag and see if you can still reproduce this.
* If the flag above fixes the issue then can you relaunch Chrome with --enable-sandbox-logging, go through the repro steps (i.e. pmset -g log reports a timeout from Chrome) and then send me a dump of the logs from Console.app .

Hi Jeremy --

I think I'm doing it wrong; could you please tell me in detail how I should invoke Chrome with those flags?

Thanks!

$ /Applications/Google\ Chrome.app/Contents/MacOS/Google\ Chrome --no-sandbox
[17796:-1390103872:203420431384093:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[17796:-1390103872:203420431489045:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[17796:-1390103872:203420431552535:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[17796:-1390103872:203420431594949:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[17796:-1390103872:203420431631854:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[17796:-1390103872:203420431690825:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
Trace/BPT trap: 5
$ 

No, that's the right way to do it - can you try a dev channel build please?

Tried it with 21.0.1171.0 dev and --no-sandbox. The problem persists. The mention of Python is worrisome since it might mean that a crankd problem has resurfaced. However, two Chrome Helper continue to be implicated.

What should I try next?


Time stamp                Domain              	Message                                                                    	Duration  	Delay     
==========                ======              	=======                                                                    	========  	=====     
UUID: C88F8569-E93D-4788-BFA9-B7E79373B18C
13.06.2012 11:48:06 PDT  sleep               	Software Sleep: Using AC (Charge:51%)                                      	          
13.06.2012 11:48:06 PDT  timedout            	Kernel: Response from Python timed out                                     	          	30000 ms  	
13.06.2012 11:48:06 PDT  timedout            	Kernel: Response from Google Chrome He timed out                           	          	30000 ms  	
13.06.2012 11:48:06 PDT  timedout            	Kernel: Response from Google Chrome He timed out                           	          	30000 ms  	
13.06.2012 11:48:15 PDT  wake                	Wake due to EHC2: Using AC (Charge:52%)                                    	          

Thanks Stephan!

If this is reproducible with --no-sandbox then it's not a sandbox issue.

Avi: any ideas?

Is it possible that a tab's contents matters? I find it odd that given how many open tabs I have at any time, I consistently only see two Helper processes in the pmset log.

Eg, I always have a tab with Gmail and a tab with Calendar open. Is it worth spending the time to see if it's related to specific tabs?

If you could find any repro info that would help. I haven't any ideas.

I had one instance (but only one...) where I launched chrome, closed all windows, opened one window and put a Gmail tab into it, and then got the sleep delay. I was unable to reproduce subsequently.

So I added just Calendar in the same window, and it didn't immediately repro. I wound up with 5 tabs open in that same window and the problem reproduces again consistently. I have also opened and closed a bunch of tabs since app launch.

There definitely is some correlation with number of open tabs and content, and perhaps with previously closed tabs. Still devoid of guaranteed repro steps here, though.

I am seeing this issue whenever I open a new tab or webpage. I have disabled all extensions, and restarted from the command line with --no-sandbox.

$ /Applications/Google\ Chrome.app/Contents/MacOS/Google\ Chrome --no-sandbox
[1330:-1405914432:1607360817593:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[1330:-1405914432:1607360900723:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[1333:-1405914432:1608043626867:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[1333:-1405914432:1608043709495:ERROR:resource_bundle.cc(98)] Failed to load 
Some features may not be available.
[1333:-1405914432:1608061601080:ERROR:renderer_main.cc(250)] Running without renderer sandbox


I am running Chrome Version 20.0.1132.43.

$ sw_vers
ProductName:	Mac OS X
ProductVersion:	10.7.4
BuildVersion:	11E53


If you have any suggestions on what I can try and provide some additional information, let me know. This is 100% reproducible for me.

Had this issue - removed google docs app from chrome and this solved it, MBP goes to sleep almost instantly.

I am seeing similar errors as well.


7/5/12 2:54:42.370 PM [0x0-0x50e50e].com.google.Chrome: [5698:-1395981632:42221105007876:ERROR:resource_bundle.cc(98)] Failed to load 
7/5/12 2:54:42.370 PM [0x0-0x50e50e].com.google.Chrome: Some features may not be available.
7/5/12 2:54:42.370 PM [0x0-0x50e50e].com.google.Chrome: [5698:-1395981632:42221105081214:ERROR:resource_bundle.cc(98)] Failed to load 
7/5/12 2:54:42.370 PM [0x0-0x50e50e].com.google.Chrome: Some features may not be available.
7/5/12 2:54:42.000 PM kernel: CODE SIGNING: cs_invalid_page(0x1000): p=5700[ksadmin] clearing CS_VALID
7/5/12 2:54:42.727 PM [0x0-0x50e50e].com.google.Chrome: [5702:-1395981632:42221462127752:ERROR:resource_bundle.cc(98)] Failed to load 
7/5/12 2:54:42.727 PM [0x0-0x50e50e].com.google.Chrome: Some features may not be available.
7/5/12 2:54:42.727 PM [0x0-0x50e50e].com.google.Chrome: [5702:-1395981632:42221462214377:ERROR:resource_bundle.cc(98)] Failed to load 
7/5/12 2:54:42.727 PM [0x0-0x50e50e].com.google.Chrome: Some features may not be available.
7/5/12 2:54:43.203 PM [0x0-0x50e50e].com.google.Chrome: [5703:-1395981632:42221937931575:ERROR:resource_bundle.cc(98)] Failed to load 
7/5/12 2:54:43.203 PM [0x0-0x50e50e].com.google.Chrome: Some features may not be available.
7/5/12 2:54:43.203 PM [0x0-0x50e50e].com.google.Chrome: [5703:-1395981632:42221938001098:ERROR:resource_bundle.cc(98)] Failed to load 
7/5/12 2:54:43.203 PM [0x0-0x50e50e].com.google.Chrome: Some features may not be available.
7/5/12 2:54:43.000 PM kernel: CODE SIGNING: cs_invalid_page(0x1000): p=5701[ksadmin] clearing CS_VALID
7/5/12 2:54:47.846 PM [0x0-0x50e50e].com.google.Chrome: [5704:-1395981632:42226581330693:ERROR:resource_bundle.cc(98)] Failed to load 
7/5/12 2:54:47.846 PM [0x0-0x50e50e].com.google.Chrome: Some features may not be available.
7/5/12 2:54:47.846 PM [0x0-0x50e50e].com.google.Chrome: [5704:-1395981632:42226581400732:ERROR:resource_bundle.cc(98)] Failed to load 
7/5/12 2:54:47.846 PM [0x0-0x50e50e].com.google.Chrome: Some features may not be available.

apmunch: Thanks, but these log entires are completely unrelated.

Marking as untriaged so this gets slotted appropriately, the note about the Google docs app in Comment #13 looks interesting - perhaps this only happens with background pages or the like?

I am getting this consistently:

Chrome Version 20.0.1132.43 (143823)
OS X 10.7.4


7/9/12 7:21:25.796 AM [0x0-0x167167].org.chromium.Chromium: Some features may not be available.
7/9/12 7:21:25.796 AM [0x0-0x167167].org.chromium.Chromium: [1809:-1396346176:18612850142997:ERROR:resource_bundle.cc(98)] Failed to load 
7/9/12 7:21:25.796 AM [0x0-0x167167].org.chromium.Chromium: Some features may not be available.
7/9/12 7:21:39.458 AM [0x0-0x167167].org.chromium.Chromium: [1811:-1396346176:18626512195336:ERROR:resource_bundle.cc(98)] Failed to load 
7/9/12 7:21:39.458 AM [0x0-0x167167].org.chromium.Chromium: Some features may not be available.
7/9/12 7:21:39.458 AM [0x0-0x167167].org.chromium.Chromium: [1811:-1396346176:18626512295789:ERROR:resource_bundle.cc(98)] Failed to load 
7/9/12 7:21:39.458 AM [0x0-0x167167].org.chromium.Chromium: Some features may not be available.
7/9/12 7:22:07.457 AM [0x0-0x167167].org.chromium.Chromium: [1815:-1396346176:18654512458799:ERROR:resource_bundle.cc(98)] Failed to load 
7/9/12 7:22:07.457 AM [0x0-0x167167].org.chromium.Chromium: Some features may not be available.
7/9/12 7:22:07.457 AM [0x0-0x167167].org.chromium.Chromium: [1815:-1396346176:18654512541911:ERROR:resource_bundle.cc(98)] Failed to load 
7/9/12 7:22:07.457 AM [0x0-0x167167].org.chromium.Chromium: Some features may not be available.

Unable to reproduce on Mac 10.6.8 or 10.7.4 with canary with or without the Google Drive App.

I have the exact same issue since at least 4 months.

The issue is persistent through several versions.
I can confirm this issue was present in all builds of
OS X 10.7.3 / 10.7.4 / 10.8.0 / 10.8.1
Chrome Stable Channel 19.x / 20.x / 21.x

and a few posts above is the fix!! Thank you so much.

I can confirm the Google Drive App (the one from the webstore) is the cause of the trouble. I could recreate this several times.
GDrive installed 30000 ms timeout
GDrive uninstalled from chrome -> instant sleep
GDrive installed 30000 ms timeout

you get the idea ;) Thanks a lot!

Had this problem on Chrome 21.0.1180.89, OS X 10.8.0. 

Problem went away after removing Gmail Offline and Calendar apps. Problem did not return after re-installing.

Good for me, don't know if this will help solve the issue.

Problem persists for me, never had Gmail Offline or Calendar apps installed. I do have Google Drive app installed.

Currently on 22.0.1229.26 Beta, OS X 10.8.1.

issue *seems* to be solved in latest canary build. From what I'm reading I guess it's a problem with the WebStorage API or something.

After enabling Offline Drive in Canary ( https://drive.google.com/#offline ) the same problem persists for me. Those of you above that suggested Canary, have you enabled Offline Drive?

To prove causation (or more closely link Offline Drive), as soon as I disabled the feature ( https://docs.google.com/offline/optout ), sleep worked perfectly.

i can confirm it's 100% reproduceable and persists in latest builds... as soon as you enable offline drive you buy yourself a 30 sec sleep delay :/
This issue persists over 6 month now and no one seems to care :/

Since this affects Drive.

We use Hotlist-GoogleApps specifically as part of a larger internal process.

100% reproducible in OSX 10.8.3 with Chrome 25.0.1364.172

Will test with offline drive disabled...

This is 100% down to Offline Google Drive.

Disable offline Google Drive and the problem goes away...

+cc mihaip who added chrome/browser/resources/default_apps/drive.crx

mihaip: Do you know who would be the right person to investigate this issue with the Drive app?

@asvitkine: I'm no longer at Google, so I can't provide precise pointers, but dbk@ would know who the right people are on the Drive side, and atwilson@ may know if background pages are involved (as suggested by comment 16).

First I've heard of this issue.  All I can think of to do is describe how offline works and see if any of the Chrome folks recognize something.

While offline is opted in, a background page is registered.  It has an iframe in it, and that in turn opens a shared worker, which is also connected to by any docs tabs which are open.  This worker is responsible for synchronizing documents.  It regularly performs XHRs, and will also regularly access indexdb and the filesystem API.  There's a good chance handles to these are kept open, as I knew of no reason not to.

I'm guessing background pages that connect to shared workers are reasonably rare, maybe this is what's special about docs offline and is triggering this problem?

Finally, docs offline uses an obscure class of background page originally created specifically for its use.  It is barely documented, and may not be used elsewhere.  In its hosted app manifest, docs has "allow_js_access": false set.  That causes the background page to spawn in its own process rather than sharing one with tabs on the same origin.  Naturally, this prevents synchronous interaction between pages and background pages, thus the name.  The goal was to avoid exceeding per-render-process memory limits by allowing docs to spread itself out over multiple render processes.  Every time something has forced many editors into one process we've had problems.

This looks suspicious from drive_uploader.cc:

        power_save_blocker(content::PowerSaveBlocker::Create(
            content::PowerSaveBlocker::kPowerSaveBlockPreventAppSuspension,
 
I'm guessing the drive uploader is doing it. Why the heck we are baking in google-drive-specific code in Chrome is a separate question :-P

DriveUploader started using PowerSaveBlocker from http://crrev.com/180687, there is no way the code affects the behavior of Chrome before M27.

FYI: DriveUploader is used for SyncFileSystem (https://sites.google.com/a/chromium.org/dev/developers/design-documents/extensions/proposed-changes/apis-under-development/syncfilesystem-api) and Files.app (built-in file manager app on Chrome OS), not for the app on the web store.

s/before M27/before M26/

It'd be worth putting a breakpoint in the PowerSaveBlocker code to see what exactly is triggering it, then, if not drive_uploader.cc.

Maybe someone on the Mac team can take a look? There's nothing in the background page code that messes with PowerSaveBlocker AFAICT - the only things that seem to do that are stuff in src/content to delay sleep while file downloads and media playback are happening.

I'm having exactly the same issue. But after uninstall the Google Drive App in Chrome, it goes to sleep immediately.

So, someone on the drive team needs to investigate this, since it seems that their app is what's triggering this. dbk, can you please suggest someone on the team to investigate on the mac? I think my suggestion in comment #41 would give them enough to go on.

+kalman, mpcomplete: note this is the hosted Drive app, not the native app. See #37. Any thoughts?

so i recently got a new rMBP and guess what?! The same story still. The result of this is that I'm not using Offline Drive for the past year(!). :( And I really really like Google Drive! This is really annoying. - Any updates?

I'm seeing this same behavior on a 2011 MBP (MacBookPro8,2) running OS X 10.8.4 (12E55) with Chrome Version 30.0.1599.22 beta.  If Chrome is open, my sleep is delayed by 10+ seconds and I see system log entries like "Aug 31 13:57:48 MacBook-Pro kernel[0]: PM notification timeout (pid 15678, Google Chrome He)".  It doesn't matter what pages I have loaded in Chrome.  If I close Chrome first, sleep is instantaneous.

This may actually be background-permission related. Ben do you know who to bring this up with?

Drive does have the background permission but I didn't think it did anything on the mac.

atwatson: does background mode exist on mac?

As atwatson suggests we should repro and put a breakpoint in the power save blocking code to see if it gets tickled. Adding some mac apps folks who may have bandwidth to repro, but I'd say they won't be able to look for at least 2 weeks.

background mode doesn't really do anything on mac - the only behavior it triggers is to make chrome launch at OS login. It doesn't do anything to affect the lifetime or mess with sleep.

I have the same behavior on a 2011 MBP (MacBookPro8,2) running OS X 10.8.5 with Chrome Version 30.0.1599.66 beta.  If Chrome is open, my sleep is delayed by 20-30 seconds and "pmset -g log" has many of these entries: "Kernel: Response from Google Chrome He timed out                           	          	30000 ms".  If I close Chrome first, sleep is instantaneous.  I do NOT have Google Drive installed.  This behavior only started in the last week or few.  I don't believe I had this problem prior to that.

jackhou / tapted: either of you guys wanna be heroes and take on this bug?

I'm also seeing this 2012 Retina MBP, 10.8.5, latest chrome (31.0.1650.4 dev), don't have Google Drive installed.

Starting seeing this a couple of weeks ago.

Lots of entries in pmset -g log like post #50. Sleep is delayed 30+ seconds if I sleep and chrome is open.

Putting it in my queue for now. I've noted that Chrome on my Macs easily picks up the 'Open at Login' flag (e.g. in the Dock menu). I haven't seen any ill effects, but "sleep" for me usually involves just closing the lid. I'll try casting some other sleep spells.

Just FYI I used just close the lid but noticed I had a pretty warm backpack on the way home after a process started pinging the CPU. 

I've started issuing the sleep command manually (via Alfred) so this bug is far more noticeable this way. 

I get the same issue, with the latest version of Chrome 30.0.1599.66 on a MBPR 2013 OSX 10.8.5. Is there any fix for this? I tried uninstalling Google Drive app but I still get the same result.

I noticed this today after I got a Google Chrome update (the one where you get the "Apps" in the bookmark bar).

Same problem under both Lion and Mountain Lion - no Google Drive app.

I am having this same same issue with a 13in MBP Running OS X 10.8.5 with Chrome 30.0.1599.66. I just upgraded from OS X 10.6.8 yesterday, and that is when problems began. So it appears to be a Lion/Mountain Lion issue.

Removing Docs and Drive apps from Chrome does nothing, nor does deleting my settings and doing a clean install of Chrome. I can reproduce the phenomenon as the original post (from 16 months ago) describes exactly.

Same issue here. If chrome is running, sleep will be delayed.

I've got the following from 'Console':

10/3/13 12:02:00.000 PM kernel[0]: PM notification timeout (pid 865, Google Chrome He)

And 'pmset -g log' contained:

10/3/13 9:33:07 AM GMT+0 Timedout Kernel: Response from Google Chrome He timed out 30000 ms

I am having same problem with 2012 iMac OSX 10.8.5 and Chrome 30.0.1599.66

03/10/2013 16:59:12 BST  Sleep               	Idle Sleep Sleep: Using AC                                                 	16556 secs
03/10/2013 16:59:12 BST  Timedout            	Kernel: Response from Google Chrome He timed out                           	          	30000 ms  	
03/10/2013 16:59:12 BST  Timedout            	Kernel: Response from Google Chrome He timed out                           	          	30000 ms  	
03/10/2013 16:59:12 BST  Timedout            	Kernel: Response from Google Chrome He timed out                           	          	30000 ms  	
03/10/2013 16:59:12 BST  Timedout            	Kernel: Response from Google Chrome He timed out                           	          	30000 ms  	
03/10/2013 16:59:12 BST  Timedout            	Kernel: Response from Google Chrome He timed out                           	          	30000 ms  	
03/10/2013 16:59:12 BST  Timedout            	Kernel: Response from Google Chrome He timed out                           	          	30000 ms  	
03/10/2013 16:59:12 BST  Assertions          	PID 57(apsd) Released ApplePushServiceTask "com.apple.apsd-waitingformessages-sandbox.push.apple.com" 00:22:24  id:0xc00000731 Aggregate:0x1040	
03/10/2013 16:59:12 BST  WakeRequests        	Clients requested wake events: None                                        	

So, this Issue has changed a bit since it was first created. To address current problems, I think this is Issue 88867 come to life again. Possibly due to the change in r215381 (cc:bajones) or one following it - it looks like renderer processes no longer register a power monitor, but still call base::PowerMonitorDeviceSource::AllocateSystemIOPorts(). See comment above https://code.google.com/p/chromium/codesearch#chromium/src/content/app/content_main_runner.cc&q=AllocateSystemIOPorts&sq=package:chromium&type=cs&l=681

The result is that each renderer process is registering for power notifications, but none of them are hooking up a function to handle them. 

This is not really my area... but running some git greps suggests that only nacl processes and the browser process allocate a new base::PowerMonitorDeviceSource(). Which suggests that a patch I've put up in https://codereview.chromium.org/25954005/ could be the fix, and I've verified that it works for me locally. But.. not really my area, so I'm happy for someone else to roll a different fix.

Putting this as a stable blocker for M31.. but perhaps we should try to get it in post-release for M30 as well. (cc karen,laforge)

------------------------------------------------------------------------
r227148 | tapted@chromium.org | 2013-10-05T00:19:40.552810Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/trunk/src/content/app/content_main_runner.cc?r1=227148&r2=227147&pathrev=227148

Mac: Do not ask to handle power events in processes with no PowerManager.

Otherwise Chrome causes a 30-second delay trying to put a Mac to sleep.

Only the main browser process, and nacl processes, create a
PowerMonitorDeviceSource. However, renderers and other processes still
call the static function PowerMonitorDeviceSource::AllocateSystemIOPorts.
This results in the process asking to receive power change
notifications, but not hooking up a function to acknowledge them. This
results in 30-second timeouts while trying to sleep a Mac.

This change removes plugin, renderer, utility and worker processes from
the list of process types that register to receive power change events
from OS X.

BUG= 132336 
TEST=Put a Mac to sleep with Chrome running. After waking, run `pmset -g
log` from Terminal. There should be no new entries for Chrome under
applicationresponse.timedout [10.6] or on a `Timedout` line [10.8]

Review URL: https://codereview.chromium.org/25954005
------------------------------------------------------------------------

I get the same delay for the last 2 days!!

Same issue on a clean install of Chrome. Tried removing user profile but it didn't help. Running OS X 10.8.5 with supplementary update 1 and Chrome 30.0.1599.69.

same issue here. had same sleep delay last year and uninstalled google drive and it fixed the problem. no such luck this time. I believe this started happening with the latest Google Chrome update.

Heads up. The issue seems to be gone with mavericks :)

I found my way to this thread after being at my wits end about not being able to put my MBA to sleep without the major delay...unless Chrome is shutdown.  And yes, latest update for Chrome has been installed (unfortunately).  This issue needs to be fixed yesterday.

Hi I have the same issue too, mac osx 10.7.5 macbook pro late 2008

Verified fix on Version 32.0.1663.2 canary. Requesting merge of r227148 to 1650 branch.

------------------------------------------------------------------------
r227608 | tapted@chromium.org | 2013-10-08T22:06:53.473160Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/branches/1650/src/content/app/content_main_runner.cc?r1=227608&r2=227607&pathrev=227608

Merge 227148 "Mac: Do not ask to handle power events in processe..."

> Mac: Do not ask to handle power events in processes with no PowerManager.
> 
> Otherwise Chrome causes a 30-second delay trying to put a Mac to sleep.
> 
> Only the main browser process, and nacl processes, create a
> PowerMonitorDeviceSource. However, renderers and other processes still
> call the static function PowerMonitorDeviceSource::AllocateSystemIOPorts.
> This results in the process asking to receive power change
> notifications, but not hooking up a function to acknowledge them. This
> results in 30-second timeouts while trying to sleep a Mac.
> 
> This change removes plugin, renderer, utility and worker processes from
> the list of process types that register to receive power change events
> from OS X.
> 
> BUG= 132336 
> TEST=Put a Mac to sleep with Chrome running. After waking, run `pmset -g
> log` from Terminal. There should be no new entries for Chrome under
> applicationresponse.timedout [10.6] or on a `Timedout` line [10.8]
> 
> Review URL: https://codereview.chromium.org/25954005

TBR=tapted@chromium.org

Review URL: https://codereview.chromium.org/26589002
------------------------------------------------------------------------

Moving to fixed for M-31.