telemetry for time spent in between CCs

RESOLVED FIXED in mozilla12

Status

()

Core
DOM
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: mccr8, Assigned: mccr8)

Tracking

(Blocks: 1 bug)

Trunk
mozilla12
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [Snappy])

Attachments

(1 attachment, 1 obsolete attachment)

(Assignee)

Description

5 years ago
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.
(Assignee)

Comment 1

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

Detect, not cause...
(Assignee)

Comment 2

5 years ago
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.
(Assignee)

Comment 3

5 years ago
Filed bug 719492 for telemetry for time in between GCs.
Summary: telemetry for time not spent in CC or GC → telemetry for time spent in between CCs
(Assignee)

Comment 4

5 years ago
Created attachment 589919 [details] [diff] [review]
telemetry for time in between CCs

https://tbpl.mozilla.org/?tree=Try&rev=564690731b33
Assignee: nobody → continuation
(Assignee)

Comment 5

5 years ago
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.
Attachment #589919 - Flags: review?(bugs)

Comment 6

5 years ago
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?
Attachment #589919 - Flags: review?(bugs) → review+
(Assignee)

Comment 7

5 years ago
I wasn't sure how conversions from PRTime worked.  But yeah, I'll try that and make sure it still has sensible results.
(Assignee)

Comment 8

5 years ago
Created attachment 590304 [details] [diff] [review]
telemetry for time in between CCs

Changed the cast as suggested.  Carrying forward bugs's r+.
Attachment #589919 - Attachment is obsolete: true
Attachment #590304 - Flags: review+
(Assignee)

Comment 9

5 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/22f182db02de
(Assignee)

Comment 10

5 years ago
https://hg.mozilla.org/mozilla-central/rev/22f182db02de
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla12
(Assignee)

Comment 11

5 years ago
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

5 years ago
(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)
No longer blocks: 698919
Blocks: 698919
You need to log in before you can comment on or make changes to this bug.