Precise GC time measurements.

src/heap.cc

 // Copyright 2012 the V8 project authors. All rights reserved.
 // Redistribution and use in source and binary forms, with or without
 // modification, are permitted provided that the following conditions are
 // met:
 //
 //     * Redistributions of source code must retain the above copyright
 //       notice, this list of conditions and the following disclaimer.
 //     * Redistributions in binary form must reproduce the above
 //       copyright notice, this list of conditions and the following
 //       disclaimer in the documentation and/or other materials provided
@@ skipping 121 matching lines @@
       global_gc_epilogue_callback_(NULL),
       gc_safe_size_of_old_object_(NULL),
       total_regexp_code_generated_(0),
       tracer_(NULL),
       young_survivors_after_last_gc_(0),
       high_survival_rate_period_length_(0),
       low_survival_rate_period_length_(0),
       survival_rate_(0),
       previous_survival_rate_trend_(Heap::STABLE),
       survival_rate_trend_(Heap::STABLE),
-      max_gc_pause_(0),
-      total_gc_time_ms_(0),
+      max_gc_pause_(0.0),
+      total_gc_time_ms_(0.0),
       max_alive_after_gc_(0),
       min_in_mutator_(kMaxInt),
       alive_after_last_gc_(0),
       last_gc_end_timestamp_(0.0),
       marking_time_(0.0),
       sweeping_time_(0.0),
       store_buffer_(this),
       marking_(this),
       incremental_marking_(this),
       number_idle_notifications_(0),
@@ skipping 235 matching lines @@
                ", committed: %6" V8_PTR_PREFIX "d KB\n",
            lo_space_->SizeOfObjects() / KB,
            lo_space_->Available() / KB,
            lo_space_->CommittedMemory() / KB);
   PrintPID("All spaces,         used: %6" V8_PTR_PREFIX "d KB"
                ", available: %6" V8_PTR_PREFIX "d KB"
                ", committed: %6" V8_PTR_PREFIX "d KB\n",
            this->SizeOfObjects() / KB,
            this->Available() / KB,
            this->CommittedMemory() / KB);
