Correct inclusive time and start tracking maximum exclusive time

runtime/vm/timeline_analysis.cc

 // Copyright (c) 2015, the Dart project authors.  Please see the AUTHORS file
 // for details. All rights reserved. Use of this source code is governed by a
 // BSD-style license that can be found in the LICENSE file.
 
 #include "vm/timeline_analysis.h"
 
 #include "vm/flags.h"
 #include "vm/log.h"
 #include "vm/os_thread.h"
 
@@ skipping 20 matching lines @@
   ASSERT(a != NULL);
   ASSERT(*a != NULL);
   ASSERT(b != NULL);
   ASSERT(*b != NULL);
   return (*a)->LowerTimeBound() - (*b)->LowerTimeBound();
 }
 
 
 void TimelineAnalysisThread::Finalize() {
   blocks_.Sort(CompareBlocksLowerTimeBound);
-  ISL_Print("Thread %" Px " has %" Pd " blocks\n",
-            OSThread::ThreadIdToIntPtr(id_),
-            blocks_.length());
+  if (FLAG_trace_timeline_analysis) {
+    ISL_Print("Thread %" Px " has %" Pd " blocks\n",
+              OSThread::ThreadIdToIntPtr(id_),
+              blocks_.length());
+  }
 }
 
 
 TimelineAnalysisThreadEventIterator::TimelineAnalysisThreadEventIterator(
     TimelineAnalysisThread* thread) {
   Reset(thread);
 }
 
 
 TimelineAnalysisThreadEventIterator::~TimelineAnalysisThreadEventIterator() {
@@ skipping 138 matching lines @@
   va_start(args, format);
   error_msg_ = zone_->VPrint(format, args);
   ASSERT(error_msg_ != NULL);
 }
 
 
 TimelineLabelPauseInfo::TimelineLabelPauseInfo(const char* name)
     : name_(name),
       inclusive_micros_(0),
       exclusive_micros_(0),
