BackgroundHangManager causes many wakeups

RESOLVED WORKSFORME

Status

()

defect
RESOLVED WORKSFORME
5 years ago
4 years ago

People

(Reporter: rvitillo, Unassigned)

Tracking

({power})

Trunk
x86
All
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [Power], URL)

Attachments

(1 attachment)

Firefox seems to consume more energy while idling on google.com compared to other browsers (see URL and the attached plot).

There is a timer running every 250ms which accounts for some of the wakeups:
var b = (0, Date.now)(), m = function() {
    var c = (0, Date.now)(), d = c - b - a;
    0 > d && (d = 0);
    e[f] = d;
    f = (f + 1) % 20;
    1 == g && (b = c, h = window.setTimeout(m, a))
};
h = window.setTimeout(m, a)

On OSX Chrome seems to have about 4-7 idle wakeups/s while FF about 10-15.
The following are some of the wakeups I traced during a 60 seconds window:
241 nsGlobalWindow::TimerCallback()
83  nsJSEnvironment::CCTimerFired()
69  nsSocketTransportService::Poll()
60  Watchdog::Sleep() (returning)
Depends on: 965348
No longer depends on: 965348
Depends on: 965348
The main culprit for the wakeups seems to be BackgroundHangManager::RunMonitorThread(). Disabling the BgHangManager thread brings the number of wakeups down to about 8 on the Google homepage.

The issue can be reproduced with the following testcase:

<!DOCTYPE html>
    <head>
        <script>
            function foo(){
                window.setTimeout(foo, 250);
            }
            window.setTimeout(foo, 250);
        </script>
    </head>
</html>
Summary: High power consumption on Google while idling → BackgroundHangManager causes many wakeups
Component: General → XPCOM
Product: Firefox → Core

Comment 3

5 years ago
Is it possible to schedule a thread to wake up in N seconds (and subsequently un-schedule that) so that this thread will only wake up if there is in fact a hang that needs to be reported?
Flags: needinfo?(nchen)
Thanks for tracking this down, Roberto. I have some questions,

* How are these measurements made?
* How is a "wake up" defined? A physical core goes from suspended to running? A thread context switches from sleeping to running?
* What is the number of wake ups before you disabled the BgHangManager thread?
* How does the number of wake ups translate to power consumption? What's the power consumption before and after you disabled the BgHangManager thread?

Thanks!


