Bug 531396 - Expose detailed GC timing information API; r=smaug,billm

Extensions such as MemChaser would really like an easier to parse and more
complete record of GC events than what can be gleaned from the message console.
This patch adds GC and CC observer messages formatted as JSON containing
detailed statistics.

dom/base/nsJSEnvironment.cpp

@@ -3161,6 +3161,44 @@ nsJSContext::CycleCollectNow(nsICycleCollectorListener *aListener,
     if (cs) {
       cs->LogStringMessage(msg.get());
     }
+
+    NS_NAMED_MULTILINE_LITERAL_STRING(kJSONFmt,
+      NS_LL("{ \"duration\": %llu, ")
+         NS_LL("\"suspected\": %lu, ")
+         NS_LL("\"visited\": { ")
+             NS_LL("\"RCed\": %lu, ")
+             NS_LL("\"GCed\": %lu }, ")
+         NS_LL("\"collected\": { ")
+             NS_LL("\"RCed\": %lu, ")
+             NS_LL("\"GCed\": %lu }, ")
+         NS_LL("\"waiting_for_gc\": %lu, ")
+         NS_LL("\"forced_gc\": %d, ")
+         NS_LL("\"forget_skippable\": { ")
+             NS_LL("\"times_before_cc\": %lu, ")
+             NS_LL("\"min\": %lu, ")
+             NS_LL("\"max\": %lu, ")
+             NS_LL("\"avg\": %lu, ")
+             NS_LL("\"total\": %lu, ")
+             NS_LL("\"removed\": %lu } ")
+       NS_LL("}"));
+    nsString json;
+    json.Adopt(nsTextFormatter::smprintf(kJSONFmt.get(),
+                                        (now - start) / PR_USEC_PER_MSEC, suspected,
+                                        ccResults.mVisitedRefCounted, ccResults.mVisitedGCed,
+                                        ccResults.mFreedRefCounted, ccResults.mFreedGCed,
+                                        sCCollectedWaitingForGC,
+                                        ccResults.mForcedGC,
+                                        sForgetSkippableBeforeCC,
+                                        sMinForgetSkippableTime / PR_USEC_PER_MSEC,
+                                        sMaxForgetSkippableTime / PR_USEC_PER_MSEC,
+                                        (sTotalForgetSkippableTime / cleanups) /
+                                          PR_USEC_PER_MSEC,
+                                        sTotalForgetSkippableTime / PR_USEC_PER_MSEC,
+                                        sRemovedPurples));
+    nsCOMPtr<nsIObserverService> observerService = mozilla::services::GetObserverService();
+    if (observerService) {
+      observerService->NotifyObservers(nsnull, "cycle-collection-statistics", json.get());
+    }
   }
   sMinForgetSkippableTime = PR_UINT32_MAX;
   sMaxForgetSkippableTime = 0;
@@ -3417,12 +3455,39 @@ nsJSContext::GC(js::gcreason::Reason aReason)
   PokeGC(aReason);
 }
 
