From 7ef280069ef3798b47cce8c570bfe94c7329f994 Mon Sep 17 00:00:00 2001 From: Steve Fink Date: Tue, 25 Apr 2017 13:24:34 -0700 Subject: [PATCH] Bug 1322560 - Record minor GC timings in profiles, r=jonco, mccr8, mstange --HG-- extra : rebase_source : 073eceb4216b0505f8cbce0947e3e5091626ead1 --- js/public/GCAPI.h | 3 +++ js/src/gc/Nursery.cpp | 25 +++++++++++++++++++ js/src/gc/Nursery.h | 4 +++ js/src/gc/Statistics.cpp | 11 ++++++++ js/src/gc/Statistics.h | 3 +++ js/src/jsgc.cpp | 7 ++++++ tools/profiler/core/ProfilerMarkerPayload.cpp | 14 +++++++++++ tools/profiler/public/ProfilerMarkerPayload.h | 21 ++++++++++++++++ xpcom/base/CycleCollectedJSRuntime.cpp | 14 +++++++++++ xpcom/base/CycleCollectedJSRuntime.h | 4 +++ 10 files changed, 106 insertions(+) diff --git a/js/public/GCAPI.h b/js/public/GCAPI.h index d5e8cb4ef0f2..e9da6cb65c40 100644 --- a/js/public/GCAPI.h +++ b/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); diff --git a/js/src/gc/Nursery.cpp b/js/src/gc/Nursery.cpp index 5655e35344e8..b49a30007312 100644 --- a/js/src/gc/Nursery.cpp +++ b/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() { diff --git a/js/src/gc/Nursery.h b/js/src/gc/Nursery.h index 84238dba24eb..906a66e94b83 100644 --- a/js/src/gc/Nursery.h +++ b/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(); diff --git a/js/src/gc/Statistics.cpp b/js/src/gc/Statistics.cpp index 2d21405f7f95..6babf01658d0 100644 --- a/js/src/gc/Statistics.cpp +++ b/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 { diff --git a/js/src/gc/Statistics.h b/js/src/gc/Statistics.h index ba2ce368c2c0..cb4b70e9177f 100644 --- a/js/src/gc/Statistics.h +++ b/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; diff --git a/js/src/jsgc.cpp b/js/src/jsgc.cpp index 827625e6875c..a6fdfe15b073 100644 --- a/js/src/jsgc.cpp +++ b/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) { diff --git a/tools/profiler/core/ProfilerMarkerPayload.cpp b/tools/profiler/core/ProfilerMarkerPayload.cpp index ecc4b5e5585e..4e53c36ff6ae 100644 --- a/tools/profiler/core/ProfilerMarkerPayload.cpp +++ b/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"); + } +} diff --git a/tools/profiler/public/ProfilerMarkerPayload.h b/tools/profiler/public/ProfilerMarkerPayload.h index cdaf0037427e..cd17a55db9e7 100644 --- a/tools/profiler/public/ProfilerMarkerPayload.h +++ b/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 diff --git a/xpcom/base/CycleCollectedJSRuntime.cpp b/xpcom/base/CycleCollectedJSRuntime.cpp index e35e9b43f0b7..7d4ff858a128 100644 --- a/xpcom/base/CycleCollectedJSRuntime.cpp +++ b/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); } diff --git a/xpcom/base/CycleCollectedJSRuntime.h b/xpcom/base/CycleCollectedJSRuntime.h index 86119dc92c29..7fb976031834 100644 --- a/xpcom/base/CycleCollectedJSRuntime.h +++ b/xpcom/base/CycleCollectedJSRuntime.h @@ -302,6 +302,10 @@ private: JS::GCSliceCallback mPrevGCSliceCallback; JS::GCNurseryCollectionCallback mPrevGCNurseryCollectionCallback; +#ifdef MOZ_GECKO_PROFILER + mozilla::TimeStamp mLatestNurseryCollectionStart; +#endif + nsDataHashtable, nsScriptObjectTracer*> mJSHolders; typedef nsDataHashtable, void*>