Bug 948554, part 3 - Capture max slice time in logs and telemetry. r=smaug
☠☠ backed out by b464f609a193 ☠ ☠
authorAndrew McCreight <continuation@gmail.com>
Wed, 18 Dec 2013 11:42:16 -0800
changeset 177164 472a1be79a9f38225cd8a6741594957c0a53d669
parent 177163 2b43b310858be199ffd84ce66d90372fa2c0cc9d
child 177165 e4d49705cdfea9acf63fd92bfeb3f3904e5cbd1f
push id3343
push userffxbld
push dateMon, 17 Mar 2014 21:55:32 +0000
treeherdermozilla-beta@2f7d3415f79f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssmaug
bugs948554
milestone29.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 948554, part 3 - Capture max slice time in logs and telemetry. r=smaug
dom/base/nsJSEnvironment.cpp
toolkit/components/telemetry/Histograms.json
--- a/dom/base/nsJSEnvironment.cpp
+++ b/dom/base/nsJSEnvironment.cpp
@@ -1998,40 +1998,53 @@ struct CycleCollectorStats
   void Clear()
   {
     mBeginSliceTime = TimeStamp();
     mBeginTime = TimeStamp();
     mMaxGCDuration = 0;
     mRanSyncForgetSkippable = false;
     mSuspected = 0;
     mMaxSkippableDuration = 0;
+    mMaxSliceTime = 0;
     mAnyLockedOut = false;
   }
 
   void PrepareForCycleCollectionSlice(int32_t aExtraForgetSkippableCalls = 0);
 
+  void FinishCycleCollectionSlice()
+  {
+    if (mBeginSliceTime.IsNull()) {
+      return;
+    }
+    uint32_t sliceTime = TimeUntilNow(mBeginSliceTime);
+    mMaxSliceTime = std::max(mMaxSliceTime, sliceTime);
+  }
+
   // Time the current slice began, including any GC finishing.
   TimeStamp mBeginSliceTime;
 
   // Time the current cycle collection began.
   TimeStamp mBeginTime;
 
   // The longest GC finishing duration for any slice of the current CC.
   uint32_t mMaxGCDuration;
 
   // True if we ran sync forget skippable in any slice of the current CC.
   bool mRanSyncForgetSkippable;
 
   // Number of suspected objects at the start of the current CC.
   uint32_t mSuspected;
 
   // The longest duration spent on sync forget skippable in any slice of the
-  // current CC
+  // current CC.
   uint32_t mMaxSkippableDuration;
 
+  // The longest pause of any slice in the current CC.
+  uint32_t mMaxSliceTime;
+
   // True if we were locked out by the GC in any slice of the current CC.
   bool mAnyLockedOut;
 };
 
 CycleCollectorStats gCCStats;
 
 static int64_t
 ICCSliceTime()
