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
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 @@
   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 @@
   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 @@
     VLOG(heap) << ConstDumpable<TimingLogger>(collector->GetTimings());
   }
   FinishGC(self, gc_type);
-  ATRACE_END();
-
   // Inform DDMS that a GC completed.
   Dbg::GcDidFinish();
   return gc_type;