- Consolidate verbose-gc output to be a single line which can be imported easily into spreadsheets.

runtime/vm/scavenger.cc

Index: runtime/vm/scavenger.cc
===================================================================
--- runtime/vm/scavenger.cc	(revision 16586)
+++ runtime/vm/scavenger.cc	(working copy)
@@ -74,7 +74,6 @@
         vm_heap_(Dart::vm_isolate()->heap()),
         delayed_weak_stack_(),
         growth_policy_(PageSpace::kControlGrowth),
-        bytes_promoted_(0),
         visiting_old_pointers_(false),
         in_scavenge_pointer_(false) {}
 
@@ -109,8 +108,6 @@
     }
   }
 
-  intptr_t bytes_promoted() { return bytes_promoted_; }
-
  private:
   void UpdateStoreBuffer(RawObject** p, RawObject* obj) {
     uword ptr = reinterpret_cast<uword>(p);
@@ -187,7 +184,6 @@
           // If promotion succeeded then we need to remember it so that it can
           // be traversed later.
           scavenger_->PushToPromotedStack(new_addr);
-          bytes_promoted_ += size;
           if (HeapTrace::is_enabled()) {
             heap_->trace()->TracePromotion(raw_addr, new_addr);
           }
@@ -200,7 +196,6 @@
           new_addr = heap_->TryAllocate(size, Heap::kOld, growth_policy_);
           if (new_addr != 0) {
             scavenger_->PushToPromotedStack(new_addr);
-            bytes_promoted_ += size;
             if (HeapTrace::is_enabled()) {
               heap_->trace()->TracePromotion(raw_addr, new_addr);
             }
@@ -247,7 +242,6 @@
   DelaySet delay_set_;
   GrowableArray<RawObject*> delayed_weak_stack_;
   PageSpace::GrowthPolicy growth_policy_;
-  intptr_t bytes_promoted_;
 
   bool visiting_old_pointers_;
   bool in_scavenge_pointer_;
@@ -303,7 +297,6 @@
 Scavenger::Scavenger(Heap* heap, intptr_t max_capacity, uword object_alignment)
     : heap_(heap),
       object_alignment_(object_alignment),
-      count_(0),
       scavenging_(false) {
   // Verify assumptions about the first word in objects which the scavenger is
   // going to use for forwarding pointers.
@@ -417,10 +410,8 @@
     delete pending;
     pending = next;
   }
-  if (FLAG_verbose_gc) {
-    OS::PrintErr("StoreBuffer: %"Pd", %"Pd" (entries, dups)\n",
-                 entries, duplicates);
-  }
+  heap_->RecordData(0, entries);
+  heap_->RecordData(1, duplicates);
   StoreBufferBlock* block = isolate->store_buffer_block();
   entries = block->Count();
   duplicates = 0;
@@ -436,20 +427,23 @@
     }
   }
   block->Reset();
-  if (FLAG_verbose_gc) {
-    OS::PrintErr("StoreBufferBlock: %"Pd", %"Pd" (entries, dups)\n",
-                 entries, duplicates);
-  }
+  heap_->RecordData(2, entries);
+  heap_->RecordData(3, duplicates);

[siva, 2013/01/04 01:40:12]

It might be more readable to have an enumeration on
top as:
enum {
  kStoreBufferEntries = 0,
  kStoreBufferDuplicates = 1,
  kStoreBufferBlockEntries = 2,
  kStoreBufferBlockDuplicates = 3
};

[Ivan Posva, 2013/01/04 02:14:31]

Done. Here and in pages.cc

 }
 
 
 void Scavenger::IterateRoots(Isolate* isolate,
                              ScavengerVisitor* visitor,
                              bool visit_prologue_weak_persistent_handles) {
-  IterateStoreBuffers(isolate, visitor);
+  int64_t start = OS::GetCurrentTimeMicros();
   isolate->VisitObjectPointers(visitor,
                                visit_prologue_weak_persistent_handles,
                                StackFrameIterator::kDontValidateFrames);
+  int64_t middle = OS::GetCurrentTimeMicros();
+  IterateStoreBuffers(isolate, visitor);
+  int64_t end = OS::GetCurrentTimeMicros();
+  heap_->RecordTime(0, middle - start);
+  heap_->RecordTime(1, end - middle);
 }
 
 
