GenerationalGC: Report timing information for minor GCs

RESOLVED FIXED in mozilla29



5 years ago
5 years ago


(Reporter: jonco, Assigned: jonco)


(Blocks: 1 bug)


Firefox Tracking Flags

(Not tracked)



(3 attachments, 1 obsolete attachment)



5 years ago
Created attachment 8363660 [details] [diff] [review]

Here's a patch that adds a way to print out timing information for minor GCs.

If the environment variable JS_MINORGC_TIME is set, it specifies a time threshold in microseconds, and and minor GC taking longer than this has its timing information printed to stderr.

It's unconditionally built at the moment, but eventually this will be removed or at least hidden behind some kind of way.
Attachment #8363660 - Flags: review?(terrence)


5 years ago
Blocks: 875863
Comment on attachment 8363660 [details] [diff] [review]

Review of attachment 8363660 [details] [diff] [review]:


::: js/src/gc/Nursery.cpp
@@ +34,4 @@
>  using namespace js;
>  using namespace gc;
>  using namespace mozilla;

I think we should add |//#define PROFILE_NURSERY| and guard the various new bits. We'll have to remove the comment, and rebuild when we want to profile, but that's not a huge cost.

@@ +639,5 @@
>  }
> +#define TIME_START(name) int64_t timstampStart_##name = PRMJ_Now()
> +#define TIME_END(name) int64_t timstampEnd_##name = PRMJ_Now()
> +#define TIME_TOTAL(name) (timstampEnd_##name - timstampStart_##name)

And we can just give these empty definition if !defined PROFILE_NURSERY to keep from cluttering the algorithm.
Attachment #8363660 - Flags: review?(terrence) → review+

Comment 4

5 years ago
Created attachment 8364393 [details]

Here's the results I've collected today while running a GGC browser with the threshold set to 1ms (it's a linux64 opt build).

Comment 5

5 years ago
...and I've broken Windows GGC builds by including a header that doesn't exist there.
Whiteboard: [leave open]
Comment on attachment 8364393 [details]

Great work! I see two obvious problems here.

First, our store buffer marking times are higher than I'd expect -- I'd think they'd be way lower than CTFP, although I guess it depends. Jandem made basically everything there inline nicely and we may need to do something similar here. We should first split the timing up by store buffer type to see where the problem cases are exactly. If we're lucky it will be a GenericBuffer entry that we aren't checking before insertion.

More easily addressed, sweep times of .5ms are insane. That has to be either LifoAlloc freeing or, more likely, traversing and freeing external slots. We should check which and then take some metrics to find out how long typical external slots are. I set the initial MaxNurserySlots value to 100 as a total whatev's with the intention of profiling later. It seems that now is later.

Also, I missed it in my review, but we should really add the GC reason to this chart.
Attachment #8364393 - Flags: feedback+

Comment 8

5 years ago
Created attachment 8365190 [details] [diff] [review]

Here's a patch to add the following:
 - report GC reason, promotion rate and nursery size in chunks
 - break store buffer marking in separate phases
 - break sweeping into separate phases
Attachment #8365190 - Flags: review?(terrence)

Comment 9

5 years ago
Created attachment 8365193 [details]

And here's the log from my browsing today.
Attachment #8364393 - Attachment is obsolete: true


5 years ago
Attachment #8365193 - Attachment mime type: text/x-log → text/plain
Comment on attachment 8365190 [details] [diff] [review]

Review of attachment 8365190 [details] [diff] [review]:

Please also make ExplainReason in gc/Statistics.cpp non-static and use it to get human-readable string for the reason. r=me
Attachment #8365190 - Flags: review?(terrence) → review+
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla29
You need to log in before you can comment on or make changes to this bug.