summaryrefslogtreecommitdiffstats
path: root/docs/performance/timerfirings_logging.md
diff options
context:
space:
mode:
Diffstat (limited to '')
-rw-r--r--docs/performance/timerfirings_logging.md136
1 files changed, 136 insertions, 0 deletions
diff --git a/docs/performance/timerfirings_logging.md b/docs/performance/timerfirings_logging.md
new file mode 100644
index 0000000000..dfbe8dca93
--- /dev/null
+++ b/docs/performance/timerfirings_logging.md
@@ -0,0 +1,136 @@
+# 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