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
--- 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");
}