1322560 - Add markers for Minor GC/Major GC

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[:Harald Kirschner :digitarald]

Just came up in the elective when I started filing that bug.

- Major GC
- Minor GC
- CC

More metadata in the markers about the reasons why the GC/CC was scheduled would be interesting if there is any.

Comment 1

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

We have this instrumentation for the devtools profiler -- its probably worth extending the devtools instrumentation classes to add Gecko Profiler markers as well to get all the devtools coverage for "free".

Actually only the minor gcs are timeline markers: http://searchfox.org/mozilla-central/rev/594937fec2e2fc45fa9308ba2fb964816631f017/xpcom/base/CycleCollectedJSContext.cpp#835

The major gc slices come from the Debugger.Memory#onGarbageCollection event.

We used to have a marker for cycle collection too, but I can't find it now, so I don't know if it was ripped out or what.

Comment 2

[:Harald Kirschner :digitarald]

There is a general theme here to add profile markers to all places where devtools profiler creates them.

Cycle collection seems to be marked by https://dxr.mozilla.org/mozilla-central/source/xpcom/base/nsCycleCollector.cpp#3626 . All GC-related markers seem to use different mark mechanisms.

Comment 3

[Markus Stange [:mstange]]

I looked into this a bit. MinorGC and cycle collection are easy, because we have timeline markers for them, and it's easy to write a patch that just inserts profiler tracing markers for all timeline markers.

MajorGC is trickier because it's currently exposed through an API that doesn't lend itself well to putting a JSON string into the profile. GarbageCollectionEvent::toJSObject exposes the information it gathered about GCs by creating JS objects inside the JSRuntime that you observe; it doesn't expose the data in any other way.
Maybe we should add GarbageCollectionEvent::toJSONString. Or maybe the caller should just use the JSRuntime's JSON.stringify function to go from the JS objects to the string that it wants.

Comment 4

[:Harald Kirschner :digitarald]

Steve mentioned he was working on something.

Comment 5

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

Attachment: Inject detailed GC timing info into profiles

Yeah, I should really be marking the dependencies here. Currently, this deadlocks.

Comment 6

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

My patch is adding some pretty detailed information into the profile. It may be that we need a lighter-weight option as well, depending on how heavy these things end up.

Comment 7

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

Attachment: Inject detailed GC timing info into profiles

Ok, this had better make it into the bug this time...

Comment 8

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

Attachment: Add APIs for retrieving major GC timing info

Trimming down to just SM portion.

Comment 9

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

Attachment: Inject detailed GC timing info into profiles

Only the major GC info for now.

Comment 10

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

Attachment: Report GC major/minor numbers in JSON

It seems useful to inject the GC counters, because in the profiler you'll end up finding these markers by looking at a given stack, and you might look at a later stack that's still in GC and have a straightforward way of knowing it's the same GC, the next GC, or that there have been a whole bunch of intervening GCs that were fast enough to not show up.

Comment 11

[Markus Stange [:mstange]]

Comment on attachment 8862154 [details] [diff] [review]
Inject detailed GC timing info into profiles

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

