Bug 1384688 - Add a pausedRanges field to the profile JSON of each process which lists time ranges during which the profiler was paused or collecting a profile. r=njn
☠☠ backed out by 40d2ccee4fa8 ☠ ☠
authorMarkus Stange <mstange@themasta.com>
Fri, 28 Jul 2017 16:40:37 -0400
changeset 420727 399d40cb5c1c2046a4296043976609863e2496bb
parent 420726 3ad8f1ba9de6ebe7fae8b41ea5c3e280b8b71b86
child 420728 802c36bf1b27ed53c8c396c6e081e3f0ab02b53f
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)
reviewersnjn
bugs1384688
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 1384688 - Add a pausedRanges field to the profile JSON of each process which lists time ranges during which the profiler was paused or collecting a profile. r=njn MozReview-Commit-ID: 6nzt7uHTLVm
tools/profiler/core/ProfileBuffer.h
tools/profiler/core/ProfileBufferEntry.cpp
tools/profiler/core/ProfileBufferEntry.h
tools/profiler/core/platform.cpp
--- a/tools/profiler/core/ProfileBuffer.h
+++ b/tools/profiler/core/ProfileBuffer.h
@@ -59,16 +59,18 @@ public:
   void StreamSamplesToJSON(SpliceableJSONWriter& aWriter, int aThreadId,
                            double aSinceTime, double* aOutFirstSampleTime,
                            JSContext* cx,
                            UniqueStacks& aUniqueStacks) const;
   void StreamMarkersToJSON(SpliceableJSONWriter& aWriter, int aThreadId,
                            const mozilla::TimeStamp& aProcessStartTime,
                            double aSinceTime,
                            UniqueStacks& aUniqueStacks) const;
+  void StreamPausedRangesToJSON(SpliceableJSONWriter& aWriter,
+                                double aSinceTime) const;
 
   // Find (via |aLS|) the most recent sample for the thread denoted by
   // |aThreadId| and clone it, patching in |aProcessStartTime| as appropriate.
   bool DuplicateLastSample(int aThreadId,
                            const mozilla::TimeStamp& aProcessStartTime,
                            LastSample& aLS);
 
   void AddStoredMarker(ProfilerMarker* aStoredMarker);
--- a/tools/profiler/core/ProfileBufferEntry.cpp
+++ b/tools/profiler/core/ProfileBufferEntry.cpp
@@ -585,30 +585,36 @@ public:
 
 private:
   const ProfileBufferEntry* const mEntries;
   int mReadPos;
   const int mWritePos;
   const int mEntrySize;
 };
 
-// Each sample is made up of multiple ProfileBuffer entries. The following
-// grammar shows legal sequences.
+// The following grammar shows legal sequences of profile buffer entries.
+// The sequences beginning with a ThreadId entry are known as "samples".
 //
 // (
-//   ThreadId
-//   Time
-//   ( NativeLeafAddr
-//   | Label DynamicStringFragment* LineNumber? Category?
-//   | JitReturnAddr
-//   )+
-//   Marker*
-//   Responsiveness?
-//   ResidentMemory?
-//   UnsharedMemory?
+//   (
+//     ThreadId
+//     Time
+//     ( NativeLeafAddr
+//     | Label DynamicStringFragment* LineNumber? Category?
+//     | JitReturnAddr
+//     )+
+//     Marker*
+//     Responsiveness?
+//     ResidentMemory?
+//     UnsharedMemory?
+//   )
+//   | CollectionStart
+//   | CollectionEnd
+//   | Pause
+//   | Resume
 // )*
 //
 // The most complicated part is the stack entry sequence that begins with
 // Label. Here are some examples.
 //
 // - PseudoStack entries without a dynamic string:
 //
 //     Label("js::RunScript")
