Bug 1322560 - Record minor GC timings in profiles, r=jonco, mccr8, mstange

--HG--
extra : rebase_source : 073eceb4216b0505f8cbce0947e3e5091626ead1

js/public/GCAPI.h

@@ -357,6 +357,9 @@ struct JS_PUBLIC_API(GCDescription) {
     JS::dbg::GarbageCollectionEvent::Ptr toGCEvent(JSContext* cx) const;
 };
 
+extern JS_PUBLIC_API(UniqueChars)
+MinorGcToJSON(JSContext* cx);
+
 typedef void
 (* GCSliceCallback)(JSContext* cx, GCProgress progress, const GCDescription& desc);
 

js/src/gc/Nursery.cpp

@@ -25,6 +25,7 @@
 #if defined(DEBUG)
 #include "vm/EnvironmentObject.h"
 #endif
+#include "vm/JSONPrinter.h"
 #include "vm/Time.h"
 #include "vm/TypedArrayObject.h"
 #include "vm/TypeInference.h"
@@ -483,6 +484,30 @@ js::TenuringTracer::TenuringTracer(JSRuntime* rt, Nursery* nursery)
 {
 }
 
+void
+js::Nursery::renderProfileJSON(JSONPrinter& json) const
+{
+    if (!isEnabled()) {
+        json.beginObject();
+        json.property("status", "nursery disabled");
+        json.endObject();
+        return;
+    }
+
+    json.beginObject();
+#define EXTRACT_NAME(name, text) #name,
+    static const char* names[] = {
+FOR_EACH_NURSERY_PROFILE_TIME(EXTRACT_NAME)
+#undef EXTRACT_NAME
+    "" };
+
+    size_t i = 0;
+    for (auto time : profileDurations_)
+        json.property(names[i++], time.ToMicroseconds());
+
+    json.endObject();
+}
+
 /* static */ void
 js::Nursery::printProfileHeader()
 {

js/src/gc/Nursery.h

@@ -59,6 +59,7 @@ class NativeObject;
 class Nursery;
 class HeapSlot;
 class ZoneGroup;
+class JSONPrinter;
 
 void SetGCZeal(JSRuntime*, uint8_t, uint32_t);
 
@@ -259,6 +260,9 @@ class Nursery
     void leaveZealMode();
 #endif
 
+    /* Write profile time JSON on JSONPrinter. */
+    void renderProfileJSON(JSONPrinter& json) const;
+
     /* Print header line for profile times. */
     static void printProfileHeader();
 

js/src/gc/Statistics.cpp

@@ -664,6 +664,17 @@ Statistics::renderJsonSlice(size_t sliceNum) const
     return UniqueChars(printer.release());
 }
 
+UniqueChars
+Statistics::renderNurseryJson(JSRuntime* rt) const
+{
+    Sprinter printer(nullptr, false);
+    if (!printer.init())
+        return UniqueChars(nullptr);
+    JSONPrinter json(printer);
+    rt->gc.nursery().renderProfileJSON(json);
+    return UniqueChars(printer.release());
+}
+
 UniqueChars
 Statistics::renderJsonMessage(uint64_t timestamp, bool includeSlices) const
 {

js/src/gc/Statistics.h

@@ -355,6 +355,9 @@ struct Statistics
     // Return JSON for the timings of just the given slice.
     UniqueChars renderJsonSlice(size_t sliceNum) const;
 
+    // Return JSON for the previous nursery collection.
+    UniqueChars renderNurseryJson(JSRuntime* rt) const;
+
   private:
     JSRuntime* runtime;
 

js/src/jsgc.cpp

@@ -7684,6 +7684,13 @@ JS::GCDescription::summaryToJSON(JSContext* cx) const
     return cx->runtime()->gc.stats().renderJsonMessage(0, false);
 }
 
