Adjust GC tracing: add a flag to ignore scavenger traces and print total GC time in verbose mode.

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),
       survival_rate_(0),
       previous_survival_rate_trend_(Heap::STABLE),
       survival_rate_trend_(Heap::STABLE),
       max_gc_pause_(0),
+      total_gc_time_ms_(0),
       max_alive_after_gc_(0),
       min_in_mutator_(kMaxInt),
       alive_after_last_gc_(0),
       last_gc_end_timestamp_(0.0),
       store_buffer_(this),
       marking_(this),
       incremental_marking_(this),
       number_idle_notifications_(0),
       last_idle_notification_gc_count_(0),
       last_idle_notification_gc_count_init_(false),
@@ skipping 210 matching lines @@
                ", committed: %6" V8_PTR_PREFIX "d KB\n",
            cell_space_->SizeOfObjects() / KB,
            cell_space_->Available() / KB,
            cell_space_->CommittedMemory() / KB);
   PrintPID("Large object space, used: %6" V8_PTR_PREFIX "d KB"
                ", available: %6" V8_PTR_PREFIX "d KB"
                ", committed: %6" V8_PTR_PREFIX "d KB\n",
            lo_space_->SizeOfObjects() / KB,
            lo_space_->Available() / KB,
            lo_space_->CommittedMemory() / KB);
+  PrintPID("Total time spent in GC  : %d 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 157 matching lines @@
 #ifdef DEBUG
   // Reset the allocation timeout to the GC interval, but make sure to
   // allow at least a few allocations after a collection. The reason
   // for this is that we have a lot of allocation sequences and we
   // assume that a garbage collection will allow the subsequent
   // allocation attempts to go through.
   allocation_timeout_ = Max(6, FLAG_gc_interval);
 #endif
 
   if (collector == SCAVENGER && !incremental_marking()->IsStopped()) {
-    if (FLAG_trace_incremental_marking) {
+    if (FLAG_trace_incremental_marking && !FLAG_trace_gc_ignore_scavenger) {

[Michael Starzinger, 2012/08/06 14:21:36]

Actually, I would like to see that with --trace-incremental-marking, it is
independent from --trace-gc.

[ulan, 2012/08/06 14:28:15]

Done.

       PrintF("[IncrementalMarking] Scavenge during marking.\n");
     }
   }
 
   if (collector == MARK_COMPACTOR &&
       !mark_compact_collector()->abort_incremental_marking_ &&
       !incremental_marking()->IsStopped() &&
       !incremental_marking()->should_hurry() &&
       FLAG_incremental_marking_steps) {
     // Make progress in incremental marking.
@@ skipping 5618 matching lines @@
 #ifdef DEBUG
   if (FLAG_verify_heap) {
     Verify();
   }
 #endif
   if (FLAG_print_cumulative_gc_stat) {
     PrintF("\n\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_alive_after_gc=%" V8_PTR_PREFIX "d ",
            get_max_alive_after_gc());
     PrintF("\n\n");
   }
 
   isolate_->global_handles()->TearDown();
 
   external_string_table_.TearDown();
 
@@ skipping 661 matching lines @@
 
   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_);
 
   // 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_));
     }
+  } else if (FLAG_trace_gc_verbose) {
+    heap_->total_gc_time_ms_ += time;
   }
 
+  if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return;
+
   PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
-

[Michael Starzinger, 2012/08/06 14:21:36]

Can we have that empty newline back?

[ulan, 2012/08/06 14:28:15]

Done.

   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,
@@ skipping 20 matching lines @@
       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("mutator=%d ", static_cast<int>(spent_in_mutator_));
     PrintF("gc=");
     switch (collector_) {
       case SCAVENGER:
         PrintF("s");
         break;
       case MARK_COMPACTOR:
         PrintF("ms");
         break;
       default:
         UNREACHABLE();
@@ skipping 305 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