Adding systrace logging to GC

Added systrace logging to GC, thread checkpoints, GC pause,
and time spent waiting for concurrent GC to complete.

Change-Id: I33f0cf260526ccfd07bfaf038dfbf0a712eab24d

4 files changed, 40 insertions, 4 deletions

diff --git a/src/gc/collector/garbage_collector.cc b/src/gc/collector/garbage_collector.cc
index 74128352ce..378a971250 100644
--- a/src/gc/collector/garbage_collector.cc
+++ b/src/gc/collector/garbage_collector.cc
@@ -14,6 +14,11 @@
  * limitations under the License.
  */
 
+#define ATRACE_TAG ATRACE_TAG_DALVIK
+
+#include <stdio.h>
+#include <cutils/trace.h>
+
 #include "garbage_collector.h"
 
 #include "base/logging.h"
@@ -68,10 +73,12 @@ void GarbageCollector::Run() {
   if (!IsConcurrent()) {
     // Pause is the entire length of the GC.
     uint64_t pause_start = NanoTime();
+    ATRACE_BEGIN("Application threads suspended");
     thread_list->SuspendAll();
     MarkingPhase();
     ReclaimPhase();
     thread_list->ResumeAll();
+    ATRACE_END();
     uint64_t pause_end = NanoTime();
     pause_times_.push_back(pause_end - pause_start);
   } else {
@@ -82,9 +89,11 @@ void GarbageCollector::Run() {
     bool done = false;
     while (!done) {
       uint64_t pause_start = NanoTime();
+      ATRACE_BEGIN("Application threads suspended");
       thread_list->SuspendAll();
       done = HandleDirtyObjectsPhase();
       thread_list->ResumeAll();
+      ATRACE_END();
       uint64_t pause_end = NanoTime();
       pause_times_.push_back(pause_end - pause_start);
     }
diff --git a/src/gc/heap.cc b/src/gc/heap.cc
index 34c0b5c058..9ec1f21243 100644
--- a/src/gc/heap.cc
+++ b/src/gc/heap.cc
@@ -16,6 +16,8 @@
 
 #include "heap.h"
 
+#define ATRACE_TAG ATRACE_TAG_DALVIK
+#include <cutils/trace.h>
 #include <sys/types.h>
 #include <sys/wait.h>
 
@@ -1121,6 +1123,19 @@ void Heap::UnMarkAllocStack(accounting::SpaceBitmap* bitmap, accounting::SpaceSe
 collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCause gc_cause,
                                                bool clear_soft_references) {
   Thread* self = Thread::Current();
+
+  switch (gc_cause) {
+    case kGcCauseForAlloc:
+      ATRACE_BEGIN("GC (alloc)");
+      break;
+    case kGcCauseBackground:
+      ATRACE_BEGIN("GC (background)");
+      break;
+    case kGcCauseExplicit:
+      ATRACE_BEGIN("GC (explicit)");
+      break;
+  }
+
   ScopedThreadStateChange tsc(self, kWaitingPerformingGc);
   Locks::mutator_lock_->AssertNotHeld(self);
 
@@ -1234,6 +1249,7 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
     gc_complete_cond_->Broadcast(self);
   }
   // Inform DDMS that a GC completed.
+  ATRACE_END();
   Dbg::GcDidFinish();
   return gc_type;
 }
@@ -1632,6 +1648,7 @@ void Heap::PostGcVerification(collector::GarbageCollector* gc) {
 collector::GcType Heap::WaitForConcurrentGcToComplete(Thread* self) {
   collector::GcType last_gc_type = collector::kGcTypeNone;
   if (concurrent_gc_) {
+    ATRACE_BEGIN("GC: Wait For Concurrent");
     bool do_wait;
     uint64_t wait_start = NanoTime();
     {
@@ -1656,6 +1673,7 @@ collector::GcType Heap::WaitForConcurrentGcToComplete(Thread* self) {
         LOG(INFO) << "WaitForConcurrentGcToComplete blocked for " << PrettyDuration(wait_time);
       }
     }
+    ATRACE_END();
   }
   return last_gc_type;
 }
diff --git a/src/thread.cc b/src/thread.cc
index 2deb7a5d75..d6bd8a45a6 100644
--- a/src/thread.cc
+++ b/src/thread.cc
@@ -14,8 +14,11 @@
  * limitations under the License.
  */
 
+#define ATRACE_TAG ATRACE_TAG_DALVIK
+
 #include "thread.h"
 
+#include <cutils/trace.h>
 #include <pthread.h>
 #include <signal.h>
 #include <sys/resource.h>
@@ -574,6 +577,13 @@ void Thread::ModifySuspendCount(Thread* self, int delta, bool for_debugger) {
   }
 }
 
+void Thread::RunCheckpointFunction() {
+  CHECK(checkpoint_function_ != NULL);
+  ATRACE_BEGIN("Checkpoint function");
+  checkpoint_function_->Run(this);
+  ATRACE_END();
+}
+
 bool Thread::RequestCheckpoint(Closure* function) {
   CHECK(!ReadFlag(kCheckpointRequest)) << "Already have a pending checkpoint request";
   checkpoint_function_ = function;
@@ -589,10 +599,12 @@ bool Thread::RequestCheckpoint(Closure* function) {
 
 void Thread::FullSuspendCheck() {
   VLOG(threads) << this << " self-suspending";
+  ATRACE_BEGIN("Full suspend check");
   // Make thread appear suspended to other threads, release mutator_lock_.
   TransitionFromRunnableToSuspended(kSuspended);
   // Transition back to runnable noting requests to suspend, re-acquire share on mutator_lock_.
   TransitionFromSuspendedToRunnable();
+  ATRACE_END();
   VLOG(threads) << this << " self-reviving";
 }
 
diff --git a/src/thread.h b/src/thread.h
index 24987cd441..0daf763359 100644
--- a/src/thread.h
+++ b/src/thread.h
@@ -554,10 +554,7 @@ class PACKED(4) Thread {
     held_mutexes_[level] = mutex;
   }
 
-  void RunCheckpointFunction() {
-    CHECK(checkpoint_function_ != NULL);
-    checkpoint_function_->Run(this);
-  }
+  void RunCheckpointFunction();
 
   bool ReadFlag(ThreadFlag flag) const {
     return (state_and_flags_.as_struct.flags & flag) != 0;