[heap] Adding fine grained timer scopes to external callbacks.

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 376 matching lines @@
     PrintIsolate(heap_->isolate(), "");
   }
   Output("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
 
   Output("%s %.1f (%.1f) -> %.1f (%.1f) MB, ", 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);
 
-  int external_time = static_cast<int>(current_.scopes[Scope::EXTERNAL]);
   double duration = current_.end_time - current_.start_time;
-  Output("%.1f / %d ms", duration, external_time);
+  Output("%.1f / %.1f ms", duration, TotalExternalTime());
 
   if (current_.type == Event::SCAVENGER) {
     if (current_.incremental_marking_steps > 0) {
       Output(" (+ %.1f ms in %d steps since last GC)",
              current_.incremental_marking_duration,
              current_.incremental_marking_steps);
     }
   } else {
     if (current_.incremental_marking_steps > 0) {
       Output(
@@ skipping 31 matching lines @@
                    "mutator=%.1f "
                    "gc=%s "
                    "reduce_memory=%d "
                    "scavenge=%.2f "
                    "old_new=%.2f "
                    "weak=%.2f "
                    "roots=%.2f "
                    "code=%.2f "
                    "semispace=%.2f "
                    "object_groups=%.2f "
+                   "external_prologue=$.2f "
+                   "external_epilogue=$.2f "
+                   "external_weak_global_handles=$.2f "
                    "steps_count=%d "
                    "steps_took=%.1f "
                    "scavenge_throughput=%" V8_PTR_PREFIX
                    "d "
                    "total_size_before=%" V8_PTR_PREFIX
                    "d "
                    "total_size_after=%" V8_PTR_PREFIX
                    "d "
                    "holes_size_before=%" V8_PTR_PREFIX
                    "d "
@@ skipping 18 matching lines @@
                    heap_->isolate()->time_millis_since_init(), 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_steps,
                    current_.incremental_marking_duration,
                    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: "
           "pause=%.1f "
           "mutator=%.1f "
           "gc=%s "
           "reduce_memory=%d "
-          "external=%.1f "
           "clear=%1.f "
           "clear.code_flush=%.1f "
           "clear.dependent_code=%.1f "
           "clear.global_handles=%.1f "
           "clear.maps=%.1f "
           "clear.slots_buffer=%.1f "
           "clear.store_buffer=%.1f "
           "clear.string_table=%.1f "
           "clear.weak_cells=%.1f "
           "clear.weak_collections=%.1f "
           "clear.weak_lists=%.1f "
           "evacuate=%.1f "
           "evacuate.candidates=%.1f "
           "evacuate.clean_up=%.1f "
           "evacuate.copy=%.1f "
           "evacuate.update_pointers=%.1f "
           "evacuate.update_pointers.between_evacuated=%.1f "
           "evacuate.update_pointers.to_evacuated=%.1f "
           "evacuate.update_pointers.to_new=%.1f "
           "evacuate.update_pointers.weak=%.1f "
+          "external.mc_prologue=%.1f "
+          "external.mc_epilogue=%.1f "
+          "external.mc_incremental_prologue=%.1f "
+          "external.mc_incremental_epilogue=%.1f "
+          "external.weak_global_handles=%.1f "
           "finish=%.1f "
           "mark=%.1f "
           "mark.finish_incremental=%.1f "
           "mark.prepare_code_flush=%.1f "
           "mark.roots=%.1f "
           "mark.weak_closure=%.1f "
           "sweep=%.1f "
           "sweep.code=%.1f "
           "sweep.map=%.1f "
           "sweep.old=%.1f "
@@ skipping 26 matching lines @@
           "promotion_ratio=%.1f%% "
           "average_survival_ratio=%.1f%% "
           "promotion_rate=%.1f%% "
           "semi_space_copy_rate=%.1f%% "
           "new_space_allocation_throughput=%" V8_PTR_PREFIX
           "d "
           "context_disposal_rate=%.1f "
           "compaction_speed=%" V8_PTR_PREFIX "d\n",
           heap_->isolate()->time_millis_since_init(), duration,
           spent_in_mutator, current_.TypeName(true), current_.reduce_memory,
-          current_.scopes[Scope::EXTERNAL], current_.scopes[Scope::MC_CLEAR],
+          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],
           current_.scopes[Scope::MC_EVACUATE],
           current_.scopes[Scope::MC_EVACUATE_CANDIDATES],
           current_.scopes[Scope::MC_EVACUATE_CLEAN_UP],
           current_.scopes[Scope::MC_EVACUATE_COPY],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_BETWEEN_EVACUATED],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_EVACUATED],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_NEW],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_WEAK],
+          current_.scopes[Scope::MC_EXTERNAL_PROLOGUE],
+          current_.scopes[Scope::MC_EXTERNAL_EPILOGUE],
+          current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
+          current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
+          current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
           current_.scopes[Scope::MC_FINISH], current_.scopes[Scope::MC_MARK],
           current_.scopes[Scope::MC_MARK_FINISH_INCREMENTAL],
           current_.scopes[Scope::MC_MARK_PREPARE_CODE_FLUSH],
           current_.scopes[Scope::MC_MARK_ROOTS],
           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE],
           current_.scopes[Scope::MC_SWEEP],
           current_.scopes[Scope::MC_SWEEP_CODE],
           current_.scopes[Scope::MC_SWEEP_MAP],
           current_.scopes[Scope::MC_SWEEP_OLD],
           current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
@@ skipping 297 matching lines @@
 
 
 bool GCTracer::SurvivalEventsRecorded() const {
   return survival_events_.size() > 0;
 }
 
 
 void GCTracer::ResetSurvivalEvents() { survival_events_.reset(); }
 }  // namespace internal
 }  // namespace v8