+JS_PUBLIC_API(JS::UniqueChars)
+JS::MinorGcToJSON(JSContext* cx)
+{
+    JSRuntime* rt = cx->runtime();
+    return rt->gc.stats().renderNurseryJson(rt);
+}
+
 JS_PUBLIC_API(JS::GCSliceCallback)
 JS::SetGCSliceCallback(JSContext* cx, GCSliceCallback callback)
 {

tools/profiler/core/ProfilerMarkerPayload.cpp

@@ -298,3 +298,17 @@ GCMajorMarkerPayload::StreamPayload(SpliceableJSONWriter& aWriter,
     aWriter.NullProperty("timings");
   }
 }
+
+void
+GCMinorMarkerPayload::StreamPayload(SpliceableJSONWriter& aWriter,
+                                    const mozilla::TimeStamp& aStartTime,
+                                    UniqueStacks& aUniqueStacks)
+{
+  MOZ_ASSERT(mTimingData);
+  streamCommonProps("GCMinor", aWriter, aStartTime, aUniqueStacks);
+  if (mTimingData) {
+    aWriter.SplicedJSONProperty("nurseryTimings", mTimingData.get());
+  } else {
+    aWriter.NullProperty("nurseryTimings");
+  }
+}

tools/profiler/public/ProfilerMarkerPayload.h

@@ -276,4 +276,25 @@ private:
   JS::UniqueChars mTimingJSON;
 };
 
+class GCMinorMarkerPayload : public ProfilerMarkerPayload
+{
+public:
+  GCMinorMarkerPayload(const mozilla::TimeStamp& aStartTime,
+                       const mozilla::TimeStamp& aEndTime,
+                       JS::UniqueChars&& aTimingData)
+   : ProfilerMarkerPayload(aStartTime, aEndTime, nullptr),
+     mTimingData(mozilla::Move(aTimingData))
+  {}
+
+  virtual ~GCMinorMarkerPayload() {};
+
+  void StreamPayload(SpliceableJSONWriter& aWriter,
+                     const mozilla::TimeStamp& aStartTime,
+                     UniqueStacks& aUniqueStacks) override;
+
+private:
+  JS::UniqueChars mTimingData;
+};
+
+
 #endif // PROFILER_MARKERS_H

xpcom/base/CycleCollectedJSRuntime.cpp

@@ -922,6 +922,20 @@ CycleCollectedJSRuntime::GCNurseryCollectionCallback(JSContext* aContext,
     timelines->AddMarkerForAllObservedDocShells(abstractMarker);
   }
 
+#ifdef MOZ_GECKO_PROFILER
+  if (aProgress == JS::GCNurseryProgress::GC_NURSERY_COLLECTION_START) {
+    self->mLatestNurseryCollectionStart = TimeStamp::Now();
+  } else if ((aProgress == JS::GCNurseryProgress::GC_NURSERY_COLLECTION_END) &&
+             profiler_is_active())
+  {
+    PROFILER_MARKER_PAYLOAD(
+      "GCMinor",
+      new GCMinorMarkerPayload(self->mLatestNurseryCollectionStart,
+                               TimeStamp::Now(),
+                               JS::MinorGcToJSON(aContext)));
+  }
+#endif
+
   if (self->mPrevGCNurseryCollectionCallback) {
     self->mPrevGCNurseryCollectionCallback(aContext, aProgress, aReason);
   }

xpcom/base/CycleCollectedJSRuntime.h

@@ -302,6 +302,10 @@ private:
   JS::GCSliceCallback mPrevGCSliceCallback;
   JS::GCNurseryCollectionCallback mPrevGCNurseryCollectionCallback;
 
+#ifdef MOZ_GECKO_PROFILER
+  mozilla::TimeStamp mLatestNurseryCollectionStart;
+#endif
+
   nsDataHashtable<nsPtrHashKey<void>, nsScriptObjectTracer*> mJSHolders;
 
   typedef nsDataHashtable<nsFuncPtrHashKey<DeferredFinalizeFunction>, void*>