136 lines
7.3 KiB
Markdown
136 lines
7.3 KiB
Markdown
# TimerFirings Loggings
|
|
|
|
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](power_profiling_overview.md)
|
|
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)
|
|
or `obs` (observer), which are the three kinds of timers that Gecko
|
|
supports.
|
|
- Then comes the function kind, one of `ONE_SHOT` (a single-use
|
|
timer), `SLACK` or `PRECISE` (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_stacks.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 following.
|
|
|
|
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.double-click.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
|