Measure time spent in background tabs

RESOLVED FIXED

Status

()

RESOLVED FIXED
3 years ago
2 years ago

People

(Reporter: billm, Assigned: billm)

Tracking

(Blocks: 1 bug)

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [e10s-multi:+])

Attachments

(4 attachments, 4 obsolete attachments)

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.
Posted patch measurement patch (obsolete) — Splinter Review
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.
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.
Posted file background-timing.py (obsolete) —
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.
Posted file background-timing.py (obsolete) —
New script.
Attachment #8782711 - Attachment is obsolete: true
Posted patch measurement patch, v2 (obsolete) — Splinter Review
New version of the patch. I disabled the JS execution tracking so that it doesn't skew the numbers.
Attachment #8782710 - Attachment is obsolete: true
More improvements to the script.
Attachment #8783110 - Attachment is obsolete: true
Posted file 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.
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.
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.
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.

Updated

3 years ago
Blocks: 1302270

Comment 11

3 years ago
Bill, do you have a more recent version of these patches?
Flags: needinfo?(wmccloskey)
No, I haven't worked on it in a while.
Flags: needinfo?(wmccloskey)

Comment 13

3 years ago
rebased patch.
Attachment #8783114 - Attachment is obsolete: true
We should do similar measurements for e10s-multi. This seems like an M2.
Whiteboard: [e10s-multi:?]

Comment 15

3 years ago
(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.
Blocks: 1207306
Whiteboard: [e10s-multi:?] → [e10s-multi:+]
I'm going to close this.
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.