Bug 1385296 - Improve JS_GC_PROFILE / MOZ_GCTIMER output r=sfink
authorJon Coppeard <jcoppeard@mozilla.com>
Mon, 31 Jul 2017 10:56:44 +0100
changeset 420770 9236439b1cd419e4b7caa60bdcfb57a975abed90
parent 420769 d8a326479290fdebaff3e555613d30bcf54a0536
child 420771 06d31a972d445d5abcad85d9201aad70ec4962f6
push id7566
push usermtabara@mozilla.com
push dateWed, 02 Aug 2017 08:25:16 +0000
treeherdermozilla-beta@86913f512c3c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssfink
bugs1385296
milestone56.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 1385296 - Improve JS_GC_PROFILE / MOZ_GCTIMER output r=sfink
js/src/gc/Nursery.cpp
js/src/gc/Statistics.cpp
js/src/gc/Statistics.h
--- a/js/src/gc/Nursery.cpp
+++ b/js/src/gc/Nursery.cpp
@@ -511,17 +511,17 @@ FOR_EACH_NURSERY_PROFILE_TIME(EXTRACT_NA
     json.endObject(); // timings value
 
     json.endObject();
 }
 
 /* static */ void
 js::Nursery::printProfileHeader()
 {
-    fprintf(stderr, "MinorGC:               Reason  PRate Size ");
+    fprintf(stderr, "MinorGC:               Reason  PRate Size        ");
 #define PRINT_HEADER(name, text)                                              \
     fprintf(stderr, " %6s", text);
 FOR_EACH_NURSERY_PROFILE_TIME(PRINT_HEADER)
 #undef PRINT_HEADER
     fprintf(stderr, "\n");
 }
 
 /* static */ void
