1296486 - Measure time spent in background tabs

Status: RESOLVED FIXED

(Core :: DOM: Content Processes, defect)

Description

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

The purpose of this bug is to measure how much time the browser spends running code for background tabs. Presumably we could run less of this code and be less janky.

Comment 1

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

Attachment: measurement patch

Here's a simple patch I've been using to measure. It tries to label different tasks based on what document they're running on behalf of as well as why they were executed (setTimeout, media event, promise resolution, etc.) It measures how much time we spend in labeled tasks.

It also tries to find "unlabeled" tasks running in background tabs. It does this by looking at what global we're running code for when we enter the JS engine. If the global is in a background tab, we print a stack trace so you can instrument that task.

I've instrumented enough stuff that I rarely see stack traces for the sites I've tried, with one important condition: you can't load anything in a background. Once you start to load stuff, tons of unlabeled tasks run. For now, though, I'm content to only consider "quiescent" tabs.

Comment 2

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

Some preliminary results:

I loaded gmail, nytimes, techcrunch, and cnn.com. I probably left the browser open for about a minute total (should quantify this better). Here's the total time we spent per task:

TimeoutOrInterval: 6.253233
PostMessageEvent: 1.591665
HTMLMediaElement::DispatchEvent: 0.210537
HttpChannelChild::DoOnStopRequest: 0.055042
WorkerRunnable: 0.049421
SourceBuffer::DispatchSimpleEvent:updateend 0.046131
HttpChannelChild::DoOnDataAvailable: 0.038006
PromiseJob: 0.03705
HttpChannelChild::DoOnStartRequest: 0.025845
nsDocument::UpdateVisibilityState: 0.019681
InactiveRefreshDriverTimer: 0.018146
XMLHttpRequestMainThread::Notify: 0.016302
PluginEvaluate: 0.00985
AsyncEvent:load 0.005284
SourceBuffer::DispatchSimpleEvent:update 0.000796
AsyncEvent:DOMAttrModified 0.000698
SourceBuffer::DispatchSimpleEvent:updatestart 0.000562
MediaDecoder::OnPlaybackEvent: 0.000506
MediaDecoder::AsyncResolveSeekDOMPromiseIfExists: 0.000191
nsScriptLoader: 0.000181
AsyncEvent:removetrack 1.4e-05
AsyncEvent:loading 1.1e-05
AsyncEvent:readystatechange 8e-06
AsyncEvent:addtrack 8e-06
AsyncEvent:loadingdone 4e-06
AsyncEvent:cancel 1e-06

As expected, setTimeout is the worst offender. However, postMessage is pretty bad too. The next step is probably to get a histogram of the times to see if each individual task is quick or if they can actually cause jank by themselves.

Comment 3

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

Attachment: background-timing.py

Simple python script to tally up the output.

Also, note that it's best to close all tabs except one before quitting. Otherwise you'll get tons of stacks related to PermitUnload/Destroy for the background tabs.

Comment 4

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

Attachment: background-timing.py

New script.

Comment 5

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

Attachment: measurement patch, v2

New version of the patch. I disabled the JS execution tracking so that it doesn't skew the numbers.

Comment 6

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

Attachment: background-timing.py, v3

More improvements to the script.

Comment 7

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

Attachment: sample measurements

Here's some data from one run of testing. I had nine background tabs open. Most are common web sites, but treeherder is also included.

Over multiple runs, I typically see between 4 and 8 seconds out of 60 being used to run tasks for background tabs. That's after everything is loaded and the tabs should be just sitting there. I see a fair amount of variation between runs. I suspect that it's based on which ads I'm served. Fox News is a big contributor to the slowdown (4.9 seconds in this run), and a lot of the variance comes from that. It seems like news sites are the worst. Gmail and Google Docs are pretty light (100ms total or less). Probably because they don't have a lot of advertising.

Comment 8

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

Attachment: sample measurements with ad blocker

I took some more measurements, but this time with uBlock Origin installed. The results are quite a bit better. Only about 2 seconds spent on background tabs out of 60. And 0.9 seconds of that comes from Treeherder, which is kind of a silly exception. Fox News and CNN showed huge improvements from using an ad blocker. Facebook improved a little bit. Other sites showed little or no improvement.

Comment 9

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

Other ideas for data to collect:

* Run the same sort of experiment with media sites like Pandora, Spotify, and YouTube playing in the background. Make sure to include some Flash sites

* Include video-heavy news sites like CBS Sports, Yahoo! Sports. They tend to have both videos and lots of ads.

* Do measurements where background tabs are loading (rather than quiescent). This will probably require a lot more task labeling.

* Measure activity of third-party frames within the foreground tab. This is also stuff that we could potentially throttle.

* Create a graph of what tasks trigger other tasks. So if a postMessage ran inside of a setTimeout handler, then there would be an edge from the setTimeout task to the postMessage task. This will require beefing up the labeling to include task identity somehow.

Comment 10

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

We'll also need to try out sites that notify users, like Gmail and IRCCloud, to see what the minimum amount of code we need to run is in order for the notification to happen. I don't know how to do that though.

Comment 11

[(no longer active)]

Bill, do you have a more recent version of these patches?

Comment 12

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

No, I haven't worked on it in a while.

Comment 13

[(no longer active)]

Attachment: measurement patch, v2 (rebased)

rebased patch.

Comment 14

[Gabor Krizsanits (INACTIVE)]

We should do similar measurements for e10s-multi. This seems like an M2.

Comment 15

[(no longer active)]

(In reply to Gabor Krizsanits [:krizsa :gabor] from comment #14)
> We should do similar measurements for e10s-multi. This seems like an M2.

Note that afarre is looking at adding telemetry probes based on some of these.  You may want to chat together to see if some of those would be useful for e10s-multi as well.

Comment 16

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

I'm going to close this.