@@ -2097,32 +2110,34 @@ nsJSContext::CycleCollectNow(nsICycleCol
 {
   if (!NS_IsMainThread()) {
     return;
   }
 
   PROFILER_LABEL("CC", "CycleCollectNow");
   gCCStats.PrepareForCycleCollectionSlice(aExtraForgetSkippableCalls);
   nsCycleCollector_collect(aListener);
+  gCCStats.FinishCycleCollectionSlice();
 }
 
 //static
 void
 nsJSContext::ScheduledCycleCollectNow(int64_t aSliceTime)
 {
   if (!NS_IsMainThread()) {
     return;
   }
 
   PROFILER_LABEL("CC", "ScheduledCycleCollectNow");
 
   // Ideally, the slice time would be decreased by the amount of
   // time spent on PrepareForCycleCollection().
   gCCStats.PrepareForCycleCollectionSlice();
   nsCycleCollector_scheduledCollect(aSliceTime);
+  gCCStats.FinishCycleCollectionSlice();
 }
 
 static void
 ICCTimerFired(nsITimer* aTimer, void* aClosure)
 {
   if (sDidShutdown) {
     return;
   }
@@ -2173,16 +2188,19 @@ nsJSContext::BeginCycleCollectionCallbac
 //static
 void
 nsJSContext::EndCycleCollectionCallback(CycleCollectorResults &aResults)
 {
   MOZ_ASSERT(NS_IsMainThread());
 
   nsJSContext::KillICCTimer();
 
+  // Update timing information for the current slice before we log it.
+  gCCStats.FinishCycleCollectionSlice();
+
   sCCollectedWaitingForGC += aResults.mFreedRefCounted + aResults.mFreedGCed;
 
   // If we collected a substantial amount of cycles, poke the GC since more objects
   // might be unreachable now.
   if (sCCollectedWaitingForGC > 250 ||
       sLikelyShortLivingObjectsNeedingGC > 2500 ||
       sNeedsGCAfterCC) {
     PokeGC(JS::gcreason::CC_WAITING);
@@ -2190,16 +2208,17 @@ nsJSContext::EndCycleCollectionCallback(
 
   TimeStamp endCCTime = TimeStamp::Now();
 
   // Log information about the CC via telemetry, JSON and the console.
   uint32_t ccNowDuration = TimeBetween(gCCStats.mBeginTime, endCCTime);
   Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_FINISH_IGC, gCCStats.mAnyLockedOut);
   Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_SYNC_SKIPPABLE, gCCStats.mRanSyncForgetSkippable);
   Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_FULL, ccNowDuration);
+  Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_MAX_PAUSE, gCCStats.mMaxSliceTime);
 
   if (!sLastCCEndTime.IsNull()) {
     uint32_t timeBetween = TimeBetween(sLastCCEndTime, gCCStats.mBeginTime);
     Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_TIME_BETWEEN, timeBetween);
   }
   sLastCCEndTime = endCCTime;
 
   Telemetry::Accumulate(Telemetry::FORGET_SKIPPABLE_MAX,
@@ -2218,21 +2237,21 @@ nsJSContext::EndCycleCollectionCallback(
     }
 
     nsCString gcMsg;
     if (aResults.mForcedGC) {
       gcMsg.AssignLiteral(", forced a GC");
     }
 
     NS_NAMED_MULTILINE_LITERAL_STRING(kFmt,
-      MOZ_UTF16("CC(T+%.1f) duration: %lums, suspected: %lu, visited: %lu RCed and %lu%s GCed, collected: %lu RCed and %lu GCed (%lu|%lu waiting for GC)%s\n")
+      MOZ_UTF16("CC(T+%.1f) max pause: %lums, total time: %lums, suspected: %lu, visited: %lu RCed and %lu%s GCed, collected: %lu RCed and %lu GCed (%lu|%lu waiting for GC)%s\n")
       MOZ_UTF16("ForgetSkippable %lu times before CC, min: %lu ms, max: %lu ms, avg: %lu ms, total: %lu ms, max sync: %lu ms, removed: %lu"));
     nsString msg;
     msg.Adopt(nsTextFormatter::smprintf(kFmt.get(), double(delta) / PR_USEC_PER_SEC,
-                                        ccNowDuration, gCCStats.mSuspected,
+                                        gCCStats.mMaxSliceTime, ccNowDuration, gCCStats.mSuspected,
                                         aResults.mVisitedRefCounted, aResults.mVisitedGCed, mergeMsg.get(),
                                         aResults.mFreedRefCounted, aResults.mFreedGCed,
                                         sCCollectedWaitingForGC, sLikelyShortLivingObjectsNeedingGC,
                                         gcMsg.get(),
                                         sForgetSkippableBeforeCC,
                                         minForgetSkippableTime / PR_USEC_PER_MSEC,
                                         sMaxForgetSkippableTime / PR_USEC_PER_MSEC,
                                         (sTotalForgetSkippableTime / cleanups) /
@@ -2245,16 +2264,17 @@ nsJSContext::EndCycleCollectionCallback(
       cs->LogStringMessage(msg.get());
     }
   }
 
   if (sPostGCEventsToObserver) {
     NS_NAMED_MULTILINE_LITERAL_STRING(kJSONFmt,
        MOZ_UTF16("{ \"timestamp\": %llu, ")
          MOZ_UTF16("\"duration\": %llu, ")
+         MOZ_UTF16("\"max_slice_pause\": %llu, ")
          MOZ_UTF16("\"max_finish_gc_duration\": %llu, ")
          MOZ_UTF16("\"max_sync_skippable_duration\": %llu, ")
          MOZ_UTF16("\"suspected\": %lu, ")
          MOZ_UTF16("\"visited\": { ")
              MOZ_UTF16("\"RCed\": %lu, ")
              MOZ_UTF16("\"GCed\": %lu }, ")
          MOZ_UTF16("\"collected\": { ")
              MOZ_UTF16("\"RCed\": %lu, ")
@@ -2266,18 +2286,18 @@ nsJSContext::EndCycleCollectionCallback(
              MOZ_UTF16("\"times_before_cc\": %lu, ")
              MOZ_UTF16("\"min\": %lu, ")
              MOZ_UTF16("\"max\": %lu, ")
              MOZ_UTF16("\"avg\": %lu, ")
              MOZ_UTF16("\"total\": %lu, ")
              MOZ_UTF16("\"removed\": %lu } ")
        MOZ_UTF16("}"));
     nsString json;
-    json.Adopt(nsTextFormatter::smprintf(kJSONFmt.get(), endCCTime,
-                                         ccNowDuration, gCCStats.mMaxGCDuration,
+    json.Adopt(nsTextFormatter::smprintf(kJSONFmt.get(), endCCTime, ccNowDuration,
+                                         gCCStats.mMaxSliceTime, gCCStats.mMaxGCDuration,
                                          gCCStats.mMaxSkippableDuration,
                                          gCCStats.mSuspected,
                                          aResults.mVisitedRefCounted, aResults.mVisitedGCed,
                                          aResults.mFreedRefCounted, aResults.mFreedGCed,
                                          sCCollectedWaitingForGC,
                                          sLikelyShortLivingObjectsNeedingGC,
                                          aResults.mForcedGC,
                                          sForgetSkippableBeforeCC,
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -72,16 +72,22 @@
     "description": "Time spent on one cycle collection in a worker (ms)"
   },
   "CYCLE_COLLECTOR_FULL": {
     "kind": "exponential",
     "high": "10000",
     "n_buckets": 50,
     "description": "Full pause time for one cycle collection, including preparation (ms)"
   },
+  "CYCLE_COLLECTOR_MAX_PAUSE": {
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "description": "Longest pause for an individual slice of 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"
   },