Bug 736643 - Add timestamp support to GC/CC JSON output (r=terrence)
authorBill McCloskey <wmccloskey@mozilla.com>
Fri, 16 Mar 2012 16:36:26 -0700
changeset 92955 31e8a3b6f4c3e4207353e794656ff97ae30553dc
parent 92954 5a566527261d9a474742ce14ed95996b4eb0c403
child 92956 7a7f8fbd62d87062c272b10183553bb45a51d458
push idunknown
push userunknown
push dateunknown
reviewersterrence
bugs736643
milestone14.0a1
Bug 736643 - Add timestamp support to GC/CC JSON output (r=terrence)
dom/base/nsJSEnvironment.cpp
js/src/gc/Statistics.cpp
js/src/gc/Statistics.h
js/src/jsfriendapi.cpp
js/src/jsfriendapi.h
--- a/dom/base/nsJSEnvironment.cpp
+++ b/dom/base/nsJSEnvironment.cpp
@@ -3158,17 +3158,18 @@ nsJSContext::CycleCollectNow(nsICycleCol
                                         sRemovedPurples));
     nsCOMPtr<nsIConsoleService> cs =
       do_GetService(NS_CONSOLESERVICE_CONTRACTID);
     if (cs) {
       cs->LogStringMessage(msg.get());
     }
 
     NS_NAMED_MULTILINE_LITERAL_STRING(kJSONFmt,
-      NS_LL("{ \"duration\": %llu, ")
+       NS_LL("{ \"timestamp\": %llu, ")
+         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, ")
@@ -3178,28 +3179,28 @@ nsJSContext::CycleCollectNow(nsICycleCol
              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));
