commit 83df2ac4a051ee10eafde7587de2faf3f0150fad
author Elliott Hughes <enh@google.com> Tue Oct 11 16:37:54 2011 -0700
committer Elliott Hughes <enh@google.com> Tue Oct 11 16:37:54 2011 -0700
tree f9733df44993a8ea798b19a6845fd3744913552a
parent d958820ec84df7a698e7ba2b3ba5ab2d88f75e0a

Basic GC logging (and class initialization timing).

Change-Id: Ibb09e556fbd42b1bb8cbd72974e8ca226aa073a5

src/class_linker.cc

diff --git a/src/class_linker.cc b/src/class_linker.cc
index 0299c4a..adabe97 100644
--- a/src/class_linker.cc
+++ b/src/class_linker.cc
@@ -1559,6 +1559,8 @@
     klass->SetStatus(Class::kStatusInitializing);
   }
 
+  uint64_t t0 = NanoTime();
+
   if (!InitializeSuperClass(klass, can_run_clinit)) {
     return false;
   }
@@ -1569,6 +1571,8 @@
     clinit->Invoke(self, NULL, NULL, NULL);
   }
 
+  uint64_t t1 = NanoTime();
+
   {
     ObjectLock lock(klass);
 
@@ -1576,9 +1580,12 @@
       WrapExceptionInInitializer();
       klass->SetStatus(Class::kStatusError);
     } else {
-      ++Runtime::Current()->GetStats()->class_init_count;
-      ++self->GetStats()->class_init_count;
-      // TODO: class_init_time_ns
+      RuntimeStats* global_stats = Runtime::Current()->GetStats();
+      RuntimeStats* thread_stats = self->GetStats();
+      ++global_stats->class_init_count;
+      ++thread_stats->class_init_count;
+      global_stats->class_init_time_ns += (t1 - t0);
+      thread_stats->class_init_time_ns += (t1 - t0);
       klass->SetStatus(Class::kStatusInitialized);
     }
     lock.NotifyAll();

src/heap.cc

diff --git a/src/heap.cc b/src/heap.cc
index 3f42c6b..019cfe2 100644
--- a/src/heap.cc
+++ b/src/heap.cc
@@ -454,6 +454,9 @@
 
   ThreadList* thread_list = Runtime::Current()->GetThreadList();
   thread_list->SuspendAll();
+
+  size_t initial_size = num_bytes_allocated_;
+  uint64_t t0 = NanoTime();
   Object* cleared_references = NULL;
   {
     MarkSweep mark_sweep;
@@ -487,9 +490,24 @@
   }
 
   GrowForUtilization();
+  uint64_t t1 = NanoTime();
   thread_list->ResumeAll();
 
   EnqueueClearedReferences(&cleared_references);
+
+  // TODO: somehow make the specific GC implementation (here MarkSweep) responsible for logging.
+  size_t bytes_freed = initial_size - num_bytes_allocated_;
+  bool is_small = (bytes_freed > 0 && bytes_freed < 1024);
+  size_t kib_freed = (bytes_freed > 0 ? std::max(bytes_freed/1024, 1U) : 0);
+
+  size_t footprint = alloc_space_->Size();
+  size_t percentFree = 100 - static_cast<size_t>(100.0f * float(num_bytes_allocated_) / footprint);
+
+  uint32_t duration = (t1 - t0)/1000/1000;
+  LOG(INFO) << "GC freed " << (is_small ? "<" : "") << kib_freed << "KiB, "
+            << percentFree << "% free "
+            << (num_bytes_allocated_/1024) << "KiB/" << (footprint/1024) << "KiB, "
+            << "paused " << duration << "ms";
 }
 
 void Heap::WaitForConcurrentGcToComplete() {

src/utils.cc

diff --git a/src/utils.cc b/src/utils.cc
index 86fa312..3017807 100644
--- a/src/utils.cc
+++ b/src/utils.cc
@@ -47,6 +47,12 @@
       ptm->tm_hour, ptm->tm_min, ptm->tm_sec);
 }
 
+uint64_t NanoTime() {
+  struct timespec now;
+  clock_gettime(CLOCK_MONOTONIC, &now);
+  return static_cast<uint64_t>(now.tv_sec) * 1000000000LL + now.tv_nsec;
+}
+
 std::string PrettyDescriptor(const String* java_descriptor) {
   if (java_descriptor == NULL) {
     return "null";

src/utils.h

diff --git a/src/utils.h b/src/utils.h
index 4f58c52..228925d 100644
--- a/src/utils.h
+++ b/src/utils.h
@@ -198,6 +198,9 @@
 // Returns the current date in ISO yyyy-mm-dd hh:mm:ss format.
 std::string GetIsoDate();
 
+// Returns the current time in nanoseconds (using the POSIX CLOCK_MONOTONIC).
+uint64_t NanoTime();
+
 // Splits a string using the given delimiter character into a vector of
 // strings. Empty strings will be omitted.
 void Split(const std::string& s, char delim, std::vector<std::string>& result);