@@ -700,78 +706,83 @@ ProfileBuffer::StreamSamplesToJSON(Splic
                                    JSContext* aContext,
                                    UniqueStacks& aUniqueStacks) const
 {
   UniquePtr<char[]> strbuf = MakeUnique<char[]>(kMaxFrameKeyLength);
 
   // Because this is a format entirely internal to the Profiler, any parsing
   // error indicates a bug in the ProfileBuffer writing or the parser itself,
   // or possibly flaky hardware.
-  #define ERROR_AND_SKIP_TO_NEXT_SAMPLE(msg) \
-    do { \
+  #define ERROR_AND_CONTINUE(msg) \
+    { \
       fprintf(stderr, "ProfileBuffer parse error: %s", msg); \
       MOZ_ASSERT(false, msg); \
-      goto skip_to_next_sample; \
-    } while (0)
+      continue; \
+    }
 
   EntryGetter e(*this);
   bool seenFirstSample = false;
 
-  // This block skips entries until we find the start of the next sample. This
-  // is useful in two situations.
-  //
-  // - The circular buffer overwrites old entries, so when we start parsing we
-  //   might be in the middle of a sample, and we must skip forward to the
-  //   start of the next sample.
-  //
-  // - We skip samples that don't have an appropriate ThreadId or Time.
-  //
-skip_to_next_sample:
-  while (e.Has()) {
-    if (e.Get().IsThreadId()) {
+  for (;;) {
+    // This block skips entries until we find the start of the next sample.
+    // This is useful in three situations.
+    //
+    // - The circular buffer overwrites old entries, so when we start parsing
+    //   we might be in the middle of a sample, and we must skip forward to the
+    //   start of the next sample.
+    //
+    // - We skip samples that don't have an appropriate ThreadId or Time.
+    //
+    // - We skip range Pause, Resume, CollectionStart, and CollectionEnd
+    //   entries between samples.
+    while (e.Has()) {
+      if (e.Get().IsThreadId()) {
+        break;
+      } else {
+        e.Next();
+      }
+    }
+
+    if (!e.Has()) {
       break;
-    } else {
-      e.Next();
     }
-  }
 
-  while (e.Has()) {
     if (e.Get().IsThreadId()) {
       int threadId = e.Get().u.mInt;
       e.Next();
 
       // Ignore samples that are for the wrong thread.
       if (threadId != aThreadId) {
-        goto skip_to_next_sample;
+        continue;
       }
     } else {
       // Due to the skip_to_next_sample block above, if we have an entry here
       // it must be a ThreadId entry.
       MOZ_CRASH();
     }
 
     ProfileSample sample;
 
     if (e.Has() && e.Get().IsTime()) {
       sample.mTime = e.Get().u.mDouble;
       e.Next();
 
       // Ignore samples that are too old.
       if (sample.mTime < aSinceTime) {
-        goto skip_to_next_sample;
+        continue;
       }
 
       if (!seenFirstSample) {
         if (aOutFirstSampleTime) {
           *aOutFirstSampleTime = sample.mTime;
         }
         seenFirstSample = true;
       }
     } else {
-      ERROR_AND_SKIP_TO_NEXT_SAMPLE("expected a Time entry");
+      ERROR_AND_CONTINUE("expected a Time entry");
     }
 
     UniqueStacks::Stack stack =
       aUniqueStacks.BeginStack(UniqueStacks::OnStackFrameKey("(root)"));
 
     int numFrames = 0;
     while (e.Has()) {
       if (e.Get().IsNativeLeafAddr()) {
@@ -857,17 +868,17 @@ skip_to_next_sample:
         e.Next();
 
       } else {
         break;
       }
     }
 
     if (numFrames == 0) {
-      ERROR_AND_SKIP_TO_NEXT_SAMPLE("expected one or more frame entries");
+      ERROR_AND_CONTINUE("expected one or more frame entries");
     }
 
     sample.mStack = stack.GetOrAddIndex();
 
     // Skip over the markers. We process them in StreamMarkersToJSON().
     while (e.Has()) {
       if (e.Get().IsMarker()) {
         e.Next();
@@ -889,17 +900,17 @@ skip_to_next_sample:
     if (e.Has() && e.Get().IsUnsharedMemory()) {
       sample.mUSS = Some(e.Get().u.mDouble);
       e.Next();
     }
 
     WriteSample(aWriter, sample);
   }
 
-  #undef ERROR_AND_SKIP_TO_NEXT_SAMPLE
+  #undef ERROR_AND_CONTINUE
 }
 
 void
 ProfileBuffer::StreamMarkersToJSON(SpliceableJSONWriter& aWriter,
                                    int aThreadId,
                                    const TimeStamp& aProcessStartTime,
                                    double aSinceTime,
                                    UniqueStacks& aUniqueStacks) const
@@ -918,16 +929,71 @@ ProfileBuffer::StreamMarkersToJSON(Splic
       if (marker->GetTime() >= aSinceTime) {
         marker->StreamJSON(aWriter, aProcessStartTime, aUniqueStacks);
       }
     }
     e.Next();
   }
 }
 
+static void
+AddPausedRange(SpliceableJSONWriter& aWriter, const char* aReason,
+               const Maybe<double> aStartTime, const Maybe<double> aEndTime)
+{
+  aWriter.Start(SpliceableJSONWriter::SingleLineStyle);
+  if (aStartTime) {
+    aWriter.DoubleProperty("startTime", *aStartTime);
+  } else {
+    aWriter.NullProperty("startTime");
+  }
+  if (aEndTime) {
+    aWriter.DoubleProperty("endTime", *aEndTime);
+  } else {
+    aWriter.NullProperty("endTime");
+  }
+  aWriter.StringProperty("reason", aReason);
+  aWriter.End();
+}
+
+void
+ProfileBuffer::StreamPausedRangesToJSON(SpliceableJSONWriter& aWriter,
+                                        double aSinceTime) const
+{
+  EntryGetter e(*this);
+
+  Maybe<double> currentPauseStartTime;
+  Maybe<double> currentCollectionStartTime;
+
+  while (e.Has()) {
+    if (e.Get().IsPause()) {
+      currentPauseStartTime = Some(e.Get().u.mDouble);
+    } else if (e.Get().IsResume()) {
+      AddPausedRange(aWriter, "profiler-paused",
+                     currentPauseStartTime, Some(e.Get().u.mDouble));
+      currentPauseStartTime = Nothing();
+    } else if (e.Get().IsCollectionStart()) {
+      currentCollectionStartTime = Some(e.Get().u.mDouble);
+    } else if (e.Get().IsCollectionEnd()) {
+      AddPausedRange(aWriter, "collecting",
+                     currentCollectionStartTime, Some(e.Get().u.mDouble));
+      currentCollectionStartTime = Nothing();
+    }
+    e.Next();
+  }
+
+  if (currentPauseStartTime) {
+    AddPausedRange(aWriter, "profiler-paused",
+                   currentPauseStartTime, Nothing());
+  }
+  if (currentCollectionStartTime) {
+    AddPausedRange(aWriter, "collecting",
+                   currentCollectionStartTime, Nothing());
+  }
+}
+
 int
 ProfileBuffer::FindLastSampleOfThread(int aThreadId, const LastSample& aLS)
   const
 {
   // |aLS| has a valid generation number if either it matches the buffer's
   // generation, or is one behind the buffer's generation, since the buffer's
   // generation is incremented on wraparound.  There's no ambiguity relative to
   // ProfileBuffer::reset, since that increments mGeneration by two.
@@ -970,16 +1036,20 @@ ProfileBuffer::DuplicateLastSample(int a
 
   AddThreadIdEntry(aThreadId, &aLS);
 
   // Go through the whole entry and duplicate it, until we find the next one.
   for (int readPos = (lastSampleStartPos + 1) % mEntrySize;
        readPos != mWritePos;
        readPos = (readPos + 1) % mEntrySize) {
     switch (mEntries[readPos].GetKind()) {
+      case ProfileBufferEntry::Kind::Pause:
+      case ProfileBufferEntry::Kind::Resume:
+      case ProfileBufferEntry::Kind::CollectionStart:
+      case ProfileBufferEntry::Kind::CollectionEnd:
       case ProfileBufferEntry::Kind::ThreadId:
         // We're done.
         return true;
       case ProfileBufferEntry::Kind::Time:
         // Copy with new time
         AddEntry(ProfileBufferEntry::Time(
           (TimeStamp::Now() - aProcessStartTime).ToMilliseconds()));
         break;
--- a/tools/profiler/core/ProfileBufferEntry.h
+++ b/tools/profiler/core/ProfileBufferEntry.h
@@ -24,24 +24,28 @@
 #include "gtest/MozGtestFriend.h"
 #include "mozilla/HashFunctions.h"
 #include "mozilla/UniquePtr.h"
 
 class ProfilerMarker;
 
 #define FOR_EACH_PROFILE_BUFFER_ENTRY_KIND(macro) \
   macro(Category,              int) \
+  macro(CollectionStart,       double) \
+  macro(CollectionEnd,         double) \
   macro(Label,                 const char*) \
   macro(DynamicStringFragment, char*) /* char[kNumChars], really */ \
   macro(JitReturnAddr,         void*) \
   macro(LineNumber,            int) \
   macro(NativeLeafAddr,        void*) \
   macro(Marker,                ProfilerMarker*) \
+  macro(Pause,                 double) \
   macro(ResidentMemory,        double) \
   macro(Responsiveness,        double) \
+  macro(Resume,                double) \
   macro(ThreadId,              int) \
   macro(Time,                  double) \
   macro(UnsharedMemory,        double)
 
 // NB: Packing this structure has been shown to cause SIGBUS issues on ARM.
 #if !defined(GP_ARCH_arm)
 #pragma pack(push, 1)
 #endif
--- a/tools/profiler/core/platform.cpp
+++ b/tools/profiler/core/platform.cpp
@@ -1598,16 +1598,20 @@ locked_profiler_stream_json_for_this_pro
                                              SpliceableJSONWriter& aWriter,
                                              double aSinceTime,
                                              bool aIsShuttingDown)
 {
   LOG("locked_profiler_stream_json_for_this_process");
 
   MOZ_RELEASE_ASSERT(CorePS::Exists() && ActivePS::Exists(aLock));
 
+  double collectionStart = profiler_time();
+
+  ProfileBuffer& buffer = ActivePS::Buffer(aLock);
+
   // Put shared library info
   aWriter.StartArrayProperty("libs");
   AppendSharedLibraries(aWriter);
   aWriter.EndArray();
 
   // Put meta data
   aWriter.StartObjectProperty("meta");
   {
@@ -1630,28 +1634,28 @@ locked_profiler_stream_json_for_this_pro
   {
     const CorePS::ThreadVector& liveThreads = CorePS::LiveThreads(aLock);
     for (size_t i = 0; i < liveThreads.size(); i++) {
       ThreadInfo* info = liveThreads.at(i);
       if (!info->IsBeingProfiled()) {
         continue;
       }
       double thisThreadFirstSampleTime =
-        info->StreamJSON(ActivePS::Buffer(aLock), aWriter,
+        info->StreamJSON(buffer, aWriter,
                          CorePS::ProcessStartTime(), aSinceTime);
       firstSampleTime = std::min(thisThreadFirstSampleTime, firstSampleTime);
     }
 
     const CorePS::ThreadVector& deadThreads = CorePS::DeadThreads(aLock);
     for (size_t i = 0; i < deadThreads.size(); i++) {
       ThreadInfo* info = deadThreads.at(i);
       MOZ_ASSERT(info->IsBeingProfiled());
       double thisThreadFirstSampleTime =
-        info->StreamJSON(ActivePS::Buffer(aLock), aWriter,
-                        CorePS::ProcessStartTime(), aSinceTime);
+        info->StreamJSON(buffer, aWriter,
+                         CorePS::ProcessStartTime(), aSinceTime);
       firstSampleTime = std::min(thisThreadFirstSampleTime, firstSampleTime);
     }
 
 #if defined(GP_OS_android)
     if (ActivePS::FeatureJava(aLock)) {
       java::GeckoJavaSampler::Pause();
 
       aWriter.Start();
@@ -1661,16 +1665,33 @@ locked_profiler_stream_json_for_this_pro
       aWriter.End();
 
       java::GeckoJavaSampler::Unpause();
     }
 #endif
   }
   aWriter.EndArray();
 
+  aWriter.StartArrayProperty("pausedRanges",
+                             SpliceableJSONWriter::SingleLineStyle);
+  {
+    buffer.StreamPausedRangesToJSON(aWriter, aSinceTime);
+  }
+  aWriter.EndArray();
+
+  double collectionEnd = profiler_time();
+
+  // Record timestamps for the collection into the buffer, so that consumers
+  // know why we didn't collect any samples for its duration.
+  // We put these entries into the buffer after we've collected the profile,
+  // so they'll be visible for the *next* profile collection (if they haven't
+  // been overwritten due to buffer wraparound by then).
+  buffer.AddEntry(ProfileBufferEntry::CollectionStart(collectionStart));
+  buffer.AddEntry(ProfileBufferEntry::CollectionEnd(collectionEnd));
+
   if (firstSampleTime != INFINITY) {
     return CorePS::ProcessStartTime() +
            TimeDuration::FromMilliseconds(firstSampleTime);
   }
 
   return TimeStamp();
 }
 
@@ -2894,16 +2915,17 @@ profiler_pause()
   {
     PSAutoLock lock(gPSMutex);
 
     if (!ActivePS::Exists(lock)) {
       return;
     }
 
     ActivePS::SetIsPaused(lock, true);
+    ActivePS::Buffer(lock).AddEntry(ProfileBufferEntry::Pause(profiler_time()));
   }
 
   // gPSMutex must be unlocked when we notify, to avoid potential deadlocks.
   ProfilerParent::ProfilerPaused();
   NotifyObservers("profiler-paused");
 }
 
 void
@@ -2915,16 +2937,17 @@ profiler_resume()
 
   {
     PSAutoLock lock(gPSMutex);
 
     if (!ActivePS::Exists(lock)) {
       return;
     }
 
+    ActivePS::Buffer(lock).AddEntry(ProfileBufferEntry::Resume(profiler_time()));
     ActivePS::SetIsPaused(lock, false);
   }
 
   // gPSMutex must be unlocked when we notify, to avoid potential deadlocks.
   ProfilerParent::ProfilerResumed();
   NotifyObservers("profiler-resumed");
 }