+                                         now, (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;
   sTotalForgetSkippableTime = 0;
@@ -3501,16 +3502,21 @@ DOMGCSliceCallback(JSRuntime *aRt, js::G
     gcstats.Adopt(aDesc.formatMessage(aRt));
     prefix.Adopt(nsTextFormatter::smprintf(kFmt.get(),
                                            double(delta) / PR_USEC_PER_SEC));
     nsString msg = prefix + gcstats;
     nsCOMPtr<nsIConsoleService> cs = do_GetService(NS_CONSOLESERVICE_CONTRACTID);
     if (cs) {
       cs->LogStringMessage(msg.get());
     }
+
+    nsString json;
+    json.Adopt(aDesc.formatJSON(aRt, now));
+    nsRefPtr<NotifyGCEndRunnable> notify = new NotifyGCEndRunnable(json);
+    NS_DispatchToMainThread(notify);
   }
 
   // Prevent cycle collections and shrinking during incremental GC.
   if (aProgress == js::GC_CYCLE_BEGIN) {
     sCCLockedOut = true;
     nsJSContext::KillShrinkGCBuffersTimer();
   } else if (aProgress == js::GC_CYCLE_END) {
     sCCLockedOut = false;
@@ -3524,21 +3530,16 @@ DOMGCSliceCallback(JSRuntime *aRt, js::G
 
   if (aProgress == js::GC_CYCLE_END) {
     // May need to kill the inter-slice GC timer
     nsJSContext::KillGCTimer();
 
     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
       // result of last-ditch or MaybeGC. In both cases it is
       // probably a time of heavy activity and we want to delay
       // the full GC, but we do want it to happen eventually.
       nsJSContext::PokeGC(js::gcreason::POST_COMPARTMENT);
     }
--- a/js/src/gc/Statistics.cpp
+++ b/js/src/gc/Statistics.cpp
@@ -305,29 +305,31 @@ formatPhases(StatisticsSerializer &ss, c
     ss.appendIfNonzeroMS("Clear Script Analysis", t(times[PHASE_CLEAR_SCRIPT_ANALYSIS]));
     ss.appendIfNonzeroMS("Finalize End Callback", t(times[PHASE_FINALIZE_END]));
     ss.appendIfNonzeroMS("Deallocate", t(times[PHASE_DESTROY]));
     ss.appendIfNonzeroMS("End Callback", t(times[PHASE_GC_END]));
     ss.endObject();
 }
 
 bool
-Statistics::formatData(StatisticsSerializer &ss)
+Statistics::formatData(StatisticsSerializer &ss, uint64_t timestamp)
 {
     int64_t total = 0, longest = 0;
     for (SliceData *slice = slices.begin(); slice != slices.end(); slice++) {
         total += slice->duration();
         if (slice->duration() > longest)
             longest = slice->duration();
     }
 
     double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
     double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
 
     ss.beginObject(NULL);
+    if (ss.isJSON())
+        ss.appendNumber("Timestamp", "%llu", "", (unsigned long long)timestamp);
     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
         ss.appendString("Reason", ExplainReason(slices[0].reason));
@@ -372,25 +374,25 @@ Statistics::formatData(StatisticsSeriali
 
     return !ss.isOOM();
 }
 
 jschar *
 Statistics::formatMessage()
 {
     StatisticsSerializer ss(StatisticsSerializer::AsText);
-    formatData(ss);
+    formatData(ss, 0);
     return ss.finishJSString();
 }
 
 jschar *
-Statistics::formatJSON()
+Statistics::formatJSON(uint64_t timestamp)
 {
     StatisticsSerializer ss(StatisticsSerializer::AsJSON);
-    formatData(ss);
+    formatData(ss, timestamp);
     return ss.finishJSString();
 }
 
 Statistics::Statistics(JSRuntime *rt)
   : runtime(rt),
     startupTime(PRMJ_Now()),
     fp(NULL),
     fullFormat(false),
@@ -444,17 +446,17 @@ Statistics::gcDuration()
     return slices.back().end - slices[0].start;
 }
 
 void
 Statistics::printStats()
 {
     if (fullFormat) {
         StatisticsSerializer ss(StatisticsSerializer::AsText);
-        formatData(ss);
+        formatData(ss, 0);
         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()),
--- a/js/src/gc/Statistics.h
+++ b/js/src/gc/Statistics.h
@@ -101,17 +101,17 @@ struct Statistics {
     void nonincremental(const char *reason) { nonincrementalReason = reason; }
 
     void count(Stat s) {
         JS_ASSERT(s < STAT_LIMIT);
         counts[s]++;
     }
 
     jschar *formatMessage();
-    jschar *formatJSON();
+    jschar *formatJSON(uint64_t timestamp);
 
   private:
     JSRuntime *runtime;
 
     int64_t startupTime;
 
     FILE *fp;
     bool fullFormat;
@@ -151,17 +151,17 @@ struct Statistics {
     /* Allocated space before the GC started. */
     size_t preBytes;
 
     void beginGC();
     void endGC();
 
     int64_t gcDuration();
     void printStats();
-    bool formatData(StatisticsSerializer &ss);
+    bool formatData(StatisticsSerializer &ss, uint64_t timestamp);
 
     double computeMMU(int64_t resolution);
 };
 
 struct AutoGCSlice {
     AutoGCSlice(Statistics &stats, JSCompartment *comp, gcreason::Reason reason
                 JS_GUARD_OBJECT_NOTIFIER_PARAM)
       : stats(stats) { JS_GUARD_OBJECT_NOTIFIER_INIT; stats.beginSlice(comp, reason); }
--- a/js/src/jsfriendapi.cpp
+++ b/js/src/jsfriendapi.cpp
@@ -719,19 +719,19 @@ SetGCSliceCallback(JSRuntime *rt, GCSlic
 
 jschar *
 GCDescription::formatMessage(JSRuntime *rt) const
 {
     return rt->gcStats.formatMessage();
 }
 
 jschar *
-GCDescription::formatJSON(JSRuntime *rt) const
+GCDescription::formatJSON(JSRuntime *rt, uint64_t timestamp) const
 {
-    return rt->gcStats.formatJSON();
+    return rt->gcStats.formatJSON(timestamp);
 }
 
 JS_FRIEND_API(bool)
 WantGCSlice(JSRuntime *rt)
 {
     if (rt->gcZeal() == gc::ZealFrameVerifierValue || rt->gcZeal() == gc::ZealFrameGCValue)
         return true;
 
--- a/js/src/jsfriendapi.h
+++ b/js/src/jsfriendapi.h
@@ -701,17 +701,17 @@ enum GCProgress {
 
 struct JS_FRIEND_API(GCDescription) {
     bool isCompartment;
 
     GCDescription(bool isCompartment)
       : isCompartment(isCompartment) {}
 
     jschar *formatMessage(JSRuntime *rt) const;
-    jschar *formatJSON(JSRuntime *rt) const;
+    jschar *formatJSON(JSRuntime *rt, uint64_t timestamp) const;
 };
 
 typedef void
 (* GCSliceCallback)(JSRuntime *rt, GCProgress progress, const GCDescription &desc);
 
 extern JS_FRIEND_API(GCSliceCallback)
 SetGCSliceCallback(JSRuntime *rt, GCSliceCallback callback);