717711 - telemetry for time spent in between CCs

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Andrew McCreight [:mccr8]]

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]]

> This will hopefully cause future GC/CC scheduling regressions.

Detect, not cause...

Comment 2

[Andrew McCreight [:mccr8]]

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]]

Filed bug 719492 for telemetry for time in between GCs.

Comment 4

[Andrew McCreight [:mccr8]]

Attachment: telemetry for time in between CCs

https://tbpl.mozilla.org/?tree=Try&rev=564690731b33

Comment 5

[Andrew McCreight [:mccr8]]

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][[e-mail]]]

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]]

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]]

Attachment: telemetry for time in between CCs

Changed the cast as suggested.  Carrying forward bugs's r+.

Comment 9

[Andrew McCreight [:mccr8]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/22f182db02de

Comment 10

[Andrew McCreight [:mccr8]]

https://hg.mozilla.org/mozilla-central/rev/22f182db02de

Comment 11

[Andrew McCreight [:mccr8]]

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)]

(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)