1464986 - Add some debug logging code to the GC

Status: RESOLVED FIXED

(Core :: JavaScript: GC, enhancement, P3)

Description

[Paul Bone [:pbone]]

I'm adding some code to add more logging to the GC, for some common debugging problems.

Comment 1

[Paul Bone [:pbone]]

Attachment: Bug 1464986 (Part 1) - Rename Statistics::fp

Comment 2

[Paul Bone [:pbone]]

Attachment: Bug 1464986 (Part 2) - Add some debug logging to the GC

Comment 3

[Paul Bone [:pbone]]

Attachment: Bug 1464986 (Part 3) - Move some calls to GCTracer into AutoGCSlice

Comment 4

[Jon Coppeard (:jonco)]

Comment on attachment 8981397 [details] [diff] [review]
Bug 1464986 (Part 2) - Add some debug logging to the GC

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

::: js/src/gc/GC.cpp
@@ +6978,5 @@
>  AutoGCSlice::AutoGCSlice(JSRuntime* rt)
>    : runtime(rt)
>  {
> +    runtime->gc.stats().writeLogMessage(TimeStamp::Now(),
> +        "begin slice");

Can you move this to gcstats::AutoGCSlice?  I think that corresponds more closely to the concept of a GC slice (i.e. the time between the mutator calling into the collector and the collector returning to the mutator again).

Yes, it's confusing that there are two classes called AutoGCSlice.  I'll file a bug.

@@ +7076,5 @@
> +        budget.describe(budgetBuffer, 32);
> +        stats().writeLogMessage(TimeStamp::Now(),
> +            "Incremental: %d, useZeal: %d, budget: %s",
> +            bool(isIncremental), bool(useZeal), budgetBuffer);
> +    }

Please make this block #ifdef DEBUG.

@@ +7632,5 @@
>      if (!checkIfGCAllowedInCurrentState(reason))
>          return;
>  
> +    stats().writeLogMessage(TimeStamp::Now(),
> +        "GCRuntime::collect() called, gc in progress: %s",

I'd prefer more meaningful messages like 'starting collector in state %s' but whatever works I guess.

@@ +7647,5 @@
>  
>          if (reason == JS::gcreason::ABORT_GC) {
>              MOZ_ASSERT(!isIncrementalGCInProgress());
> +            stats().writeLogMessage(TimeStamp::Now(),
> +                "GCRuntime::collect() ABORT_GC breaking loop");

Ditto, this should probably say 'GC aborted by request'.

::: js/src/gc/Statistics.cpp
@@ +114,5 @@
> +        file = stderr;
> +    } else {
> +        file = fopen(value, "a");
> +        if (!file)
> +            MOZ_CRASH("Failed to open MOZ_GCTIMER log file.");

This doesn't only refer to the MOZ_GCTIMER log any more.

@@ +582,5 @@
> +    va_list args;
> +    va_start(args, fmt);
> +
> +    if (gcDebugFile) {
> +        TimeDuration since_start = now - TimeStamp::ProcessCreation();

nit: should be |sinceStart|

::: js/src/gc/Statistics.h
@@ +269,5 @@
>      UniqueChars renderNurseryJson(JSRuntime* rt) const;
>  
> +#ifdef DEBUG
> +    // Print a logging message.
> +    void writeLogMessage(TimeStamp now, const char *fmt, ...);

Since this is always called with TimeStamp::Now(), can you remove this parameter and get the timestamp inside the function.

Comment 5

[Paul Bone [:pbone]]

I want to land Bug 1465062 first to make the changes this bug makes easier to follow.

Comment 6

[Paul Bone [:pbone]]

(In reply to Jon Coppeard (:jonco) from comment #4)
> Comment on attachment 8981397 [details] [diff] [review]
> Bug 1464986 (Part 2) - Add some debug logging to the GC
> 
> Review of attachment 8981397 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: js/src/gc/Statistics.h
> @@ +269,5 @@
> >      UniqueChars renderNurseryJson(JSRuntime* rt) const;
> >  
> > +#ifdef DEBUG
> > +    // Print a logging message.
> > +    void writeLogMessage(TimeStamp now, const char *fmt, ...);
> 
> Since this is always called with TimeStamp::Now(), can you remove this
> parameter and get the timestamp inside the function.

I've changed some other details so instead I'll add two versions of writeLogMessage and re-request review.

Comment 7

[Paul Bone [:pbone]]

Comment on attachment 8981398 [details] [diff] [review]
Bug 1464986 (Part 3) - Move some calls to GCTracer into AutoGCSlice

Changed my mind about this patch, I won't include it.

Comment 8

[Paul Bone [:pbone]]

Attachment: Bug 1464986 (Part 2) - Add some debug logging to the GC

Comment 9

[Jon Coppeard (:jonco)]

Comment on attachment 8981863 [details] [diff] [review]
Bug 1464986 (Part 2) - Add some debug logging to the GC

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

Thanks for the updates.

::: js/src/gc/Statistics.h
@@ +280,5 @@
> +    void writeLogMessageNow(const char* fmt, ...) { };
> +
> +  private:
> +    void writeLogMessageV(TimeStamp when, const char* fmt, va_list args) { };
> +#endif

I still don't see the need for supplying a timestamp.  It does't matter if the debug log timestamp doesn't exactly match the one we record in the statistics.  Keep it simple IMO...

Comment 10

[Paul Bone [:pbone]]

Oh, I can do that. I just wanted to avoid calculating the time more often than necessary.  But this is in debug builds so that's not so important.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/0fdd6e0d963f
(Part 1) - Rename Statistics::fp r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/52b867481d72
(Part 2) - Add some debug logging to the GC r=jonco

Comment 12

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/0fdd6e0d963f
https://hg.mozilla.org/mozilla-central/rev/52b867481d72