Clean-up and repair cumulative marking and sweeping time stats.

BUG=
R=ernstm@chromium.org

Review URL: https://codereview.chromium.org/432743002

git-svn-id: https://v8.googlecode.com/svn/branches/bleeding_edge@22777 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

src/gc-tracer.cc

@@ -75,7 +75,9 @@ GCTracer::GCTracer(Heap* heap)
       cumulative_incremental_marking_steps_(0),
       cumulative_incremental_marking_bytes_(0),
       cumulative_incremental_marking_duration_(0.0),
-      longest_incremental_marking_step_(0.0) {
+      longest_incremental_marking_step_(0.0),
+      cumulative_marking_duration_(0.0),
+      cumulative_sweeping_duration_(0.0) {
   current_ = Event(Event::START, NULL, NULL);
   current_.end_time = base::OS::TimeCurrentMillis();
   previous_ = previous_mark_compactor_event_ = current_;
@@ -174,6 +176,7 @@ void GCTracer::AddIncrementalMarkingStep(double duration, intptr_t bytes) {
   cumulative_incremental_marking_duration_ += duration;
   longest_incremental_marking_step_ =
       Max(longest_incremental_marking_step_, duration);
+  cumulative_marking_duration_ += duration;
 }
 
 

src/gc-tracer.h

@@ -220,6 +220,26 @@ class GCTracer BASE_EMBEDDED {
   // Log an incremental marking step.
   void AddIncrementalMarkingStep(double duration, intptr_t bytes);
 
+  // Log time spent in marking.
+  void AddMarkingTime(double duration) {
+    cumulative_marking_duration_ += duration;
+  }
+
+  // Time spent in marking.
+  double cumulative_marking_duration() const {
+    return cumulative_marking_duration_;
+  }
+
+  // Log time spent in sweeping on main thread.
+  void AddSweepingTime(double duration) {
+    cumulative_sweeping_duration_ += duration;
+  }
+
+  // Time spent in sweeping on main thread.
+  double cumulative_sweeping_duration() const {
+    return cumulative_sweeping_duration_;
+  }
+
   // Compute the mean duration of the last scavenger events. Returns 0 if no
   // events have been recorded.
   double MeanScavengerDuration() const {
@@ -301,6 +321,19 @@ class GCTracer BASE_EMBEDDED {
   // Longest incremental marking step since start of marking.
   double longest_incremental_marking_step_;
 
+  // Total marking time.
+  // This timer is precise when run with --print-cumulative-gc-stat
+  double cumulative_marking_duration_;
+
+  // Total sweeping time on the main thread.
+  // This timer is precise when run with --print-cumulative-gc-stat
+  // TODO(hpayer): Account for sweeping time on sweeper threads. Add a
+  // different field for that.
+  // TODO(hpayer): This timer right now just holds the sweeping time
+  // of the initial atomic sweeping pause. Make sure that it accumulates
+  // all sweeping operations performed on the main thread.
+  double cumulative_sweeping_duration_;
+
   DISALLOW_COPY_AND_ASSIGN(GCTracer);
 };
 }

src/heap.cc

@@ -5206,8 +5206,8 @@ void Heap::TearDown() {
     PrintF("min_in_mutator=%.1f ", get_min_in_mutator());
     PrintF("max_alive_after_gc=%" V8_PTR_PREFIX "d ",
            get_max_alive_after_gc());
-    PrintF("total_marking_time=%.1f ", marking_time());
-    PrintF("total_sweeping_time=%.1f ", sweeping_time());
+    PrintF("total_marking_time=%.1f ", tracer_.cumulative_sweeping_duration());
+    PrintF("total_sweeping_time=%.1f ", tracer_.cumulative_sweeping_duration());
     PrintF("\n\n");
   }
 

src/heap.h

@@ -1246,24 +1246,6 @@ class Heap {
   // Returns minimal interval between two subsequent collections.
   double get_min_in_mutator() { return min_in_mutator_; }
 
-  // TODO(hpayer): remove, should be handled by GCTracer
-  void AddMarkingTime(double marking_time) {
-    marking_time_ += marking_time;
-  }
-
-  double marking_time() const {
-    return marking_time_;
-  }
-
-  // TODO(hpayer): remove, should be handled by GCTracer
-  void AddSweepingTime(double sweeping_time) {
-    sweeping_time_ += sweeping_time;
-  }
-
-  double sweeping_time() const {
-    return sweeping_time_;
-  }
-
   MarkCompactCollector* mark_compact_collector() {
     return &mark_compact_collector_;
   }

src/incremental-marking.cc

@@ -731,7 +731,7 @@ void IncrementalMarking::Hurry() {
     if (FLAG_trace_incremental_marking || FLAG_print_cumulative_gc_stat) {
       double end = base::OS::TimeCurrentMillis();
       double delta = end - start;
-      heap_->AddMarkingTime(delta);
+      heap_->tracer()->AddMarkingTime(delta);
       if (FLAG_trace_incremental_marking) {
         PrintF("[IncrementalMarking] Complete (hurry), spent %d ms.\n",
                static_cast<int>(delta));
@@ -963,7 +963,6 @@ void IncrementalMarking::Step(intptr_t allocated_bytes,
     // when we just started incremental marking. In these cases we did not
     // process the marking deque.
     heap_->tracer()->AddIncrementalMarkingStep(duration, bytes_processed);
-    heap_->AddMarkingTime(duration);
   }
 }
 

src/mark-compact.cc

@@ -2291,6 +2291,10 @@ void MarkCompactCollector::ProcessTopOptimizedFrame(ObjectVisitor* visitor) {
 
 void MarkCompactCollector::MarkLiveObjects() {
   GCTracer::Scope gc_scope(heap()->tracer(), GCTracer::Scope::MC_MARK);
+  double start_time = 0.0;
+  if (FLAG_print_cumulative_gc_stat) {
+    start_time = base::OS::TimeCurrentMillis();
+  }
   // The recursive GC marker detects when it is nearing stack overflow,
   // and switches to a different marking system.  JS interrupts interfere
   // with the C stack limit check.
@@ -2395,6 +2399,10 @@ void MarkCompactCollector::MarkLiveObjects() {
   ProcessEphemeralMarking(&root_visitor);
 
   AfterMarking();
+
+  if (FLAG_print_cumulative_gc_stat) {
+    heap_->tracer()->AddMarkingTime(base::OS::TimeCurrentMillis() - start_time);
+  }
 }
 
 
@@ -3284,11 +3292,6 @@ static int SweepPrecisely(PagedSpace* space,
   ASSERT(parallelism == MarkCompactCollector::SWEEP_ON_MAIN_THREAD ||
          sweeping_mode == SWEEP_ONLY);
 
-  double start_time = 0.0;
-  if (FLAG_print_cumulative_gc_stat) {
-    start_time = base::OS::TimeCurrentMillis();
-  }
-
   Address free_start = p->area_start();
   ASSERT(reinterpret_cast<intptr_t>(free_start) % (32 * kPointerSize) == 0);
   int offsets[16];
@@ -3359,9 +3362,6 @@ static int SweepPrecisely(PagedSpace* space,
 #endif
   }
   p->ResetLiveBytes();
-  if (FLAG_print_cumulative_gc_stat) {
-    space->heap()->AddSweepingTime(base::OS::TimeCurrentMillis() - start_time);
-  }
 
   if (parallelism == MarkCompactCollector::SWEEP_IN_PARALLEL) {
     // When concurrent sweeping is active, the page will be marked after
@@ -4308,6 +4308,11 @@ static bool ShouldWaitForSweeperThreads(
 
 void MarkCompactCollector::SweepSpaces() {
   GCTracer::Scope gc_scope(heap()->tracer(), GCTracer::Scope::MC_SWEEP);
+  double start_time = 0.0;
+  if (FLAG_print_cumulative_gc_stat) {
+    start_time = base::OS::TimeCurrentMillis();
+  }
+
 #ifdef DEBUG
   state_ = SWEEP_SPACES;
 #endif
@@ -4372,6 +4377,11 @@ void MarkCompactCollector::SweepSpaces() {
 
   // Deallocate evacuated candidate pages.
   ReleaseEvacuationCandidates();
+
+  if (FLAG_print_cumulative_gc_stat) {
+    heap_->tracer()->AddSweepingTime(base::OS::TimeCurrentMillis() -
+                                     start_time);
+  }
 }