962576 - GenerationalGC: Report timing information for minor GCs

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Jon Coppeard (:jonco)]

Attachment: time-minor-gc

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.

Comment 1

[Terrence Cole [:terrence]]

Comment on attachment 8363660 [details] [diff] [review]
time-minor-gc

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

r=me

::: 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.

Comment 2

[Jon Coppeard (:jonco)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/e6197abbed3a

Comment 3

[Jon Coppeard (:jonco)]

Fix warning:

https://hg.mozilla.org/integration/mozilla-inbound/rev/73d1c5429eaa

Comment 4

[Jon Coppeard (:jonco)]

Attachment: minorgc-browser.txt

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

[Jon Coppeard (:jonco)]

...and I've broken Windows GGC builds by including a header that doesn't exist there.

Comment 6

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e6197abbed3a
https://hg.mozilla.org/mozilla-central/rev/73d1c5429eaa

Comment 7

[Terrence Cole [:terrence]]

Comment on attachment 8364393 [details]
minorgc-browser.txt

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.

Comment 8

[Jon Coppeard (:jonco)]

Attachment: gc-profile-improvements

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

Comment 9

[Jon Coppeard (:jonco)]

Attachment: minorgc.log

And here's the log from my browsing today.

Comment 10

[Terrence Cole [:terrence]]

Comment on attachment 8365190 [details] [diff] [review]
gc-profile-improvements

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

Comment 11

[Jon Coppeard (:jonco)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ae1c853220e4

Comment 12

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/ae1c853220e4