From 0ba328a50790a0a584f6ec96eb1523b19506f570 Mon Sep 17 00:00:00 2001 From: Terrence Cole Date: Mon, 5 Mar 2012 15:33:24 -0800 Subject: [PATCH] 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 | 77 ++++++- js/src/gc/Statistics.cpp | 385 +++++++++++++++++++++++++++-------- js/src/gc/Statistics.h | 14 +- js/src/jsarray.cpp | 1 - js/src/jsfriendapi.cpp | 12 ++ js/src/jsfriendapi.h | 10 +- 6 files changed, 392 insertions(+), 107 deletions(-) diff --git a/dom/base/nsJSEnvironment.cpp b/dom/base/nsJSEnvironment.cpp index 51049168fd08..b537f582fb43 100644 --- a/dom/base/nsJSEnvironment.cpp +++ b/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 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 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 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 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 diff --git a/js/src/gc/Statistics.cpp b/js/src/gc/Statistics.cpp index 607102d9eaec..1d7fd64ad525 100644 --- a/js/src/gc/Statistics.cpp +++ b/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 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 -Statistics::fmt(const char *f, ...) +static double +t(int64_t t) { - va_list va; - size_t off = strlen(buffer); - - va_start(va, f); - JS_vsnprintf(buffer + off, BUFFER_SIZE - off, f, va); - va_end(va); + return double(t) / PRMJ_USEC_PER_MSEC; } -void -Statistics::fmtIfNonzero(const char *name, double t) +static void +formatPhases(StatisticsSerializer &ss, const char *name, int64_t *times) { - if (t) { - if (needComma) - fmt(", "); - fmt("%s: %.1f", name, t); - needComma = true; - } + ss.beginObject(name); + ss.appendIfNonzeroMS("Mark", t(times[PHASE_MARK])); + ss.appendIfNonzeroMS("Mark Roots", t(times[PHASE_MARK_ROOTS])); + ss.appendIfNonzeroMS("Mark Delayed", t(times[PHASE_MARK_DELAYED])); + 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 -Statistics::formatPhases(int64_t *times) +bool +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"); - fmt(", MMU(20ms): %d%%, MMU(50ms): %d%%", int(mmu20 * 100), int(mmu50 * 100)); - - if (slices.length() > 1) - fmt(", MaxPause: %.1f", t(longest)); + ss.beginObject(NULL); + ss.appendNumber("Total Time", "%.1f", "ms", t(total)); + ss.appendString("Type", compartment ? "compartment" : "global"); + ss.appendNumber("MMU (20ms)", "%d", "%", int(mmu20 * 100)); + 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) - fmt(", NonIncrementalReason: %s", nonincrementalReason); - - fmt(", +chunks: %d, -chunks: %d\n", counts[STAT_NEW_CHUNK], counts[STAT_DESTROY_CHUNK]); - - if (slices.length() > 1) { + if (slices.length() > 1 || ss.isJSON()) { + ss.beginArray("Slices"); 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", - i, - t(slices[i].end - slices[0].start), - t(width), - ExplainReason(slices[i].reason)); + ss.beginObject(NULL); + ss.extra(" "); + ss.appendNumber("Slice", "%d", "", i); + ss.appendNumber("Time", "%.1f", "ms", t(slices[i].end - slices[0].start)); + 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); - fmt("): "); - formatPhases(slices[i].phaseTimes); - fmt("\n"); + ss.appendString("Reset", slices[i].resetReason); + ss.extra("): "); + formatPhases(ss, "times", slices[i].phaseTimes); + ss.endLine(); + ss.endObject(); } - - fmt(" Totals: "); + ss.endArray(); } + ss.extra(" Totals: "); + formatPhases(ss, "totals", phaseTimes); + ss.endObject(); - formatPhases(phaseTimes); - fmt("\n"); + return !ss.isOOM(); +} - 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), - needComma(false) + nonincrementalReason(NULL) { PodArrayZero(phaseTotals); PodArrayZero(counts); @@ -209,9 +414,13 @@ Statistics::~Statistics() { if (fp) { if (fullFormat) { - buffer[0] = 0x00; - formatPhases(phaseTotals); - fprintf(fp, "TOTALS\n%s\n\n-------\n", buffer); + StatisticsSerializer ss(StatisticsSerializer::AsText); + formatPhases(ss, "", phaseTotals); + 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", - t(slices[0].start - startupTime) / 1000.0, - formatData()); + StatisticsSerializer ss(StatisticsSerializer::AsText); + formatData(ss); + 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) { - GCDescription desc(NULL, !!compartment); - (*cb)(runtime, first ? GC_CYCLE_BEGIN : GC_SLICE_BEGIN, desc); - } + if (GCSliceCallback cb = runtime->gcSliceCallback) + (*cb)(runtime, first ? GC_CYCLE_BEGIN : GC_SLICE_BEGIN, GCDescription(!!compartment)); } 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)); } } diff --git a/js/src/gc/Statistics.h b/js/src/gc/Statistics.h index 31b8d5d699e8..6767ccade2ac 100644 --- a/js/src/gc/Statistics.h +++ b/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, ...); - void fmtIfNonzero(const char *name, double t); - void formatPhases(int64_t *times); - const char *formatData(); + bool formatData(StatisticsSerializer &ss); double computeMMU(int64_t resolution); }; diff --git a/js/src/jsarray.cpp b/js/src/jsarray.cpp index c1cd20e4fc21..ed441d55e437 100644 --- a/js/src/jsarray.cpp +++ b/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" diff --git a/js/src/jsfriendapi.cpp b/js/src/jsfriendapi.cpp index f4bd7aa16116..7a25917f3bea 100644 --- a/js/src/jsfriendapi.cpp +++ b/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) { diff --git a/js/src/jsfriendapi.h b/js/src/jsfriendapi.h index b4d2f0418264..afdb0d5e56c3 100644 --- a/js/src/jsfriendapi.h +++ b/js/src/jsfriendapi.h @@ -699,12 +699,14 @@ enum GCProgress { GC_CYCLE_END }; -struct GCDescription { - const char *logMessage; +struct JS_FRIEND_API(GCDescription) { bool isCompartment; - GCDescription(const char *msg, bool isCompartment) - : logMessage(msg), isCompartment(isCompartment) {} + GCDescription(bool isCompartment) + : isCompartment(isCompartment) {} + + jschar *formatMessage(JSRuntime *rt) const; + jschar *formatJSON(JSRuntime *rt) const; }; typedef void