1364547 - Test and tweak the GC statistics JSON output

Status: RESOLVED FIXED

(Core :: JavaScript: GC, enhancement)

Description

[Steve Fink [:sfink] [:s:]]

It's a big chunk of code, lightly tested, and it seems like there should be a better way to look into problems.

Comment 1

[Steve Fink [:sfink] [:s:]]

Attachment: Add shell testing functions to examine JSON generated for GC statistics

Ok, these are hokey, because the exact results depend on GC timing. And if you throw from within the callback, you'll probably end up in a weird state. Maybe it would be better to clear any exceptions?

Comment 2

[Steve Fink [:sfink] [:s:]]

Attachment: Add number of slices to major GC summary

Trivial addition that was useful when tracking down unexpected output from the test functions.

Comment 3

[Steve Fink [:sfink] [:s:]]

Attachment: Track nursery timings if profiling is enabled and do not report untracked timings for nursery collections

It's deceptive if you look at the nursery json, because MOZ_GECKO_PROFILER is not enabled (nor is JS_GC_PROFILE_NURSERY likely to be set), so the nursery doesn't track any timings other than an overall one.

So at the very least, we probably shouldn't report timings that we didn't collect.

But I'm hoping that the timings are cheap enough that we could enable them at least whenever we have an --enable-profiling build? Not so sure about that, but I'll send this r? to you to ask.

Comment 4

[Steve Fink [:sfink] [:s:]]

Attachment: Call the slice end callback for every slice

Here's the scary one.

Currently, the final slice of an incremental GC only gets a GC_CYCLE_END callback, not a GC_SLICE_END callback. So if you are doing anything that expects to see all of the slices, you will be missing one.

So I made it do a GC_SLICE_END callback for every slice, and additionally do a GC_CYLE_END for the overall GC. That means one more callback than we're currently doing. It seems simpler to me, but I'm a little worried this will confuse other callers, so feedback? mccr8.

Note that this doesn't add any additional information -- you *could* just handle the slice end in GC_CYCLE_END.

And maybe it would be better to make this change, but additionally suppress a slice end callback for a non-incremental GC? I'm not sure about that.

This patch is totally optional, I could instead change my test code to treat GC_CYCLE_END as having an implicit GC_SLICE_END within it.

Comment 5

[Steve Fink [:sfink] [:s:]]

Attachment: Add shell testing functions to examine JSON generated for GC statistics

Oops, forgot I meant to rename this.

Naming suggestions are welcome. "MajorJSON" is ugly.

Comment 6

[Andrew McCreight [:mccr8]]

Comment on attachment 8867323 [details] [diff] [review]
Call the slice end callback for every slice

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

I guess this is fine. DOMGCSliceCallback will end up creating and then destroying a timer but I don't think that's too terrible.

Comment 7

[Steve Fink [:sfink] [:s:]]

Comment on attachment 8867323 [details] [diff] [review]
Call the slice end callback for every slice

Whoops. Answering my own question: no, it is NOT ok to change GC_SLICE_END like this, because DOMGCSliceCallback() uses GC_SLICE_END to specifically mean "there's more work to be done, let's schedule another slice."

I'm assuming I should revert this change and fix my testing stuff to make GC_CYCLE_END imply GC_SLICE_END (for my purposes), but just in case mccr8 has an opinion about this, I'll leave the feedback flag on for now.

Comment 8

[Steve Fink [:sfink] [:s:]]

Attachment: Call the slice end callback for every slice

Oops, I missed mccr8's f+ comment. I agree, it looks like this would work fine, with the cost of an immediately-canceled timer.

Maybe I'll submit an optional followup patch to fix that.

Comment 9

[Jon Coppeard (:jonco)]

Comment on attachment 8867319 [details] [diff] [review]
Track nursery timings if profiling is enabled and do not report untracked timings for nursery collections

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

I agree we shouldn't report timings that we didn't collect.

But I don't understand what the MOZ_PROFILING change is about.  It seems that's about external profiling tools.  Why do we need to track times if that is defined?

Comment 10

[Jon Coppeard (:jonco)]

Comment on attachment 8867324 [details] [diff] [review]
Add shell testing functions to examine JSON generated for GC statistics

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

