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

--HG--
extra : rebase_source : 9ba0f7d87ee39dff3b54916d3f7369432240b2df

tools/profiler/core/ProfileBuffer.h

@@ -64,6 +64,8 @@ public:
                            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.

tools/profiler/core/ProfileBufferEntry.cpp

@@ -590,20 +590,26 @@ private:
   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
@@ -705,42 +711,47 @@ ProfileBuffer::StreamSamplesToJSON(SpliceableJSONWriter& aWriter, int aThreadId,
   // 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()) {
-      break;
-    } else {
-      e.Next();
+  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;
     }
-  }
 
-  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
@@ -756,7 +767,7 @@ skip_to_next_sample:
 
       // Ignore samples that are too old.
       if (sample.mTime < aSinceTime) {
-        goto skip_to_next_sample;
+        continue;
       }
 
       if (!seenFirstSample) {
@@ -766,7 +777,7 @@ skip_to_next_sample:
         seenFirstSample = true;
       }
     } else {
-      ERROR_AND_SKIP_TO_NEXT_SAMPLE("expected a Time entry");
+      ERROR_AND_CONTINUE("expected a Time entry");
     }
 
     UniqueStacks::Stack stack =
@@ -862,7 +873,7 @@ skip_to_next_sample:
     }
 
     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();
@@ -894,7 +905,7 @@ skip_to_next_sample:
     WriteSample(aWriter, sample);
   }
 
-  #undef ERROR_AND_SKIP_TO_NEXT_SAMPLE
+  #undef ERROR_AND_CONTINUE
 }
 
 void
@@ -923,6 +934,61 @@ ProfileBuffer::StreamMarkersToJSON(SpliceableJSONWriter& aWriter,
   }
 }
 
+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
@@ -975,6 +1041,10 @@ ProfileBuffer::DuplicateLastSample(int aThreadId,
        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;

tools/profiler/core/ProfileBufferEntry.h

@@ -29,14 +29,18 @@ 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)

tools/profiler/core/platform.cpp

@@ -1603,6 +1603,10 @@ locked_profiler_stream_json_for_this_process(PSLockRef aLock,
 
   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);
@@ -1635,7 +1639,7 @@ locked_profiler_stream_json_for_this_process(PSLockRef aLock,
         continue;
       }
       double thisThreadFirstSampleTime =
-        info->StreamJSON(ActivePS::Buffer(aLock), aWriter,
+        info->StreamJSON(buffer, aWriter,
                          CorePS::ProcessStartTime(), aSinceTime);
       firstSampleTime = std::min(thisThreadFirstSampleTime, firstSampleTime);
     }
@@ -1645,8 +1649,8 @@ locked_profiler_stream_json_for_this_process(PSLockRef aLock,
       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);
     }
 
@@ -1666,6 +1670,23 @@ locked_profiler_stream_json_for_this_process(PSLockRef aLock,
   }
   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);
@@ -2899,6 +2920,7 @@ profiler_pause()
     }
 
     ActivePS::SetIsPaused(lock, true);
+    ActivePS::Buffer(lock).AddEntry(ProfileBufferEntry::Pause(profiler_time()));
   }
 
   // gPSMutex must be unlocked when we notify, to avoid potential deadlocks.
@@ -2920,6 +2942,7 @@ profiler_resume()
       return;
     }
 
+    ActivePS::Buffer(lock).AddEntry(ProfileBufferEntry::Resume(profiler_time()));
     ActivePS::SetIsPaused(lock, false);
   }