TimerFirings logging is a feature built into Gecko that prints a line of data for every timer fired. This is useful because timer firings are a major cause of wakeups, which can cause high power consumption.
Note: The power profiling overview is worth reading at this point if you haven't already. It may make parts of this document easier to understand.
Invocation
TimerFirings logging uses Gecko's own logging mechanism, and so is able to be used in any build. Set the following environment variable to enable it.
NSPR_LOG_MODULES=TimerFirings:4
Output
Once enabled, TimerFirings will print one line of logging output per timer fired. It's best to redirect this output to a file.
The following sample shows the basics of this output.
-991946880[7f46c365ba00]: [6775] fn timer (SLACK 100 ms): LayerActivityTracker -991946880[7f46c365ba00]: [6775] fn timer (ONE_SHOT 250 ms): PresShell::sPaintSuppressionCallback -991946880[7f46c365ba00]: [6775] fn timer (ONE_SHOT 160 ms): nsBrowserStatusFilter::TimeoutHandler -991946880[7f46c365ba00]: [6775] iface timer (ONE_SHOT 200 ms): 7f46964d7f80 -1340643584[7f46c365ec00]: [6775] obs timer (SLACK 1000 ms): 7f46a95a0200
Each line has the following information.
- The first two values identify the thread. This is not especially useful.
- The next value is the process ID (pid). This is useful in a multi-process scenario.
- Next is the timer kind, one of
fn(function),iface(interface) orobs(observer), which are the three kinds of timers that Gecko supports. - Then comes the function kind, one of
ONE_SHOT(a single-use timer),SLACKorPRECISE(repeating timers of differing precision). - Then comes the timer period, measured in milliseconds.
- Finally there is the identifying information for the timer. Function timers have an informative label. Interface and observer timers only have an address, which is less useful, but they are uncommon enough that this usually doesn't matter much.
The above example shows only timers from C++ within Gecko. There are also timers for setTimer or setInterval calls in JavaScript code, as the following sample shows.
-991946880[7f46c365ba00]: [6775] fn timer (ONE_SHOT 0 ms): [content] chrome://browser/content/tabbrowser.xml:1816:0 711637568[7f3219c48000]: [6835] fn timer (ONE_SHOT 100 ms): [content] http://edition.cnn.com/:5:7231 711637568[7f3219c48000]: [6835] fn timer (ONE_SHOT 100 ms): [content] http://a.visualrevenue.com/vrs.js:6:9423
These JS timers are annotated with [content] and show the JavaScript source location where they were created. They can come from chrome code within Firefox, or from web content.
The informative labels are only present on function timers that have had their creation site annotated. For unannotated function timers, there are three possible behaviours.
First, on Mac the code uses dladdr to get the name immediately, and the output will look like the following.
2082435840[100445640]: [81190] fn timer (ONE_SHOT 8000 ms): [from dladdr] gfxFontInfoLoader::DelayedStartCallback(nsITimer*, void*)
Second, on Linux the code uses dladdr to get the symbol library and address, which can be post-processed by tools/rb/fix_linux_stack.py. The following two lines show the output before and after being post-processed by that script.
2088737280[7f606bf68140]: [30710] fn timer (ONE_SHOT 16 ms): [from dladdr] #0: ???[/home/njn/moz/mi1/o64/dist/bin/libxul.so +0x2144f94] 2088737280[7f606bf68140]: [30710] fn timer (ONE_SHOT 16 ms): [from dladdr] #0: mozilla::RefreshDriverTimer::TimerTick(nsITimer*, void*) (/home/njn/moz/mi1/o64/layout/b
Third, on other platforms dladdr is not implemented or doesn't work well, and the output will look like the followin.
711637568[7f3219c48000]: [6835] fn timer (ONE_SHOT 16 ms): ???[dladdr is unimplemented or doesn't work well on this OS]
The ??? indicates that the function timer lacks an explicit name, and the comment within the square brackets explains why the fallback mechanism wasn't used.
If an unannotated timer function appears frequently it is worth explicitly annotating it so that it will be usefully identified on other platforms. (Running on Mac or Linux is obviously necessary to learn the timer function's name.) This is done by initializing it with initWithNamedFuncCallback or initWithNameableFuncCallback instead of initWithNameCallback.
Post-processing
TimerFirings logging quickly produces thousands of lines of output. This output needs post-processing for it to be useful. If the output is redirected to a file called out, then the following command will pull out the timer-related lines, count how many times each unique line appears, and then print them with the most common ones first.
cat out | grep timer | sort | uniq -c | sort -r -n
The following is sample output from this command.
204 801266240[7f7c1f248000]: [7163] fn timer (ONE_SHOT 50 ms): [content] http://widgets.outbrain.com/outbrain.js:20:330
135 -495057024[7f74e105ba00]: [7108] fn timer (ONE_SHOT 4 ms): [content] https://self-repair.mozilla.org/en-US/repair/:7:13669
118 801266240[7f7c1f248000]: [7163] fn timer (ONE_SHOT 100 ms): [content] http://a.visualrevenue.com/vrs.js:6:9423
103 801266240[7f7c1f248000]: [7163] fn timer (ONE_SHOT 50 ms): [content] http://static.dynamicyield.com/scripts/12086/dy-min.js?v=12086:3:3389
94 801266240[7f7c1f248000]: [7163] fn timer (ONE_SHOT 50 ms): [content] https://ad.doubleclick.net/ddm/adi/N7921.1283839CADREON.COM.AU/B9038144.122190976;sz=300x600;click=http://pixel.mathtag.com/click/img?mt_aid=2744535504761193354&mt_id=1895890&mt_adid=148611&mt_sid=973379&mt_exid=9&mt_inapp=0&mt_uuid=353d5460-19f6-4400-9bbd-d0fcc3bcf595&mt_3pck=http%3A//beacon-apac-hkg1.rubiconproject.com/beacon/t/d1f9921d-4e47-448f-b6ba-36cae1c31b65/&redirect=;ord=2744535504761193354?:83:0
94 801266240[7f7c1f248000]: [7163] fn timer (ONE_SHOT 160 ms): nsBrowserStatusFilter::TimeoutHandler
92 -495057024[7f74e105ba00]: [7108] fn timer (ONE_SHOT 160 ms): nsBrowserStatusFilter::TimeoutHandler
The first column shows how many times the particular line appeared.
It is sometimes useful to pre-process the output by stripping out certain parts of each line before doing this aggregation step, for example, by inserting one or more of the following commands into the command pipeline.
sed 's/^[^:]\+: //' # strip thread IDs sed 's/\[[0-9]\+\] //' # strip process IDs sed 's/ \+[0-9]\+ ms//' # strip timer periods
The following is the previous sample output with all three of these commands added into the pipeline.
204 fn timer (ONE_SHOT): [content] http://widgets.outbrain.com/outbrain.js:20:330
186 fn timer (ONE_SHOT): nsBrowserStatusFilter::TimeoutHandler
138 fn timer (ONE_SHOT): [content] https://self-repair.mozilla.org/en-US/repair/:7:13669
118 fn timer (ONE_SHOT): [content] http://a.visualrevenue.com/vrs.js:6:9423
108 fn timer (SLACK): LayerActivityTracker
104 fn timer (SLACK): nsIDocument::SelectorCache
104 fn timer (SLACK): CCTimerFired