If you think a bug might affect users in the 57 release, please set the correct tracking and status flags for Release Management.

High power usage on BuzzFeed

NEW
Unassigned

Status

()

Core
Layout
2 years ago
2 years ago

People

(Reporter: njn, Unassigned)

Tracking

(Depends on: 2 bugs, {power})

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [Power:P1])

Attachments

(3 attachments)

(Reporter)

Description

2 years ago
Created attachment 8642870 [details]
graph of results

The following blog post identified Firefox as having much higher power consumption than Safari or Chrome on BuzzFeed:

http://blog.getbatterybox.com/which-browser-is-the-most-energy-efficient-chrome-vs-safari-vs-firefox/

The attached graph shows the results.

Firefox was also the worst on Reddit, though the difference was much smaller.
(Reporter)

Comment 1

2 years ago
I tested a Firefox trunk build (with e10s enabled) vs Safari 7.1.8 with
tools/power/rapl for 60 seconds with the page open, to get power estimates.

I also looked at Activity Monitor to get a rough idea of the CPU usage and
wakeups count.

> rapl on blank page:
> - Safari:  3.08 W
> - Firefox: 3.16 W
> 
> rapl on Buzzfeed:
> - Safari:   4.19 W
> - Firefox: 20.57 W
> 
> Activity Monitor on Buzzfeed:
> - Safari (two processes): ~0% CPU, ~0 wakeups/s
> 
> - Firefox:
>   - Parent process:  ~16% CPU, ~60 wakeups/s
>   - Content process: ~60% CPU, ~20 wakeups/s

No mysteries there. We compare well on a blank page, but we're way worse on
both CPU usage and wakeups on BuzzFeed.
(Reporter)

Comment 2

2 years ago
I instrumented Firefox with a slightly tweaked version of the patch mentioned in http://robertovitillo.com/2014/02/04/idle-wakeups-are-evil/ to instrument timer firings. Here are the top 10:

> 1936 counts:
> (  1)      628 (32.4%, 32.4%):  function timer: nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (  2)      621 (32.1%, 64.5%):  function timer: nsExpirationTracker<mozilla::LayerActivity, 4u>::TimerCallback(nsITimer*, void*)
> (  3)      322 (16.6%, 81.1%):  function timer: CCTimerFired(nsITimer*, void*)
> (  4)       66 ( 3.4%, 84.6%):  function timer: nsBrowserStatusFilter::TimeoutHandler(nsITimer*, void*)
> (  5)       38 ( 2.0%, 86.5%):  function timer: mozilla::layout::ScrollbarActivity::FadeBeginTimerFired(nsITimer*, void*)
> (  6)       35 ( 1.8%, 88.3%):  function timer: nsExpirationTracker<mozilla::layers::TileClient, 3u>::TimerCallback(nsITimer*, void*)
> (  7)       25 ( 1.3%, 89.6%):  function timer: nsExpirationTracker<nsIDocument::SelectorCacheKey, 4u>::TimerCallback(nsITimer*, void*)
> (  8)       21 ( 1.1%, 90.7%):  function timer: mozilla::dom::workers::(anonymous namespace)::DummyCallback(nsITimer*, void*)
> (  9)       20 ( 1.0%, 91.7%): observer timer: 0x119b62000
> ( 10)       12 ( 0.6%, 92.4%):  function timer: ICCTimerFired(nsITimer*, void*)

I ran this for ~60 seconds. 1936 timer firings means ~32 timers/s which is only 40% of the ~80 wakeups/s. Still, it's a starting point. The top three timers obviously dominate.
(Reporter)

Comment 3

2 years ago
I added some ad hoc instrumentation to CCTimerFired().

- About 43% of the time it executes without any of the tested conditions being true. I.e. the only useful work it does is increment sCCTimerFireCount.

- About 53% of the time it executes like that, but the condition involving |sPreviousSuspectedCount + 100| is also met, so FireForgetSkippable() gets called.

- The remaining ~4% of the time the pattern is different.

The interval on the CCTimerFired timer is 250 ms, so across two processes in 60 seconds we'd actually expect it to fire 60 * 4 * 2 = 480 times. 322 is quite a lot lower than that. Maybe it's explained by slackness in the timers? Not sure.
(Reporter)

Comment 4

2 years ago
> (  2)      621 (32.1%, 64.5%):  function timer: nsExpirationTracker<mozilla::LayerActivity, 4u>::TimerCallback(nsITimer*, void*)

