commit 40112dd31260c624337f353ec00c444df64458d4
author Mathieu Chartier <mathieuc@google.com> Mon Jun 26 17:49:09 2017 -0700
committer Mathieu Chartier <mathieuc@google.com> Mon Jun 26 18:31:16 2017 -0700
tree 4910fb8b95ce5a6c39ef95fb8b85b82345d04eab
parent 80b99c23b09bf1c4ca49385cff15879d821aecb9

Make waiting for blocking GC more intuitive

Now tells what GC cause blocked on what other GC cause.

Example output:
WaitForGcToComplete blocked HeapTrim on ProfileSaver for 396.361ms

Bug: 62941975
Test: test-art-host

(cherry picked from commit 87a619f43d4cb79b8723b42dc53cb10f7577f1de)

Change-Id: I1e3a35244db16974487dd8b82baae81669ae9aee

runtime/gc/gc_cause.cc

diff --git a/runtime/gc/gc_cause.cc b/runtime/gc/gc_cause.cc
index 39b5e39..a3a2051 100644
--- a/runtime/gc/gc_cause.cc
+++ b/runtime/gc/gc_cause.cc
@@ -25,6 +25,7 @@
 
 const char* PrettyCause(GcCause cause) {
   switch (cause) {
+    case kGcCauseNone: return "None";
     case kGcCauseForAlloc: return "Alloc";
     case kGcCauseBackground: return "Background";
     case kGcCauseExplicit: return "Explicit";

runtime/gc/gc_cause.h

diff --git a/runtime/gc/gc_cause.h b/runtime/gc/gc_cause.h
index b2b3a91..78496f3 100644
--- a/runtime/gc/gc_cause.h
+++ b/runtime/gc/gc_cause.h
@@ -24,6 +24,8 @@
 
 // What caused the GC?
 enum GcCause {
+  // Invalid GC cause used as a placeholder.
+  kGcCauseNone,
   // GC triggered by a failed allocation. Thread doing allocation is blocked waiting for GC before
   // retrying allocation.
   kGcCauseForAlloc,

runtime/gc/heap.cc

diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index d944ce4..880b2d4 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -214,6 +214,7 @@
       disable_thread_flip_count_(0),
       thread_flip_running_(false),
       collector_type_running_(kCollectorTypeNone),
+      last_gc_cause_(kGcCauseNone),
       thread_running_gc_(nullptr),
       last_gc_type_(collector::kGcTypeNone),
       next_gc_type_(collector::kGcTypePartial),
@@ -1458,6 +1459,7 @@
   // Ensure there is only one GC at a time.
   WaitForGcToCompleteLocked(cause, self);
   collector_type_running_ = collector_type;
+  last_gc_cause_ = cause;
   thread_running_gc_ = self;
 }
 
@@ -3537,6 +3539,7 @@
 
 collector::GcType Heap::WaitForGcToCompleteLocked(GcCause cause, Thread* self) {
   collector::GcType last_gc_type = collector::kGcTypeNone;
+  GcCause last_gc_cause = kGcCauseNone;
   uint64_t wait_start = NanoTime();
   while (collector_type_running_ != kCollectorTypeNone) {
     if (self != task_processor_->GetRunningThread()) {
@@ -3551,12 +3554,13 @@
     // We must wait, change thread state then sleep on gc_complete_cond_;
     gc_complete_cond_->Wait(self);
     last_gc_type = last_gc_type_;
+    last_gc_cause = last_gc_cause_;
   }
   uint64_t wait_time = NanoTime() - wait_start;
   total_wait_time_ += wait_time;
   if (wait_time > long_pause_log_threshold_) {
-    LOG(INFO) << "WaitForGcToComplete blocked for " << PrettyDuration(wait_time)
-        << " for cause " << cause;
+    LOG(INFO) << "WaitForGcToComplete blocked " << cause << " on " << last_gc_cause << " for "
+              << PrettyDuration(wait_time);
   }
   if (self != task_processor_->GetRunningThread()) {
     // The current thread is about to run a collection. If the thread

runtime/gc/heap.h

diff --git a/runtime/gc/heap.h b/runtime/gc/heap.h
index 0289250..3484e02 100644
--- a/runtime/gc/heap.h
+++ b/runtime/gc/heap.h
@@ -1189,9 +1189,12 @@
   // Task processor, proxies heap trim requests to the daemon threads.
   std::unique_ptr<TaskProcessor> task_processor_;
 
-  // True while the garbage collector is running.
+  // Collector type of the running GC.
   volatile CollectorType collector_type_running_ GUARDED_BY(gc_complete_lock_);
 
+  // Cause of the last running GC.
+  volatile GcCause last_gc_cause_ GUARDED_BY(gc_complete_lock_);
+
   // The thread currently running the GC.
   volatile Thread* thread_running_gc_ GUARDED_BY(gc_complete_lock_);