Add TimelinePauses analysis and tests

runtime/vm/timeline_analysis.cc

Index: runtime/vm/timeline_analysis.cc
diff --git a/runtime/vm/timeline_analysis.cc b/runtime/vm/timeline_analysis.cc
index 34bedda4bf06c973163a1e8201621528f17129a5..5cb2e2fb12bbb944e6646b525aad074f1452e0d5 100644
--- a/runtime/vm/timeline_analysis.cc
+++ b/runtime/vm/timeline_analysis.cc
@@ -5,11 +5,12 @@
 #include "vm/timeline_analysis.h"
 
 #include "vm/flags.h"
+#include "vm/log.h"
+#include "vm/os_thread.h"
 
 namespace dart {
 
-DECLARE_FLAG(bool, trace_timeline);
-
+DEFINE_FLAG(bool, trace_timeline_analysis, false, "Trace timeline analysis");
 
 TimelineAnalysisThread::TimelineAnalysisThread(ThreadId id)
     : id_(id) {
@@ -37,6 +38,9 @@ static int CompareBlocksLowerTimeBound(TimelineEventBlock* const* a,
 
 void TimelineAnalysisThread::Finalize() {
   blocks_.Sort(CompareBlocksLowerTimeBound);
+  ISL_Print("Thread %" Px " has %" Pd " blocks\n",
+            OSThread::ThreadIdToIntPtr(id_),
+            blocks_.length());
 }
 
 
@@ -156,9 +160,13 @@ void TimelineAnalysis::DiscoverThreads() {
       continue;
     }
     if (!block->CheckBlock()) {
-      // Skip bad blocks.
-      // TODO(johnmccutchan): Make this into an error?
-      continue;
+      if (FLAG_trace_timeline_analysis) {
+        ISL_Print("DiscoverThreads block %" Pd " "
+                  "violates invariants.\n", block->block_index());
+      }
+      SetError("Block %" Pd " violates invariants. See "
+               "TimelineEventBlock::CheckBlock", block->block_index());
+      return;
     }
     TimelineAnalysisThread* thread = GetOrAddThread(block->thread());
     ASSERT(thread != NULL);
@@ -187,6 +195,30 @@ void TimelineAnalysis::SetError(const char* format, ...) {
 }
 
 
+TimelineLabelPauseInfo::TimelineLabelPauseInfo(const char* name)
+    : name_(name),
+      inclusive_micros_(0),
+      exclusive_micros_(0),
+      max_duration_micros_(0) {
+  ASSERT(name_ != NULL);
+}
+
+
+void TimelineLabelPauseInfo::OnPush(int64_t micros) {
+  add_inclusive_micros(micros);
+  add_exclusive_micros(micros);
+  if (micros > max_duration_micros_) {
+    max_duration_micros_ = micros;
+  }
+}
+
+
+void TimelineLabelPauseInfo::OnChildPush(int64_t micros) {
+  ASSERT(micros >= 0);
+  add_exclusive_micros(-micros);
+}
+
+
 TimelinePauses::TimelinePauses(Zone* zone,
                                Isolate* isolate,
                                TimelineEventRecorder* recorder)
@@ -194,7 +226,170 @@ TimelinePauses::TimelinePauses(Zone* zone,
 }
 
 
-void TimelinePauses::CalculatePauseTimes() {
+void TimelinePauses::Setup() {
+  BuildThreads();
+}
+
+
+void TimelinePauses::CalculatePauseTimesForThread(ThreadId tid) {
+  if (has_error()) {
+    return;
+  }
+  TimelineAnalysisThread* thread = GetThread(tid);
+  if (thread == NULL) {
+    SetError("Thread %" Px " does not exist.", OSThread::ThreadIdToIntPtr(tid));
+    return;
+  }
+  ProcessThread(thread);
+}
+
+
+TimelineLabelPauseInfo* TimelinePauses::GetLabel(const char* name) const {
+  ASSERT(name != NULL);
+  // Linear lookup because we expect N (# of labels in an isolate) to be small.
+  for (intptr_t i = 0; i < labels_.length(); i++) {
+    TimelineLabelPauseInfo* label = labels_.At(i);
+    if (strcmp(label->name(), name) == 0) {
+      return label;
+    }
+  }
+  return NULL;
+}
+
+
+int64_t TimelinePauses::InclusiveTime(const char* name) const {
+  TimelineLabelPauseInfo* pause_info = GetLabel(name);
+  ASSERT(pause_info != NULL);
+  return pause_info->inclusive_micros();
+}
+
+
+int64_t TimelinePauses::ExclusiveTime(const char* name) const {
+  TimelineLabelPauseInfo* pause_info = GetLabel(name);
+  ASSERT(pause_info != NULL);
+  return pause_info->exclusive_micros();
+}
+
+
+int64_t TimelinePauses::MaxDurationTime(const char* name) const {
+  TimelineLabelPauseInfo* pause_info = GetLabel(name);
+  ASSERT(pause_info != NULL);
+  return pause_info->max_duration_micros();
+}
+
+
+void TimelinePauses::ProcessThread(TimelineAnalysisThread* thread) {
+  ASSERT(thread != NULL);
+  stack_.Clear();
+  labels_.Clear();
+
+  TimelineAnalysisThreadEventIterator it(thread);
+  if (FLAG_trace_timeline_analysis) {
+    ISL_Print(">>> TimelinePauses::ProcessThread %" Px "\n",
+              OSThread::ThreadIdToIntPtr(thread->id()));
+  }
+  intptr_t event_count = 0;
+  while (it.HasNext()) {
+    TimelineEvent* event = it.Next();
+    if (!event->IsFinishedDuration()) {
+      // We only care about finished duration events.
+      continue;
+    }
+    int64_t start = event->TimeOrigin();
+    PopFinished(start);
+    if (!CheckStack(event)) {
+      SetError("Duration check fail.");
+      return;
+    }
+    event_count++;
+    Push(event);
+  }
+  // Pop remaining stack.
+  PopFinished(kMaxInt64);
+  if (FLAG_trace_timeline_analysis) {
+    ISL_Print("<<< TimelinePauses::ProcessThread %" Px " had %" Pd " events\n",
+              OSThread::ThreadIdToIntPtr(thread->id()),
+              event_count);
+  }
+}
+
+
+// Verify that |event| is contained within all parent events on the stack.
+bool TimelinePauses::CheckStack(TimelineEvent* event) {
+  ASSERT(event != NULL);
+  for (intptr_t i = 0; i < stack_.length(); i++) {
+    TimelineEvent* slot = stack_.At(i);
+    if (!slot->DurationContains(event)) {
+      return false;
+    }
+  }
+  return true;
+}
+
+
+void TimelinePauses::PopFinished(int64_t start) {
+  while (stack_.length() > 0) {
+    TimelineEvent* top = stack_.Last();
+    if (top->DurationFinishedBefore(start)) {
+      // Top of stack completes before |start|.
+      stack_.RemoveLast();
+      if (FLAG_trace_timeline_analysis) {
+        ISL_Print("Popping %s (%" Pd64 " <= %" Pd64 ")\n",
+                  top->label(),
+                  top->TimeEnd(),
+                  start);
+      }
+    } else {
+      return;
+    }
+  }
+}
+
+
+void TimelinePauses::Push(TimelineEvent* event) {
+  TimelineLabelPauseInfo* pause_info = GetOrAddLabel(event->label());
+  ASSERT(pause_info != NULL);
+  // |pause_info| will be running for |event->TimeDuration()|.
+  if (FLAG_trace_timeline_analysis) {
+    ISL_Print("Pushing %s %" Pd64 " us\n",
+              pause_info->name(),
+              event->TimeDuration());
+  }
+  pause_info->OnPush(event->TimeDuration());
+  TimelineLabelPauseInfo* top_pause_info = GetTopLabel();
+  if (top_pause_info != NULL) {
+    // |top_pause_info| is under |event|'s shadow, adjust the exclusive micros.
+    if (FLAG_trace_timeline_analysis) {
+      ISL_Print("Adjusting %s by %" Pd64 " us\n",
+                top_pause_info->name(),
+                event->TimeDuration());
+    }
+    top_pause_info->OnChildPush(event->TimeDuration());
+  }
+  // Push onto the stack.
+  stack_.Add(event);
+}
+
+
+TimelineLabelPauseInfo* TimelinePauses::GetTopLabel() {
+  if (stack_.length() == 0) {
+    return NULL;
+  }
+  TimelineEvent* event = stack_.Last();
+  return GetLabel(event->label());
+}
+
+
+TimelineLabelPauseInfo* TimelinePauses::GetOrAddLabel(const char* name) {
+  ASSERT(name != NULL);
+  TimelineLabelPauseInfo* label = GetLabel(name);
+  if (label != NULL) {
+    return label;
+  }
+  // New label.
+  label = new TimelineLabelPauseInfo(name);
+  labels_.Add(label);
+  return label;
 }
 
 }  // namespace dart