Closed Bug 962576 Opened 10 years ago Closed 10 years ago

GenerationalGC: Report timing information for minor GCs


(Core :: JavaScript Engine, defect)

Not set





(Reporter: jonco, Assigned: jonco)


(Blocks 1 open bug)



(3 files, 1 obsolete file)

Attached patch time-minor-gcSplinter 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)
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+
Attached file minorgc-browser.txt (obsolete) —
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).
...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+
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)
Attached file minorgc.log
And here's the log from my browsing today.
Attachment #8364393 - Attachment is obsolete: true
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+
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla29
Blocks: 1507445
You need to log in before you can comment on or make changes to this bug.