Last Comment Bug 717711 - telemetry for time spent in between CCs
: telemetry for time spent in between CCs
Status: RESOLVED FIXED
[Snappy]
:
Product: Core
Classification: Components
Component: DOM (show other bugs)
: Trunk
: All All
: -- normal (vote)
: mozilla12
Assigned To: Andrew McCreight [:mccr8]
:
Mentors:
Depends on:
Blocks: 698919
  Show dependency treegraph
 
Reported: 2012-01-12 11:50 PST by Andrew McCreight [:mccr8]
Modified: 2012-05-20 12:35 PDT (History)
6 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
telemetry for time in between CCs (4.08 KB, patch)
2012-01-19 11:12 PST, Andrew McCreight [:mccr8]
bugs: review+
Details | Diff | Splinter Review
telemetry for time in between CCs (4.07 KB, patch)
2012-01-20 12:40 PST, Andrew McCreight [:mccr8]
continuation: review+
Details | Diff | Splinter Review

Description Andrew McCreight [:mccr8] 2012-01-12 11:50:36 PST
In addition to timing how long we spend doing GC and CC, we should measure how much time is spent in between these.  This will hopefully cause future GC/CC scheduling regressions.  We could also potentially combine this with GC/CC times to measure % of time not spent in GC/CC for some kind of throughput measure.

The idea is to save the time whenever we end a GC or CC, then look again before we start.
Comment 1 Andrew McCreight [:mccr8] 2012-01-12 11:54:28 PST
> This will hopefully cause future GC/CC scheduling regressions.

Detect, not cause...
Comment 2 Andrew McCreight [:mccr8] 2012-01-18 10:22:30 PST
It probably makes more sense to deal with the CC and GC separately, as the central invocation for the CC is in DOM, whereas for the GC it will be in JS.  The combination of those two numbers, plus the time spent in the GC and CC directly, should let us find if more time is being spent in the CC or GC, and if those are being called more often.

I also need to figure out what kind of scale makes sense for the buckets.  Milliseconds seems like overkill, seconds may be too coarse.  I'll try it out and see how it goes.
Comment 3 Andrew McCreight [:mccr8] 2012-01-19 10:39:26 PST
Filed bug 719492 for telemetry for time in between GCs.
Comment 4 Andrew McCreight [:mccr8] 2012-01-19 11:12:19 PST
Created attachment 589919 [details] [diff] [review]
telemetry for time in between CCs

https://tbpl.mozilla.org/?tree=Try&rev=564690731b33
Comment 5 Andrew McCreight [:mccr8] 2012-01-19 13:27:16 PST
Comment on attachment 589919 [details] [diff] [review]
telemetry for time in between CCs

This patch computes the time from the end of the last CC to the start of the current one, and adds a new telemetry for it.  It reports the time in seconds, going up to two minutes.  It uses an exponential spread so the upper end of the range will get less fine-grained coverage, which is fine.  Linux and Linux64 look okay in my try run.  I manually compared the results from the error console to the individual computations, and they matched up, and I also checked that the telemetry in about:telemetry more or less matched up with the values I was computing.
Comment 6 Olli Pettay [:smaug] (vacation Aug 25-28) 2012-01-20 04:57:36 PST
Comment on attachment 589919 [details] [diff] [review]
telemetry for time in between CCs


>+  PRTime now = PR_Now();
>+
>+  if (sLastCCEndTime) {
>+    PRUint32 timeBetween = (PRUint32) double(start - sLastCCEndTime) / PR_USEC_PER_SEC;
Why double?
Wouldn't PRUint32(start - sLastCCEndTime) / PR_USEC_PER_SEC; work?
Comment 7 Andrew McCreight [:mccr8] 2012-01-20 09:46:32 PST
I wasn't sure how conversions from PRTime worked.  But yeah, I'll try that and make sure it still has sensible results.
Comment 8 Andrew McCreight [:mccr8] 2012-01-20 12:40:34 PST
Created attachment 590304 [details] [diff] [review]
telemetry for time in between CCs

Changed the cast as suggested.  Carrying forward bugs's r+.
Comment 9 Andrew McCreight [:mccr8] 2012-01-20 12:43:11 PST
https://hg.mozilla.org/integration/mozilla-inbound/rev/22f182db02de
Comment 10 Andrew McCreight [:mccr8] 2012-01-20 19:51:08 PST
https://hg.mozilla.org/mozilla-central/rev/22f182db02de
Comment 11 Andrew McCreight [:mccr8] 2012-01-22 14:03:59 PST
This has been around for a nightly or two now.  We run the cycle collector quite a bit.  Most of the time, when the CC runs, it has been 5-10 seconds since the last one.  There's also a tiny spike at 120 seconds (the max value), but that's only about 20% as often as when it has been 10 seconds since the last one.
Comment 12 (dormant account) 2012-01-23 09:23:36 PST
(In reply to Andrew McCreight [:mccr8] from comment #11)
> This has been around for a nightly or two now.  We run the cycle collector
> quite a bit.  Most of the time, when the CC runs, it has been 5-10 seconds
> since the last one.  There's also a tiny spike at 120 seconds (the max
> value), but that's only about 20% as often as when it has been 10 seconds
> since the last one.

file a bug? Also note that this is mostly the first 5-10min of browser uptime atm(still bad, but lots of pageloading is making things worse)

Note You need to log in before you can comment on or make changes to this bug.