Fix hung renderer timer code in RenderWidgetHost (task spam bug)

Fix MessageLoop task spam bug caused by hung renderer timer code in RenderWidgetHost.

BUG=103667
TEST=in about:tracing, verify that the chrome UI thread doesn't show lots of tasks from StartHangMonitorTimeout.

Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=109662

[jbates, 2011-11-10 01:51:31]

I noticed creis and brettw in the code. I know brett is OOTO right now, so creis
this is probably your review. PTAL.

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
File content/browser/renderer_host/render_widget_host.cc (left):

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
content/browser/renderer_host/render_widget_host.cc:514:
hung_renderer_timer_.GetCurrentDelay() <= delay &&
This code seems to assume that GetCurrentDelay is the time remaining until the
task fires, but it's actually just the original delay set for the timer. This
caused the Stop/Start code below to execute every few milliseconds in some cases
(possibly based on mouse inputs and other forwarded communication). This showed
up in about:tracing as null MessageLoop tasks running every few milliseconds.

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
content/browser/renderer_host/render_widget_host.cc:529:
time_when_considered_hung_ = Time();
Instead of overloading the meaning of this time, I added a bool to indicate
whether we are monitoring for hung renderer.

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
File content/browser/renderer_host/render_widget_host.cc (right):

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
content/browser/renderer_host/render_widget_host.cc:520:
time_of_last_renderer_response_ = TimeTicks::Now();
Storing the time_of_last_renderer_response_ rather than the
time_when_considered_hung_ simplifies the code a bit.

[Charlie Reis, 2011-11-10 19:35:54]

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
File content/browser/renderer_host/render_widget_host.cc (left):

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
content/browser/renderer_host/render_widget_host.cc:514:
hung_renderer_timer_.GetCurrentDelay() <= delay &&
On 2011/11/10 01:51:31, jbates wrote:
> This code seems to assume that GetCurrentDelay is the time remaining until the
> task fires, but it's actually just the original delay set for the timer. This
> caused the Stop/Start code below to execute every few milliseconds in some
cases
> (possibly based on mouse inputs and other forwarded communication). This
showed
> up in about:tracing as null MessageLoop tasks running every few milliseconds.

Thanks for catching this!

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
content/browser/renderer_host/render_widget_host.cc:529:
time_when_considered_hung_ = Time();
On 2011/11/10 01:51:31, jbates wrote:
> Instead of overloading the meaning of this time, I added a bool to indicate
> whether we are monitoring for hung renderer.

I like it.

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
File content/browser/renderer_host/render_widget_host.cc (right):

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
content/browser/renderer_host/render_widget_host.cc:520:
time_of_last_renderer_response_ = TimeTicks::Now();
On 2011/11/10 01:51:31, jbates wrote:
> Storing the time_of_last_renderer_response_ rather than the
> time_when_considered_hung_ simplifies the code a bit.

I like simplifying it, but I'm not sure this is correct.  If someone calls
StartHangMonitorTimeout directly, this field doesn't get set.  That means the
timeout reflects the time since the last IPC received from the renderer
(possibly a long time ago), not the time since StartHangMonitorTimeout was
called.

Because of the way CheckRendererIsUnresponsive calls StartHangMonitorTimeout, I
also think it's not as simple as updating time_of_last_renderer_response_ in
StartHangMonitorTimeout.

Is there another way to fix it?  Or should we rename Restart to Start and Start
to Resume?

http://codereview.chromium.org/8510038/diff/1/content/browser/renderer_host/r...
content/browser/renderer_host/render_widget_host.cc:858: TimeDelta hung_delay =
TimeDelta::FromMilliseconds(kHungRendererDelayMs);
This isn't correct-- we use different values in different places.  (It's a much
longer delay for interaction response than for closing a tab, for example.  See
kUnloadTimeoutMS.)

[jbates, 2011-11-11 01:09:13]

Thanks creis, I totally missed those other use cases. I drilled down to the root
cause with the existing code and just fixed the bug without other changes.

The problem was this sequence:
Input: StartHangMonitorTimeout
InputAck: StopHangMonitorTimeout
(repeat every few milliseconds as inputs arrive...)

Each of those pairs left an orphaned 20-second-delay task in the message loop.
With this change, the task is only orphaned when the new delay is less than the
existing timer delay (which is required for close tab behavior).

[Charlie Reis, 2011-11-11 02:20:10]

LGTM!

Took me a second to understand, but it's the Stop() call that orphans the task,
correct?  Yes, this will avoid orphaning a timer if it's still useful for us.

http://codereview.chromium.org/8510038/diff/3002/content/browser/renderer_hos...
File content/browser/renderer_host/render_widget_host.cc (right):

http://codereview.chromium.org/8510038/diff/3002/content/browser/renderer_hos...
content/browser/renderer_host/render_widget_host.cc:514: // If we already have a
timer that will expire at or before the given delay,
Maybe we can update this comment to reflect what you said about GetCurrentDelay
(that it returns the timer's total duration, not the remaining time).  Something
like:
"If we already have a timer with the same or shorter duration, then we can wait
for it to finish."

This may of course finish before the time_when_considered_hung_, but
CheckRendererIsUnresponsive can handle that by starting a new timer for the
remainder, so we're fine.

[jbates, 2011-11-11 02:40:13]

Adding jam for OWNERS stamp.

http://codereview.chromium.org/8510038/diff/3002/content/browser/renderer_hos...
File content/browser/renderer_host/render_widget_host.cc (right):

http://codereview.chromium.org/8510038/diff/3002/content/browser/renderer_hos...
content/browser/renderer_host/render_widget_host.cc:514: // If we already have a
timer that will expire at or before the given delay,
On 2011/11/11 02:20:10, creis wrote:
> Maybe we can update this comment to reflect what you said about
GetCurrentDelay
> (that it returns the timer's total duration, not the remaining time). 
Something
> like:
> "If we already have a timer with the same or shorter duration, then we can
wait
> for it to finish."
> 
> This may of course finish before the time_when_considered_hung_, but
> CheckRendererIsUnresponsive can handle that by starting a new timer for the
> remainder, so we're fine.

Done.

[jbates, 2011-11-11 02:46:31]

On 2011/11/11 02:20:10, creis wrote:
> LGTM!
> 
> Took me a second to understand, but it's the Stop() call that orphans the
task,
> correct?

That's correct. Maybe OneShotTimer::Stop should be renamed to OrphanTask to make
it more clear. Stop/Start doesn't really imply the subtle issues going on.

>  Yes, this will avoid orphaning a timer if it's still useful for us.
> 
>
http://codereview.chromium.org/8510038/diff/3002/content/browser/renderer_hos...
> File content/browser/renderer_host/render_widget_host.cc (right):
> 
>
http://codereview.chromium.org/8510038/diff/3002/content/browser/renderer_hos...
> content/browser/renderer_host/render_widget_host.cc:514: // If we already have
a
> timer that will expire at or before the given delay,
> Maybe we can update this comment to reflect what you said about
GetCurrentDelay
> (that it returns the timer's total duration, not the remaining time). 
Something
> like:
> "If we already have a timer with the same or shorter duration, then we can
wait
> for it to finish."
> 
> This may of course finish before the time_when_considered_hung_, but
> CheckRendererIsUnresponsive can handle that by starting a new timer for the
> remainder, so we're fine.

[jam, 2011-11-11 18:08:04]

rubberstamp lgtm