::: tools/profiler/core/ProfilerMarkers.cpp
@@ +247,5 @@
> +{
> +  MOZ_ASSERT(mTimingJSON);
> +  streamCommonProps("GCSlice", aWriter, aStartTime, aUniqueStacks);
> +  if (mTimingJSON) {
> +    aWriter.StringProperty("timings", mTimingJSON.get());

I've recently tried to stamp out all instances of "JSON strings inside JSON" in the profile format. I'd prefer not to add any new ones.

Can you add a public JSONWriter::JSONProperty method that just forwards to JSONWriter::Scalar?

Comment 12

[Markus Stange [:mstange]]

Or maybe that method should be on SpliceableJSONWriter and be called SplicedJSONProperty.

Comment 13

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

Comment on attachment 8862153 [details] [diff] [review]
Add APIs for retrieving major GC timing info

Argh. I forgot that bzexport doesn't handle |hg split| very well. This got obsoleted by the other half.

Comment 14

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

Attachment: Inject detailed GC timing info into profiles

Ok. I'm not sure I understand the "Spliced" prefix on SplicedJSONProperty (unless this is a different "spliced" from the "spliceable" in the class name?). But I won't worry about it.

Comment 15

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

Attachment: Refactor js::jit::JSONPrinter -> js::JSONPrinter

Move this to a shared location.

Also changed to an overload-happy interface. I may regret that decision, since now I've discovered mfbt/JSONWriter.h, but for now this is different enough that I just want to do a simple refactoring.

Comment 16

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

Attachment: Implement TimeDuration property in JSONPrinter

Implement the %llu.%03llu nastiness in JSONPrinter.

Comment 17

[Markus Stange [:mstange]]

Comment on attachment 8862183 [details] [diff] [review]
Inject detailed GC timing info into profiles

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

::: tools/profiler/core/ProfileJSONWriter.h
@@ +101,5 @@
>  
>    void Splice(const ChunkedJSONWriteFunc* aFunc);
>    void Splice(const char* aStr);
>  
> +  void SplicedJSONProperty(const char* aMaybePropertyName,

My thought with the "Spliced" prefix was: The only other functions that allow you to insert a string as-is into the JSON are called "Splice" and "TakeAndSplice". This one does something similar but as a property.

@@ +104,5 @@
>  
> +  void SplicedJSONProperty(const char* aMaybePropertyName,
> +                           const char* aStringValue)
> +  {
> +      Scalar(aMaybePropertyName, aStringValue);

This file has two-space indent.

Comment 18

[Jon Coppeard (:jonco)]

Comment on attachment 8862153 [details] [diff] [review]
Add APIs for retrieving major GC timing info

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

Sorry for all the nitpicky comments; this is basically all good.

::: js/public/GCAPI.h
@@ +350,5 @@
> +    mozilla::TimeStamp endTime(JSContext* cx) const;
> +    mozilla::TimeStamp lastSliceStart(JSContext* cx) const;
> +    mozilla::TimeStamp lastSliceEnd(JSContext* cx) const;
> +    JS::UniqueChars sliceToJSON(JSContext* cx) const;
> +    JS::UniqueChars gcToJSON(JSContext* cx) const;

Can we name these to make it clear which of the new JSON-producing methods correspond to the string-producing methods above?

::: js/src/gc/Statistics.h
@@ +322,5 @@
>      typedef SliceDataVector::ConstRange SliceRange;
>  
>      SliceRange sliceRange() const { return slices.all(); }
>      size_t slicesLength() const { return slices.length(); }
> +    const SliceData& mostRecentSlice() const { return slices.back(); }

Would it be simpler just to expose slices, i.e. have |const SliceDataVector& slices() { return slices_; }|?

@@ +327,2 @@
>  
>      // Occasionally print header lines for profiling information.

This comment is now with the wrong method.

@@ +334,5 @@
> +    TimeStamp end() const {
> +        MOZ_ASSERT(phaseStartTimes[PHASE_GC_BEGIN]);
> +        MOZ_ASSERT(!slices.empty());
> +        return slices.back().end;
> +    }

start() and end() aren't symmetric - could start() return slices.front().start?

::: js/src/jsgc.cpp
@@ +7641,5 @@
> +
> +TimeStamp
> +JS::GCDescription::endTime(JSContext* cx) const
> +{
> +    return cx->runtime()->gc.stats().mostRecentSlice().end;

Should startTime and endTime call the start and end methods on gc.stats()?

Comment 19

[Jon Coppeard (:jonco)]

Comment on attachment 8862155 [details] [diff] [review]
Report GC major/minor numbers in JSON

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

Good idea.

Comment 20

[Jon Coppeard (:jonco)]

Comment on attachment 8862186 [details] [diff] [review]
Refactor js::jit::JSONPrinter -> js::JSONPrinter

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

Looks good.

::: js/src/vm/JSONPrinter.cpp
@@ +123,5 @@
>  void
> +JSONPrinter::property(const char* name, uint32_t value)
> +{
> +    propertyName(name);
> +    out_.printf("%u", value);

I guess for maximum portability you could make this use PRIu32.

Comment 21

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

Attachment: const-ify gc::Statistics API

Minor patch that I forgot to put up for review. I remember trying this earlier and running into problems. But it seems fine now.

Comment 22

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

Attachment: Implement TimeDuration property in JSONPrinter

This will be needed for replacing the JSON generation in Statistics.cpp.

Comment 23

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

Attachment: Convert GC statistics over to JSONPrinter

I will land all that earlier stuff separately, but here's the next chunk -- switch over to JSONPrinter. The code looks much nicer, though I really hate to drag in this jsdtoa stuff. If I wanted to sink even more time into this, I would hack mfbt's JSONWriter to accept a fallible allocator and move everything I need over into it. But for now, I just want to port these over, then start emitting JSON for nursery GCs.

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/86277c75f5f7
const-ify gc::Statistics API
https://hg.mozilla.org/integration/mozilla-inbound/rev/4dee851a0d45
Add APIs for retrieving major GC timing info
https://hg.mozilla.org/integration/mozilla-inbound/rev/5fe280e53d4f
Inject detailed GC timing info into profiles, r=mstange
https://hg.mozilla.org/integration/mozilla-inbound/rev/3b458dc06af4
Report GC major/minor numbers in JSON, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/9c91d92a0215
Refactor js::jit::JSONPrinter -> js::JSONPrinter, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/a8668eecdab4
Implement TimeDuration property in JSONPrinter
https://hg.mozilla.org/integration/mozilla-inbound/rev/2cd1662bcc5b
Convert GC statistics over to JSONPrinter

Comment 25

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/85d31cb54903
Backed out changeset 2cd1662bcc5b 
https://hg.mozilla.org/integration/mozilla-inbound/rev/8606077bfecc
Backed out changeset a8668eecdab4 
https://hg.mozilla.org/integration/mozilla-inbound/rev/1805d0a9e85b
Backed out changeset 9c91d92a0215 
https://hg.mozilla.org/integration/mozilla-inbound/rev/01017013edc7
Backed out changeset 3b458dc06af4 
https://hg.mozilla.org/integration/mozilla-inbound/rev/f36cff1ee55f
Backed out changeset 5fe280e53d4f 
https://hg.mozilla.org/integration/mozilla-inbound/rev/7bf6fa55b2c7
Backed out changeset 4dee851a0d45 
https://hg.mozilla.org/integration/mozilla-inbound/rev/f40f9adb88a6
Backed out changeset 86277c75f5f7 
https://hg.mozilla.org/integration/mozilla-inbound/rev/793cb1b17440
Backed out changeset 3ed8f64c76a5 on a CLOSED TREE for rebase bustage.

Comment 26

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

I was wrong. The error was actually in unconditionally using a DEBUG-only variable.

Comment 27

[Jon Coppeard (:jonco)]

Comment on attachment 8862945 [details] [diff] [review]
Convert GC statistics over to JSONPrinter

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

Thanks for doing this, this is so much nicer!

::: js/src/gc/Statistics.cpp
@@ +750,5 @@
>  
>  UniqueChars
>  FilterJsonKey(const char*const buffer)
>  {
>      char* mut = strdup(buffer);

Existing, but should check for OOM here.

::: js/src/gc/Statistics.h
@@ +449,5 @@
>      UniqueChars formatDetailedSliceDescription(unsigned i, const SliceData& slice) const;
>      UniqueChars formatDetailedPhaseTimes(const PhaseTimeTable& phaseTimes) const;
>      UniqueChars formatDetailedTotals() const;
>  
> +    void formatJsonDescription(uint64_t timestamp, JSONPrinter&) const;

nit: I think the style guide says to always name arguments, even though here it's self-explanatory.

::: js/src/vm/JSONPrinter.cpp
@@ +150,5 @@
> +JSONPrinter::floatProperty(const char* name, double value, size_t precision)
> +{
> +    if (!mozilla::IsFinite(value)) {
> +        propertyName(name);
> +        out_.printf("null");

TIL JSON doesn't let you say NaN.

Comment 28

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

Comment on attachment 8862945 [details] [diff] [review]
Convert GC statistics over to JSONPrinter

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

::: js/src/gc/Statistics.cpp
@@ +750,5 @@
>  
>  UniqueChars
>  FilterJsonKey(const char*const buffer)
>  {
>      char* mut = strdup(buffer);

Nice catch. Handling this required me to add a way to tell the JSONPrinter that we hit OOM (normally it only figures that out internally and nerfs itself.) And this function should be static, and should have a different name. I called it SanitizeJsonKey. Forgive my z's.

Comment 29

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

Attachment: Record minor GC timings in profiles

I know this isn't pretty.

Comment 30

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

Attachment: Record minor GC timings in profiles

Oops, sorry. This version has some small changes in CycleCollectedJSRuntime.cpp so that it now compiles.

Comment 31

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

Comment on attachment 8863952 [details] [diff] [review]
Record minor GC timings in profiles

Ugh, sorry, cancelling review for now. It all seems to work fine, except that everything but the total time is zero in all of the minor GCs I looked at. I am suspicious.

Comment 32

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

Attachment: Record minor GC timings in profiles

Ah. The nursery doesn't track timings unless it's going to be printing them out. I'll split that into a separate patch.

Comment 33

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

Attachment: Track nursery timings if the Gecko profiler is compiled in

I'm assuming the timings are pretty cheap. If not, I guess I could check whether the profiler is currently active or not.

Comment 34

[Jon Coppeard (:jonco)]

Comment on attachment 8864132 [details] [diff] [review]
Record minor GC timings in profiles

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

r=me for the SM parts.

::: js/src/gc/Statistics.cpp
@@ +665,5 @@
> +    Sprinter printer(nullptr, false);
> +    if (!printer.init())
> +        return UniqueChars(nullptr);
> +    JSONPrinter json(printer);
> +    gcrt->nursery().renderProfileJSON(json);

Do we need to pass GCRuntime?  I think we can use runtime->gc here.

Comment 35

[Jon Coppeard (:jonco)]

Comment on attachment 8864133 [details] [diff] [review]
Track nursery timings if the Gecko profiler is compiled in

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

This is OK but possibly we should have a method trackTimings()

Comment 36

[Andrew McCreight [:mccr8]]

Comment on attachment 8864132 [details] [diff] [review]
Record minor GC timings in profiles

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

r=me for the XPCOM changes. Please get somebody to review the profiler changes.

::: xpcom/base/CycleCollectedJSRuntime.cpp
@@ +925,5 @@
> +#ifdef MOZ_GECKO_PROFILER
> +  if (aProgress == JS::GCNurseryProgress::GC_NURSERY_COLLECTION_START) {
> +    self->mLatestNurseryCollectionStart = TimeStamp::Now();
> +  }
> +  if ((aProgress == JS::GCNurseryProgress::GC_NURSERY_COLLECTION_END) && profiler_is_active()) {

maybe use an else here?

Comment 37

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

Comment on attachment 8864132 [details] [diff] [review]
Record minor GC timings in profiles

r?mstange for the profiler changes.

Comment 38

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/aaf50fe1a70a
const-ify gc::Statistics API, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/10285754c730
Add APIs for retrieving major GC timing info, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/833cb8125ee5
Inject detailed GC timing info into profiles, r=mstange
https://hg.mozilla.org/integration/mozilla-inbound/rev/96b92dca99df
Report GC major/minor numbers in JSON, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/2a6fdddce069
Refactor js::jit::JSONPrinter -> js::JSONPrinter, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/f6799d715258
Implement TimeDuration property in JSONPrinter, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/aec8e4eeac44
Convert GC statistics over to JSONPrinter, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/8578fa3a14d6
Use %*s for padding rather than hardcoded indents, r=me
https://hg.mozilla.org/integration/mozilla-inbound/rev/004f776b242e
Record minor GC timings in profiles, r=jonco, mccr8, mstange
https://hg.mozilla.org/integration/mozilla-inbound/rev/8a952848e55f
Track nursery timings if the Gecko profiler is compiled in, r=jonco

Comment 39

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

https://hg.mozilla.org/mozilla-central/rev/aaf50fe1a70a
https://hg.mozilla.org/mozilla-central/rev/10285754c730
https://hg.mozilla.org/mozilla-central/rev/833cb8125ee5
https://hg.mozilla.org/mozilla-central/rev/96b92dca99df
https://hg.mozilla.org/mozilla-central/rev/2a6fdddce069
https://hg.mozilla.org/mozilla-central/rev/f6799d715258
https://hg.mozilla.org/mozilla-central/rev/aec8e4eeac44
https://hg.mozilla.org/mozilla-central/rev/8578fa3a14d6
https://hg.mozilla.org/mozilla-central/rev/004f776b242e
https://hg.mozilla.org/mozilla-central/rev/8a952848e55f

Comment 40

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

Only GC markers landed in this bug.

Comment 41

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

Filed bug 1370377 for CC.