6 files changed, 36 insertions, 4 deletions

diff --git a/runtime/gc/collector/garbage_collector.cc b/runtime/gc/collector/garbage_collector.cc
index 5e3692ea9a..0294db7b7e 100644
--- a/runtime/gc/collector/garbage_collector.cc
+++ b/runtime/gc/collector/garbage_collector.cc
@@ -77,8 +77,9 @@ void GarbageCollector::RegisterPause(uint64_t nano_length) {
 
 void GarbageCollector::ResetCumulativeStatistics() {
   cumulative_timings_.Reset();
-  total_time_ns_ = 0;
-  total_freed_objects_ = 0;
+  total_thread_cpu_time_ns_ = 0u;
+  total_time_ns_ = 0u;
+  total_freed_objects_ = 0u;
   total_freed_bytes_ = 0;
   MutexLock mu(Thread::Current(), pause_histogram_lock_);
   pause_histogram_.Reset();
@@ -88,6 +89,7 @@ void GarbageCollector::Run(GcCause gc_cause, bool clear_soft_references) {
   ScopedTrace trace(android::base::StringPrintf("%s %s GC", PrettyCause(gc_cause), GetName()));
   Thread* self = Thread::Current();
   uint64_t start_time = NanoTime();
+  uint64_t thread_cpu_start_time = ThreadCpuNanoTime();
   Iteration* current_iteration = GetCurrentIteration();
   current_iteration->Reset(gc_cause, clear_soft_references);
   // Note transaction mode is single-threaded and there's no asynchronous GC and this flag doesn't
@@ -102,6 +104,8 @@ void GarbageCollector::Run(GcCause gc_cause, bool clear_soft_references) {
   total_freed_bytes_ += current_iteration->GetFreedBytes() +
       current_iteration->GetFreedLargeObjectBytes();
   uint64_t end_time = NanoTime();
+  uint64_t thread_cpu_end_time = ThreadCpuNanoTime();
+  total_thread_cpu_time_ns_ += thread_cpu_end_time - thread_cpu_start_time;
   current_iteration->SetDurationNs(end_time - start_time);
   if (Locks::mutator_lock_->IsExclusiveHeld(self)) {
     // The entire GC was paused, clear the fake pauses which might be in the pause times and add
@@ -159,8 +163,9 @@ void GarbageCollector::ResetMeasurements() {
     pause_histogram_.Reset();
   }
   cumulative_timings_.Reset();
-  total_time_ns_ = 0;
-  total_freed_objects_ = 0;
+  total_thread_cpu_time_ns_ = 0u;
+  total_time_ns_ = 0u;
+  total_freed_objects_ = 0u;
   total_freed_bytes_ = 0;
 }
 
diff --git a/runtime/gc/collector/garbage_collector.h b/runtime/gc/collector/garbage_collector.h
index f722e8d855..2857881456 100644
--- a/runtime/gc/collector/garbage_collector.h
+++ b/runtime/gc/collector/garbage_collector.h
@@ -81,6 +81,9 @@ class GarbageCollector : public RootVisitor, public IsMarkedVisitor, public Mark
   void SwapBitmaps()
       REQUIRES(Locks::heap_bitmap_lock_)
       REQUIRES_SHARED(Locks::mutator_lock_);
+  uint64_t GetTotalCpuTime() const {
+    return total_thread_cpu_time_ns_;
+  }
   uint64_t GetTotalPausedTimeNs() REQUIRES(!pause_histogram_lock_);
   int64_t GetTotalFreedBytes() const {
     return total_freed_bytes_;
@@ -146,6 +149,7 @@ class GarbageCollector : public RootVisitor, public IsMarkedVisitor, public Mark
   std::string name_;
   // Cumulative statistics.
   Histogram<uint64_t> pause_histogram_ GUARDED_BY(pause_histogram_lock_);
+  uint64_t total_thread_cpu_time_ns_;
   uint64_t total_time_ns_;
   uint64_t total_freed_objects_;
   int64_t total_freed_bytes_;
diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index f0f81fc67e..e7f14c39d4 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -1062,6 +1062,14 @@ void Heap::RemoveSpace(space::Space* space) {
   }
 }
 
+uint64_t Heap::GetTotalGcCpuTime() {
+  uint64_t sum = 0;
+  for (auto& collector : garbage_collectors_) {
+    sum += collector->GetTotalCpuTime();
+  }
+  return sum;
+}
+
 void Heap::DumpGcPerformanceInfo(std::ostream& os) {
   // Dump cumulative timings.
   os << "Dumping cumulative Gc timings\n";
diff --git a/runtime/gc/heap.h b/runtime/gc/heap.h
index c3ee5267b5..a43f3156f5 100644
--- a/runtime/gc/heap.h
+++ b/runtime/gc/heap.h
@@ -395,6 +395,8 @@ class Heap {
     REQUIRES(!Locks::heap_bitmap_lock_)
     REQUIRES(Locks::mutator_lock_);
 
+  uint64_t GetTotalGcCpuTime();
+
   // Set target ideal heap utilization ratio, implements
   // dalvik.system.VMRuntime.setTargetHeapUtilization.
   void SetTargetHeapUtilization(float target);
diff --git a/runtime/runtime.cc b/runtime/runtime.cc
index 19c1623d1f..f016e874ca 100644
--- a/runtime/runtime.cc
+++ b/runtime/runtime.cc
@@ -278,6 +278,7 @@ Runtime::Runtime()
       // Initially assume we perceive jank in case the process state is never updated.
       process_state_(kProcessStateJankPerceptible),
       zygote_no_threads_(false),
+      process_cpu_start_time_(ProcessCpuNanoTime()),
       verifier_logging_threshold_ms_(100) {
   static_assert(Runtime::kCalleeSaveSize ==
                     static_cast<uint32_t>(CalleeSaveType::kLastCalleeSaveType), "Unexpected size");
@@ -321,11 +322,20 @@ Runtime::~Runtime() {
   }
 
   if (dump_gc_performance_on_shutdown_) {
+    process_cpu_end_time_ = ProcessCpuNanoTime();
     ScopedLogSeverity sls(LogSeverity::INFO);
     // This can't be called from the Heap destructor below because it
     // could call RosAlloc::InspectAll() which needs the thread_list
     // to be still alive.
     heap_->DumpGcPerformanceInfo(LOG_STREAM(INFO));
+
+    uint64_t process_cpu_time = process_cpu_end_time_ - process_cpu_start_time_;
+    uint64_t gc_cpu_time = heap_->GetTotalGcCpuTime();
+    float ratio = static_cast<float>(gc_cpu_time) / process_cpu_time;
+    LOG_STREAM(INFO) << "GC CPU time " << PrettyDuration(gc_cpu_time)
+        << " out of process CPU time " << PrettyDuration(process_cpu_time)
+        << " (" << ratio << ")"
+        << "\n";
   }
 
   if (jit_ != nullptr) {
diff --git a/runtime/runtime.h b/runtime/runtime.h
index a696c2845e..3c057f3c41 100644
--- a/runtime/runtime.h
+++ b/runtime/runtime.h
@@ -1109,6 +1109,9 @@ class Runtime {
 
   MemMap protected_fault_page_;
 
+  uint64_t process_cpu_start_time_;
+  uint64_t process_cpu_end_time_;
+
   uint32_t verifier_logging_threshold_ms_;
 
   DISALLOW_COPY_AND_ASSIGN(Runtime);