697134 - [CC] Additional cycle collector timing telemetry

Status: RESOLVED WORKSFORME

(Core :: XPCOM, defect)

Description

[Andrew McCreight [:mccr8]]

I thought I'd filed a bug for this already, but it doesn't look like it.  There are more things I would like cycle collector telemetry for.

- How often does the CC force a GC?  This would be a boolean, and record at the start of each CC whether a GC was forced or not.  These are triggered by overflow while ungraying.

- Finer grained timing telemetry: how long does each phase of the CC take?  In local testing, building the graph dominates the CC time.  Occasionally freeing white nodes takes a measurable amount of time, too.  I could either time every phase (there are 4 or 5 total), or just those phases we expect to take a while.  I've also noticed in local testing that the total of the timing for the phases doesn't add up to the supposed total time of the CC, which is odd.

- Number of edge blocks.  We already compute this for about memory.  Number of node blocks isn't that interesting because we already know the total number of nodes.  This one is probably not that exciting.

Comment 2

[Andrew McCreight [:mccr8]]

Smaug, I was thinking of adding time for the graph building phase (MarkRoots) and the unlink phase (CollectWhite).  In my own profiling, these are the only CC phases that usually take any time at all.  Does that line up with what you wanted to measure?

Comment 3

[Olli Pettay [:smaug][[e-mail]]]

yes.

Comment 4

[Andrew McCreight [:mccr8]]

Attachment: add telemetry for CC-force GCs

If UnmarkGray overflows, then mark bits are bogus, and the CC may force a GC immediately before it runs.  This will be awful for pause times, so we should see how often this happens in practice to decide whether we need to improve the situation.

Comment 5

[Andrew McCreight [:mccr8]]

Attachment: clean up timers in cycle collector

In the CC, COLLECT_TIME_DEBUG uses PRTime, but the existing telemetry uses TimeStamp instead.  To simplify things a little, this patch mechanically replaces the remaining uses of PRTime with TimeStamp.  In addition, it removes a totally pointless NS_TIME_FUNCTION, puts a little more information into COLLECT_TIME_DEBUG logging, and removes two headers files that are no longer needed after the prior changes.

Comment 6

[Andrew McCreight [:mccr8]]

Attachment: part 3: add telemetry for CC graph building and freeing time

This adds the telemetry for timing how long building the CC graph and freeing things takes.  In my local experiments, these two phases constitute the bulk of CC time.  I reduced the bucket size here compared to the full CC timing.  If a CC is taking more than 2 seconds, it is fine to just let it count against 2 seconds, as that is already really awful.  I also reduced the number of buckets in half, because it had separate buckets for 3 and 4 ms, which seemed silly.

Comment 7

[Andrew McCreight [:mccr8]]

I've read that TimeStamp only has 10ms resolution on Windows, so I'm not sure if it is the right thing to use for measuring the various phases of the CC.

Comment 8

[Andrew McCreight [:mccr8]]

I spun off bug 706164 for the forced GC telemetry.

Comment 9

[Andrew McCreight [:mccr8]]

Attachment: crude CC time logging

In the wake of the landing of Smaug's CC improvements, I thought I'd check out where we are spending out time.  There's currently COLLECT_TIME_DEBUG, but it isn't very thorough.  This new patch makes COLLECT_TIME_DEBUG cover everything that should take any time, and also splits CollectWhite into separate categories, so we can tell where the time is going there.  For now, this is implemented with hacky macros, but I should make it into a nice class, hook it into telemetry or something, etc., but this is interesting as is.

Comment 10

[Andrew McCreight [:mccr8]]

This is what happens when you close that gigantic W3C HTML spec page:

cc: mRuntimes[*]->BeginCycleCollection() took 1ms
cc: SelectPurple() took 11ms
cc: MarkRoots() took 437ms
cc: ScanRoots() took 32ms
cc: 	CollectWhite::Root took 31ms
cc: 	CollectWhite::Unlink took 206ms
cc: 	CollectWhite::Unroot took 477ms
cc: CollectWhite() took 715ms
cc: ClearGraph() took 29ms
cc: total cycle collector time was 1241ms

This suggests that bug 652781 will help with pause times when we have a lot to free, but will not eliminate it entirely.

One thing that might help is to make the Traverse function for a DOM node could add every other node in the DOM that we think is alive.  That will avoid the virtual call overhead.  Which may or may matter much.  I'll do a shark run at some point.

Similarly, if we could somehow Unlink an entire DOM at once, using a DOM-side thing, maybe that would be faster.


Some other random large CCs I saw:

cc: PrepareForCollection() took 62ms
cc: mRuntimes[*]->BeginCycleCollection() took 1ms
cc: SelectPurple() took 59ms
cc: MarkRoots() took 7ms
cc: total cycle collector time was 159ms

cc: PrepareForCollection() took 29ms
cc: mRuntimes[*]->BeginCycleCollection() took 1ms
cc: MarkRoots() took 6ms
cc: ClearGraph() took 9ms
cc: total cycle collector time was 49ms

The only thing that PrepareForCollection does that should take any time is notify observers that the CC has begun.  I'm going to guess that most of the time in SelectPurple is calling CanSkipInCC.

It looks like ScanRoots (that actually colors the graph) is still not an issue.

Comment 11

[Andrew McCreight [:mccr8]]

I should say that the above large CCs are uncommon.  Most of the time (in the usual 35ms-50ms), MarkRoots still dominates the time.

cc: PrepareForCollection() took 3ms
cc: mRuntimes[*]->BeginCycleCollection() took 4ms
cc: MarkRoots() took 44ms
cc: ScanRoots() took 2ms
cc: total cycle collector time was 56ms

Comment 12

[Olli Pettay [:smaug][[e-mail]]]

Yeah, need to get the graph smaller.

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

One thing to try is to not add fully disconnected DOM trees to CC at all.
They can blast themselves into pieces during forgetSkippable.

Comment 14

[Andrew McCreight [:mccr8]]

Attachment: use a class instead of gross macros

Looks like I am reinventing NS_FUNCTION_TIMER here, so I should rework this patch to use that...

Comment 15

[Andrew McCreight [:mccr8]]

I ended up landing TimeLog over in bug 726374.  CC forcing GC telemetry has been in for a while.  I think that's the important stuff here, so I'll just close this.