Closed Bug 1458337 Opened 2 years ago Closed Last year

runnable telemetry showing up in profiles on Windows

Categories

(Core :: XPCOM, enhancement)

All
Windows
enhancement
Not set

Tracking

()

RESOLVED FIXED
mozilla62
Tracking Status
firefox61 --- wontfix
firefox62 --- fixed

People

(Reporter: froydnj, Assigned: froydnj)

Details

Attachments

(1 file)

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).
Flags: needinfo?(afarre)
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.
Flags: needinfo?(afarre)
We no longer care about these histograms, and the measurements that they
take can be noticed in profiles.
Attachment #8985268 - Flags: review?(afarre)
Attachment #8985268 - Flags: review?(afarre) → review+
Pushed by nfroyd@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/25ff84f2bac3
eliminate unneeded runnable histograms; r=farre
https://hg.mozilla.org/mozilla-central/rev/25ff84f2bac3
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
Assignee: nobody → nfroyd
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
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
(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?
Flags: needinfo?(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.
Flags: needinfo?(erahm)
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!
You need to log in before you can comment on or make changes to this bug.