Fix systrace logging, total paused time, and bytes saved message.

Moved the GC top level systrace logging to be inside of Collector::Run.
This prevents cases where we forgot to call it such as background
compaction. Fixed a unit error regarding total pause time. Fixed
negative bytes saved to use the word "expanded".

Bug: 15702709

Change-Id: Ic2991ecad2daa000d0aee9d559b8bc77d8c160aa

4 files changed, 14 insertions, 5 deletions

diff --git a/runtime/base/histogram.h b/runtime/base/histogram.h
index a7d51e2..1e12be8 100644
--- a/runtime/base/histogram.h
+++ b/runtime/base/histogram.h
@@ -71,6 +71,10 @@ template <class Value> class Histogram {
     return sum_;
   }
 
+  Value AdjustedSum() const {
+    return sum_ * kAdjust;
+  }
+
   Value Min() const {
     return min_value_added_;
   }
diff --git a/runtime/gc/collector/garbage_collector.cc b/runtime/gc/collector/garbage_collector.cc
index 16add0b..a17c36b 100644
--- a/runtime/gc/collector/garbage_collector.cc
+++ b/runtime/gc/collector/garbage_collector.cc
@@ -56,6 +56,7 @@ void GarbageCollector::ResetCumulativeStatistics() {
 }
 
 void GarbageCollector::Run(GcCause gc_cause, bool clear_soft_references) {
+  ATRACE_BEGIN(StringPrintf("%s %s GC", PrettyCause(gc_cause), GetName()).c_str());
   Thread* self = Thread::Current();
   uint64_t start_time = NanoTime();
   timings_.Reset();
@@ -86,6 +87,7 @@ void GarbageCollector::Run(GcCause gc_cause, bool clear_soft_references) {
   for (uint64_t pause_time : pause_times_) {
     pause_histogram_.AddValue(pause_time / 1000);
   }
+  ATRACE_END();
 }
 
 void GarbageCollector::SwapBitmaps() {
diff --git a/runtime/gc/collector/garbage_collector.h b/runtime/gc/collector/garbage_collector.h
index 02dd4d9..f4f9dbb 100644
--- a/runtime/gc/collector/garbage_collector.h
+++ b/runtime/gc/collector/garbage_collector.h
@@ -105,7 +105,7 @@ class GarbageCollector {
   }
 
   uint64_t GetTotalPausedTimeNs() const {
-    return pause_histogram_.Sum();
+    return pause_histogram_.AdjustedSum();
   }
 
   int64_t GetTotalFreedBytes() const {
diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index 5cde451..e6a5380 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -1419,8 +1419,14 @@ void Heap::TransitionCollector(CollectorType collector_type) {
   FinishGC(self, collector::kGcTypeFull);
   int32_t after_allocated = num_bytes_allocated_.LoadSequentiallyConsistent();
   int32_t delta_allocated = before_allocated - after_allocated;
+  std::string saved_str;
+  if (delta_allocated >= 0) {
+    saved_str = " saved at least " + PrettySize(delta_allocated);
+  } else {
+    saved_str = " expanded " + PrettySize(-delta_allocated);
+  }
   LOG(INFO) << "Heap transition to " << process_state_ << " took "
-      << PrettyDuration(duration) << " saved at least " << PrettySize(delta_allocated);
+      << PrettyDuration(duration) << saved_str;
 }
 
 void Heap::ChangeCollector(CollectorType collector_type) {
@@ -1810,7 +1816,6 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
   CHECK(collector != nullptr)
       << "Could not find garbage collector with collector_type="
       << static_cast<size_t>(collector_type_) << " and gc_type=" << gc_type;
-  ATRACE_BEGIN(StringPrintf("%s %s GC", PrettyCause(gc_cause), collector->GetName()).c_str());
   collector->Run(gc_cause, clear_soft_references || runtime->IsZygote());
   total_objects_freed_ever_ += collector->GetFreedObjects();
   total_bytes_freed_ever_ += collector->GetFreedBytes();
@@ -1852,8 +1857,6 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
     VLOG(heap) << ConstDumpable<TimingLogger>(collector->GetTimings());
   }
   FinishGC(self, gc_type);
-  ATRACE_END();
-
   // Inform DDMS that a GC completed.
   Dbg::GcDidFinish();
   return gc_type;