See attached for powercfg output from r427961 vs r427966

Deleted: r427961.jpg 100 KB

	r427961.jpg 100 KB View Download

Deleted: r427966.jpg 106 KB

	r427966.jpg 106 KB View Download

Hi, Jerry,
1, 
About the second red rectangle in r427966.jpg, 'Requesting process id 2248' is confirmed as a Renderer Process?

2, 
Would you please help to confirm current behavior on latest canary version of Chrome?

Thanks!

loeon/2:

1) yes
2) yes

I just reconfirmed in my latest Canary (58.0.3023.0; 64-bit; r453044).  Then, went to latest snapshot build and replicated (see attached).

Deleted: r453109.jpg 101 KB

	r453109.jpg 101 KB View Download

Deleted: taskman.jpg 36.1 KB

	taskman.jpg 36.1 KB View Download

Also, to replicate, Chrome must be using Direct3D11 (verify GL_RENDERER at chrome://gpu)  If using Direct3D9Ex, that runtime itself (not Chrome), requests a 1ms timer, which messes with results.  If that is the case, it is possible to run Chrome with --disable-gpu-driver-bug-workarounds to force Chrome to use Direct3D11 to replicate results.

Hi Jerry,

I notice that the first number is also different in your first jpg from the second two. Is that unrelated?

All that matters is the "Requested Period" of the renderer process.  On AC->battery, staying at '1ms' is very bad.

Hi Jerry,

I don't have a Windows laptop to repro on unfortunately. It sounds like you're up for building Chromium yourself. Is that correct? If so, can I post a patch for you to apply to get some debugging info?

blundell, sorry, no - don't have build environment.

From code inspection, it looks like what's happening is that the renderer's high resolution timer manager (https://cs.chromium.org/chromium/src/content/renderer/renderer_main.cc?type=cs&q=hi_res_timer_manager+package:%5Echromium$&l=192) is not getting the callback that the power was changed to battery (https://cs.chromium.org/chromium/src/base/timer/hi_res_timer_manager_win.cc?type=cs&q=hi_res_timer_manager&l=26).

Ke He, I assume that you have a Linux build environment? Can you put in logging and verify that if you go to the page that Jerry outlined above and then pull out the power cord, the callback that I reference above is called in the renderer displaying that page? If that's *not* happening, you can debug from there. If it *is* happening, we'll have to try to find an engineer with a Windows build environment (ideally a laptop) to help debug.

Thanks,

Colin

The callback "HighResolutionTimerManager::OnPowerStateChange()" in "hi_res_timer_manager_posix.cc" is not called. I'll debug from there.
Thank you Colin!

Oops, I just noticed that hi_res_timer_manager_posix.cc doesn't add itself as an observer of the PowerMonitor. To do the test meaningfully, you'll need to augment hi_res_timer_manager_posix.cc to mimic what hi_res_timer_manager_win.cc is doing wrt observing the PowerMonitor (unless you already did that, in which case full speed ahead).

Sorry I didn't notice it either:(  I'll mimic hi_res_timer_manager_win.cc and see then.

I found chromium-linux is not able to receive the power-changed event, no matter in hi_res_timer_manager_posix.cc we mimic or not. Because in //base/power_monitor/power_monitor_device_source_posix.cc, there is no implements to listen and receive the platform events(the impl for windows and chromeos do have).

I added some test code, it shows the mojo interface "power_monitor_client_->PowerStateChange(on_battery_power);" works well, renderer side can receive the fake powerstatechange event from browser side, and it can broadcast to all the observers, including the mimic hi_res_timer_manager_posix.

Sorry I don't have the windows environment either, I will continue debug on this.

I can try to repro on a Windows laptop.

Scott, that's awesome, thanks!

Hi, I confirmed the results of the bisect.

Just to confirm, at HEAD I see the browser's timer rate getting throttled down to 4ms, but the renderer's does not, and stays at 1ms.

I'll take a look and see if I can see some obvious cause.

As always, I find debugging Mojo connections infuriating :( but the PowerMonitorMessageBroadcaster is created in the browser

>	content.dll!device::PowerMonitorMessageBroadcaster::Create() Line 28	C++
 	content.dll!device::DeviceService::Create(const service_manager::Identity & request, mojo::InterfaceRequest<device::mojom::PowerMonitor>) Line 58	C++
 	content.dll!service_manager::internal::InterfaceFactoryBinder<device::mojom::PowerMonitor>::BindInterface(const service_manager::Identity & remote_identity, const std::basic_string<char, std::char_traits<char>, std::allocator<char> > & client_handle, mojo::ScopedHandleBase<mojo::MessagePipeHandle>) Line 27	C++
 	content.dll!service_manager::InterfaceRegistry::GetInterface(const std::basic_string<char, std::char_traits<char>, std::allocator<char> > & interface_name, mojo::ScopedHandleBase<mojo::MessagePipeHandle> handle) Line 204	C++
 	content.dll!service_manager::mojom::InterfaceProviderStubDispatch::Accept(mojo::Message * impl) Line 108	C++
 	content.dll!service_manager::mojom::InterfaceProviderStub<mojo::RawPtrImplRefTraits<service_manager::mojom::InterfaceProvider> >::Accept(mojo::Message * message) Line 119	C++
 	bindings.dll!mojo::InterfaceEndpointClient::HandleValidatedMessage(mojo::Message * message) Line 411	C++
 	bindings.dll!mojo::InterfaceEndpointClient::HandleIncomingMessageThunk::Accept(mojo::Message * message) Line 129	C++
 	bindings.dll!mojo::FilterChain::Accept(mojo::Message * message) Line 40	C++


SetClient() gets called (I don't actually see PowerMonitorBroadcastSource getting run, but I'm not sure why, I think that's the only place this can be sent from):

>	content.dll!device::PowerMonitorMessageBroadcaster::SetClient(mojo::InterfacePtr<device::mojom::PowerMonitorClient> power_monitor_client) Line 34	C++
 	content.dll!device::mojom::PowerMonitorStubDispatch::Accept(mojo::Message * impl) Line 96	C++
 	content.dll!device::mojom::PowerMonitorStub<mojo::RawPtrImplRefTraits<device::mojom::PowerMonitor> >::Accept(mojo::Message * message) Line 182	C++
 	bindings.dll!mojo::InterfaceEndpointClient::HandleValidatedMessage(mojo::Message * message) Line 411	C++
 	bindings.dll!mojo::InterfaceEndpointClient::HandleIncomingMessageThunk::Accept(mojo::Message * message) Line 129	C++
 	bindings.dll!mojo::FilterChain::Accept(mojo::Message * message) Line 40	C++
 	bindings.dll!mojo::InterfaceEndpointClient::HandleIncomingMessage(mojo::Message * message) Line 295	C++
 	bindings.dll!mojo::internal::MultiplexRouter::ProcessIncomingMessage(mojo::Message * message, mojo::internal::MultiplexRouter::ClientCallBehavior client_call_behavior, base::SingleThreadTaskRunner * current_task_runner) Line 901	C++
 	bindings.dll!mojo::internal::MultiplexRouter::Accept(mojo::Message * message) Line 633	C++


and then the PowerMonitorMessageBroadcaster is immediately destroyed:

>	content.dll!device::PowerMonitorMessageBroadcaster::~PowerMonitorMessageBroadcaster() Line 20	C++
 	content.dll!device::PowerMonitorMessageBroadcaster::~PowerMonitorMessageBroadcaster() Line 19	C++
 	content.dll!??_EPowerMonitorMessageBroadcaster@device@@W3AEPAXI@Z() Line 0	C++
 	[External Code]	
 	content.dll!mojo::StrongBinding<device::mojom::PowerMonitor>::~StrongBinding() Line 96	C++
 	content.dll!mojo::StrongBinding<device::mojom::PowerMonitor>::Close() Line 76	C++
 	content.dll!mojo::StrongBinding<device::mojom::PowerMonitor>::OnConnectionError(unsigned int custom_reason, const std::basic_string<char, std::char_traits<char>, std::allocator<char> > & description) Line 105	C++
 	content.dll!base::internal::FunctorTraits<void (mojo::StrongBinding<device::mojom::PowerMonitor>::*)(unsigned int, const std::basic_string<char, std::char_traits<char>, std::allocator<char> > &) __attribute__((thiscall)), void>::Invoke<mojo::StrongBinding<device::mojom::PowerMonitor> *,unsigned int,const std::basic_string<char,std::char_traits<char>,std::allocator<char> > &>(mojo::StrongBinding<device::mojom::PowerMonitor> * && method, unsigned int && receiver_ptr, const std::basic_string<char, std::char_traits<char>, std::allocator<char> > & args) Line 214	C++
 	content.dll!base::internal::InvokeHelper<false, void>::MakeItSo<void (mojo::StrongBinding<device::mojom::PowerMonitor>::*const &)(unsigned int, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > &) __attribute__((thiscall)),mojo::StrongBinding<device::mojom::PowerMonitor> *,unsigned int,const std::basic_string<char,std::char_traits<char>,std::allocator<char> > &>(mojo::StrongBinding<device::mojom::PowerMonitor> * && functor, unsigned int && args, const std::basic_string<char, std::char_traits<char>, std::allocator<char> > & args) Line 285	C++

apparently due to "OnConnectionError". I'm not sure why that's happening yet.

Thanks for this analysis, Scott!

Oof. As always with these things, once you spot the bug, it's glaringly obvious:

- PowerMonitorMessageBroadcaster uses a StrongBinding, meaning it's bound to the lifetime of its incoming connection.
- PowerMonitorBroadcastSource keeps its outgoing connection to PowerMonitor live only for the duration of its constructor.
- Bad times :(.

I think the cleanest solution is for PowerMonitorMessageBroadcaster to use a Binding instead of a StrongBinding, to set error handlers on both its binding and on its client interface_ptr when that gets bound, and to die when either:

(1) its client interface_ptr has an error OR
(2) its own binding has an error and its client interface_ptr isn't yet bound (i.e., the client dropped the connection without ever calling SetClient()).

Aha. (Not sure about "StrongBinding" as a name...)

ke.he@ will you make the fix, or shall I?

Scott, why don't you fix it since you can locally verify the fix?

(StrongBinding means "impl is strongly bound to the pipe")

https://codereview.chromium.org/2729293002/

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/0471e6079c754e7478a61ac81765cec789f5249a

commit 0471e6079c754e7478a61ac81765cec789f5249a
Author: scottmg <scottmg@chromium.org>
Date: Fri Mar 03 23:13:11 2017

Fix renderers not getting power broadcast messages

Switches from a StrongBinding to a BindingSet, otherwise, as soon as the
renderer had finished calling SetClient() the connection was detached
and the PowerMonitorMessageBroadcaster destroyed, because the client did
not maintain the connection.

Instead, we now have a single PowerMonitorMessageBroadcaster that
maintains a set of bound clients, and notifies all of them on power
messages.

R=blundell@chromium.org
BUG= 696197 

Review-Url: https://codereview.chromium.org/2729293002
Cr-Commit-Position: refs/heads/master@{#454703}

[modify] https://crrev.com/0471e6079c754e7478a61ac81765cec789f5249a/services/device/device_service.cc
[modify] https://crrev.com/0471e6079c754e7478a61ac81765cec789f5249a/services/device/device_service.h
[modify] https://crrev.com/0471e6079c754e7478a61ac81765cec789f5249a/services/device/power_monitor/power_monitor_message_broadcaster.cc
[modify] https://crrev.com/0471e6079c754e7478a61ac81765cec789f5249a/services/device/power_monitor/power_monitor_message_broadcaster.h
[modify] https://crrev.com/0471e6079c754e7478a61ac81765cec789f5249a/services/device/power_monitor/power_monitor_message_broadcaster_unittest.cc
[modify] https://crrev.com/0471e6079c754e7478a61ac81765cec789f5249a/services/device/public/cpp/power_monitor/power_monitor_broadcast_source.cc
[modify] https://crrev.com/0471e6079c754e7478a61ac81765cec789f5249a/services/device/public/interfaces/power_monitor.mojom

Thanks for pitching in here, Scott!

I think this regressed (or some similar battery status reporting issue) again as of 59.0.3067.0, see the story as told by WatchTime on battery/AC fix (when the above patch landed) and regress later:

https://uma.googleplex.com/p/chrome/timeline_v2?sid=693dd3d6b527539934932a8e234ecbc0

https://chromium.googlesource.com/chromium/src/+log/59.0.3065.0..59.0.3067.0?pretty=fuller&n=10000

I don't have a windows laptop to try on today, so won't be able to verify if the test case fails. scottmg@ can you see if the original issue reproduces again? Nothing stands out as too suspicious in the change log. +ben@ has the only non-mechanical change touching device_service.

Yeah, I'll take a look and file a new bug if I can repro.

https://bugs.chromium.org/p/chromium/issues/detail?id=714206