1234618 - BHR doesn't seem to handle the idle case correctly

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Mike Conley (:mconley) (:⚙️)]

Noticed this while investigating bug 1223780. It seems that, regardless of whether or not e10s is enabled, we report microhangs for the main process if a caret is blinking and the process is idle.

STR:

1) Open up a Firefox profile, and install chutten's statuser add-on[1] - this will add a toolbar item that will display how many chrome hangs have been reported to Telemetry.
2) Open about:home, and select the search input so that the caret is blinking.
3) Don't touch the mouse or keyboard. Just let the process go idle.

ER:

No hangs should be repoted.

AR:

Hangs are reported and the count goes up in the toolbar item pretty rapidly.


jrmuizel has been working with me on this. We suspect the BHR is not handling the idle case correctly. I'll let him elaborate, since I think he's got more of the problem swapped into his head.

[1]: https://github.com/chutten/statuser

Comment 1

[Jeff Muizelaar [:jrmuizel]]

It looks when we call NotifyActivity after waiting for a long time we'll store mIntervalNow in currentThread->mInterval.
Then we wake the Hang Monitor.
It updates the mIntervalNow to the current time. Let's say 150 ms in the future
We then compare the new mIntervalNow to currentThread->mInterval and make the assumption that we've been hanging for 150ms.

It's not clear to me how this is supposed to be working.

Comment 2

[(inactive) Jim Chen [:jchen] [:darchons]]

Does this happen on all platforms?

In a nutshell, the hang monitor thread is supposed to keep track of updates to currentThread->mInterval, and expects mInterval to be updated regularly.

When it sees that mInterval hasn't been updated for longer than the timeout value, it records the thread as hanging. When mInterval is finally updated again and the thread was hanging before, it calculates and records the hang duration.

This mechanism is disabled if the thread called NotifyWait before the NotifyActivity call.

Also, mIntervalNow is not the absolute current time. We add a time delta to mIntervalNow each time the hang monitor runs, provided the time delta is smaller than a certain value. However, if the system was sleeping, or if the hang monitor thread didn't get run frequently enough, we keep mIntervalNow the same, and let it get out-of-sync with the absolute time.

Comment 3

[(No longer employed by Mozilla) Aaron Klotz]

(In reply to Jim Chen [:jchen] [:darchons] from comment #2)
> Does this happen on all platforms?

> This mechanism is disabled if the thread called NotifyWait before the
> NotifyActivity call.

Good point. If it is limited to specific platforms, we should audit their message pumps to ensure that we're not missing any of these calls. I previously found a missing call on the Mac in bug 1132305.

Comment 4

[Jeff Muizelaar [:jrmuizel]]

(In reply to Jim Chen [:jchen] [:darchons] from comment #2)
> In a nutshell, the hang monitor thread is supposed to keep track of updates
> to currentThread->mInterval, and expects mInterval to be updated regularly.

Except it's not updated regularly. A bunch of threads have their wait time set to PR_INTERVAL_NO_TIMEOUT and so we divide this by 4 and set waitTime to that. This causes us to wait a very long but not PR_INTERVAL_NO_TIMEOUT amount of time and so we still update mIntervalNow and think that we've been hung for a long time.

Comment 5

[Jeff Muizelaar [:jrmuizel]]

Attachment: Fix misdetecting hangs

Comment 6

[(inactive) Jim Chen [:jchen] [:darchons]]

Comment on attachment 8701195 [details] [diff] [review]
Fix misdetecting hangs

Review of attachment 8701195 [details] [diff] [review]:
-----------------------------------------------------------------

LGTM

Comment 7

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d86b3de54ca0

Comment 8

[Jeff Muizelaar [:jrmuizel]]

Comment on attachment 8701195 [details] [diff] [review]
Fix misdetecting hangs

Approval Request Comment
[Feature/regressing bug #]: The original BHR implementation
[User impact if declined]: We have more inaccurate BHR reports. Not immediately visible.
[Describe test coverage new/current, TreeHerder]: None
[Risks and why]: Should be pretty low. The safety of the patch is pretty obvious from inspection.

Comment 9

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d86b3de54ca0

Comment 10

[Vladan Djeric (:vladan)]

Thanks for fixing this, let's get it uplifted :)

Comment 11

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8701195 [details] [diff] [review]
Fix misdetecting hangs

Helps get more accurate telemetry data, seems like a good idea. Beta44+, Aurora45+

Comment 12

[Vladan Djeric (:vladan)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/f72d07c0184a
 https://hg.mozilla.org/releases/mozilla-beta/rev/3fb3e6af646f

Comment 13

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Setting status 44 and 45 to fixed for comment 12.

Comment 14

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Wes, I think something might have gone wrong with the landing on beta. The patch was landed on the branch GECKO430b7_2015112614_RELBRANCH, which I don't think is in use. Can you confirm this is true and re-land if so?

Comment 15

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Here's a non-relbranch beta version: https://hg.mozilla.org/releases/mozilla-beta/rev/2e553b97f22f

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-b2g44_v2_5/rev/2e553b97f22f