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 (file)
--- a/runtime/gc/collector/garbage_collector.cc
+++ b/runtime/gc/collector/garbage_collector.cc
@@ -65,6 +65,7 @@ void GarbageCollector::Run(GcCause gc_cause, bool clear_soft_references) {
   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 (file)
--- a/runtime/gc/collector/mark_sweep.cc
+++ b/runtime/gc/collector/mark_sweep.cc
@@ -104,7 +104,6 @@ MarkSweep::MarkSweep(Heap* heap, bool is_concurrent, const std::string& name_pre
 }
 
 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 (file)
--- a/runtime/gc/collector/semi_space.cc
+++ b/runtime/gc/collector/semi_space.cc
@@ -110,7 +110,6 @@ SemiSpace::SemiSpace(Heap* heap, bool generational, const std::string& name_pref
 }
 
 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 (file)
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -1910,36 +1910,37 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
   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_;
-      }
-    }
-    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());
-    }
+    for (uint64_t pause : pause_times) {
+      log_gc = log_gc || pause >= long_pause_log_threshold_;
+    }
+  }
+  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();