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 draft
authorMarkus Stange <mstange@themasta.com>
Mon, 31 Jul 2017 14:44:35 -0400
changeset 618570 c0c14c758588be6ca6b58492d54736df95f38506
parent 618569 7458f2c4b12a0848462a17d750fbc6d932313917
child 618571 493f9368d1a4d3a988c2db74e7d7c979839dcbc1
push id71382
push userbmo:mstange@themasta.com
push dateMon, 31 Jul 2017 18:46:43 +0000
reviewersnjn
bugs1384688
milestone56.0a1
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");
 }