Make incremental marking tracing format consistent with GC tracing.

src/heap/gc-tracer.cc

 // Copyright 2014 the V8 project authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "src/heap/gc-tracer.h"
 
 #include "src/counters.h"
 #include "src/heap/heap-inl.h"
 #include "src/isolate.h"
 
@@ skipping 210 matching lines @@
        i <= Scope::LAST_INCREMENTAL_SCOPE; i++) {
     current_.scopes[i] =
         current_.incremental_marking_scopes[i].cumulative_duration -
         baseline.incremental_marking_scopes[i].cumulative_duration;
   }
 }
 
 void GCTracer::Stop(GarbageCollector collector) {
   start_counter_--;
   if (start_counter_ != 0) {
-    PrintIsolate(heap_->isolate(), "[Finished reentrant %s during %s.]\n",
-                 collector == SCAVENGER ? "Scavenge" : "Mark-sweep",
-                 current_.TypeName(false));
+    heap_->isolate()->PrintWithTimestamp(
+        "[Finished reentrant %s during %s.]\n",
+        collector == SCAVENGER ? "Scavenge" : "Mark-sweep",
+        current_.TypeName(false));
     return;
   }
 
   DCHECK(start_counter_ >= 0);
   DCHECK((collector == SCAVENGER && current_.type == Event::SCAVENGER) ||
          (collector == MARK_COMPACTOR &&
           (current_.type == Event::MARK_COMPACTOR ||
            current_.type == Event::INCREMENTAL_MARK_COMPACTOR)));
 
   for (int i = Scope::FIRST_INCREMENTAL_SCOPE;
@@ skipping 157 matching lines @@
 
   heap_->AddToRingBuffer(buffer.start());
 }
 
 
 void GCTracer::Print() const {
   double duration = current_.end_time - current_.start_time;
   const size_t kIncrementalStatsSize = 128;
   char incremental_buffer[kIncrementalStatsSize] = {0};
 
-  if (current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps > 0) {
-    if (current_.type == Event::SCAVENGER) {
-      base::OS::SNPrintF(
-          incremental_buffer, kIncrementalStatsSize,
-          " (+ %.1f ms in %d steps since last GC)",
-          current_.scopes[Scope::MC_INCREMENTAL],
-          current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps);
-    } else {
-      base::OS::SNPrintF(
-          incremental_buffer, kIncrementalStatsSize,
-          " (+ %.1f ms in %d steps since start of marking, "
-          "biggest step %.1f ms)",
-          current_.scopes[Scope::MC_INCREMENTAL],
-          current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
-          current_.incremental_marking_scopes[Scope::MC_INCREMENTAL]
-              .longest_step);
-    }
+  if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
+    base::OS::SNPrintF(
+        incremental_buffer, kIncrementalStatsSize,
+        " (+ %.1f ms in %d steps since start of marking, "
+        "biggest step %.1f ms, walltime since start of marking %.f ms)",
+        current_.scopes[Scope::MC_INCREMENTAL],
+        current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
+        current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].longest_step,
+        current_.end_time - incremental_marking_start_time_);
   }
 
   // Avoid PrintF as Output also appends the string to the tracing ring buffer
   // that gets printed on OOM failures.
   Output(
       "[%d:%p] "
       "%8.0f ms: "
       "%s %.1f (%.1f) -> %.1f (%.1f) MB, "
       "%.1f / %.1f ms %s %s %s\n",
       base::OS::GetCurrentProcessId(),
       reinterpret_cast<void*>(heap_->isolate()),
       heap_->isolate()->time_millis_since_init(), current_.TypeName(false),
       static_cast<double>(current_.start_object_size) / MB,
       static_cast<double>(current_.start_memory_size) / MB,
       static_cast<double>(current_.end_object_size) / MB,
       static_cast<double>(current_.end_memory_size) / MB, duration,
       TotalExternalTime(), incremental_buffer,
       current_.gc_reason != nullptr ? current_.gc_reason : "",
       current_.collector_reason != nullptr ? current_.collector_reason : "");
 }
 
 
 void GCTracer::PrintNVP() const {
   double duration = current_.end_time - current_.start_time;
   double spent_in_mutator = current_.start_time - previous_.end_time;
   intptr_t allocated_since_last_gc =
       current_.start_object_size - previous_.end_object_size;
 
+  double incremental_walltime_duration = 0;
+
+  if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
+    incremental_walltime_duration =
+        current_.end_time - incremental_marking_start_time_;
+  }
+
   switch (current_.type) {
     case Event::SCAVENGER:
-      PrintIsolate(
-          heap_->isolate(),
-          "%8.0f ms: "
+      heap_->isolate()->PrintWithTimestamp(
           "pause=%.1f "
           "mutator=%.1f "
           "gc=%s "
           "reduce_memory=%d "
           "scavenge=%.2f "
           "old_new=%.2f "
           "weak=%.2f "
           "roots=%.2f "
           "code=%.2f "
           "semispace=%.2f "
@@ skipping 20 matching lines @@
           " "
           "nodes_died_in_new=%d "
           "nodes_copied_in_new=%d "
           "nodes_promoted=%d "
           "promotion_ratio=%.1f%% "
           "average_survival_ratio=%.1f%% "
           "promotion_rate=%.1f%% "
           "semi_space_copy_rate=%.1f%% "
           "new_space_allocation_throughput=%.1f "
           "context_disposal_rate=%.1f\n",
-          heap_->isolate()->time_millis_since_init(), duration,
-          spent_in_mutator, current_.TypeName(true), current_.reduce_memory,
-          current_.scopes[Scope::SCAVENGER_SCAVENGE],
+          duration, spent_in_mutator, current_.TypeName(true),
+          current_.reduce_memory, current_.scopes[Scope::SCAVENGER_SCAVENGE],
           current_.scopes[Scope::SCAVENGER_OLD_TO_NEW_POINTERS],
           current_.scopes[Scope::SCAVENGER_WEAK],
           current_.scopes[Scope::SCAVENGER_ROOTS],
           current_.scopes[Scope::SCAVENGER_CODE_FLUSH_CANDIDATES],
           current_.scopes[Scope::SCAVENGER_SEMISPACE],
           current_.scopes[Scope::SCAVENGER_OBJECT_GROUPS],
           current_.scopes[Scope::SCAVENGER_EXTERNAL_PROLOGUE],
           current_.scopes[Scope::SCAVENGER_EXTERNAL_EPILOGUE],
           current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
           current_.incremental_marking_scopes[GCTracer::Scope::MC_INCREMENTAL]
               .steps,
           current_.scopes[Scope::MC_INCREMENTAL],
           ScavengeSpeedInBytesPerMillisecond(), current_.start_object_size,
           current_.end_object_size, current_.start_holes_size,
           current_.end_holes_size, allocated_since_last_gc,
           heap_->promoted_objects_size(),
           heap_->semi_space_copied_object_size(),
           heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
           heap_->nodes_promoted_, heap_->promotion_ratio_,
           AverageSurvivalRatio(), heap_->promotion_rate_,
           heap_->semi_space_copied_rate_,
           NewSpaceAllocationThroughputInBytesPerMillisecond(),
           ContextDisposalRateInMilliseconds());
       break;
     case Event::MARK_COMPACTOR:
     case Event::INCREMENTAL_MARK_COMPACTOR:
-      PrintIsolate(
-          heap_->isolate(),
-          "%8.0f ms: "
+      heap_->isolate()->PrintWithTimestamp(
           "pause=%.1f "
           "mutator=%.1f "
           "gc=%s "
           "reduce_memory=%d "
           "clear=%1.f "
           "clear.code_flush=%.1f "
           "clear.dependent_code=%.1f "
           "clear.global_handles=%.1f "
           "clear.maps=%.1f "
           "clear.slots_buffer=%.1f "
@@ skipping 38 matching lines @@
           "incremental.finalize.external.epilogue=%.1f "
           "incremental.finalize.object_grouping=%.1f "
           "incremental.wrapper_prologue=%.1f "
           "incremental.wrapper_tracing=%.1f "
           "incremental_wrapper_tracing_longest_step=%.1f "
           "incremental_finalize_longest_step=%.1f "
           "incremental_finalize_steps_count=%d "
           "incremental_longest_step=%.1f "
           "incremental_steps_count=%d "
           "incremental_marking_throughput=%.f "
+          "incremental_walltime_duration=%.f "
           "total_size_before=%" V8PRIdPTR
           " "
           "total_size_after=%" V8PRIdPTR
           " "
           "holes_size_before=%" V8PRIdPTR
           " "
           "holes_size_after=%" V8PRIdPTR
           " "
           "allocated=%" V8PRIdPTR
           " "
           "promoted=%" V8PRIdPTR
           " "
           "semi_space_copied=%" V8PRIdPTR
           " "
           "nodes_died_in_new=%d "
           "nodes_copied_in_new=%d "
           "nodes_promoted=%d "
           "promotion_ratio=%.1f%% "
           "average_survival_ratio=%.1f%% "
           "promotion_rate=%.1f%% "
           "semi_space_copy_rate=%.1f%% "
           "new_space_allocation_throughput=%.1f "
           "context_disposal_rate=%.1f "
           "compaction_speed=%.f\n",
-          heap_->isolate()->time_millis_since_init(), duration,
-          spent_in_mutator, current_.TypeName(true), current_.reduce_memory,
-          current_.scopes[Scope::MC_CLEAR],
+          duration, spent_in_mutator, current_.TypeName(true),
+          current_.reduce_memory, current_.scopes[Scope::MC_CLEAR],
           current_.scopes[Scope::MC_CLEAR_CODE_FLUSH],
           current_.scopes[Scope::MC_CLEAR_DEPENDENT_CODE],
           current_.scopes[Scope::MC_CLEAR_GLOBAL_HANDLES],
           current_.scopes[Scope::MC_CLEAR_MAPS],
           current_.scopes[Scope::MC_CLEAR_SLOTS_BUFFER],
           current_.scopes[Scope::MC_CLEAR_STORE_BUFFER],
           current_.scopes[Scope::MC_CLEAR_STRING_TABLE],
           current_.scopes[Scope::MC_CLEAR_WEAK_CELLS],
           current_.scopes[Scope::MC_CLEAR_WEAK_COLLECTIONS],
           current_.scopes[Scope::MC_CLEAR_WEAK_LISTS],
@@ skipping 39 matching lines @@
           current_
               .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
               .longest_step,
           current_
               .incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE_BODY]
               .steps,
           current_.incremental_marking_scopes[Scope::MC_INCREMENTAL]
               .longest_step,
           current_.incremental_marking_scopes[Scope::MC_INCREMENTAL].steps,
           IncrementalMarkingSpeedInBytesPerMillisecond(),
-          current_.start_object_size, current_.end_object_size,
-          current_.start_holes_size, current_.end_holes_size,
-          allocated_since_last_gc, heap_->promoted_objects_size(),
+          incremental_walltime_duration, current_.start_object_size,
+          current_.end_object_size, current_.start_holes_size,
+          current_.end_holes_size, allocated_since_last_gc,
+          heap_->promoted_objects_size(),
           heap_->semi_space_copied_object_size(),
           heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
           heap_->nodes_promoted_, heap_->promotion_ratio_,
           AverageSurvivalRatio(), heap_->promotion_rate_,
           heap_->semi_space_copied_rate_,
           NewSpaceAllocationThroughputInBytesPerMillisecond(),
           ContextDisposalRateInMilliseconds(),
           CompactionSpeedInBytesPerMillisecond());
       break;
     case Event::START:
@@ skipping 124 matching lines @@
   double sum = recorded_survival_ratios_.Sum(
       [](double a, double b) { return a + b; }, 0.0);
   return sum / recorded_survival_ratios_.Count();
 }
 
 bool GCTracer::SurvivalEventsRecorded() const {
   return recorded_survival_ratios_.Count() > 0;
 }
 
 void GCTracer::ResetSurvivalEvents() { recorded_survival_ratios_.Reset(); }
+
+void GCTracer::NotifyIncrementalMarkingStart() {
+  incremental_marking_start_time_ = heap_->MonotonicallyIncreasingTimeInMs();
+}
+
 }  // namespace internal
 }  // namespace v8