@@ -531,17 +531,17 @@ js::Nursery::printProfileDurations(const
         fprintf(stderr, " %6" PRIi64, static_cast<int64_t>(time.ToMicroseconds()));
     fprintf(stderr, "\n");
 }
 
 void
 js::Nursery::printTotalProfileTimes()
 {
     if (enableProfiling_) {
-        fprintf(stderr, "MinorGC TOTALS: %7" PRIu64 " collections:      ", minorGcCount_);
+        fprintf(stderr, "MinorGC TOTALS: %7" PRIu64 " collections:             ", minorGcCount_);
         printProfileDurations(totalDurations_);
     }
 }
 
 void
 js::Nursery::maybeClearProfileDurations()
 {
     for (auto& duration : profileDurations_)
@@ -664,17 +664,17 @@ js::Nursery::collect(JS::gcreason::Reaso
     rt->addTelemetry(JS_TELEMETRY_GC_PRETENURE_COUNT, pretenureCount);
 
     rt->gc.stats().endNurseryCollection(reason);
     TraceMinorGCEnd();
 
     if (enableProfiling_ && totalTime >= profileThreshold_) {
         rt->gc.stats().maybePrintProfileHeaders();
 
-        fprintf(stderr, "MinorGC: %20s %5.1f%% %4u ",
+        fprintf(stderr, "MinorGC: %20s %5.1f%% %4u        ",
                 JS::gcreason::ExplainReason(reason),
                 promotionRate * 100,
                 numChunks());
         printProfileDurations(profileDurations_);
 
         if (reportTenurings_) {
             for (auto& entry : tenureCounts.entries) {
                 if (entry.count >= reportTenurings_) {
--- a/js/src/gc/Statistics.cpp
+++ b/js/src/gc/Statistics.cpp
@@ -457,36 +457,43 @@ Statistics::formatDetailedSliceDescripti
                    slice.wasReset() ? "yes - " : "no",
                    slice.wasReset() ? ExplainAbortReason(slice.resetReason) : "",
                    gc::StateName(slice.initialState), gc::StateName(slice.finalState),
                    uint64_t(slice.endFaults - slice.startFaults),
                    t(slice.duration()), budgetDescription, t(slice.start - slices_[0].start));
     return DuplicateString(buffer);
 }
 
+static bool
+IncludePhase(TimeDuration duration)
+{
+    // Don't include durations that will print as "0.000ms".
+    return duration.ToMilliseconds() >= 0.001;
+}
+
 UniqueChars
 Statistics::formatDetailedPhaseTimes(const PhaseTimeTable& phaseTimes) const
 {
     static const TimeDuration MaxUnaccountedChildTime = TimeDuration::FromMicroseconds(50);
 
     FragmentVector fragments;
     char buffer[128];
     for (auto phase : AllPhases()) {
         uint8_t level = phases[phase].depth;
         TimeDuration ownTime = phaseTimes[phase];
         TimeDuration childTime = SumChildTimes(phase, phaseTimes);
-        if (!ownTime.IsZero()) {
-            SprintfLiteral(buffer, "      %*s: %.3fms\n",
-                           level * 2, phases[phase].name, t(ownTime));
+        if (IncludePhase(ownTime)) {
+            SprintfLiteral(buffer, "      %*s%s: %.3fms\n",
+                           level * 2, "", phases[phase].name, t(ownTime));
             if (!fragments.append(DuplicateString(buffer)))
                 return UniqueChars(nullptr);
 
             if (childTime && (ownTime - childTime) > MaxUnaccountedChildTime) {
-                SprintfLiteral(buffer, "      %*s: %.3fms\n",
-                               (level + 1) * 2, "Other", t(ownTime - childTime));
+                SprintfLiteral(buffer, "      %*s%s: %.3fms\n",
+                               (level + 1) * 2, "", "Other", t(ownTime - childTime));
                 if (!fragments.append(DuplicateString(buffer)))
                     return UniqueChars(nullptr);
             }
         }
     }
     return Join(fragments);
 }
 
@@ -1293,32 +1300,29 @@ Statistics::computeMMU(TimeDuration wind
 }
 
 void
 Statistics::maybePrintProfileHeaders()
 {
     static int printedHeader = 0;
     if ((printedHeader++ % 200) == 0) {
         printProfileHeader();
-        for (ZoneGroupsIter group(runtime); !group.done(); group.next()) {
-            if (group->nursery().enableProfiling()) {
-                Nursery::printProfileHeader();
-                break;
-            }
-        }
+        if (runtime->gc.nursery().enableProfiling())
+            Nursery::printProfileHeader();
     }
 }
 
 void
 Statistics::printProfileHeader()
 {
     if (!enableProfiling_)
         return;
 
-    fprintf(stderr, "MajorGC:               Reason States      ");
+    fprintf(stderr, "MajorGC:               Reason States SRN  ");
+    fprintf(stderr, " %6s", "budget");
     fprintf(stderr, " %6s", "total");
 #define PRINT_PROFILE_HEADER(name, text, phase)                               \
     fprintf(stderr, " %6s", text);
 FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_HEADER)
 #undef PRINT_PROFILE_HEADER
     fprintf(stderr, "\n");
 }
 
@@ -1332,18 +1336,31 @@ Statistics::printProfileTimes(const Prof
 
 void
 Statistics::printSliceProfile()
 {
     const SliceData& slice = slices_.back();
 
     maybePrintProfileHeaders();
 
-    fprintf(stderr, "MajorGC: %20s %1d -> %1d      ",
-            ExplainReason(slice.reason), int(slice.initialState), int(slice.finalState));
+    bool shrinking = gckind == GC_SHRINK;
+    bool reset = slice.resetReason != AbortReason::None;
+    bool nonIncremental = nonincrementalReason_ != AbortReason::None;
+
+    fprintf(stderr, "MajorGC: %20s %1d -> %1d %1s%1s%1s  ",
+            ExplainReason(slice.reason),
+            int(slice.initialState), int(slice.finalState),
+            shrinking ? "S" : "",
+            reset ? "R" : "",
+            nonIncremental ? "N" : "");
+
+    if (!nonIncremental && !slice.budget.isUnlimited() && slice.budget.isTimeBudget())
+        fprintf(stderr, " %6" PRIi64, static_cast<int64_t>(slice.budget.timeBudget.budget));
+    else
+        fprintf(stderr, "       ");
 
     ProfileDurations times;
     times[ProfileKey::Total] = slice.duration();
     totalTimes_[ProfileKey::Total] += times[ProfileKey::Total];
 
 #define GET_PROFILE_TIME(name, text, phase)                                   \
     times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes);              \
     totalTimes_[ProfileKey::name] += times[ProfileKey::name];
@@ -1352,13 +1369,13 @@ FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIM
 
     printProfileTimes(times);
 }
 
 void
 Statistics::printTotalProfileTimes()
 {
     if (enableProfiling_) {
-        fprintf(stderr, "MajorGC TOTALS: %7" PRIu64 " slices:           ", sliceCount_);
+        fprintf(stderr, "MajorGC TOTALS: %7" PRIu64 " slices:                  ", sliceCount_);
         printProfileTimes(totalTimes_);
     }
 }
 
--- a/js/src/gc/Statistics.h
+++ b/js/src/gc/Statistics.h
@@ -75,25 +75,25 @@ struct ZoneGCStats
     ZoneGCStats()
       : collectedZoneCount(0), zoneCount(0), sweptZoneCount(0),
         collectedCompartmentCount(0), compartmentCount(0), sweptCompartmentCount(0)
     {}
 };
 
 #define FOR_EACH_GC_PROFILE_TIME(_)                                           \
     _(BeginCallback, "bgnCB",  PhaseKind::GC_BEGIN)                           \
+    _(MinorForMajor, "evct4m", PhaseKind::EVICT_NURSERY_FOR_MAJOR_GC)         \
     _(WaitBgThread,  "waitBG", PhaseKind::WAIT_BACKGROUND_THREAD)             \
-    _(DiscardCode,   "discrd", PhaseKind::MARK_DISCARD_CODE)                  \
-    _(RelazifyFunc,  "relzfy", PhaseKind::RELAZIFY_FUNCTIONS)                 \
-    _(PurgeTables,   "prgTbl", PhaseKind::PURGE_SHAPE_TABLES)                 \
-    _(Purge,         "purge",  PhaseKind::PURGE)                              \
+    _(Prepare,       "prep",   PhaseKind::PREPARE)                            \
     _(Mark,          "mark",   PhaseKind::MARK)                               \
     _(Sweep,         "sweep",  PhaseKind::SWEEP)                              \
     _(Compact,       "cmpct",  PhaseKind::COMPACT)                            \
     _(EndCallback,   "endCB",  PhaseKind::GC_END)                             \
+    _(MinorGC,       "minor",  PhaseKind::MINOR_GC)                           \
+    _(EvictNursery,  "evict",  PhaseKind::EVICT_NURSERY)                      \
     _(Barriers,      "brrier", PhaseKind::BARRIER)
 
 const char* ExplainAbortReason(gc::AbortReason reason);
 const char* ExplainInvocationKind(JSGCInvocationKind gckind);
 
 /*
  * Struct for collecting timing statistics on a "phase tree". The tree is
  * specified as a limited DAG, but the timings are collected for the whole tree