Bug 821371, part 2 - Log time taken for cycle collector prep. r=smaug
authorAndrew McCreight <amccreight@mozilla.com>
Mon, 31 Dec 2012 15:55:07 -0500
changeset 126385 8c4236dde5e31ad86a6449e7bcacfae5ab60a32b
parent 126384 faf5e1fdde8873a60b04bb86bf9d0a1f8bdda7e5
child 126386 1e90b28485128b15614b53c6ecda73d50967a844
push id2151
push userlsblakk@mozilla.com
push dateTue, 19 Feb 2013 18:06:57 +0000
treeherdermozilla-beta@4952e88741ec [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssmaug
bugs821371
milestone20.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 821371, part 2 - Log time taken for cycle collector prep. r=smaug
dom/base/nsJSEnvironment.cpp
toolkit/components/telemetry/Histograms.json
--- a/dom/base/nsJSEnvironment.cpp
+++ b/dom/base/nsJSEnvironment.cpp
@@ -3089,66 +3089,91 @@ FireForgetSkippable(uint32_t aSuspected,
   if (sMaxForgetSkippableTime < delta) {
     sMaxForgetSkippableTime = delta;
   }
   sTotalForgetSkippableTime += delta;
   sRemovedPurples += (aSuspected - sPreviousSuspectedCount);
   ++sForgetSkippableBeforeCC;
 }
 
+MOZ_ALWAYS_INLINE
+static uint32_t
+TimeBetween(PRTime start, PRTime end)
+{
+  MOZ_ASSERT(end >= start);
+  return (uint32_t)(end - start) / PR_USEC_PER_MSEC;
+}
+
 //static
 void
 nsJSContext::CycleCollectNow(nsICycleCollectorListener *aListener,
                              int32_t aExtraForgetSkippableCalls,
                              bool aForced)
 {
   if (!NS_IsMainThread()) {
     return;
   }
 
+  SAMPLE_LABEL("CC", "CycleCollectNow");
+
+  PRTime start = PR_Now();
+
+  // Before we begin the cycle collection, make sure there is no active GC.
+  bool finishedIGC = sCCLockedOut;
   FinishAnyIncrementalGC();
-
-  SAMPLE_LABEL("GC", "CycleCollectNow");
+  PRTime endGCTime = PR_Now();
+  uint32_t gcDuration = TimeBetween(start, endGCTime);
 
   KillCCTimer();
 
-  PRTime start = PR_Now();
-
   uint32_t suspected = nsCycleCollector_suspectedCount();
-
-  // nsCycleCollector_forgetSkippable may mark some gray js to black.
+  bool ranSyncForgetSkippable = false;
+
+  // Run forgetSkippable synchronously to reduce the size of the CC graph. This
+  // is particularly useful if we recently finished a GC.
   if (sCleanupsSinceLastGC < 2 && aExtraForgetSkippableCalls >= 0) {
     while (sCleanupsSinceLastGC < 2) {
       FireForgetSkippable(nsCycleCollector_suspectedCount(), false);
+      ranSyncForgetSkippable = true;
     }
   }
 
   for (int32_t i = 0; i < aExtraForgetSkippableCalls; ++i) {
     FireForgetSkippable(nsCycleCollector_suspectedCount(), false);
+    ranSyncForgetSkippable = true;
   }
 
+  PRTime endSkippableTime = PR_Now();
+  uint32_t skippableDuration = TimeBetween(endGCTime, endSkippableTime);
+
+  // Prepare to actually run the CC.
   bool mergingCC = DoMergingCC(aForced);
-
   nsCycleCollectorResults ccResults;
   nsCycleCollector_collect(mergingCC, &ccResults, aListener);
   sCCollectedWaitingForGC += ccResults.mFreedRefCounted + ccResults.mFreedGCed;
 
   // If we collected a substantial amount of cycles, poke the GC since more objects
   // might be unreachable now.
   if (sCCollectedWaitingForGC > 250) {
     PokeGC(js::gcreason::CC_WAITING);
   }
 
-  PRTime now = PR_Now();
+  PRTime endCCTime = PR_Now();
+
+  // Log information about the CC via telemetry, JSON and the console.
+  uint32_t ccNowDuration = TimeBetween(start, endCCTime);
+  Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_FINISH_IGC, finishedIGC);
+  Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_SYNC_SKIPPABLE, ranSyncForgetSkippable);
+  Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_FULL, ccNowDuration);
 
   if (sLastCCEndTime) {
     uint32_t timeBetween = (uint32_t)(start - sLastCCEndTime) / PR_USEC_PER_SEC;
     Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_TIME_BETWEEN, timeBetween);
   }
-  sLastCCEndTime = now;
+  sLastCCEndTime = endCCTime;
 
   Telemetry::Accumulate(Telemetry::FORGET_SKIPPABLE_MAX,
                         sMaxForgetSkippableTime / PR_USEC_PER_MSEC);
 
   PRTime delta = GetCollectionTimeDelta();
 
   uint32_t cleanups = sForgetSkippableBeforeCC ? sForgetSkippableBeforeCC : 1;
   uint32_t minForgetSkippableTime = (sMinForgetSkippableTime == UINT32_MAX)