-      max_duration_micros_(0) {
+      max_inclusive_micros_(0),
+      max_exclusive_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::OnPush(int64_t micros, bool already_on_stack) {
+  if (!already_on_stack) {
+    // Only adjust inclusive counts if we aren't already on the stack.
+    add_inclusive_micros(micros);
+    if (micros > max_inclusive_micros_) {
+      max_inclusive_micros_ = micros;
+    }
   }
 }
 
 
-void TimelineLabelPauseInfo::OnChildPush(int64_t micros) {
-  ASSERT(micros >= 0);
-  add_exclusive_micros(-micros);
+void TimelineLabelPauseInfo::OnPop(int64_t exclusive_micros) {
+  add_exclusive_micros(exclusive_micros);
+  if (exclusive_micros > max_exclusive_micros_) {
+    max_exclusive_micros_ = exclusive_micros;
+  }
 }
 
 
 TimelinePauses::TimelinePauses(Zone* zone,
                                Isolate* isolate,
                                TimelineEventRecorder* recorder)
     : TimelineAnalysis(zone, isolate, recorder) {
 }
 
 
 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 {
+TimelineLabelPauseInfo* TimelinePauses::GetLabelPauseInfo(
+    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);
+  TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
   ASSERT(pause_info != NULL);
   return pause_info->inclusive_micros();
 }
 
 
 int64_t TimelinePauses::ExclusiveTime(const char* name) const {
-  TimelineLabelPauseInfo* pause_info = GetLabel(name);
+  TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
   ASSERT(pause_info != NULL);
   return pause_info->exclusive_micros();
 }
 
 
-int64_t TimelinePauses::MaxDurationTime(const char* name) const {
-  TimelineLabelPauseInfo* pause_info = GetLabel(name);
+int64_t TimelinePauses::MaxInclusiveTime(const char* name) const {
+  TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
   ASSERT(pause_info != NULL);
-  return pause_info->max_duration_micros();
+  return pause_info->max_inclusive_micros();
 }
 
 
+int64_t TimelinePauses::MaxExclusiveTime(const char* name) const {
+  TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
+  ASSERT(pause_info != NULL);
+  return pause_info->max_exclusive_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()));
   }
@@ skipping 20 matching lines @@
               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)) {
+    const StackItem& slot = stack_.At(i);
+    if (!slot.event->DurationContains(event)) {
       return false;
     }
   }
   return true;
 }
 
 
 void TimelinePauses::PopFinished(int64_t start) {
   while (stack_.length() > 0) {
-    TimelineEvent* top = stack_.Last();
-    if (top->DurationFinishedBefore(start)) {
+    const StackItem& top = stack_.Last();
+    if (top.event->DurationFinishedBefore(start)) {
+      top.pause_info->OnPop(top.exclusive_micros);
       // Top of stack completes before |start|.
       stack_.RemoveLast();
       if (FLAG_trace_timeline_analysis) {
         ISL_Print("Popping %s (%" Pd64 " <= %" Pd64 ")\n",
-                  top->label(),
-                  top->TimeEnd(),
+                  top.event->label(),
+                  top.event->TimeEnd(),
                   start);
       }
     } else {
       return;
     }
   }
 }
 
 
 void TimelinePauses::Push(TimelineEvent* event) {
-  TimelineLabelPauseInfo* pause_info = GetOrAddLabel(event->label());
+  TimelineLabelPauseInfo* pause_info = GetOrAddLabelPauseInfo(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());
+  pause_info->OnPush(event->TimeDuration(), IsLabelOnStack(event->label()));

[srdjan, 2015/08/17 17:37:11]

Is it better to do:
if (!isLabelOnStack(..)) {
  pause_info->OnPush(event->TimeDuration())
}

or is it better to pass an extra argument?

[Cutch, 2015/08/17 17:51:12]

At one point we needed the extra argument, right now we don't but I'd like to
keep providing the bit of information to ::OnPush in case I need it again.

+  if (StackDepth() > 0) {
+    StackItem& top = GetStackTop();
+    // |top| is under |event|'s shadow, adjust the exclusive micros.
+    top.exclusive_micros -= event->TimeDuration();
   }
   // Push onto the stack.
-  stack_.Add(event);
+  StackItem item;
+  item.event = event;
+  item.pause_info = pause_info;
+  item.exclusive_micros = event->TimeDuration();
+  stack_.Add(item);
 }
 
 
-TimelineLabelPauseInfo* TimelinePauses::GetTopLabel() {
-  if (stack_.length() == 0) {
-    return NULL;
+bool TimelinePauses::IsLabelOnStack(const char* label) {

[srdjan, 2015/08/17 17:37:11]

const

[Cutch, 2015/08/17 17:51:12]

Done (in a CL I'm working on now).

+  ASSERT(label != NULL);
+  for (intptr_t i = 0; i < stack_.length(); i++) {
+    const StackItem& slot = stack_.At(i);
+    if (strcmp(slot.event->label(), label) == 0) {
+      return true;
+    }
   }
-  TimelineEvent* event = stack_.Last();
-  return GetLabel(event->label());
+  return false;
 }
 
 
-TimelineLabelPauseInfo* TimelinePauses::GetOrAddLabel(const char* name) {
+intptr_t TimelinePauses::StackDepth() const {
+  return stack_.length();
+}
+
+
+TimelinePauses::StackItem& TimelinePauses::GetStackTop() {

[srdjan, 2015/08/17 17:37:11]

const

[Cutch, 2015/08/17 17:51:12]

Cannot be done because StackItem& is modified by the caller.

+  ASSERT(stack_.length() > 0);
+  return stack_.Last();
+}
+
+
+TimelineLabelPauseInfo* TimelinePauses::GetOrAddLabelPauseInfo(
+    const char* name) {
   ASSERT(name != NULL);
-  TimelineLabelPauseInfo* label = GetLabel(name);
-  if (label != NULL) {
-    return label;
+  TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
+  if (pause_info != NULL) {
+    return pause_info;
   }
   // New label.
-  label = new TimelineLabelPauseInfo(name);
-  labels_.Add(label);
-  return label;
+  pause_info = new TimelineLabelPauseInfo(name);
+  labels_.Add(pause_info);
+  return pause_info;
 }
 
 }  // namespace dart