# 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 IceCat, 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
