1458337 - runnable telemetry showing up in profiles on Windows

Status: RESOLVED FIXED

(Core :: XPCOM, enhancement)

Description

[Nathan Froyd [:froydnj]]

I am seeing TimeStamp::Now() called multiple times underneath nsThread::ProcessNextEvent, and taking ~5-7% of the time of main thread time on profiles taken while watching YouTube or similar on Windows.  No user interaction, just watching.

The calls are coming from three places:

1) Maybe<Telemetry::AutoTimer>::emplace()
2) Maybe<Telemetry::AutoTimer>::~Maybe()
3) Some unattributed call(s?) directly from ProcessNextEvent.

It's not obvious to me why these calls are so expensive; there are stacks for TimeStamp::Now() called underneath XPCJSContext::{Before,After}ProcessTask that are taking 0.1%-0.5% of the time of the profile (and not counted in the above 5-7% figure!), which is still surprisingly large.  I suppose that *ProcessTask is only called when we need to call the script observer, which doesn't happen all the time (?).  Not really sure about that.

Anyway, do we need the telemetry this timer is collecting?  I think it's MAIN_THREAD_RUNNABLE_MS; it's *possible* it's IDLE_RUNNABLE_BUDGET_OVERUSE_MS, but that probe would probably be collected less often?

If we're still in need of both timers, it may be worth trying to common up TimeStamp::Now() calls ourself, just to make sure we're not calling it more often than we should (e.g. https://searchfox.org/mozilla-central/source/xpcom/threads/nsThread.cpp#1034).

Comment 1

[Andreas Farre [:farre]]

I think that we can safely remove them, MAIN_THREAD_RUNNABLE_MS was to find long unlabeled runnables. IDLE_RUNNABLE_BUDGET_OVERUSE_MS can go as well, since we have better ways of profiling for jank.

Comment 2

[Nathan Froyd [:froydnj]]

Attachment: eliminate unneeded runnable histograms

We no longer care about these histograms, and the measurements that they
take can be noticed in profiles.

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/25ff84f2bac3
eliminate unneeded runnable histograms; r=farre

Comment 4

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/25ff84f2bac3

Comment 5

[Ionuț Goldan [:igoldan]]

Slight perf improvement win:

== Change summary for alert #13826 (as of Thu, 14 Jun 2018 18:52:00 GMT) ==

Improvements:

  2%  tart linux64-qr opt e10s stylo     1.62 -> 1.58

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=13826

Comment 6

[Ionuț Goldan [:igoldan]]

And big perf wins on Windows, according to AWSY:

== Change summary for alert #13824 (as of Thu, 14 Jun 2018 13:52:58 GMT) ==

Improvements:

 12%  Images windows10-64 opt stylo     8,576,061.30 -> 7,511,306.00
  8%  Images windows10-64 pgo stylo     8,294,465.55 -> 7,657,828.31
  3%  Images windows7-32 pgo stylo      6,975,856.84 -> 6,750,523.08

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=13824

Comment 7

[Nathan Froyd [:froydnj]]

(In reply to Ionuț Goldan [:igoldan], Performance Sheriffing from comment #6)
> And big perf wins on Windows, according to AWSY:
> 
> == Change summary for alert #13824 (as of Thu, 14 Jun 2018 13:52:58 GMT) ==
> 
> Improvements:
> 
>  12%  Images windows10-64 opt stylo     8,576,061.30 -> 7,511,306.00
>   8%  Images windows10-64 pgo stylo     8,294,465.55 -> 7,657,828.31
>   3%  Images windows7-32 pgo stylo      6,975,856.84 -> 6,750,523.08
> 
> For up to date results, see:
> https://treeherder.mozilla.org/perf.html#/alerts?id=13824

This is sort of bizarre.  Eric, do you know why this might happen?

Comment 8

[Eric Rahm [:erahm]]

(In reply to Nathan Froyd [:froydnj] from comment #7)
> (In reply to Ionuț Goldan [:igoldan], Performance Sheriffing from comment #6)
> > And big perf wins on Windows, according to AWSY:
> > 
> > == Change summary for alert #13824 (as of Thu, 14 Jun 2018 13:52:58 GMT) ==
> > 
> > Improvements:
> > 
> >  12%  Images windows10-64 opt stylo     8,576,061.30 -> 7,511,306.00
> >   8%  Images windows10-64 pgo stylo     8,294,465.55 -> 7,657,828.31
> >   3%  Images windows7-32 pgo stylo      6,975,856.84 -> 6,750,523.08
> > 
> > For up to date results, see:
> > https://treeherder.mozilla.org/perf.html#/alerts?id=13824
> 
> This is sort of bizarre.  Eric, do you know why this might happen?

It looks like that alert is actually highlighting a push from bug 1423895.

Comment 9

[Chris H-C :chutten]

Very nice reduction in Telemetry payload sizes on Nightly: https://bug1470908.bmoattachments.org/attachment.cgi?id=8988221

Thank you very much for cleaning up no-longer-helpful probes!