@@ -626,14 +620,14 @@
 }
 
 
-void Scavenger::Scavenge(const char* gc_reason) {
+void Scavenger::Scavenge() {
   // TODO(cshapiro): Add a decision procedure for determining when the
   // the API callbacks should be invoked.
-  Scavenge(false, gc_reason);
+  Scavenge(false);
 }
 
 
-void Scavenger::Scavenge(bool invoke_api_callbacks, const char* gc_reason) {
+void Scavenger::Scavenge(bool invoke_api_callbacks) {
   // Scavenging is not reentrant. Make sure that is the case.
   ASSERT(!scavenging_);
   scavenging_ = true;
@@ -647,50 +641,26 @@
     OS::PrintErr(" done.\n");
   }
 
-  if (FLAG_verbose_gc) {
-    OS::PrintErr("Start scavenge for %s collection\n", gc_reason);
-  }
   uword prev_first_obj_start = FirstObjectStart();
   uword prev_top_addr = *(TopAddress());
-  Timer timer(FLAG_verbose_gc, "Scavenge");
-  timer.Start();
 
-  intptr_t in_use_before = in_use();
-
   // Setup the visitor and run a scavenge.
   ScavengerVisitor visitor(isolate, this);
   Prologue(isolate, invoke_api_callbacks);
   IterateRoots(isolate, &visitor, !invoke_api_callbacks);
+  int64_t start = OS::GetCurrentTimeMicros();
   ProcessToSpace(&visitor);
+  int64_t middle = OS::GetCurrentTimeMicros();
   IterateWeakReferences(isolate, &visitor);
   ScavengerWeakVisitor weak_visitor(this);
   IterateWeakRoots(isolate, &weak_visitor, invoke_api_callbacks);
   visitor.Finalize();
   ProcessPeerReferents();
+  int64_t end = OS::GetCurrentTimeMicros();
+  heap_->RecordTime(2, middle - start);
+  heap_->RecordTime(3, end - middle);

[siva, 2013/01/04 01:40:12]

Ditto for these 0, 1, 2, 3 values.

   Epilogue(isolate, invoke_api_callbacks);
-  timer.Stop();
 
-  if (FLAG_verbose_gc) {
-    const intptr_t KB2 = KB / 2;
-    double survival = ((in_use() + visitor.bytes_promoted()) /
-                       static_cast<double>(in_use_before)) * 100.0;
-    double promoted = (visitor.bytes_promoted() /
-                       static_cast<double>(in_use() + visitor.bytes_promoted()))
-                      * 100.0;
-    OS::PrintErr("Scavenge[%d]: %"Pd64"us (%"Pd"K -> %"Pd"K, %"Pd"K)\n"
-                 "Surviving %"Pd"K %.1f%%\n"
-                 "Promoted survivors %"Pd"K %.1f%%\n",
-                 count_,
-                 timer.TotalElapsedTime(),
-                 (in_use_before + KB2) / KB,
-                 (in_use() + KB2) / KB,
-                 (capacity() + KB2) / KB,
-                 (in_use() + visitor.bytes_promoted() + KB2) / KB,
-                 survival,
-                 (visitor.bytes_promoted() + KB2) / KB,
-                 promoted);
-  }
-
   if (FLAG_verify_after_gc) {
     OS::PrintErr("Verifying after Scavenge...");
     heap_->Verify();
@@ -701,7 +671,6 @@
     heap_->trace()->TraceDeathRange(prev_first_obj_start, prev_top_addr);
   }
 
-  count_++;
   // Done scavenging. Reset the marker.
   ASSERT(scavenging_);
   scavenging_ = false;