Add a C++ equivalent of Android's TimingLogger, and use it for the heap.

This also changes us over to one big stats update at the end of sweeping,
like Dalvik, rather than recording every single free individually.

Change-Id: Ib8e2a83d41d36e35e154183a4e173e915af79ae9
diff --git a/src/heap.cc b/src/heap.cc
index 019cfe2..9bed951 100644
--- a/src/heap.cc
+++ b/src/heap.cc
@@ -11,6 +11,7 @@
 #include "object.h"
 #include "space.h"
 #include "stl_util.h"
+#include "timing_logger.h"
 #include "thread_list.h"
 
 namespace art {
@@ -88,12 +89,12 @@
     limit = std::max(limit, space->GetLimit());
   }
 
-  Space* space = Space::Create(initial_size, maximum_size, requested_base);
-  if (space == NULL) {
+  alloc_space_ = Space::Create("alloc space", initial_size, maximum_size, requested_base);
+  if (alloc_space_ == NULL) {
     LOG(FATAL) << "Failed to create alloc space";
   }
-  base = std::min(base, space->GetBase());
-  limit = std::max(limit, space->GetLimit());
+  base = std::min(base, alloc_space_->GetBase());
+  limit = std::max(limit, alloc_space_->GetLimit());
   DCHECK_LT(base, limit);
   size_t num_bytes = limit - base;
 
@@ -109,8 +110,7 @@
     LOG(FATAL) << "Failed to create mark bitmap";
   }
 
-  alloc_space_ = space;
-  spaces_.push_back(space);
+  spaces_.push_back(alloc_space_);
   maximum_size_ = maximum_size;
   live_bitmap_ = live_bitmap.release();
   mark_bitmap_ = mark_bitmap.release();
@@ -257,27 +257,27 @@
   live_bitmap_->Set(obj);
 }
 