(In reply to Benjamin Smedberg  [:bsmedberg] from comment #3)
> Is it possible to schedule a thread to wake up in N seconds (and
> subsequently un-schedule that) so that this thread will only wake up if
> there is in fact a hang that needs to be reported?

To avoid threads racing to schedule/unschedule the monitor thread, I think all scheduling should be done inside the monitor thread. Unfortunately that means the monitor thread may end up waking up more. There may be some optimizations we can do here though.
Flags: needinfo?(nchen) → needinfo?(rvitillo)

Comment 5

5 years ago
On Windows it should be possible to achieve this using a waitable timer:

* have one timer object per tracked thread
* when an event starts, call SetWaitableTimer
* when an event is finished, call CancelWaitableTimer

* the monitoring thread calls WaitForMultipleObjects with all of the timers

In this case I believe the monitoring thread wakes up in the event of a thread hang and will never wake up otherwise.

I really don't know whether other OSes have similar mechanisms.
(In reply to Jim Chen [:jchen :nchen] from comment #4)
> Thanks for tracking this down, Roberto. I have some questions,
> 
> * How are these measurements made?

With Power Gadget, powertop on Linux and Activity Monitor On OSX.

> * How is a "wake up" defined? A physical core goes from suspended to
> running? A thread context switches from sleeping to running?

A wakeup is a change of the CPU’s C-state from C(N!=0) to C0. If process A is responsible for the wakeup (e.g. timer firing) then that wakeup is attributed to A.

> * What is the number of wakeups before you disabled the BgHangManager
> thread?

The number of wakeups ranged from 10 to 15 on Activity Monitor.

> * How does the number of wake ups translate to power consumption? 

That depends on the frequency of the wakeups and the amount of work performed by the process. There is no hard and fast rule. Usually reducing the number of wakeups allows the CPU to stay longer in deep power saving c-states.

> What's the power consumption before and after you disabled the BgHangManager thread?

Without the BgHangManager thread the energy impact (Activity Monitor) is about 0.9 while with the BgHangManager it’s about 1.17.
Flags: needinfo?(rvitillo)

Updated

4 years ago
OS: Mac OS X → All
Whiteboard: [Power]
I just measured the test case in comment 2 using NSPR_LOG_MODULES=TimerFirings:4 and some post-processing:

> 645 counts:
> ( 1)    234 (36.3%, 36.3%): 1939817216[109040000]: [42049]    fn timer (ONE_SHOT   250 ms): [content] file:///Users/njn/a.html:5:16
> ( 2)    125 (19.4%, 55.7%): 1939817216[109040000]: [42049]    fn timer (SLACK      250 ms): CCTimerFired
> ( 3)     98 (15.2%, 70.9%): 1939817216[100445640]: [42048]    fn timer (SLACK      250 ms): CCTimerFired
> ( 4)     39 ( 6.0%, 76.9%): 1939817216[100445640]: [42048]    fn timer (SLACK      100 ms): LayerActivityTracker
> ( 5)     17 ( 2.6%, 79.5%): 272842752[10e895fc0]: [42048]    fn timer (ONE_SHOT  5000 ms): dom::workers::DummyCallback(2)
> ( 6)     12 ( 1.9%, 81.4%): 1939817216[100445640]: [42048]    fn timer (ONE_SHOT   250 ms): PresShell::sPaintSuppressionCallback
> ( 7)      9 ( 1.4%, 82.8%): 1939817216[100445640]: [42048]    fn timer (SLACK     1000 ms): nsIDocument::SelectorCache
> ( 8)      7 ( 1.1%, 83.9%): 1939817216[100445640]: [42048]    fn timer (ONE_SHOT   100 ms): InterSliceGCTimerFired
> ( 9)      6 ( 0.9%, 84.8%): 1939817216[100445640]: [42048]    fn timer (SLACK     1000 ms): TileExpiry
> (10)      5 ( 0.8%, 85.6%): 1939817216[109040000]: [42049]    fn timer (SLACK      100 ms): LayerActivityTracker
> (11)      4 ( 0.6%, 86.2%): 1939817216[100445640]: [42048] iface timer (SLACK    15000 ms): 11d6cf1c0
> (12)      4 ( 0.6%, 86.8%): 1939817216[100445640]: [42048]    fn timer (SLACK    10000 ms): GradientCache
> (13)      4 ( 0.6%, 87.4%): 1939817216[100445640]: [42048]    fn timer (SLACK       32 ms): ICCTimerFired
> (14)      3 ( 0.5%, 87.9%): 1939817216[100445640]: [42048]    fn timer (SLACK    10000 ms): imgCacheExpirationTracker
> (15)      3 ( 0.5%, 88.4%): 1939817216[109040000]: [42049]    fn timer (SLACK    10000 ms): RuleProcessorCache::ExpirationTracker
> (16)      3 ( 0.5%, 88.8%): 1939817216[100445640]: [42048]    fn timer (SLACK    10000 ms): RuleProcessorCache::ExpirationTracker
> (17)      3 ( 0.5%, 89.3%): 1939817216[100445640]: [42048]    fn timer (SLACK    10000 ms): FrameTextRunCache
> (18)      2 ( 0.3%, 89.6%): 1939817216[100445640]: [42048]    fn timer (ONE_SHOT   450 ms): ScrollbarActivity::FadeBeginTimerFired
> (19)      2 ( 0.3%, 89.9%): 1939817216[100445640]: [42048] iface timer (ONE_SHOT  5000 ms): 113897c00
> (20)      2 ( 0.3%, 90.2%): 1939817216[100445640]: [42048]    fn timer (ONE_SHOT     0 ms): [content] chrome://browser/content/browser.js:12135:8

I don't see any sign of the BackgroundHangManager. Roberto, am I missing something? How did you determine that the BackgroundHangManager was significant here?
Flags: needinfo?(rvitillo)
The last time I checked this was well over a year ago so I am not surprised that things might have changed. Given your report I say we can close this bug.
Flags: needinfo?(rvitillo)
Also, please see Comment 6 on how I attributed the wakeups to the BgHangManager, i.e. I measured the energy impact with and without BgHangManager.
I remeasured the test case from comment 2 on Mac with and without the BHM enabled, and I couldn't see any notable differences in power consumption or wakeup frequency.

I also instrumented the loop in BackgroundHangManager::RunMonitorThread(), which comment 2 says is the cause of the original problem. It triggered a few times on start-up but I couldn't get it to trigger again after that.

BHM is currently disabled on Beta and Release, and this bug is cited as the reason:

> For now, we should be getting enough data from Nightly/Aurora channels, and the hang monitor has
> non-trivial power consumption in certain idle cases, so it makes sense to disable it on Release
> and Beta.

This bug is the source of the power consumption claim. I don't know if the "enough data" part is still true.

Either way, it seems like this bug can be closed. Whether or not there should be a follow-up bug to re-enable the BHM for Beta and maybe Release, I don't know. jchen, any thoughts?
Status: NEW → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → WORKSFORME
NI'ing jchen for the above comment
Flags: needinfo?(nchen)
(In reply to Nicholas Nethercote [:njn] from comment #10)
> 
> Either way, it seems like this bug can be closed. Whether or not there
> should be a follow-up bug to re-enable the BHM for Beta and maybe Release, I
> don't know. jchen, any thoughts?

Closing this bug sounds reasonable. BHM is actually enabled in 1% of Beta builds, and I think we probably won't enable it for all of Beta or Release just because we won't be able to process all the data.
Flags: needinfo?(nchen)
Thank you for the confirmation.
You need to log in before you can comment on or make changes to this bug.