-  PrintPID("Total time spent in GC  : %d ms\n", total_gc_time_ms_);
+  PrintPID("Total time spent in GC  : %.1f ms\n", total_gc_time_ms_);
 }
 
 
 // TODO(1238405): Combine the infrastructure for --heap-stats and
 // --log-gc to avoid the complicated preprocessor and flag testing.
 void Heap::ReportStatisticsAfterGC() {
   // Similar to the before GC, we use some complicated logic to ensure that
   // NewSpace statistics are logged exactly once when --log-gc is turned on.
 #if defined(DEBUG)
   if (FLAG_heap_stats) {
@@ skipping 5931 matching lines @@
 #ifdef VERIFY_HEAP
   if (FLAG_verify_heap) {
     Verify();
   }
 #endif
 
   if (FLAG_print_cumulative_gc_stat) {
     PrintF("\n");
     PrintF("gc_count=%d ", gc_count_);
     PrintF("mark_sweep_count=%d ", ms_count_);
-    PrintF("max_gc_pause=%d ", get_max_gc_pause());
-    PrintF("total_gc_time=%d ", total_gc_time_ms_);
-    PrintF("min_in_mutator=%d ", get_min_in_mutator());
+    PrintF("max_gc_pause=%.1f ", get_max_gc_pause());
+    PrintF("total_gc_time=%.1f ", total_gc_time_ms_);
+    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=%f ", marking_time());
-    PrintF("total_sweeping_time=%f ", sweeping_time());
+    PrintF("total_marking_time=%.1f ", marking_time());
+    PrintF("total_sweeping_time=%.1f ", sweeping_time());
     PrintF("\n\n");
   }
 
   isolate_->global_handles()->TearDown();
 
   external_string_table_.TearDown();
 
   error_object_list_.TearDown();
 
   new_space_.TearDown();
@@ skipping 658 matching lines @@
 
 GCTracer::~GCTracer() {
   // Printf ONE line iff flag is set.
   if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
 
   bool first_gc = (heap_->last_gc_end_timestamp_ == 0);
 
   heap_->alive_after_last_gc_ = heap_->SizeOfObjects();
   heap_->last_gc_end_timestamp_ = OS::TimeCurrentMillis();
 
-  int time = static_cast<int>(heap_->last_gc_end_timestamp_ - start_time_);
+  double time = heap_->last_gc_end_timestamp_ - start_time_;
 
   // Update cumulative GC statistics if required.
   if (FLAG_print_cumulative_gc_stat) {
     heap_->total_gc_time_ms_ += time;
     heap_->max_gc_pause_ = Max(heap_->max_gc_pause_, time);
     heap_->max_alive_after_gc_ = Max(heap_->max_alive_after_gc_,
                                      heap_->alive_after_last_gc_);
     if (!first_gc) {
       heap_->min_in_mutator_ = Min(heap_->min_in_mutator_,
-                                   static_cast<int>(spent_in_mutator_));
+                                   spent_in_mutator_);
     }
   } else if (FLAG_trace_gc_verbose) {
     heap_->total_gc_time_ms_ += time;
   }
 
   if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return;
 
   heap_->AddMarkingTime(scopes_[Scope::MC_MARK]);
 
   if (FLAG_print_cumulative_gc_stat && !FLAG_trace_gc) return;
   PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
 
   if (!FLAG_trace_gc_nvp) {
     int external_time = static_cast<int>(scopes_[Scope::EXTERNAL]);
 
     double end_memory_size_mb =
         static_cast<double>(heap_->isolate()->memory_allocator()->Size()) / MB;
 
     PrintF("%s %.1f (%.1f) -> %.1f (%.1f) MB, ",
            CollectorString(),
            static_cast<double>(start_object_size_) / MB,
            static_cast<double>(start_memory_size_) / MB,
            SizeOfHeapObjects(),
            end_memory_size_mb);
 
     if (external_time > 0) PrintF("%d / ", external_time);
-    PrintF("%d ms", time);
+    PrintF("%.1f ms", time);
     if (steps_count_ > 0) {
       if (collector_ == SCAVENGER) {
-        PrintF(" (+ %d ms in %d steps since last GC)",
-               static_cast<int>(steps_took_since_last_gc_),
+        PrintF(" (+ %.1f ms in %d steps since last GC)",
+               steps_took_since_last_gc_,
                steps_count_since_last_gc_);
       } else {
-        PrintF(" (+ %d ms in %d steps since start of marking, "
-                   "biggest step %f ms)",
-               static_cast<int>(steps_took_),
+        PrintF(" (+ %.1f ms in %d steps since start of marking, "
+                   "biggest step %.1f ms)",
+               steps_took_,
                steps_count_,
                longest_step_);
       }
     }
 
     if (gc_reason_ != NULL) {
       PrintF(" [%s]", gc_reason_);
     }
 
     if (collector_reason_ != NULL) {
       PrintF(" [%s]", collector_reason_);
     }
 
     PrintF(".\n");
   } else {
-    PrintF("pause=%d ", time);
-    PrintF("mutator=%d ", static_cast<int>(spent_in_mutator_));
+    PrintF("pause=%.1f ", time);
+    PrintF("mutator=%.1f ", spent_in_mutator_);
     PrintF("gc=");
     switch (collector_) {
       case SCAVENGER:
         PrintF("s");
         break;
       case MARK_COMPACTOR:
         PrintF("ms");
         break;
       default:
         UNREACHABLE();
     }
     PrintF(" ");
 
-    PrintF("external=%d ", static_cast<int>(scopes_[Scope::EXTERNAL]));
-    PrintF("mark=%d ", static_cast<int>(scopes_[Scope::MC_MARK]));
-    PrintF("sweep=%d ", static_cast<int>(scopes_[Scope::MC_SWEEP]));
-    PrintF("sweepns=%d ", static_cast<int>(scopes_[Scope::MC_SWEEP_NEWSPACE]));
-    PrintF("evacuate=%d ", static_cast<int>(scopes_[Scope::MC_EVACUATE_PAGES]));
-    PrintF("new_new=%d ",
-           static_cast<int>(scopes_[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]));
-    PrintF("root_new=%d ",
-           static_cast<int>(scopes_[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]));
-    PrintF("old_new=%d ",
-           static_cast<int>(scopes_[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]));
-    PrintF("compaction_ptrs=%d ",
-           static_cast<int>(scopes_[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]));
-    PrintF("intracompaction_ptrs=%d ", static_cast<int>(scopes_[
-        Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]));
-    PrintF("misc_compaction=%d ",
-           static_cast<int>(scopes_[Scope::MC_UPDATE_MISC_POINTERS]));
+    PrintF("external=%.1f ", scopes_[Scope::EXTERNAL]);
+    PrintF("mark=%.1f ", scopes_[Scope::MC_MARK]);
+    PrintF("sweep=%.1f ", scopes_[Scope::MC_SWEEP]);
+    PrintF("sweepns=%.1f ", scopes_[Scope::MC_SWEEP_NEWSPACE]);
+    PrintF("evacuate=%.1f ", scopes_[Scope::MC_EVACUATE_PAGES]);
+    PrintF("new_new=%.1f ", scopes_[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]);
+    PrintF("root_new=%.1f ", scopes_[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]);
+    PrintF("old_new=%.1f ", scopes_[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]);
+    PrintF("compaction_ptrs=%.1f ",
+        scopes_[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]);
+    PrintF("intracompaction_ptrs=%.1f ",
+        scopes_[Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]);
+    PrintF("misc_compaction=%.1f ", scopes_[Scope::MC_UPDATE_MISC_POINTERS]);
 
     PrintF("total_size_before=%" V8_PTR_PREFIX "d ", start_object_size_);
     PrintF("total_size_after=%" V8_PTR_PREFIX "d ", heap_->SizeOfObjects());
     PrintF("holes_size_before=%" V8_PTR_PREFIX "d ",
            in_free_list_or_wasted_before_gc_);
     PrintF("holes_size_after=%" V8_PTR_PREFIX "d ", CountTotalHolesSize(heap_));
 
     PrintF("allocated=%" V8_PTR_PREFIX "d ", allocated_since_last_gc_);
     PrintF("promoted=%" V8_PTR_PREFIX "d ", promoted_objects_size_);
     PrintF("nodes_died_in_new=%d ", nodes_died_in_new_space_);
     PrintF("nodes_copied_in_new=%d ", nodes_copied_in_new_space_);
     PrintF("nodes_promoted=%d ", nodes_promoted_);
 
     if (collector_ == SCAVENGER) {
       PrintF("stepscount=%d ", steps_count_since_last_gc_);
-      PrintF("stepstook=%d ", static_cast<int>(steps_took_since_last_gc_));
+      PrintF("stepstook=%.1f ", steps_took_since_last_gc_);
     } else {
       PrintF("stepscount=%d ", steps_count_);
-      PrintF("stepstook=%d ", static_cast<int>(steps_took_));
-      PrintF("longeststep=%.f ", longest_step_);
+      PrintF("stepstook=%.1f ", steps_took_);
+      PrintF("longeststep=%.1f ", longest_step_);
     }
 
     PrintF("\n");
   }
 
   heap_->PrintShortHeapStatistics();
 }
 
 
 const char* GCTracer::CollectorString() {
@@ skipping 377 matching lines @@
       static_cast<int>(object_sizes_last_time_[index]));
   FIXED_ARRAY_SUB_INSTANCE_TYPE_LIST(ADJUST_LAST_TIME_OBJECT_COUNT)
 #undef ADJUST_LAST_TIME_OBJECT_COUNT
 
   memcpy(object_counts_last_time_, object_counts_, sizeof(object_counts_));
   memcpy(object_sizes_last_time_, object_sizes_, sizeof(object_sizes_));
   ClearObjectStats();
 }
 
 } }  // namespace v8::internal