-void Heap::RecordFreeLocked(Space* space, const Object* obj) {
+void Heap::RecordFreeLocked(size_t freed_objects, size_t freed_bytes) {
   lock_->AssertHeld();
-  size_t size = space->AllocationSize(obj);
-  DCHECK_NE(size, 0u);
-  if (size < num_bytes_allocated_) {
-    num_bytes_allocated_ -= size;
+
+  if (freed_objects < num_objects_allocated_) {
+    num_objects_allocated_ -= freed_objects;
+  } else {
+    num_objects_allocated_ = 0;
+  }
+  if (freed_bytes < num_bytes_allocated_) {
+    num_bytes_allocated_ -= freed_bytes;
   } else {
     num_bytes_allocated_ = 0;
   }
-  live_bitmap_->Clear(obj);
-  if (num_objects_allocated_ > 0) {
-    num_objects_allocated_ -= 1;
-  }
 
   if (Runtime::Current()->HasStatsEnabled()) {
     RuntimeStats* global_stats = Runtime::Current()->GetStats();
     RuntimeStats* thread_stats = Thread::Current()->GetStats();
     ++global_stats->freed_objects;
     ++thread_stats->freed_objects;
-    global_stats->freed_bytes += size;
-    thread_stats->freed_bytes += size;
+    global_stats->freed_bytes += freed_bytes;
+    thread_stats->freed_bytes += freed_bytes;
   }
 }
 
@@ -456,14 +456,18 @@
   thread_list->SuspendAll();
 
   size_t initial_size = num_bytes_allocated_;
+  TimingLogger timings("CollectGarbageInternal");
   uint64_t t0 = NanoTime();
   Object* cleared_references = NULL;
   {
     MarkSweep mark_sweep;
+    timings.AddSplit("ctor");
 
     mark_sweep.Init();
+    timings.AddSplit("Init");
 
     mark_sweep.MarkRoots();
+    timings.AddSplit("MarkRoots");
 
     // Push marked roots onto the mark stack
 
@@ -472,6 +476,7 @@
     //   thread_list->ResumeAll();
 
     mark_sweep.RecursiveMark();
+    timings.AddSplit("RecursiveMark");
 
     // TODO: if concurrent
     //   lock heap
@@ -480,16 +485,19 @@
     //   scan dirty objects
 
     mark_sweep.ProcessReferences(false);
+    timings.AddSplit("ProcessReferences");
 
     // TODO: if concurrent
     //    swap bitmaps
 
     mark_sweep.Sweep();
+    timings.AddSplit("Sweep");
 
     cleared_references = mark_sweep.GetClearedReferences();
   }
 
   GrowForUtilization();
+  timings.AddSplit("GrowForUtilization");
   uint64_t t1 = NanoTime();
   thread_list->ResumeAll();
 
@@ -508,6 +516,7 @@
             << percentFree << "% free "
             << (num_bytes_allocated_/1024) << "KiB/" << (footprint/1024) << "KiB, "
             << "paused " << duration << "ms";
+  timings.Dump();
 }
 
 void Heap::WaitForConcurrentGcToComplete() {
diff --git a/src/heap.h b/src/heap.h
index aa9db6e..ffe2abf 100644
--- a/src/heap.h
+++ b/src/heap.h
@@ -153,7 +153,7 @@
   }
 
   // Callers must hold the heap lock.
-  static void RecordFreeLocked(Space* space, const Object* object);
+  static void RecordFreeLocked(size_t freed_objects, size_t freed_bytes);
 
   // Must be called if a field of an Object in the heap changes, and before any GC safe-point.
   // The call is not needed if NULL is stored in the field.
diff --git a/src/mark_sweep.cc b/src/mark_sweep.cc
index 6512aef..a0ca6b2 100644
--- a/src/mark_sweep.cc
+++ b/src/mark_sweep.cc
@@ -17,6 +17,7 @@
 #include "object.h"
 #include "runtime.h"
 #include "space.h"
+#include "timing_logger.h"
 #include "thread.h"
 
 namespace art {
@@ -88,7 +89,6 @@
 // Populates the mark stack based on the set of marked objects and
 // recursively marks until the mark stack is emptied.
 void MarkSweep::RecursiveMark() {
-
   // RecursiveMark will build the lists of known instances of the Reference classes.
   // See DelayReferenceReferent for details.
   CHECK(soft_reference_list_ == NULL);
@@ -97,16 +97,20 @@
   CHECK(phantom_reference_list_ == NULL);
   CHECK(cleared_reference_list_ == NULL);
 
+  TimingLogger timings("MarkSweep::RecursiveMark");
   void* arg = reinterpret_cast<void*>(this);
   const std::vector<Space*>& spaces = Heap::GetSpaces();
   for (size_t i = 0; i < spaces.size(); ++i) {
-    if (spaces[i]->IsCondemned()) {
+    if (!spaces[i]->IsImageSpace()) {
       uintptr_t base = reinterpret_cast<uintptr_t>(spaces[i]->GetBase());
       mark_bitmap_->ScanWalk(base, &MarkSweep::ScanBitmapCallback, arg);
     }
+    timings.AddSplit(StringPrintf("ScanWalk space #%i (%s)", i, spaces[i]->GetName().c_str()));
   }
   finger_ = reinterpret_cast<Object*>(~0);
   ProcessMarkStack();
+  timings.AddSplit("ProcessMarkStack");
+  timings.Dump();
 }
 
 void MarkSweep::ReMarkRoots() {
@@ -134,12 +138,15 @@
 
 void MarkSweep::SweepCallback(size_t num_ptrs, void** ptrs, void* arg) {
   // TODO, lock heap if concurrent
+  size_t freed_objects = num_ptrs;
+  size_t freed_bytes = 0;
   Space* space = static_cast<Space*>(arg);
   for (size_t i = 0; i < num_ptrs; ++i) {
     Object* obj = static_cast<Object*>(ptrs[i]);
-    Heap::RecordFreeLocked(space, obj);
+    freed_bytes += space->AllocationSize(obj);
     space->Free(obj);
   }
+  Heap::RecordFreeLocked(freed_objects, freed_bytes);
   // TODO, unlock heap if concurrent
 }
 
@@ -148,7 +155,7 @@
 
   const std::vector<Space*>& spaces = Heap::GetSpaces();
   for (size_t i = 0; i < spaces.size(); ++i) {
-    if (spaces[i]->IsCondemned()) {
+    if (!spaces[i]->IsImageSpace()) {
       uintptr_t base = reinterpret_cast<uintptr_t>(spaces[i]->GetBase());
       uintptr_t limit = reinterpret_cast<uintptr_t>(spaces[i]->GetLimit());
       void* arg = static_cast<void*>(spaces[i]);
diff --git a/src/object.h b/src/object.h
index 35e355d..5bbdc6b 100644
--- a/src/object.h
+++ b/src/object.h
@@ -770,12 +770,12 @@
   }
 
   uint32_t GetOatCodeOffset() const {
-    CHECK(!Runtime::Current()->IsStarted());
+    DCHECK(!Runtime::Current()->IsStarted());
     return reinterpret_cast<uint32_t>(GetCode());
   }
 
   void SetOatCodeOffset(uint32_t code_offset) {
-    CHECK(!Runtime::Current()->IsStarted());
+    DCHECK(!Runtime::Current()->IsStarted());
     SetCode(reinterpret_cast<void*>(code_offset));
   }
 
@@ -809,12 +809,12 @@
   }
 
   uint32_t GetOatMappingTableOffset() const {
-    CHECK(!Runtime::Current()->IsStarted());
+    DCHECK(!Runtime::Current()->IsStarted());
     return reinterpret_cast<uint32_t>(GetMappingTableRaw());
   }
 
   void SetOatMappingTableOffset(uint32_t mapping_table_offset) {
-    CHECK(!Runtime::Current()->IsStarted());
+    DCHECK(!Runtime::Current()->IsStarted());
     SetMappingTable(reinterpret_cast<const uint32_t*>(mapping_table_offset));
   }
 
@@ -843,12 +843,12 @@
   }
 
   uint32_t GetOatVmapTableOffset() const {
-    CHECK(!Runtime::Current()->IsStarted());
+    DCHECK(!Runtime::Current()->IsStarted());
     return reinterpret_cast<uint32_t>(GetVmapTableRaw());
   }
 
   void SetOatVmapTableOffset(uint32_t vmap_table_offset) {
-    CHECK(!Runtime::Current()->IsStarted());
+    DCHECK(!Runtime::Current()->IsStarted());
     SetVmapTable(reinterpret_cast<uint16_t*>(vmap_table_offset));
   }
 
@@ -906,12 +906,12 @@
   }
 
   uint32_t GetOatInvokeStubOffset() const {
-    CHECK(!Runtime::Current()->IsStarted());
+    DCHECK(!Runtime::Current()->IsStarted());
     return reinterpret_cast<uint32_t>(GetInvokeStub());
   }
 
   void SetOatInvokeStubOffset(uint32_t invoke_stub_offset) {
-    CHECK(!Runtime::Current()->IsStarted());
+    DCHECK(!Runtime::Current()->IsStarted());
     SetInvokeStub(reinterpret_cast<InvokeStub*>(invoke_stub_offset));
   }
 
diff --git a/src/runtime.h b/src/runtime.h
index a3d04f6..76bd318 100644
--- a/src/runtime.h
+++ b/src/runtime.h
@@ -82,7 +82,7 @@
   }
 
   const std::string& GetHostPrefix() const {
-    CHECK(!IsStarted());
+    DCHECK(!IsStarted());
     return host_prefix_;
   }
 
diff --git a/src/space.cc b/src/space.cc
index ae35f57..9acb54e 100644
--- a/src/space.cc
+++ b/src/space.cc
@@ -13,8 +13,8 @@
 
 namespace art {
 
-Space* Space::Create(size_t initial_size, size_t maximum_size, byte* requested_base) {
-  UniquePtr<Space> space(new Space());
+Space* Space::Create(const std::string& name, size_t initial_size, size_t maximum_size, byte* requested_base) {
+  UniquePtr<Space> space(new Space(name));
   bool success = space->Init(initial_size, maximum_size, requested_base);
   if (!success) {
     return NULL;
@@ -25,7 +25,7 @@
 
 Space* Space::CreateFromImage(const std::string& image_file_name) {
   CHECK(image_file_name != NULL);
-  UniquePtr<Space> space(new Space());
+  UniquePtr<Space> space(new Space(image_file_name));
   bool success = space->InitFromImage(image_file_name);
   if (!success) {
     return NULL;
diff --git a/src/space.h b/src/space.h
index 758d80c..e354aab 100644
--- a/src/space.h
+++ b/src/space.h
@@ -1,8 +1,24 @@
-// Copyright 2011 Google Inc. All Rights Reserved.
+/*
+ * Copyright (C) 2011 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
 
 #ifndef ART_SRC_SPACE_H_
 #define ART_SRC_SPACE_H_
 
+#include <string>
+
 #include "UniquePtr.h"
 #include "globals.h"
 #include "image.h"
@@ -21,7 +37,8 @@
   // base address is not guaranteed to be granted, if it is required,
   // the caller should call GetBase on the returned space to confirm
   // the request was granted.
-  static Space* Create(size_t initial_size, size_t maximum_size, byte* requested_base);
+  static Space* Create(const std::string& name,
+      size_t initial_size, size_t maximum_size, byte* requested_base);
 
   // create a Space from an image file. cannot be used for future allocation or collected.
   static Space* CreateFromImage(const std::string& image);
@@ -49,6 +66,10 @@
     return limit_;
   }
 
+  const std::string& GetName() const {
+    return name_;
+  }
+
   size_t Size() const {
     return limit_ - base_;
   }
@@ -64,10 +85,6 @@
 
   size_t AllocationSize(const Object* obj);
 
-  bool IsCondemned() const {
-    return mspace_ != NULL;
-  }
-
  private:
   // The boundary tag overhead.
   static const size_t kChunkOverhead = kWordSize;
@@ -75,7 +92,9 @@
   // create a Space from an existing memory mapping, taking ownership of the address space.
   static Space* Create(MemMap* mem_map);
 
-  Space() : mspace_(NULL), maximum_size_(0), image_header_(NULL), base_(0), limit_(0) {}
+  Space(const std::string& name)
+      : name_(name), mspace_(NULL), maximum_size_(0), image_header_(NULL), base_(0), limit_(0) {
+  }
 
   // Initializes the space and underlying storage.
   bool Init(size_t initial_size, size_t maximum_size, byte* requested_base);
@@ -90,6 +109,8 @@
 
   static void DontNeed(void* start, void* end, void* num_bytes);
 
+  std::string name_;
+
   // TODO: have a Space subclass for non-image Spaces with mspace_ and maximum_size_
   void* mspace_;
   size_t maximum_size_;
diff --git a/src/space_test.cc b/src/space_test.cc
index ce7140f..0a6067c 100644
--- a/src/space_test.cc
+++ b/src/space_test.cc
@@ -13,23 +13,23 @@
 TEST_F(SpaceTest, Init) {
   {
     // Less than
-    UniquePtr<Space> space(Space::Create(16 * MB, 32 * MB, NULL));
+    UniquePtr<Space> space(Space::Create("test", 16 * MB, 32 * MB, NULL));
     EXPECT_TRUE(space.get() != NULL);
   }
   {
     // Equal to
-    UniquePtr<Space> space(Space::Create(16 * MB, 16 * MB, NULL));
+    UniquePtr<Space> space(Space::Create("test", 16 * MB, 16 * MB, NULL));
     EXPECT_TRUE(space.get() != NULL);
   }
   {
     // Greater than
-    UniquePtr<Space> space(Space::Create(32 * MB, 16 * MB, NULL));
+    UniquePtr<Space> space(Space::Create("test", 32 * MB, 16 * MB, NULL));
     EXPECT_TRUE(space.get() == NULL);
   }
 }
 
 TEST_F(SpaceTest, AllocAndFree) {
-  UniquePtr<Space> space(Space::Create(4 * MB, 16 * MB, NULL));
+  UniquePtr<Space> space(Space::Create("test", 4 * MB, 16 * MB, NULL));
   ASSERT_TRUE(space.get() != NULL);
 
   // Succeeds, fits without adjusting the max allowed footprint.
diff --git a/src/timing_logger.h b/src/timing_logger.h
new file mode 100644
index 0000000..f91b830
--- /dev/null
+++ b/src/timing_logger.h
@@ -0,0 +1,61 @@
+/*
+ * Copyright (C) 2011 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef ART_SRC_TIMING_LOGGER_H_
+#define ART_SRC_TIMING_LOGGER_H_
+
+#include "logging.h"
+#include "utils.h"
+
+#include <stdint.h>
+
+#include <string>
+#include <vector>
+
+namespace art {
+
+class TimingLogger {
+public:
+  TimingLogger(const char* name) : name_(name) {
+    AddSplit("");
+  }
+
+  void AddSplit(const std::string& label) {
+    times_.push_back(NanoTime());
+    labels_.push_back(label);
+  }
+
+  void Dump() {
+    LOG(INFO) << name_ << ": begin";
+    for (size_t i = 1; i < times_.size(); ++i) {
+      LOG(INFO) << name_ << StringPrintf(": %8lld ms, ", ToMs(times_[i] - times_[i-1])) << labels_[i];
+    }
+    LOG(INFO) << name_ << ": end, " << ToMs(times_.back() - times_.front()) << " ms";
+  }
+
+private:
+  static uint64_t ToMs(uint64_t ns) {
+    return ns/1000/1000;
+  }
+
+  std::string name_;
+  std::vector<uint64_t> times_;
+  std::vector<std::string> labels_;
+};
+
+}  // namespace art
+
+#endif  // ART_SRC_TIMING_LOGGER_H_