Revert^2 "ART: add GC time ratio metrics to GC performance"
Make GC time ratio metrics work for all collectors.
This reverts commit 4d57c69ab7753690738d9dc802b5b640cb6af491.
Test: Run art with -XX:DumpGCPerformanceOnShutdown on some benchmarks.
Bug: 112187497
Change-Id: I5cce0cf2a5204126b70b7c8fdf686986f9b3d7e7
diff --git a/runtime/gc/collector/garbage_collector.cc b/runtime/gc/collector/garbage_collector.cc
index 5e3692e..0294db7 100644
--- a/runtime/gc/collector/garbage_collector.cc
+++ b/runtime/gc/collector/garbage_collector.cc
@@ -77,8 +77,9 @@
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 @@
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 @@
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 @@
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 f722e8d..2857881 100644
--- a/runtime/gc/collector/garbage_collector.h
+++ b/runtime/gc/collector/garbage_collector.h
@@ -81,6 +81,9 @@
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 @@
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 f0f81fc..e7f14c3 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -1062,6 +1062,14 @@
}
}
+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 c3ee526..a43f315 100644
--- a/runtime/gc/heap.h
+++ b/runtime/gc/heap.h
@@ -395,6 +395,8 @@
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 19c1623..f016e87 100644
--- a/runtime/runtime.cc
+++ b/runtime/runtime.cc
@@ -278,6 +278,7 @@
// 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 @@
}
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 a696c28..3c057f3 100644
--- a/runtime/runtime.h
+++ b/runtime/runtime.h
@@ -1109,6 +1109,9 @@
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);