Add scavenger events to GC tracer

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/v8.h"
 
 #include "src/heap/gc-tracer.h"
 
 namespace v8 {
 namespace internal {
@@ skipping 371 matching lines @@
 
   if (current_.collector_reason != NULL) {
     Output(" [%s]", current_.collector_reason);
   }
 
   Output(".\n");
 }
 
 
 void GCTracer::PrintNVP() const {
-  PrintIsolate(heap_->isolate(), "[I:%p] %8.0f ms: ", heap_->isolate(),
+  PrintIsolate(heap_->isolate(), "[I:%p] %8.0f gc-trace: ", heap_->isolate(),

[Hannes Payer (out of office), 2015/07/20 08:50:24]

why did you delete the ms?

[Michael Lippautz, 2015/07/20 09:34:05]

whoops. reverted to "ms".

                heap_->isolate()->time_millis_since_init());
 
   double duration = current_.end_time - current_.start_time;
   double spent_in_mutator = current_.start_time - previous_.end_time;
 
   PrintF("pause=%.1f ", duration);
   PrintF("mutator=%.1f ", spent_in_mutator);
   PrintF("gc=%s ", current_.TypeName(true));
 
-  PrintF("external=%.1f ", current_.scopes[Scope::EXTERNAL]);
-  PrintF("mark=%.1f ", current_.scopes[Scope::MC_MARK]);
-  PrintF("sweep=%.2f ", current_.scopes[Scope::MC_SWEEP]);
-  PrintF("sweepns=%.2f ", current_.scopes[Scope::MC_SWEEP_NEWSPACE]);
-  PrintF("sweepos=%.2f ", current_.scopes[Scope::MC_SWEEP_OLDSPACE]);
-  PrintF("sweepcode=%.2f ", current_.scopes[Scope::MC_SWEEP_CODE]);
-  PrintF("sweepcell=%.2f ", current_.scopes[Scope::MC_SWEEP_CELL]);
-  PrintF("sweepmap=%.2f ", current_.scopes[Scope::MC_SWEEP_MAP]);
-  PrintF("evacuate=%.1f ", current_.scopes[Scope::MC_EVACUATE_PAGES]);
-  PrintF("new_new=%.1f ",
-         current_.scopes[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]);
-  PrintF("root_new=%.1f ",
-         current_.scopes[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]);
-  PrintF("old_new=%.1f ",
-         current_.scopes[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]);
-  PrintF("compaction_ptrs=%.1f ",
-         current_.scopes[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]);
-  PrintF("intracompaction_ptrs=%.1f ",
-         current_.scopes[Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]);
-  PrintF("misc_compaction=%.1f ",
-         current_.scopes[Scope::MC_UPDATE_MISC_POINTERS]);
-  PrintF("weak_closure=%.1f ", current_.scopes[Scope::MC_WEAKCLOSURE]);
-  PrintF("inc_weak_closure=%.1f ",
-         current_.scopes[Scope::MC_INCREMENTAL_WEAKCLOSURE]);
-  PrintF("weakcollection_process=%.1f ",
-         current_.scopes[Scope::MC_WEAKCOLLECTION_PROCESS]);
-  PrintF("weakcollection_clear=%.1f ",
-         current_.scopes[Scope::MC_WEAKCOLLECTION_CLEAR]);
-  PrintF("weakcollection_abort=%.1f ",
-         current_.scopes[Scope::MC_WEAKCOLLECTION_ABORT]);
+  switch (current_.type) {
+    case Event::SCAVENGER:
+      PrintF("scavenge=%.2f ", current_.scopes[Scope::SCAVENGER_SCAVENGE]);
+      PrintF("old_new=%.2f ",
+             current_.scopes[Scope::SCAVENGER_OLD_TO_NEW_POINTERS]);
+      PrintF("semispace=%.2f ", current_.scopes[Scope::SCAVENGER_SEMISPACE]);
+      PrintF("steps_count=%d ", current_.incremental_marking_steps);
+      PrintF("steps_took=%.1f ", current_.incremental_marking_duration);
+      PrintF("scavenge_throughput=%" V8_PTR_PREFIX "d ",
+             ScavengeSpeedInBytesPerMillisecond());
+      break;
+    case Event::MARK_COMPACTOR:

[Hannes Payer (out of office), 2015/07/20 08:50:24]

Here we could further distinguish between incremental marking and
non-incremental marking. But that may not be necessary.

[Michael Lippautz, 2015/07/20 09:34:05]

Acknowledged.

+    case Event::INCREMENTAL_MARK_COMPACTOR:
+      PrintF("external=%.1f ", current_.scopes[Scope::EXTERNAL]);
+      PrintF("mark=%.1f ", current_.scopes[Scope::MC_MARK]);
+      PrintF("sweep=%.2f ", current_.scopes[Scope::MC_SWEEP]);
+      PrintF("sweepns=%.2f ", current_.scopes[Scope::MC_SWEEP_NEWSPACE]);
+      PrintF("sweepos=%.2f ", current_.scopes[Scope::MC_SWEEP_OLDSPACE]);
+      PrintF("sweepcode=%.2f ", current_.scopes[Scope::MC_SWEEP_CODE]);
+      PrintF("sweepcell=%.2f ", current_.scopes[Scope::MC_SWEEP_CELL]);
+      PrintF("sweepmap=%.2f ", current_.scopes[Scope::MC_SWEEP_MAP]);
+      PrintF("evacuate=%.1f ", current_.scopes[Scope::MC_EVACUATE_PAGES]);
+      PrintF("new_new=%.1f ",
+             current_.scopes[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]);
+      PrintF("root_new=%.1f ",
+             current_.scopes[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]);
+      PrintF("old_new=%.1f ",
+             current_.scopes[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]);
+      PrintF("compaction_ptrs=%.1f ",
+             current_.scopes[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]);
+      PrintF("intracompaction_ptrs=%.1f ",
+             current_.scopes[Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]);
+      PrintF("misc_compaction=%.1f ",
+             current_.scopes[Scope::MC_UPDATE_MISC_POINTERS]);
+      PrintF("weak_closure=%.1f ", current_.scopes[Scope::MC_WEAKCLOSURE]);
+      PrintF("inc_weak_closure=%.1f ",
+             current_.scopes[Scope::MC_INCREMENTAL_WEAKCLOSURE]);
+      PrintF("weakcollection_process=%.1f ",
+             current_.scopes[Scope::MC_WEAKCOLLECTION_PROCESS]);
+      PrintF("weakcollection_clear=%.1f ",
+             current_.scopes[Scope::MC_WEAKCOLLECTION_CLEAR]);
+      PrintF("weakcollection_abort=%.1f ",
+             current_.scopes[Scope::MC_WEAKCOLLECTION_ABORT]);
+
+      PrintF("steps_count=%d ", current_.incremental_marking_steps);
+      PrintF("steps_took=%.1f ", current_.incremental_marking_duration);
+      PrintF("longest_step=%.1f ", current_.longest_incremental_marking_step);
+      PrintF("incremental_marking_throughput=%" V8_PTR_PREFIX "d ",
+             IncrementalMarkingSpeedInBytesPerMillisecond());
+      break;
+    case Event::START:
+      break;
+    default:
+      break;

[Hannes Payer (out of office), 2015/07/20 08:50:25]

The default case should never happen:
default:
  UNREACHABLE();

[Michael Lippautz, 2015/07/20 09:34:05]

Done.

+  }
+
 
   PrintF("total_size_before=%" V8_PTR_PREFIX "d ", current_.start_object_size);
   PrintF("total_size_after=%" V8_PTR_PREFIX "d ", current_.end_object_size);
   PrintF("holes_size_before=%" V8_PTR_PREFIX "d ", current_.start_holes_size);
   PrintF("holes_size_after=%" V8_PTR_PREFIX "d ", current_.end_holes_size);
 
   intptr_t allocated_since_last_gc =
       current_.start_object_size - previous_.end_object_size;
   PrintF("allocated=%" V8_PTR_PREFIX "d ", allocated_since_last_gc);
   PrintF("promoted=%" V8_PTR_PREFIX "d ", heap_->promoted_objects_size_);
   PrintF("semi_space_copied=%" V8_PTR_PREFIX "d ",
          heap_->semi_space_copied_object_size_);
   PrintF("nodes_died_in_new=%d ", heap_->nodes_died_in_new_space_);
   PrintF("nodes_copied_in_new=%d ", heap_->nodes_copied_in_new_space_);
   PrintF("nodes_promoted=%d ", heap_->nodes_promoted_);
   PrintF("promotion_ratio=%.1f%% ", heap_->promotion_ratio_);
   PrintF("average_survival_ratio=%.1f%% ", AverageSurvivalRatio());
   PrintF("promotion_rate=%.1f%% ", heap_->promotion_rate_);
   PrintF("semi_space_copy_rate=%.1f%% ", heap_->semi_space_copied_rate_);
   PrintF("new_space_allocation_throughput=%" V8_PTR_PREFIX "d ",
          NewSpaceAllocationThroughputInBytesPerMillisecond());
   PrintF("context_disposal_rate=%.1f ", ContextDisposalRateInMilliseconds());
 
-  if (current_.type == Event::SCAVENGER) {
-    PrintF("steps_count=%d ", current_.incremental_marking_steps);
-    PrintF("steps_took=%.1f ", current_.incremental_marking_duration);
-    PrintF("scavenge_throughput=%" V8_PTR_PREFIX "d ",
-           ScavengeSpeedInBytesPerMillisecond());
-  } else {
-    PrintF("steps_count=%d ", current_.incremental_marking_steps);
-    PrintF("steps_took=%.1f ", current_.incremental_marking_duration);
-    PrintF("longest_step=%.1f ", current_.longest_incremental_marking_step);
-    PrintF("incremental_marking_throughput=%" V8_PTR_PREFIX "d ",
-           IncrementalMarkingSpeedInBytesPerMillisecond());
-  }
-
   PrintF("\n");
 }
 
 
 double GCTracer::MeanDuration(const EventBuffer& events) const {
   if (events.empty()) return 0.0;
 
   double mean = 0.0;
   EventBuffer::const_iterator iter = events.begin();
   while (iter != events.end()) {
@@ skipping 243 matching lines @@
 
 
 bool GCTracer::SurvivalEventsRecorded() const {
   return survival_events_.size() > 0;
 }
 
 
 void GCTracer::ResetSurvivalEvents() { survival_events_.reset(); }
 }  // namespace internal
 }  // namespace v8