I tried changing LayerActivityTracker::GENERATION_MS from 100 to 1000 -- with no idea what side-effects that might have -- and saw a corresponding ~10x reduction in the number of these timer firings, but the change in the power estimates were negligible, possibly because that only reduces the idle wakeup rate by ~10%.
(Reporter)

Comment 5

2 years ago
I added printing of the delay in each timer.

> ( 3)    126 ( 6.5%, 50.0%): [75209] function timer (500 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> ( 5)     74 ( 3.8%, 58.7%): [75209] function timer (247 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> ( 6)     58 ( 3.0%, 61.7%): [75209] function timer (1000 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> ( 8)     39 ( 2.0%, 66.2%): [75209] function timer (246 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (10)     33 ( 1.7%, 69.6%): [75209] function timer (248 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (13)     22 ( 1.1%, 73.5%): [75209] function timer (497 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (15)     20 ( 1.0%, 75.6%): [75209] function timer (100 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (16)     20 ( 1.0%, 76.7%): [75209] function timer (245 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (18)     17 ( 0.9%, 78.5%): [75209] function timer (494 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (19)     15 ( 0.8%, 79.2%): [75209] function timer (496 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (20)     15 ( 0.8%, 80.0%): [75209] function timer (238 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (21)     13 ( 0.7%, 80.7%): [75209] function timer (495 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (23)     12 ( 0.6%, 82.0%): [75209] function timer (498 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (24)     11 ( 0.6%, 82.5%): [75209] function timer (243 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (26)     11 ( 0.6%, 83.7%): [75209] function timer (237 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (27)     11 ( 0.6%, 84.2%): [75209] function timer (250 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (28)     10 ( 0.5%, 84.7%): [75209] function timer (244 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (29)     10 ( 0.5%, 85.2%): [75209] function timer (240 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (30)     10 ( 0.5%, 85.8%): [75209] function timer (239 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (31)      9 ( 0.5%, 86.2%): [75209] function timer (242 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (34)      8 ( 0.4%, 87.5%): [75209] function timer (241 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (35)      7 ( 0.4%, 87.8%): [75209] function timer (492 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (36)      7 ( 0.4%, 88.2%): [75209] function timer (493 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (41)      5 ( 0.3%, 89.7%): [75209] function timer (236 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (42)      5 ( 0.3%, 90.0%): [75209] function timer (993 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (44)      5 ( 0.3%, 90.5%): [75208] function timer (0 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (45)      5 ( 0.3%, 90.7%): [75209] function timer (994 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (46)      5 ( 0.3%, 91.0%): [75209] function timer (491 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (48)      4 ( 0.2%, 91.5%): [75209] function timer (249 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (50)      4 ( 0.2%, 91.9%): [75209] function timer (995 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (51)      4 ( 0.2%, 92.1%): [75209] function timer (499 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (52)      4 ( 0.2%, 92.3%): [75209] function timer (996 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (58)      3 ( 0.2%, 93.4%): [75209] function timer (987 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> (59)      3 ( 0.2%, 93.6%): [75209] function timer (990 ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)

Almost all the values are slightly less than 250 ms, 500 ms or 1000 ms. Not
sure what to make of that.
Yeah, the CC timer stuff is a bit of a mess. We could probably rearrange things so there aren't so many of these timers that do nothing. For the |sPreviousSuspectedCount + 100| condition could be checked inside the CC itself, when we add something to the purple buffer. It could trigger a callback somewhere when the condition is met.
Depends on: 1197902
(Reporter)

Comment 7

2 years ago
(In reply to Nicholas Nethercote [:njn] from comment #1)
> >
> > rapl on Buzzfeed:
> > - Firefox: 20.57 W
> > 
> > Activity Monitor on Buzzfeed:
> > - Firefox:
> >   - Parent process:  ~16% CPU, ~60 wakeups/s
> >   - Content process: ~60% CPU, ~20 wakeups/s

Those results were with e10s on. I tried turning e10s off and power consumption dropped dramatically, from ~20.5 Watts to ~6.5 Watts.

CPU usage for the single process was ~30--40% and the wakeup frequency was ~60 wakeups/s.

I tried running dtrace to get more data on the cause of wakeups. The three most
common stack traces were the following:

>   libsystem_kernel.dylib`__psynch_cvbroad+0xa
>   XUL`base::SyncWaiter::Fire(base::WaitableEvent*)+0x40
> 12257
>
>   libsystem_kernel.dylib`__sendmsg+0xa
> 16573
>
>   libsystem_kernel.dylib`write+0xa
> 17088

I'm not quite sure how to interpret these, but SyncWaiter::Fire() is part of
the Chromium IPC code, and sendmsg() also relates to IPC.
Flags: needinfo?(wmccloskey)
(Reporter)

Comment 8

2 years ago
> Firefox was also the worst on Reddit, though the difference was much smaller.

I see the following power estimates on Reddit (with rapl):

- e10s:    4.20 W
- no-e10s: 3.95 W
- Safari:  3.66 W

So only a tiny bit worse there.
(In reply to Nicholas Nethercote [:njn] from comment #7)
> I'm not quite sure how to interpret these, but SyncWaiter::Fire() is part of
> the Chromium IPC code, and sendmsg() also relates to IPC.

If you run with MOZ_IPC_MESSAGE_LOG=1 you can get information about what the messages are, and compare it to say Reddit to see what the difference in message traffic is. eg maybe Buzzfeed is repeatedly polling the parent process for some value we could cache in the child.
Created attachment 8653699 [details]
IPC traffic on BuzzFeed

I tried out my suggestion and ran with MOZ_IPC_MESSAGE_LOG=1 (which only does something in a debug build). There's certainly a lot of IPC traffic. The console is basically continually spammed with stuff. This attachment contains an excerpt of the IPC traffic.

It is mostly stuff that looks like this:

[time:1440706243964858][66179->66178][PLayerTransactionChild] Sending Msg_PLayerConstructor([TODO])

Then later:
[time:1440706243966050][66179->66178][PLayerChild] Sending Msg___delete__([TODO])

There's also a fair amount of this:
[time:1440706240085226][66179->66178][PBrowserChild] Sending Msg_SetBackgroundColor([TODO])

In contrast, on Reddit, there isn't too much going on when the browser is idle, just an occasional burst of stuff.
Created attachment 8653707 [details]
stacks for calls to SetBackgroundColor

This doesn't mean anything to me, but here are the stacks from where we are calling SetBackgroundColor.
It looks like this SetBackgroundColor() call was added in bug 694706.

roc, do you know why we're sending so many of these SetBackgroundColor messages to the parent? It is happening many times a second. (It would also be good to know why we're sending even more of these layer creater destroy things, though maybe that's less odd.)
Flags: needinfo?(roc)
If you scroll down the page a bit, then the color changing stops, but it didn't seem to affect the power impact in my informal testing.
Depends on: 1199534
Filed bug 1199534 on the SetBackgroundColor calls.
The patch in bug 1199534 should fix the SetBackgroundColor calls.

It seems to me that in comment #10 we're frequently/constantly painting on the Buzzfeed page, in a way that triggers layer construction. Were you doing anything to trigger painting (even just moving the mouse)? If not, unnecessary repaints might be a (big) problem in itself.
Flags: needinfo?(roc)
(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #15)
> The patch in bug 1199534 should fix the SetBackgroundColor calls.

Thanks!

> It seems to me that in comment #10 we're frequently/constantly painting on
> the Buzzfeed page, in a way that triggers layer construction. Were you doing
> anything to trigger painting (even just moving the mouse)? If not,
> unnecessary repaints might be a (big) problem in itself.

I don't think I was, but I can double check tomorrow. I did see some mozilla::dom::TabChild::RecvRealMouseButtonEvent in the stacks in comment 11 which seems a little weird given that I don't think I was touching the computer.
(Reporter)

Comment 17

2 years ago
FWIW, I'm certain I wasn't touching the mouse when I did my measurements in comment 1. In fact, the Firefox window didn't even have focus -- a Terminal window did -- though the Firefox window was mostly visible.
(Reporter)

Comment 18

2 years ago
> > The patch in bug 1199534 should fix the SetBackgroundColor calls.

I just tried it on my Mac. It dropped the mean power consumption during a 30 second window from ~22.5 W to ~22.0 W. I measured several windows and I *think* the drop was large enough to be distinguishable from noise, though it's a close thing.

There are certainly still other things to be fixed.
(In reply to Andrew McCreight [:mccr8] from comment #16)
> I don't think I was, but I can double check tomorrow. I did see some
> mozilla::dom::TabChild::RecvRealMouseButtonEvent in the stacks in comment 11
> which seems a little weird given that I don't think I was touching the
> computer.

That sounds worth investigating!
It seems like buzzfeed lazily loads content and inserts it into the page after the page appears to be finished loading. For about a minute after loading the page I would get periodic flashes of the disappearing scrollbar, indicating that scrollable height was changing.
Looks like there is a invisible spinner with an active css animation. This causes use to build a display list 60 times a second to discover that nothing needs to be done. Search ".loader" in the dev tools inspector to see it. It is visibility: hidden. We've had this bug for display: none before, and I think we fixed it. Perhaps we can do the same for visibility: hidden?
Flags: needinfo?(bbirtles)
(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #19)
> That sounds worth investigating!

I couldn't reproduce. I assume I must have been moving the mouse when I had it happen the first time.

(In reply to Timothy Nikkel (:tn) from comment #20)
> For about a minute after
> loading the page I would get periodic flashes of the disappearing scrollbar,
> indicating that scrollable height was changing.

If you scroll past the top of the page, the weird scrollbar flashing stops, though this didn't help the power situation. (Also, FWIW, neither Chrome nor Safari exhibited the scrollbar flashing.)
Component: General → Layout
Product: Firefox → Core
(In reply to Timothy Nikkel (:tn) from comment #21)
> Perhaps we can do the same for visibility: hidden?

That won't be straighforward though, since any descendant element can be visibility: visible.
(In reply to Timothy Nikkel (:tn) from comment #23)
> (In reply to Timothy Nikkel (:tn) from comment #21)
> > Perhaps we can do the same for visibility: hidden?
> 
> That won't be straighforward though, since any descendant element can be
> visibility: visible.

This is being tackled in bug 1166500.
Flags: needinfo?(bbirtles)
(Reporter)

Comment 25

2 years ago
(In reply to Timothy Nikkel (:tn) from comment #21)
> Looks like there is a invisible spinner with an active css animation.

How did you find this?
(In reply to Nicholas Nethercote [:njn] from comment #25)
> (In reply to Timothy Nikkel (:tn) from comment #21)
> > Looks like there is a invisible spinner with an active css animation.
> 
> How did you find this?

See bug 1190721, comment 10.
(Reporter)

Comment 27

2 years ago
Running for 10 minutes, I get the following timer frequencies:

> 15071 counts:
> ( 1)   5697 (37.8%, 37.8%): [53856]    fn timer (SLACK        N ms): nsExpirationTracker<mozilla::LayerActivity, 4u>::TimerCallback(nsITimer*, void*)
> ( 2)   4783 (31.7%, 69.5%): [53856]    fn timer (ONE_SHOT     N ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> ( 3)   2287 (15.2%, 84.7%): [53856]    fn timer (SLACK        N ms): CCTimerFired(nsITimer*, void*)
> ( 4)    672 ( 4.5%, 89.2%): [53855]    fn timer (SLACK        N ms): CCTimerFired(nsITimer*, void*)
> ( 5)    569 ( 3.8%, 92.9%): [53856]    fn timer (ONE_SHOT    N ms): nsGlobalWindow::TimerCallback(nsITimer*, void*)
> ( 6)    357 ( 2.4%, 95.3%): [53855]    fn timer (ONE_SHOT    N ms): mozilla::dom::workers::(anonymous namespace)::DummyCallback(nsITimer*, void*)
> ( 7)    100 ( 0.7%, 96.0%): [53856]    fn timer (SLACK         N ms): ICCTimerFired(nsITimer*, void*)
> ( 8)     56 ( 0.4%, 96.4%): [53855]    fn timer (ONE_SHOT    N ms): nsIdleService::StaticIdleTimerCallback(nsITimer*, void*)
> ( 9)     53 ( 0.4%, 96.7%): [53856]    fn timer (ONE_SHOT     N ms): nsBrowserStatusFilter::TimeoutHandler(nsITimer*, void*)
> (10)     42 ( 0.3%, 97.0%): [53856]    fn timer (ONE_SHOT     N ms): mozilla::layout::ScrollbarActivity::FadeBeginTimerFired(nsITimer*, void*)

The number in square brackets is the PID, so the child process (53856) dominates. 15071 timer firings in 600 seconds is 25.1 per second.

Additional instrumentation of the nsGlobalWindow::TimerCallback firings (which are from web content) gives this:

> 5380 counts:
> ( 1)   2383 (44.3%, 44.3%): - nsGlobalWindow: http://s3-ak.buzzfed.com/static/js/General_concat_header.js?v=201508311148:10:1048
> ( 2)   1133 (21.1%, 65.4%): - nsGlobalWindow: http://s3-ak.buzzfed.com/static/js/prototype/prototype.1.7-compact.js:1:6779
> ( 3)   1129 (21.0%, 86.3%): - nsGlobalWindow: http://partner.googleadservices.com/gpt/pubads_impl_70r.js:36:236
> ( 4)    578 (10.7%, 97.1%): - nsGlobalWindow: http://pagead2.googlesyndication.com/pagead/osd.js:84:222

I looked into the first three of these.

(1) There is a setInterval() call with an interval of 250 ms. Every time it
fires it checks if the page has been scrolled and does some stuff if it has.

(2) There is a setInterval() call with an interval of 500 ms. I couldn't work
out what it was for.

(3) There is a setTimeout() call with a timeout of 500 ms. Every time it fires
it appears to contact "https://www.google.com/csi" or
"http://csi.gstatic.com/csi" to report something about JS timings(?). It looks
like the code is trying to do this with increasing intervals via an exponential
backoff, but some ad hoc debugging shows this isn't working. I suspect
mis-binding of |this| is the problem.

Anyway, that's 8 timers firing per second in web content. So I was wondering
how Safari manages to get down to ~0 wakeups per second. It looks like Safari
starts off doing 8--12 wakeups per second, but if you switch to a non-Safari
window (even if the Safari window is still visible) then Safari will, after a
while, throttle timers firing in some way and drop to ~0. Then if you interact
with Safari again it jumps back up.
Depends on: 1166500
Maybe they're throttling JS timers in foreground tabs after some interval of not being in the foreground. That might be a reasonable thing to do, though you can easily imagine cases where it would break pages. What if you've got a script doing setInterval-driven animation that the user is watching while another window happens to be in the foreground?
(Reporter)

Comment 29

2 years ago
> What if you've got
> a script doing setInterval-driven animation that the user is watching while
> another window happens to be in the foreground?

It would be worth trying to trigger this kind of behaviour.
(In reply to Nicholas Nethercote [:njn] from comment #27)
> Running for 10 minutes, I get the following timer frequencies:
> 
> > 15071 counts:
> > ( 1)   5697 (37.8%, 37.8%): [53856]    fn timer (SLACK        N ms): nsExpirationTracker<mozilla::LayerActivity, 4u>::TimerCallback(nsITimer*, void*)

I think this will happen any time we repeatedly update a transform property (in this case from an active animation). Brian, would bug 1166500 also eliminate this (as well as the useless paints the invisible animation triggers)?
Flags: needinfo?(bbirtles)
(In reply to Timothy Nikkel (:tn) from comment #30)
> (In reply to Nicholas Nethercote [:njn] from comment #27)
> > Running for 10 minutes, I get the following timer frequencies:
> > 
> > > 15071 counts:
> > > ( 1)   5697 (37.8%, 37.8%): [53856]    fn timer (SLACK        N ms): nsExpirationTracker<mozilla::LayerActivity, 4u>::TimerCallback(nsITimer*, void*)
> 
> I think this will happen any time we repeatedly update a transform property
> (in this case from an active animation). Brian, would bug 1166500 also
> eliminate this (as well as the useless paints the invisible animation
> triggers)?

Maybe, but I'm not really familiar with the ActiveLayerTracker. Compositor animations shouldn't be keeping the timer for the ActiveLayerTracker expiration tracker active, however. Bug 1149848 should have fixed that.

Supposing we're animating the transform on an invisible layer using CSS animations/transitions and we're *not* using OMTA, then I guess bug 1166500 should help us. Specifically it should stop us from doing unnecessary style updates, which should hopefully mean we avoid calling ActiveLayerTracker::NotifyRestyle so the the expiration tracker's timer can eventually expire all its objects and stop. But, that's just a guess based on what I gather this site is doing from the comments above. There are lots of variables there. If that invisible animation could affect the overflow region then in bug 1166500 we might still run it every so often (~200ms) like we do for OMTA transform animations so it might not help.
Flags: needinfo?(bbirtles)
(Reporter)

Updated

2 years ago
Whiteboard: [Power]
(Reporter)

Updated

2 years ago
No longer blocks: 1190718
Flags: needinfo?(wmccloskey)
(Reporter)

Updated

2 years ago
Whiteboard: [Power] → [Power:P2]
(Reporter)

Comment 32

2 years ago
I've upgraded to [Power:P1] on froydnj's suggestion, because BuzzFeed is 38th most popular site in the US according to Alexa.
Whiteboard: [Power:P2] → [Power:P1]
Depends on: 1237454
You need to log in before you can comment on or make changes to this bug.