1203427 - Add logging for timer firings

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Nicholas Nethercote [inactive]]

Timer firings cause wakeups, which increases power consumption. Therefore, the ability to profile timer firings is useful. The hard part is that you need to be able to identify the callback function when a timer fires.

Back in 2010 azakai tried passing in an extra argument to the timer initialization functions, in order to identify them, using source instrumentation via a script (https://wiki.mozilla.org/Mobile/Powersaving/Wakeups/Debugging). This worked but was fragile -- I resurrected his scripts and got them working but it took non-trivial effort.

Then last year rvitillo tried a less invasive approach of using dladdr() to lookup the callback name (http://robertovitillo.com/2014/02/04/idle-wakeups-are-evil/). This is great but it only works on Mac. (Even on Linux it doesn't work due to the linker not doing the right things with symbol tables.)

I'm working on something of a hybrid approach. There are lots of timers in the codebase but for profiling purposes a relatively small number of them account for almost all the timer firings that occur in practice. So I want to manually annotate the frequent ones with explicit names, and then have the dladdr() fallback available to identify which additional ones should be explicitly named.

Comment 1

[Nicholas Nethercote [inactive]]

Attachment: (part 3) - Add logging of timer firings

Putting this up for feedback rather than review because it's still a bit rough.

This is part 3, but parts 1 and 2 are just minor refactorings so you don't need
to see them right now.

The key additions are the new initWithNamedFuncCallback() and
initWithNameableFuncCallback() functions, which can be used to give an explicit
name to a timer. The former takes a C string, the latter takes a callback,
which is necessary for timers in content JS code that occur via nsGlobalWindow.

Doing the output via MOZ_LOG seemed reasonable, though I don't like the ugly
thread IDs that get put onto every line. You invoke it like this:

  NSPR_LOG_MODULES=TimerFirings:4 firefox > out

And then simple post-processing can identify the timers that occur frequently.

Sample output for explicitly named timers within Gecko:

> 1562818432[7f795be55a00]: [16906]   fn timer (SLACK        100 ms): LayerActivityTracker
> 1562818432[7f795be55a00]: [16906]   fn timer (SLACK       1000 ms): nsIDocument::SelectorCache

Sample output for JS content timers:

> 1562818432[7f795be55a00]: [16906]   fn timer (ONE_SHOT       0 ms): (content
timer) chrome://browser/content/tabbrowser.xml:1807:0
> -2099578304[7f4772642000]: [16964]   fn timer (ONE_SHOT      60 ms): (content timer) http://int.nyt.com/applications/portals/assets/portal/app-d37d526acc5f1ea70c6a0bee273416cc.js:4:12064

Sample output for an unnamed timer obtained on Mac (which does have a working
dladdr()):

> 2082435840[100445640]: [8654]   fn timer (ONE_SHOT     250 ms): [from dladdr]
PresShell::sPaintSuppressionCallback(nsITimer*, void*)

Sample output for an unnamed timer obtained on Linux (which doesn't have a
working dladdr()):

> 1562818432[7f795be55a00]: [16906]   fn timer (ONE_SHOT     160 ms): ???[no dladdr on this platform]

The coverage could be improved quite a bit just by giving explicit names to a
few more timers.

I feel like this is far from the cleanest code I've ever written, so comments
on how that might be improved would be welcome. Thanks.

Comment 2

[Nicholas Nethercote [inactive]]

Attachment: (part 3) - Add logging of timer firings

Here's a somewhat cleaned-up version. I also improved the coverage by giving
names to a few more timers.

BTW, here's sample output for timers that have the |Interface| and |Observer|
types:

> 403998592[7fc616a5ba00]: [8167] iface timer (ONE_SHOT     0 ms): 7fc5ed84cde0
> 403998592[7fc616a5ba00]: [8167]   obs timer (ONE_SHOT     0 ms): 7fc5ffa55f80

These aren't nearly as common as |Function| timers so I'm not too concerned by
the fact that I am only printing a pointer for them.

Comment 3

[Nicholas Nethercote [inactive]]

Attachment: (part 1) - Add nsExpirationTracker::mName

There are many sub-classes of nsExpirationTracker. In order to distinguish them
nicely in the logging of timer firings, it's necessary to manually name each
one. (This wouldn't be necessary if there was a way to stringify template
parameters, but there isn't.)

Comment 4

[Nicholas Nethercote [inactive]]

Attachment: (part 2) - Remove an argument to nsTimeout::InitTimer

The first argument to this method is always nsGlobalWindow::TimerCallback, and
hard-wiring this makes subsequent patches simpler.

Comment 5

[Nicholas Nethercote [inactive]]

Attachment: (part 3) - Change order of InitCommon() arguments

This makes the order of |aDelay| and |aType| match those of the InitWith*()
functions.

I've made this change because the inconsistency tripped me up during the
development of part 4.

Comment 6

[Nicholas Nethercote [inactive]]

Attachment: (part 4) - Remove trailing whitespace from nsITimer.idl

Comment 7

[Nicholas Nethercote [inactive]]

Attachment: (part 5) - Add logging of timer firings

Comment 8

[Nathan Froyd [:froydnj]]

Comment on attachment 8659756 [details] [diff] [review]
(part 4) - Remove trailing whitespace from nsITimer.idl

Review of attachment 8659756 [details] [diff] [review]:
-----------------------------------------------------------------

Thank you for separating this out.

Comment 9

[Nathan Froyd [:froydnj]]

Comment on attachment 8659754 [details] [diff] [review]
(part 3) - Change order of InitCommon() arguments

Review of attachment 8659754 [details] [diff] [review]:
-----------------------------------------------------------------

Hooray for a foolish consistency.

Comment 10

[Nathan Froyd [:froydnj]]

Comment on attachment 8659751 [details] [diff] [review]
(part 1) - Add nsExpirationTracker::mName

Review of attachment 8659751 [details] [diff] [review]:
-----------------------------------------------------------------

We have the same problem vis-a-vis stringifying template parameters for things like MOZ_COUNT_CTOR.  It leads to sadness for people.

Comment 11

[Nathan Froyd [:froydnj]]

Comment on attachment 8659752 [details] [diff] [review]
(part 2) - Remove an argument to nsTimeout::InitTimer

Review of attachment 8659752 [details] [diff] [review]:
-----------------------------------------------------------------

I'm OK with this, but I think this is more Andrew's code than mine.

Comment 12

[Andrew McCreight [:mccr8]]

Comment on attachment 8659752 [details] [diff] [review]
(part 2) - Remove an argument to nsTimeout::InitTimer

Review of attachment 8659752 [details] [diff] [review]:
-----------------------------------------------------------------

Well, this is peculiar. I don't know why this code was like that, but it is pretty old so it should be okay.

Comment 13

[Nathan Froyd [:froydnj]]

Comment on attachment 8659783 [details] [diff] [review]
(part 5) - Add logging of timer firings

Review of attachment 8659783 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with the idl changes and using mozilla::Variant.

::: xpcom/threads/nsITimer.idl
@@ +160,5 @@
> +  [noscript] void initWithNamedFuncCallback(in nsTimerCallbackFunc aCallback,
> +                                            in voidPtr aClosure,
> +                                            in unsigned long aDelay,
> +                                            in unsigned long aType,
> +                                            in string aName);

Please move these declarations to the end of the interface definition so they don't interfere with vtable orderings.

::: xpcom/threads/nsTimerImpl.cpp
@@ +590,5 @@
> +  }
> +
> +  switch (aCallbackType) {
> +    case CallbackType::Function: {
> +      bool needToFreeName = false;

There has got to be some better way of doing this "sometimes a static buffer, sometimes a dynamically allocated before" dance.  (Not a criticism of the patch, just frustration that it's not easier.)

@@ +606,5 @@
> +
> +      } else {
> +        MOZ_ASSERT(mName.mTag == Name::NameType::None);
> +#if defined(XP_MACOSX)
> +        annotation = "[from dladdr] ";

I wonder if build peers would let us pass --dynamic-list to the linker, so we could pass in a list of relevant timer callbacks on Linux, so dladdr() could work there...at least for developer builds.

::: xpcom/threads/nsTimerImpl.h
@@ +124,5 @@
>  
> +  void LogFiring(CallbackType aCallbackType, CallbackUnion aCallbackUnion);
> +
> +  // A tagged union type representing one of (a) nothing, (b) a string, or (c)
> +  // a function.

We have mozilla/Variant.h for this.  It might require a bit more verbiage to use, but I don't think that'd be a bad thing.

Comment 14

[Nicholas Nethercote [inactive]]

> Hooray for a foolish consistency.

“A foolish consistency is the hobgoblin of little minds, adored by little statesmen and philosophers and divines." - Ralph Waldo Emerson

"Pythagoras was misunderstood, and Socrates, and Jesus, and Luther, and Copernicus, and Galileo, and Newton, and every pure and wise spirit that ever took flesh. To be great is to be misunderstood." - Ralph Waldo Emerson

"I pity the fool." - Mr. T

Comment 15

[Nicholas Nethercote [inactive]]

> There has got to be some better way of doing this "sometimes a static
> buffer, sometimes a dynamically allocated before" dance.  (Not a criticism
> of the patch, just frustration that it's not easier.)

Indeed. I tried and failed to come up with something better. Hard to avoid when I'm dealing with two pre-existing APIs that use different conventions.


> > +  // A tagged union type representing one of (a) nothing, (b) a string, or (c)
> > +  // a function.
> 
> We have mozilla/Variant.h for this.  It might require a bit more verbiage to
> use, but I don't think that'd be a bad thing.

One downside of Variant is that it doesn't handle the "nothing" case naturally; I'd have to use a dummy |int| or somesuch. I'll try it and see how it looks in comparison with the hand-rolled version.

Comment 16

[Nicholas Nethercote [inactive]]

Attachment: (part 5b) - Use mozilla::Variant

Nathan, using mozilla::Variant is shorter but the handling of the "nothing"
case is a bit odd. Do you have any preference between the two versions?

Comment 17

[Nicholas Nethercote [inactive]]

Attachment: (part 5b) - Use mozilla::Variant

Comment 18

[Nicholas Nethercote [inactive]]

Attachment: (part 5b) - Use mozilla::Variant

Comment 19

[Nathan Froyd [:froydnj]]

Comment on attachment 8661007 [details] [diff] [review]
(part 5b) - Use mozilla::Variant

Review of attachment 8661007 [details] [diff] [review]:
-----------------------------------------------------------------

WFM.  This is maybe getting ridiculous, but you could use mozilla/Maybe.h:

mozilla::Maybe<mozilla::Variant<>>

That handles the Nothing case, and if you have Something, it must be one of the two variant cases.

Comment 20

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/96dba490e51b
https://hg.mozilla.org/integration/mozilla-inbound/rev/00eeeae71d65
https://hg.mozilla.org/integration/mozilla-inbound/rev/89de619e863b
https://hg.mozilla.org/integration/mozilla-inbound/rev/afa92bf6913e
https://hg.mozilla.org/integration/mozilla-inbound/rev/21235635ebde

Comment 21

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/309502b3ea1f

Comment 22

[Nicholas Nethercote [inactive]]

(In reply to Pulsebot from comment #21)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/309502b3ea1f

This was a follow-up patch where I linked to the MDN docs that I just wrote:
https://developer.mozilla.org/en-US/docs/Mozilla/Performance/TimerFirings_logging

Comment 23

[Mike Hommey [:glandium]]

> On non-Mac platforms, unannotated function timer firings will look like the following.
>
> 711637568[7f3219c48000]: [6835]    fn timer (ONE_SHOT    16 ms): ???[dladdr: unavailable/doesn't work on this platform]

Outputing something that can be postprocessed by fix_linux_stack.py would have been helpful.

Comment 24

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/96dba490e51b
https://hg.mozilla.org/mozilla-central/rev/00eeeae71d65
https://hg.mozilla.org/mozilla-central/rev/89de619e863b
https://hg.mozilla.org/mozilla-central/rev/afa92bf6913e
https://hg.mozilla.org/mozilla-central/rev/21235635ebde
https://hg.mozilla.org/mozilla-central/rev/309502b3ea1f

Comment 25

[Nicholas Nethercote [inactive]]

> Outputing something that can be postprocessed by fix_linux_stack.py would
> have been helpful.

That requires a library name and offset. Can we get that from a function pointer?

Comment 26

[Mike Hommey [:glandium]]

The dli_fname and dli_fbase members of the Dl_info struct that dladdr fills contain, respectively, the library path and the base address where it's loaded. You can derive the lib name by taking the part of the path after tha last / if there is one, and the offset by substracting the address you're dladdr'ing with the base address.

Comment 27

[Nicholas Nethercote [inactive]]

(In reply to Mike Hommey [:glandium] from comment #26)
> The dli_fname and dli_fbase members of the Dl_info struct that dladdr fills
> contain, respectively, the library path and the base address where it's
> loaded.

Bug 1205941!

> You can derive the lib name by taking the part of the path after tha
> last / if there is one

It turns out using the whole path works; no need to trim it down.