Always log explicit GC.
People who use DDMS want to see that a GC actually occurs when they
press GC button.
Bug: 14325353
Change-Id: I44e0450c92abf7223d33552ed37f626fe63e1c28
diff --git a/runtime/gc/collector/garbage_collector.cc b/runtime/gc/collector/garbage_collector.cc
index 6380cba..615ec98 100644
--- a/runtime/gc/collector/garbage_collector.cc
+++ b/runtime/gc/collector/garbage_collector.cc
@@ -65,6 +65,7 @@
ThreadList* thread_list = Runtime::Current()->GetThreadList();
Thread* self = Thread::Current();
uint64_t start_time = NanoTime();
+ timings_.Reset();
pause_times_.clear();
duration_ns_ = 0;
clear_soft_references_ = clear_soft_references;
diff --git a/runtime/gc/collector/mark_sweep.cc b/runtime/gc/collector/mark_sweep.cc
index 8af4fd8..007eb23 100644
--- a/runtime/gc/collector/mark_sweep.cc
+++ b/runtime/gc/collector/mark_sweep.cc
@@ -104,7 +104,6 @@
}
void MarkSweep::InitializePhase() {
- timings_.Reset();
TimingLogger::ScopedSplit split("InitializePhase", &timings_);
mark_stack_ = heap_->mark_stack_.get();
DCHECK(mark_stack_ != nullptr);
diff --git a/runtime/gc/collector/semi_space.cc b/runtime/gc/collector/semi_space.cc
index b67bbb1..61f49b0 100644
--- a/runtime/gc/collector/semi_space.cc
+++ b/runtime/gc/collector/semi_space.cc
@@ -110,7 +110,6 @@
}
void SemiSpace::InitializePhase() {
- timings_.Reset();
TimingLogger::ScopedSplit split("InitializePhase", &timings_);
mark_stack_ = heap_->mark_stack_.get();
DCHECK(mark_stack_ != nullptr);
diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index 5d72bc1..a9799b9 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -1910,36 +1910,37 @@
EnqueueClearedReferences();
// Grow the heap so that we know when to perform the next GC.
GrowForUtilization(collector);
- if (CareAboutPauseTimes()) {
- const size_t duration = collector->GetDurationNs();
- std::vector<uint64_t> pauses = collector->GetPauseTimes();
+ const size_t duration = collector->GetDurationNs();
+ const std::vector<uint64_t>& pause_times = collector->GetPauseTimes();
+ // Print the GC if it is an explicit GC (e.g. Runtime.gc()) or a slow GC
+ // (mutator time blocked >= long_pause_log_threshold_).
+ bool log_gc = gc_cause == kGcCauseExplicit;
+ if (!log_gc && CareAboutPauseTimes()) {
// GC for alloc pauses the allocating thread, so consider it as a pause.
- bool was_slow = duration > long_gc_log_threshold_ ||
+ log_gc = duration > long_gc_log_threshold_ ||
(gc_cause == kGcCauseForAlloc && duration > long_pause_log_threshold_);
- if (!was_slow) {
- for (uint64_t pause : pauses) {
- was_slow = was_slow || pause > long_pause_log_threshold_;
- }
+ for (uint64_t pause : pause_times) {
+ log_gc = log_gc || pause >= long_pause_log_threshold_;
}
- if (was_slow) {
- const size_t percent_free = GetPercentFree();
- const size_t current_heap_size = GetBytesAllocated();
- const size_t total_memory = GetTotalMemory();
- std::ostringstream pause_string;
- for (size_t i = 0; i < pauses.size(); ++i) {
- pause_string << PrettyDuration((pauses[i] / 1000) * 1000)
- << ((i != pauses.size() - 1) ? ", " : "");
- }
- LOG(INFO) << gc_cause << " " << collector->GetName()
- << " GC freed " << collector->GetFreedObjects() << "("
- << PrettySize(collector->GetFreedBytes()) << ") AllocSpace objects, "
- << collector->GetFreedLargeObjects() << "("
- << PrettySize(collector->GetFreedLargeObjectBytes()) << ") LOS objects, "
- << percent_free << "% free, " << PrettySize(current_heap_size) << "/"
- << PrettySize(total_memory) << ", " << "paused " << pause_string.str()
- << " total " << PrettyDuration((duration / 1000) * 1000);
- VLOG(heap) << ConstDumpable<TimingLogger>(collector->GetTimings());
+ }
+ if (log_gc) {
+ const size_t percent_free = GetPercentFree();
+ const size_t current_heap_size = GetBytesAllocated();
+ const size_t total_memory = GetTotalMemory();
+ std::ostringstream pause_string;
+ for (size_t i = 0; i < pause_times.size(); ++i) {
+ pause_string << PrettyDuration((pause_times[i] / 1000) * 1000)
+ << ((i != pause_times.size() - 1) ? ", " : "");
}
+ LOG(INFO) << gc_cause << " " << collector->GetName()
+ << " GC freed " << collector->GetFreedObjects() << "("
+ << PrettySize(collector->GetFreedBytes()) << ") AllocSpace objects, "
+ << collector->GetFreedLargeObjects() << "("
+ << PrettySize(collector->GetFreedLargeObjectBytes()) << ") LOS objects, "
+ << percent_free << "% free, " << PrettySize(current_heap_size) << "/"
+ << PrettySize(total_memory) << ", " << "paused " << pause_string.str()
+ << " total " << PrettyDuration((duration / 1000) * 1000);
+ VLOG(heap) << ConstDumpable<TimingLogger>(collector->GetTimings());
}
FinishGC(self, gc_type);
ATRACE_END();