@@ -3162,41 +3187,43 @@ nsJSContext::CycleCollectNow(nsICycleCol
 
     nsCString gcMsg;
     if (ccResults.mForcedGC) {
       gcMsg.AssignLiteral(", forced a GC");
     }
 
     NS_NAMED_MULTILINE_LITERAL_STRING(kFmt,
       NS_LL("CC(T+%.1f) duration: %llums, suspected: %lu, visited: %lu RCed and %lu%s GCed, collected: %lu RCed and %lu GCed (%lu waiting for GC)%s\n")
-      NS_LL("ForgetSkippable %lu times before CC, min: %lu ms, max: %lu ms, avg: %lu ms, total: %lu ms, removed: %lu"));
+      NS_LL("ForgetSkippable %lu times before CC, min: %lu ms, max: %lu ms, avg: %lu ms, total: %lu ms, sync: %lu ms, removed: %lu"));
     nsString msg;
     msg.Adopt(nsTextFormatter::smprintf(kFmt.get(), double(delta) / PR_USEC_PER_SEC,
-                                        (now - start) / PR_USEC_PER_MSEC, suspected,
+                                        ccNowDuration, suspected,
                                         ccResults.mVisitedRefCounted, ccResults.mVisitedGCed, mergeMsg.get(),
                                         ccResults.mFreedRefCounted, ccResults.mFreedGCed,
                                         sCCollectedWaitingForGC, gcMsg.get(),
                                         sForgetSkippableBeforeCC,
                                         minForgetSkippableTime / PR_USEC_PER_MSEC,
                                         sMaxForgetSkippableTime / PR_USEC_PER_MSEC,
                                         (sTotalForgetSkippableTime / cleanups) /
                                           PR_USEC_PER_MSEC,
                                         sTotalForgetSkippableTime / PR_USEC_PER_MSEC,
-                                        sRemovedPurples));
+                                        skippableDuration, sRemovedPurples));
     nsCOMPtr<nsIConsoleService> cs =
       do_GetService(NS_CONSOLESERVICE_CONTRACTID);
     if (cs) {
       cs->LogStringMessage(msg.get());
     }
   }
 
   if (sPostGCEventsToObserver) {
     NS_NAMED_MULTILINE_LITERAL_STRING(kJSONFmt,
        NS_LL("{ \"timestamp\": %llu, ")
          NS_LL("\"duration\": %llu, ")
+         NS_LL("\"finish_gc_duration\": %llu, ")
+         NS_LL("\"sync_skippable_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, ")
@@ -3205,34 +3232,37 @@ nsJSContext::CycleCollectNow(nsICycleCol
              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, (now - start) / PR_USEC_PER_MSEC, suspected,
+    json.Adopt(nsTextFormatter::smprintf(kJSONFmt.get(), endCCTime,
+                                         ccNowDuration, gcDuration, skippableDuration,
+                                         suspected,
                                          ccResults.mVisitedRefCounted, ccResults.mVisitedGCed,
                                          ccResults.mFreedRefCounted, ccResults.mFreedGCed,
                                          sCCollectedWaitingForGC,
                                          ccResults.mForcedGC,
                                          sForgetSkippableBeforeCC,
                                          minForgetSkippableTime / 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(nullptr, "cycle-collection-statistics", json.get());
     }
   }
+
+  // Update global state to indicate we have just run a cycle collection.
   sMinForgetSkippableTime = UINT32_MAX;
   sMaxForgetSkippableTime = 0;
   sTotalForgetSkippableTime = 0;
   sRemovedPurples = 0;
   sForgetSkippableBeforeCC = 0;
   sNeedsFullCC = false;
 }
 
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -23,16 +23,30 @@
     "description": "time spent updating accessibility (ms)"
   },
   "CYCLE_COLLECTOR": {
     "kind": "exponential",
     "high": "10000",
     "n_buckets": 50,
     "description": "Time spent on one cycle collection (ms)"
   },
+  "CYCLE_COLLECTOR_FULL": {
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "description": "Full pause time for one cycle collection, including preparation (ms)"
+  },
+  "CYCLE_COLLECTOR_FINISH_IGC": {
+    "kind": "boolean",
+    "description": "Cycle collection finished an incremental GC"
+  },
+  "CYCLE_COLLECTOR_SYNC_SKIPPABLE": {
+    "kind": "boolean",
+    "description": "Cycle collection synchronously ran forget skippable"
+  },
   "CYCLE_COLLECTOR_VISITED_REF_COUNTED": {
     "kind": "exponential",
     "high": "300000",
     "n_buckets": 50,
     "description": "Number of ref counted objects visited by the cycle collector"
   },
   "CYCLE_COLLECTOR_VISITED_GCED": {
     "kind": "exponential",