::: js/src/builtin/TestingFunctions.cpp
@@ +4973,5 @@
>  "    'majorGC' - run a major collection, nesting up to a given 'depth'\n"),
>  
> +    JS_FN_HELP("recordGCActivity", RecordGCActivity, 1, 0,
> +"recordGCActivity()",
> +"  Update properties on the global 'PriorGC' property to the GC statistics\n"

Which global does this this property get set on in a system with multiple zones?  Seems like it's the most recently entered one for the context at the time of GC.  That could be confusing.

(Also nitpicking about names: the property name should have 'stats' in it somewhere to make it clearer what it is and this function should be named similarly to associate them).

Comment 11

[Jon Coppeard (:jonco)]

Comment on attachment 8867370 [details] [diff] [review]
Call the slice end callback for every slice

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

I think this is much clearer and we should make this change.

You'll need to update the comment in the definition of GCProgress that explains the current system.

I think we should probably go further and make non-incremental GCs report like incremental GCs with a single slice.

Comment 12

[Steve Fink [:sfink] [:s:]]

(In reply to Jon Coppeard (:jonco) from comment #9)
> Comment on attachment 8867319 [details] [diff] [review]
> Track nursery timings if profiling is enabled and do not report untracked
> timings for nursery collections
> 
> Review of attachment 8867319 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I agree we shouldn't report timings that we didn't collect.
> 
> But I don't understand what the MOZ_PROFILING change is about.  It seems
> that's about external profiling tools.  Why do we need to track times if
> that is defined?

You're right, they're not necessarily related.

My concrete reason is that I wanted this code to be tested in nightly builds, so either the test harness needs to set JS_GC_PROFILE_NURSERY, or the timings should be enabled by default. (And MOZ_PROFILING is enabled in nightly by default.)

My abstract reason for why tying them together makes sense is that MOZ_PROFILING is meant to be enabled when you're looking into performance issues, and so you're willing to slow things down a little (eg use the frame pointer register) in order to get better information out. This seems to fit that description, assuming it doesn't add too much overhead. And I was planning on being lazy and letting awfy tell me that.

But if you'd rather, I can either time manually, or not do this and change the test harness instead. ni? you for that.

Comment 13

[Jon Coppeard (:jonco)]

(In reply to Steve Fink [:sfink] [:s:] from comment #12)
Oh OK.  I think if you want to enable this on nightly you should just use NIGHTLY_BUILD instead.  I doubt that this will add much overhead.

Comment 14

[Steve Fink [:sfink] [:s:]]

(In reply to Jon Coppeard (:jonco) from comment #10)
> Comment on attachment 8867324 [details] [diff] [review]
> Add shell testing functions to examine JSON generated for GC statistics
> 
> Review of attachment 8867324 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: js/src/builtin/TestingFunctions.cpp
> @@ +4973,5 @@
> >  "    'majorGC' - run a major collection, nesting up to a given 'depth'\n"),
> >  
> > +    JS_FN_HELP("recordGCActivity", RecordGCActivity, 1, 0,
> > +"recordGCActivity()",
> > +"  Update properties on the global 'PriorGC' property to the GC statistics\n"
> 
> Which global does this this property get set on in a system with multiple
> zones?  Seems like it's the most recently entered one for the context at the
> time of GC.  That could be confusing.

Yes, I avoided thinking too hard about this because I didn't really have a good answer, and I just wanted the information out in the basic case. It helped uncover a number of weirdnesses.

But you're right, the current behavior is pretty bizarre. Unfortunately, I can't think of a simple, straightforward way of fixing it.

The best I could come up with is storing the UniqueChars somewhere global -- the GCRuntime, maybe -- and then making accessors just grab the latest. Then it wouldn't matter which global called recordGCActivity; as soon as it was called, the information would be available anywhere (permanently).

I'm probably going to land the fixes that came out of this testing first, and only worry about fixing up the test setup if I find time.

> (Also nitpicking about names: the property name should have 'stats' in it
> somewhere to make it clearer what it is and this function should be named
> similarly to associate them).

You are right. s/recordGCActivity/recordGCStatistics/

Comment 15

[Steve Fink [:sfink] [:s:]]

Attachment: Call the slice end callback for every slice

Currently, the final slice of an incremental GC only gets a GC_CYCLE_END callback, not a GC_SLICE_END callback. So if you are doing anything that expects to see all of the slices, you will be missing one.

MozReview-Commit-ID: KZ6CICQ0Gcd

Comment 16

[Steve Fink [:sfink] [:s:]]

Attachment: Tell Gecko whether a slice is a final slice

Somewhat optional, but it bothered me to be doing unnecessary work here.

Comment 17

[Andrew McCreight [:mccr8]]

Comment on attachment 8867785 [details] [diff] [review]
Tell Gecko whether a slice is a final slice

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

This is nicer, thanks.

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/116478bef4d2
Add number of slices to major GC summary, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/e8724e8463cf
Call the slice end callback for every slice, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/973df75647b5
Tell Gecko whether a slice is a final slice, r=jonco,mccr8
https://hg.mozilla.org/integration/mozilla-inbound/rev/75c5e8d20bef
Do not report untracked timings for nursery collections, r=jonco

Comment 19

[Iris Hsiao [:ihsiao]]

https://hg.mozilla.org/mozilla-central/rev/116478bef4d2
https://hg.mozilla.org/mozilla-central/rev/e8724e8463cf
https://hg.mozilla.org/mozilla-central/rev/973df75647b5
https://hg.mozilla.org/mozilla-central/rev/75c5e8d20bef

Comment 20

[Landry Breuil (:gaston)]

https://hg.mozilla.org/mozilla-central/rev/116478bef4d2 doesn't build here (OpenBSD/amd64, clang 4.0):

13:35.48 /home/landry/src/m-c/js/src/gc/Statistics.cpp:584:10: error: call to member function 'property' is ambiguous                      13:35.48     json.property("slices", slices_.length());                                                                                    13:35.48     ~~~~~^~~~~~~~                                                                                                                 13:35.49 /home/landry/src/m-c/js/src/vm/JSONPrinter.h:50:10: note: candidate function                                                      13:35.49     void property(const char* name, int32_t value);                                                                               13:35.51          ^                                                                                                                        13:35.51 /home/landry/src/m-c/js/src/vm/JSONPrinter.h:51:10: note: candidate function                                                      13:35.51     void property(const char* name, uint32_t value);                                                                              13:35.51          ^                                                                                                                        13:35.51 /home/landry/src/m-c/js/src/vm/JSONPrinter.h:52:10: note: candidate function                                                      13:35.51     void property(const char* name, int64_t value);                                                                               13:35.51          ^                                                                                                                        13:35.51 /home/landry/src/m-c/js/src/vm/JSONPrinter.h:53:10: note: candidate function                                                      13:35.51     void property(const char* name, uint64_t value);                                                                              13:35.51          ^                                                                          
13:35.51 /home/landry/src/m-c/js/src/vm/JSONPrinter.h:49:10: note: candidate function not viable: no known conversion from 'size_t' (aka 'unsigned long') to 'const char *' for 2nd argument                        
13:35.51     void property(const char* name, const char* value);                                                                           13:35.51          ^                                                                                                                    
13:35.51 /home/landry/src/m-c/js/src/vm/JSONPrinter.h:66:10: note: candidate function not viable: requires 3 arguments, but 2 were provided13:35.51     void property(const char* name, const mozilla::TimeDuration& dur, TimePrecision precision);
13:35.51          ^

Comment 21

[Landry Breuil (:gaston)]

Adding an (uint64_t) cast works around it, but on OpenBSD size_t is an unsigned long. Dunno if that 'fix' is acceptable.

Comment 22

[Sebastien Marie [:semarie]]

Attachment: fix JSONPrinter::property(const char* name, size_t value) for OpenBSD

:landry the attached diff should fix the issue.

Code is already present for managing JSONPrinter::property(const char* name, size_t value), but it is guarded by #ifdef XP_DARWIN.

I just extended the guard to include OpenBSD.

Comment 23

[Landry Breuil (:gaston)]

Comment on attachment 8868960 [details] [diff] [review]
fix JSONPrinter::property(const char* name, size_t value) for OpenBSD

Indeed fixes the build issue for me, maybe i'd just amend the comment talking about OSX. :jonco, can this be taken as a followup or a new bug is needed ? (please $deity no.)

Comment 24

[Jon Coppeard (:jonco)]

Comment on attachment 8868960 [details] [diff] [review]
fix JSONPrinter::property(const char* name, size_t value) for OpenBSD

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

This seems fine, but please update the comment to mention OpenBSD.

Comment 25

[Landry Breuil (:gaston)]

Attachment: bug-1364547

Comment 26

[Landry Breuil (:gaston)]

Fixed the comment and formatted as a hg patch, setting c-n, carrying over r+ from :jonco on att #8868960

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1e7ca2f2bcb1
Followup to fix build on OpenBSD where size_t is an unsigned long (like OSX). r=jonco

Comment 28

[Steve Fink [:sfink] [:s:]]

Note that I took the easy way out with this size_t thing. I think the better fix would be something like

    class JSONPrinterBaseClassJustForTheDarnSizeTProblem {
      public:
        void property(const char* name, size_t value);
        ...everything that the above method requires...
    };

    class JSONPrinter : public JSONPrinterBaseClassJustForTheDarnSizeTProblem {
       ...all remaining functionality...
    };

I spent way too much time looking into this, and my conclusion is that the above should work, but by that time I was fed up and did the XP_DARWIN hack instead. (You could also put everything but the other property() definitions into the base class. Or perhaps put *only* the size_t overload into JSONPrinter; I don't think the order matters.)

But I guess what landed here is fine. At least until other systems hit this.

Comment 29

[Steve Fink [:sfink] [:s:]]

Comment on attachment 8867324 [details] [diff] [review]
Add shell testing functions to examine JSON generated for GC statistics

Clearing review because I don't think the patch is landable without fixing the which-global problem.

Comment 30

[Steve Fink [:sfink] [:s:]]

Comment on attachment 8867319 [details] [diff] [review]
Track nursery timings if profiling is enabled and do not report untracked timings for nursery collections

Moved to a different bug.

Comment 31

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/1e7ca2f2bcb1