docs/performance/timerfirings_logging.md

   1 # TimerFirings Loggings
   2
   3 TimerFirings logging is a feature built into Gecko that prints a line of
   4 data for every timer fired. This is useful because timer firings are a
   5 major cause of wakeups, which can cause high power consumption.
   6
   7 **Note**: The [power profiling
   8 overview](power_profiling_overview.md)
   9 is worth reading at this point if you haven\'t already. It may make
  10 parts of this document easier to understand.
  11
  12 ## Invocation
  13
  14 TimerFirings logging uses Gecko\'s own logging mechanism, and so is able
  15 to be used in any build. Set the following environment variable to
  16 enable it.
  17
  18     NSPR_LOG_MODULES=TimerFirings:4
  19
  20 ## Output
  21
  22 Once enabled, TimerFirings will print one line of logging output per
  23 timer fired. It\'s best to redirect this output to a file.
  24
  25 The following sample shows the basics of this output.
  26
  27     -991946880[7f46c365ba00]: [6775]    fn timer (SLACK      100 ms): LayerActivityTracker
  28     -991946880[7f46c365ba00]: [6775]    fn timer (ONE_SHOT   250 ms): PresShell::sPaintSuppressionCallback
  29     -991946880[7f46c365ba00]: [6775]    fn timer (ONE_SHOT   160 ms): nsBrowserStatusFilter::TimeoutHandler
  30     -991946880[7f46c365ba00]: [6775] iface timer (ONE_SHOT   200 ms): 7f46964d7f80
  31     -1340643584[7f46c365ec00]: [6775]   obs timer (SLACK     1000 ms): 7f46a95a0200
  32
  33 Each line has the following information.
  34
  35 -   The first two values identify the thread. This is not especially
  36     useful.
  37 -   The next value is the process ID (pid). This is useful in a
  38     multi-process scenario.
  39 -   Next is the timer kind, one of `fn` (function), `iface` (interface)
  40     or `obs` (observer), which are the three kinds of timers that Gecko
  41     supports.
  42 -   Then comes the function kind, one of `ONE_SHOT` (a single-use
  43     timer), `SLACK` or `PRECISE` (repeating timers of differing
  44     precision).
  45 -   Then comes the timer period, measured in milliseconds.
  46 -   Finally there is the identifying information for the timer. Function
  47     timers have an informative label. Interface and observer timers only
  48     have an address, which is less useful, but they are uncommon enough
  49     that this usually doesn\'t matter much.
  50
  51 The above example shows only timers from C++ within Gecko. There are
  52 also timers for `setTimer` or `setInterval` calls in JavaScript code, as
  53 the following sample shows.
  54
  55     -991946880[7f46c365ba00]: [6775]    fn timer (ONE_SHOT     0 ms): [content] chrome://browser/content/tabbrowser.xml:1816:0
  56     711637568[7f3219c48000]: [6835]    fn timer (ONE_SHOT   100 ms): [content] http://edition.cnn.com/:5:7231
  57     711637568[7f3219c48000]: [6835]    fn timer (ONE_SHOT   100 ms): [content] http://a.visualrevenue.com/vrs.js:6:9423
  58
  59 These JS timers are annotated with `[content]` and show the JavaScript
  60 source location where they were created. They can come from chrome code
  61 within Firefox, or from web content.
  62
  63 The informative labels are only present on function timers that have had
  64 their creation site annotated. For unannotated function timers, there
  65 are three possible behaviours.
  66
  67 First, on Mac the code uses `dladdr` to get the name immediately, and
  68 the output will look like the following.
  69
  70     2082435840[100445640]: [81190] fn timer (ONE_SHOT 8000 ms): [from dladdr] gfxFontInfoLoader::DelayedStartCallback(nsITimer*, void*)
  71
  72 Second, on Linux the code uses `dladdr` to get the symbol library and
  73 address, which can be post-processed by `tools/rb/fix_stacks.py`. The
  74 following two lines show the output before and after being
  75 post-processed by that script.
  76
  77     2088737280[7f606bf68140]: [30710]    fn timer (ONE_SHOT    16 ms): [from dladdr] #0: ???[/home/njn/moz/mi1/o64/dist/bin/libxul.so +0x2144f94]
  78     2088737280[7f606bf68140]: [30710]    fn timer (ONE_SHOT    16 ms): [from dladdr] #0: mozilla::RefreshDriverTimer::TimerTick(nsITimer*, void*) (/home/njn/moz/mi1/o64/layout/b
  79
  80 Third, on other platforms `dladdr` is not implemented or doesn\'t work
  81 well, and the output will look like the following.
  82
  83     711637568[7f3219c48000]: [6835]    fn timer (ONE_SHOT    16 ms): ???[dladdr is unimplemented or doesn't work well on this OS]
  84
  85 The `???` indicates that the function timer lacks an explicit name, and
  86 the comment within the square brackets explains why the fallback
  87 mechanism wasn\'t used`.`
  88
  89 If an unannotated timer function appears frequently it is worth
  90 explicitly annotating it so that it will be usefully identified on other
  91 platforms. (Running on Mac or Linux is obviously necessary to learn the
  92 timer function\'s name.) This is done by initializing it with
  93 `initWithNamedFuncCallback` or `initWithNameableFuncCallback` instead of
  94 `initWithNameCallback`.
  95
  96 ## Post-processing
  97
  98 TimerFirings logging quickly produces thousands of lines of output. This
  99 output needs post-processing for it to be useful. If the output is
 100 redirected to a file called *`out`*, then the following command will
 101 pull out the timer-related lines, count how many times each unique line
 102 appears, and then print them with the most common ones first.
 103
 104     cat out | grep timer | sort | uniq -c | sort -r -n
 105
 106 The following is sample output from this command.
 107
 108         204 801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT    50 ms): [content] http://widgets.outbrain.com/outbrain.js:20:330
 109         135 -495057024[7f74e105ba00]: [7108]    fn timer (ONE_SHOT     4 ms): [content] https://self-repair.mozilla.org/en-US/repair/:7:13669
 110         118 801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT   100 ms): [content] http://a.visualrevenue.com/vrs.js:6:9423
 111         103 801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT    50 ms): [content] http://static.dynamicyield.com/scripts/12086/dy-min.js?v=12086:3:3389
 112          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
 113          94 801266240[7f7c1f248000]: [7163]    fn timer (ONE_SHOT   160 ms): nsBrowserStatusFilter::TimeoutHandler
 114          92 -495057024[7f74e105ba00]: [7108]    fn timer (ONE_SHOT   160 ms): nsBrowserStatusFilter::TimeoutHandler
 115
 116 The first column shows how many times the particular line appeared.
 117
 118 It is sometimes useful to pre-process the output by stripping out
 119 certain parts of each line before doing this aggregation step, for
 120 example, by inserting one or more of the following commands into the
 121 command pipeline.
 122
 123     sed 's/^[^:]\+: //'           # strip thread IDs
 124     sed 's/\[[0-9]\+\] //'        # strip process IDs
 125     sed 's/ \+[0-9]\+ ms//'       # strip timer periods
 126
 127 The following is the previous sample output with all three of these
 128 commands added into the pipeline.
 129
 130         204    fn timer (ONE_SHOT): [content] http://widgets.outbrain.com/outbrain.js:20:330
 131         186    fn timer (ONE_SHOT): nsBrowserStatusFilter::TimeoutHandler
 132         138    fn timer (ONE_SHOT): [content] https://self-repair.mozilla.org/en-US/repair/:7:13669
 133         118    fn timer (ONE_SHOT): [content] http://a.visualrevenue.com/vrs.js:6:9423
 134         108    fn timer (SLACK): LayerActivityTracker
 135         104    fn timer (SLACK): nsIDocument::SelectorCache
 136         104    fn timer (SLACK): CCTimerFired