Last Comment Bug 1296486 - Measure time spent in background tabs
: Measure time spent in background tabs
Status: NEW
[e10s-multi:+]
:
Product: Core
Classification: Components
Component: DOM: Content Processes (show other bugs)
: unspecified
: Unspecified Unspecified
-- normal with 4 votes (vote)
: ---
Assigned To: Bill McCloskey (:billm)
:
: Bill McCloskey (:billm)
Mentors:
Depends on:
Blocks: e10s-multi QuantumDOM
  Show dependency treegraph
 
Reported: 2016-08-18 17:30 PDT by Bill McCloskey (:billm)
Modified: 2017-02-02 09:41 PST (History)
16 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
measurement patch (39.83 KB, patch)
2016-08-18 17:33 PDT, Bill McCloskey (:billm)
no flags Details | Diff | Splinter Review
background-timing.py (719 bytes, text/plain)
2016-08-18 17:38 PDT, Bill McCloskey (:billm)
no flags Details
background-timing.py (1.76 KB, text/x-python)
2016-08-19 16:08 PDT, Bill McCloskey (:billm)
no flags Details
measurement patch, v2 (39.89 KB, patch)
2016-08-19 16:28 PDT, Bill McCloskey (:billm)
no flags Details | Diff | Splinter Review
background-timing.py, v3 (2.17 KB, text/x-python)
2016-08-19 16:29 PDT, Bill McCloskey (:billm)
no flags Details
sample measurements (19.72 KB, text/plain)
2016-08-19 16:34 PDT, Bill McCloskey (:billm)
no flags Details
sample measurements with ad blocker (24.47 KB, text/plain)
2016-08-19 16:45 PDT, Bill McCloskey (:billm)
no flags Details
measurement patch, v2 (rebased) (39.05 KB, patch)
2016-10-20 12:20 PDT, :Ehsan Akhgari
no flags Details | Diff | Splinter Review

Description User image Bill McCloskey (:billm) 2016-08-18 17:30:01 PDT
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 User image Bill McCloskey (:billm) 2016-08-18 17:33:32 PDT
Created attachment 8782710 [details] [diff] [review]
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 User image Bill McCloskey (:billm) 2016-08-18 17:37:40 PDT
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 User image Bill McCloskey (:billm) 2016-08-18 17:38:42 PDT
Created attachment 8782711 [details]
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 User image Bill McCloskey (:billm) 2016-08-19 16:08:09 PDT
Created attachment 8783110 [details]
background-timing.py

New script.
Comment 5 User image Bill McCloskey (:billm) 2016-08-19 16:28:43 PDT
Created attachment 8783114 [details] [diff] [review]
measurement patch, v2

New version of the patch. I disabled the JS execution tracking so that it doesn't skew the numbers.
Comment 6 User image Bill McCloskey (:billm) 2016-08-19 16:29:54 PDT
Created attachment 8783116 [details]
background-timing.py, v3

More improvements to the script.
Comment 7 User image Bill McCloskey (:billm) 2016-08-19 16:34:25 PDT
Created attachment 8783117 [details]
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 User image Bill McCloskey (:billm) 2016-08-19 16:45:09 PDT
Created attachment 8783121 [details]
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 User image Bill McCloskey (:billm) 2016-08-19 19:24:44 PDT
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 User image Bill McCloskey (:billm) 2016-08-19 20:07:22 PDT
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 User image :Ehsan Akhgari 2016-10-11 12:51:17 PDT
Bill, do you have a more recent version of these patches?
Comment 12 User image Bill McCloskey (:billm) 2016-10-11 21:21:15 PDT
No, I haven't worked on it in a while.
Comment 13 User image :Ehsan Akhgari 2016-10-20 12:20:57 PDT
Created attachment 8803059 [details] [diff] [review]
measurement patch, v2 (rebased)

rebased patch.
Comment 14 User image Gabor Krizsanits [:krizsa :gabor] 2016-10-21 03:38:51 PDT
We should do similar measurements for e10s-multi. This seems like an M2.
Comment 15 User image :Ehsan Akhgari 2016-10-21 13:03:44 PDT
(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.

Note You need to log in before you can comment on or make changes to this bug.