+class NotifyGCEndRunnable : public nsRunnable
+{
+  nsString mMessage;
+
+public:
+  NotifyGCEndRunnable(const nsString& aMessage) : mMessage(aMessage) {}
+
+  NS_DECL_NSIRUNNABLE
+};
+
+NS_IMETHODIMP
+NotifyGCEndRunnable::Run()
+{
+  MOZ_ASSERT(NS_IsMainThread());
+
+  nsCOMPtr<nsIObserverService> observerService = mozilla::services::GetObserverService();
+  if (!observerService) {
+    return NS_OK;
+  }
+
+  const jschar oomMsg[3] = { '{', '}', 0 };
+  const jschar *toSend = mMessage.get() ? mMessage.get() : oomMsg;
+  observerService->NotifyObservers(nsnull, "garbage-collection-statistics", toSend);
+
+  return NS_OK;
+}
+
 static void
 DOMGCSliceCallback(JSRuntime *aRt, js::GCProgress aProgress, const js::GCDescription &aDesc)
 {
   NS_ASSERTION(NS_IsMainThread(), "GCs must run on the main thread");
 
-  if (aDesc.logMessage && sPostGCEventsToConsole) {
+  if (aProgress == js::GC_CYCLE_END && sPostGCEventsToConsole) {
     PRTime now = PR_Now();
     PRTime delta = 0;
     if (sFirstCollectionTime) {
@@ -3432,10 +3497,11 @@ DOMGCSliceCallback(JSRuntime *aRt, js::GCProgress aProgress, const js::GCDescrip
     }
 
     NS_NAMED_LITERAL_STRING(kFmt, "GC(T+%.1f) %s");
-    nsString msg;
+    nsString msg, gcstats;
+    gcstats.Adopt(aDesc.formatMessage(aRt));
     msg.Adopt(nsTextFormatter::smprintf(kFmt.get(),
                                         double(delta) / PR_USEC_PER_SEC,
-                                        aDesc.logMessage));
+                                        gcstats.get()));
     nsCOMPtr<nsIConsoleService> cs = do_GetService(NS_CONSOLESERVICE_CONTRACTID);
     if (cs) {
       cs->LogStringMessage(msg.get());
@@ -3463,6 +3529,11 @@ DOMGCSliceCallback(JSRuntime *aRt, js::GCProgress aProgress, const js::GCDescrip
     sCCollectedWaitingForGC = 0;
     sCleanupSinceLastGC = false;
 
+    nsString json;
+    json.Adopt(aDesc.formatJSON(aRt));
+    nsRefPtr<NotifyGCEndRunnable> notify = new NotifyGCEndRunnable(json);
+    NS_DispatchToMainThread(notify);
+
     if (aDesc.isCompartment) {
       // If this is a compartment GC, restart it. We still want
       // a full GC to happen. Compartment GCs usually happen as a

js/src/gc/Statistics.cpp

@@ -54,6 +54,210 @@
 namespace js {
 namespace gcstats {
 
+/* Except for the first and last, slices of less than 12ms are not reported. */
+static const int64_t SLICE_MIN_REPORT_TIME = 12 * PRMJ_USEC_PER_MSEC;
+
+class StatisticsSerializer
+{
+    typedef Vector<char, 128, SystemAllocPolicy> CharBuffer;
+    CharBuffer buf_;
+    bool asJSON_;
+    bool needComma_;
+    bool oom_;
+
+    const static int MaxFieldValueLength = 128;
+
+  public:
+    enum Mode {
+        AsJSON = true,
+        AsText = false
+    };
+
+    StatisticsSerializer(Mode asJSON)
+      : buf_(), asJSON_(asJSON), needComma_(false), oom_(false)
+    {}
+
+    bool isJSON() { return asJSON_; }
+
+    bool isOOM() { return oom_; }
+
+    void endLine() {
+        if (!asJSON_) {
+            p("\n");
+            needComma_ = false;
+        }
+    }
+
+    void extra(const char *str) {
+        if (!asJSON_) {
+            needComma_ = false;
+            p(str);
+        }
+    }
+
+    void appendString(const char *name, const char *value) {
+        put(name, value, "", true);
+    }
+
+    void appendNumber(const char *name, const char *vfmt, const char *units, ...) {
+        va_list va;
+        va_start(va, units);
+        append(name, vfmt, va, units);
+        va_end(va);
+    }
+
+    void appendIfNonzeroMS(const char *name, double v) {
+        if (asJSON_ || v)
+            appendNumber(name, "%.1f", "ms", v);
+    }
+
+    void beginObject(const char *name) {
+        if (needComma_)
+            pJSON(", ");
+        if (asJSON_ && name) {
+            putQuoted(name);
+            pJSON(": ");
+        }
+        pJSON("{");
+        needComma_ = false;
+    }
+
+    void endObject() {
+        needComma_ = false;
+        pJSON("}");
+        needComma_ = true;
+    }
+
+    void beginArray(const char *name) {
+        if (needComma_)
+            pJSON(", ");
+        if (asJSON_)
+            putQuoted(name);
+        pJSON(": [");
+        needComma_ = false;
+    }
+
+    void endArray() {
+        needComma_ = false;
+        pJSON("]");
+        needComma_ = true;
+    }
+
+    jschar *finishJSString() {
+        char *buf = finishCString();
+        if (!buf)
+            return NULL;
+
+        size_t nchars = strlen(buf);
+        jschar *out = (jschar *)js_malloc(sizeof(jschar) * (nchars + 1));
+        if (!out) {
+            oom_ = true;
+            js_free(buf);
+            return NULL;
+        }
+
+        size_t outlen = nchars;
+        bool ok = InflateStringToBuffer(NULL, buf, nchars, out, &outlen);
+        js_free(buf);
+        if (!ok) {
+            oom_ = true;
+            js_free(out);
+            return NULL;
+        }
+        out[nchars] = 0;
+
+        return out;
+    }
+
+    char *finishCString() {
+        if (oom_)
+            return NULL;
+
+        buf_.append('\0');
+
+        char *buf = buf_.extractRawBuffer();
+        if (!buf)
+            oom_ = true;
+
+        return buf;
+    }
+
+  private:
+    void append(const char *name, const char *vfmt,
+                va_list va, const char *units)
+    {
+        char val[MaxFieldValueLength];
+        JS_vsnprintf(val, MaxFieldValueLength, vfmt, va);
+        put(name, val, units, false);
+    }
+
+    void p(const char *cstr) {
+        if (oom_)
+            return;
+
+        if (!buf_.append(cstr, strlen(cstr)))
+            oom_ = true;
+    }
+
+    void p(const char c) {
+        if (oom_)
+            return;
+
+        if (!buf_.append(c))
+            oom_ = true;
+    }
+
+    void pJSON(const char *str) {
+        if (asJSON_)
+            p(str);
+    }
+
+    void put(const char *name, const char *val, const char *units, bool valueIsQuoted) {
+        if (needComma_)
+            p(", ");
+        needComma_ = true;
+
+        putKey(name);
+        p(": ");
+        if (valueIsQuoted)
+            putQuoted(val);
+        else
+            p(val);
+        if (!asJSON_)
+            p(units);
+    }
+
+    void putQuoted(const char *str) {
+        pJSON("\"");
+        p(str);
+        pJSON("\"");
+    }
+
+    void putKey(const char *str) {
+        if (!asJSON_) {
+            p(str);
+            return;
+        }
+
+        p("\"");
+        const char *c = str;
+        while (*c) {
+            if (*c == ' ' || *c == '\t')
+                p('_');
+            else if (isupper(*c))
+                p(tolower(*c));
+            else if (*c == '+')
+                p("added_");
+            else if (*c == '-')
+                p("removed_");
+            else if (*c != '(' && *c != ')')
+                p(*c);
+            c++;
+        }
+        p("\"");
+    }
+};
+
 static const char *
 ExplainReason(gcreason::Reason reason)
 {
@@ -70,57 +274,36 @@ ExplainReason(gcreason::Reason reason)
     }
 }
 
-void
+static double
-Statistics::fmt(const char *f, ...)
+t(int64_t t)
 {
-    va_list va;
+    return double(t) / PRMJ_USEC_PER_MSEC;
-    size_t off = strlen(buffer);
-
-    va_start(va, f);
-    JS_vsnprintf(buffer + off, BUFFER_SIZE - off, f, va);
-    va_end(va);
 }
 
-void
+static void
-Statistics::fmtIfNonzero(const char *name, double t)
+formatPhases(StatisticsSerializer &ss, const char *name, int64_t *times)
 {
-    if (t) {
+    ss.beginObject(name);
-        if (needComma)
+    ss.appendIfNonzeroMS("Mark", t(times[PHASE_MARK]));
-            fmt(", ");
+    ss.appendIfNonzeroMS("Mark Roots", t(times[PHASE_MARK_ROOTS]));
-        fmt("%s: %.1f", name, t);
+    ss.appendIfNonzeroMS("Mark Delayed", t(times[PHASE_MARK_DELAYED]));
-        needComma = true;
+    ss.appendIfNonzeroMS("Mark Other", t(times[PHASE_MARK_OTHER]));
-    }
+    ss.appendIfNonzeroMS("Sweep", t(times[PHASE_SWEEP]));
+    ss.appendIfNonzeroMS("Sweep Object", t(times[PHASE_SWEEP_OBJECT]));
+    ss.appendIfNonzeroMS("Sweep String", t(times[PHASE_SWEEP_STRING]));
+    ss.appendIfNonzeroMS("Sweep Script", t(times[PHASE_SWEEP_SCRIPT]));
+    ss.appendIfNonzeroMS("Sweep Shape", t(times[PHASE_SWEEP_SHAPE]));
+    ss.appendIfNonzeroMS("Discard Code", t(times[PHASE_DISCARD_CODE]));
+    ss.appendIfNonzeroMS("Discard Analysis", t(times[PHASE_DISCARD_ANALYSIS]));
+    ss.appendIfNonzeroMS("XPConnect", t(times[PHASE_XPCONNECT]));
+    ss.appendIfNonzeroMS("Deallocate", t(times[PHASE_DESTROY]));
+    ss.endObject();
 }
 
-void
+bool
-Statistics::formatPhases(int64_t *times)
+Statistics::formatData(StatisticsSerializer &ss)
 {
-    needComma = false;
-    fmtIfNonzero("mark", t(times[PHASE_MARK]));
-    fmtIfNonzero("mark-roots", t(times[PHASE_MARK_ROOTS]));
-    fmtIfNonzero("mark-delayed", t(times[PHASE_MARK_DELAYED]));
-    fmtIfNonzero("mark-other", t(times[PHASE_MARK_OTHER]));
-    fmtIfNonzero("sweep", t(times[PHASE_SWEEP]));
-    fmtIfNonzero("sweep-obj", t(times[PHASE_SWEEP_OBJECT]));
-    fmtIfNonzero("sweep-string", t(times[PHASE_SWEEP_STRING]));
-    fmtIfNonzero("sweep-script", t(times[PHASE_SWEEP_SCRIPT]));
-    fmtIfNonzero("sweep-shape", t(times[PHASE_SWEEP_SHAPE]));
-    fmtIfNonzero("discard-code", t(times[PHASE_DISCARD_CODE]));
-    fmtIfNonzero("discard-analysis", t(times[PHASE_DISCARD_ANALYSIS]));
-    fmtIfNonzero("xpconnect", t(times[PHASE_XPCONNECT]));
-    fmtIfNonzero("deallocate", t(times[PHASE_DESTROY]));
-}
-
-/* Except for the first and last, slices of less than 12ms are not reported. */
-static const int64_t SLICE_MIN_REPORT_TIME = 12 * PRMJ_USEC_PER_MSEC;
-
-const char *
-Statistics::formatData()
-{
-    buffer[0] = 0x00;
-
     int64_t total = 0, longest = 0;
-
     for (SliceData *slice = slices.begin(); slice != slices.end(); slice++) {
         total += slice->duration();
         if (slice->duration() > longest)
@@ -130,47 +313,70 @@ Statistics::formatData()
     double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
     double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
 
-    fmt("TotalTime: %.1fms, Type: %s", t(total), compartment ? "compartment" : "global");
+    ss.beginObject(NULL);
-    fmt(", MMU(20ms): %d%%, MMU(50ms): %d%%", int(mmu20 * 100), int(mmu50 * 100));
+    ss.appendNumber("Total Time", "%.1f", "ms", t(total));
-
+    ss.appendString("Type", compartment ? "compartment" : "global");
-    if (slices.length() > 1)
+    ss.appendNumber("MMU (20ms)", "%d", "%", int(mmu20 * 100));
-        fmt(", MaxPause: %.1f", t(longest));
+    ss.appendNumber("MMU (50ms)", "%d", "%", int(mmu50 * 100));
+    if (slices.length() > 1 || ss.isJSON())
+        ss.appendNumber("Max Pause", "%.1f", "ms", t(longest));
     else
-        fmt(", Reason: %s", ExplainReason(slices[0].reason));
+        ss.appendString("Reason", ExplainReason(slices[0].reason));
+    if (nonincrementalReason || ss.isJSON()) {
+        ss.appendString("Nonincremental Reason",
+                        nonincrementalReason ? nonincrementalReason : "none");
+    }
+    ss.appendNumber("+Chunks", "%d", "", counts[STAT_NEW_CHUNK]);
+    ss.appendNumber("-Chunks", "%d", "", counts[STAT_DESTROY_CHUNK]);
+    ss.endLine();
 
-    if (nonincrementalReason)
+    if (slices.length() > 1 || ss.isJSON()) {
-        fmt(", NonIncrementalReason: %s", nonincrementalReason);
+        ss.beginArray("Slices");
-
-    fmt(", +chunks: %d, -chunks: %d\n", counts[STAT_NEW_CHUNK], counts[STAT_DESTROY_CHUNK]);
-
-    if (slices.length() > 1) {
         for (size_t i = 0; i < slices.length(); i++) {
             int64_t width = slices[i].duration();
             if (i != 0 && i != slices.length() - 1 && width < SLICE_MIN_REPORT_TIME &&
-                !slices[i].resetReason)
+                !slices[i].resetReason && !ss.isJSON())
             {
                 continue;
             }
 
-            fmt("    Slice %d @ %.1fms (Pause: %.1f, Reason: %s",
+            ss.beginObject(NULL);
-                i,
+            ss.extra("    ");
-                t(slices[i].end - slices[0].start),
+            ss.appendNumber("Slice", "%d", "", i);
-                t(width),
+            ss.appendNumber("Time", "%.1f", "ms", t(slices[i].end - slices[0].start));
-                ExplainReason(slices[i].reason));
+            ss.extra(" (");
+            ss.appendNumber("Pause", "%.1f", "", t(width));
+            ss.appendString("Reason", ExplainReason(slices[i].reason));
             if (slices[i].resetReason)
-                fmt(", Reset: %s", slices[i].resetReason);
+                ss.appendString("Reset", slices[i].resetReason);
-            fmt("): ");
+            ss.extra("): ");
-            formatPhases(slices[i].phaseTimes);
+            formatPhases(ss, "times", slices[i].phaseTimes);
-            fmt("\n");
+            ss.endLine();
+            ss.endObject();
         }
-
+        ss.endArray();
-        fmt("    Totals: ");
     }
+    ss.extra("    Totals: ");
+    formatPhases(ss, "totals", phaseTimes);
+    ss.endObject();
 
-    formatPhases(phaseTimes);
+    return !ss.isOOM();
-    fmt("\n");
+}
 
-    return buffer;
+jschar *
+Statistics::formatMessage()
+{
+    StatisticsSerializer ss(StatisticsSerializer::AsText);
+    formatData(ss);
+    return ss.finishJSString();
+}
+
+jschar *
+Statistics::formatJSON()
+{
+    StatisticsSerializer ss(StatisticsSerializer::AsJSON);
+    formatData(ss);
+    return ss.finishJSString();
 }
 
 Statistics::Statistics(JSRuntime *rt)
@@ -179,8 +385,7 @@ Statistics::Statistics(JSRuntime *rt)
     fp(NULL),
     fullFormat(false),
     compartment(NULL),
-    nonincrementalReason(NULL),
+    nonincrementalReason(NULL)
-    needComma(false)
 {
     PodArrayZero(phaseTotals);
     PodArrayZero(counts);
@@ -209,9 +414,13 @@ Statistics::~Statistics()
 {
     if (fp) {
         if (fullFormat) {
-            buffer[0] = 0x00;
+            StatisticsSerializer ss(StatisticsSerializer::AsText);
-            formatPhases(phaseTotals);
+            formatPhases(ss, "", phaseTotals);
-            fprintf(fp, "TOTALS\n%s\n\n-------\n", buffer);
+            char *msg = ss.finishCString();
+            if (msg) {
+                fprintf(fp, "TOTALS\n%s\n\n-------\n", msg);
+                js_free(msg);
+            }
         }
 
         if (fp != stdout && fp != stderr)
@@ -219,12 +428,6 @@ Statistics::~Statistics()
     }
 }
 
-double
-Statistics::t(int64_t t)
-{
-    return double(t) / PRMJ_USEC_PER_MSEC;
-}
-
 int64_t
 Statistics::gcDuration()
 {
@@ -235,9 +438,13 @@ void
 Statistics::printStats()
 {
     if (fullFormat) {
-        fprintf(fp, "GC(T+%.3fs) %s\n",
+        StatisticsSerializer ss(StatisticsSerializer::AsText);
-                t(slices[0].start - startupTime) / 1000.0,
+        formatData(ss);
-                formatData());
+        char *msg = ss.finishCString();
+        if (msg) {
+            fprintf(fp, "GC(T+%.3fs) %s\n", t(slices[0].start - startupTime) / 1000.0, msg);
+            js_free(msg);
+        }
     } else {
         fprintf(fp, "%f %f %f\n",
                 t(gcDuration()),
@@ -301,10 +508,8 @@ Statistics::beginSlice(JSCompartment *comp, gcreason::Reason reason)
     if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback)
         (*cb)(JS_TELEMETRY_GC_REASON, reason);
 
-    if (GCSliceCallback cb = runtime->gcSliceCallback) {
+    if (GCSliceCallback cb = runtime->gcSliceCallback)
-        GCDescription desc(NULL, !!compartment);
+        (*cb)(runtime, first ? GC_CYCLE_BEGIN : GC_SLICE_BEGIN, GCDescription(!!compartment));
-        (*cb)(runtime, first ? GC_CYCLE_BEGIN : GC_SLICE_BEGIN, desc);
-    }
 }
 
 void
@@ -323,9 +528,9 @@ Statistics::endSlice()
 
     if (GCSliceCallback cb = runtime->gcSliceCallback) {
         if (last)
-            (*cb)(runtime, GC_CYCLE_END, GCDescription(formatData(), !!compartment));
+            (*cb)(runtime, GC_CYCLE_END, GCDescription(!!compartment));
         else
-            (*cb)(runtime, GC_SLICE_END, GCDescription(NULL, !!compartment));
+            (*cb)(runtime, GC_SLICE_END, GCDescription(!!compartment));
     }
 }
 

js/src/gc/Statistics.h

@@ -76,7 +76,7 @@ enum Stat {
     STAT_LIMIT
 };
 
-static const size_t BUFFER_SIZE = 8192;
+class StatisticsSerializer;
 
 struct Statistics {
     Statistics(JSRuntime *rt);
@@ -96,6 +96,9 @@ struct Statistics {
         counts[s]++;
     }
 
+    jschar *formatMessage();
+    jschar *formatJSON();
+
   private:
     JSRuntime *runtime;
 
@@ -136,19 +139,12 @@ struct Statistics {
     /* Number of events of this type for this GC. */
     unsigned int counts[STAT_LIMIT];
 
-    char buffer[BUFFER_SIZE];
-    bool needComma;
-
     void beginGC();
     void endGC();
 
     int64_t gcDuration();
-    double t(int64_t t);
     void printStats();
-    void fmt(const char *f, ...);
+    bool formatData(StatisticsSerializer &ss);
-    void fmtIfNonzero(const char *name, double t);
-    void formatPhases(int64_t *times);
-    const char *formatData();
 
     double computeMMU(int64_t resolution);
 };

js/src/jsarray.cpp

@@ -120,7 +120,6 @@
 #include "jsnum.h"
 #include "jsobj.h"
 #include "jsscope.h"
-#include "jsstr.h"
 #include "jswrapper.h"
 #include "methodjit/MethodJIT.h"
 #include "methodjit/StubCalls.h"

js/src/jsfriendapi.cpp

@@ -717,6 +717,18 @@ SetGCSliceCallback(JSRuntime *rt, GCSliceCallback callback)
     return old;
 }
 
+jschar *
+GCDescription::formatMessage(JSRuntime *rt) const
+{
+    return rt->gcStats.formatMessage();
+}
+
+jschar *
+GCDescription::formatJSON(JSRuntime *rt) const
+{
+    return rt->gcStats.formatJSON();
+}
+
 JS_FRIEND_API(bool)
 WantGCSlice(JSRuntime *rt)
 {

js/src/jsfriendapi.h

@@ -699,12 +699,14 @@ enum GCProgress {
     GC_CYCLE_END
 };
 
-struct GCDescription {
+struct JS_FRIEND_API(GCDescription) {
-    const char *logMessage;
     bool isCompartment;
 
-    GCDescription(const char *msg, bool isCompartment)
+    GCDescription(bool isCompartment)
-      : logMessage(msg), isCompartment(isCompartment) {}
+      : isCompartment(isCompartment) {}
+
+    jschar *formatMessage(JSRuntime *rt) const;
+    jschar *formatJSON(JSRuntime *rt) const;
 };
 
 typedef void