Adding systrace logging to GC
Added systrace logging to GC, thread checkpoints, GC pause,
and time spent waiting for concurrent GC to complete.
Change-Id: I33f0cf260526ccfd07bfaf038dfbf0a712eab24d
diff --git a/src/gc/collector/garbage_collector.cc b/src/gc/collector/garbage_collector.cc
index 7412835..378a971 100644
--- a/src/gc/collector/garbage_collector.cc
+++ b/src/gc/collector/garbage_collector.cc
@@ -14,6 +14,11 @@
* limitations under the License.
*/
+#define ATRACE_TAG ATRACE_TAG_DALVIK
+
+#include <stdio.h>
+#include <cutils/trace.h>
+
#include "garbage_collector.h"
#include "base/logging.h"
@@ -68,10 +73,12 @@
if (!IsConcurrent()) {
// Pause is the entire length of the GC.
uint64_t pause_start = NanoTime();
+ ATRACE_BEGIN("Application threads suspended");
thread_list->SuspendAll();
MarkingPhase();
ReclaimPhase();
thread_list->ResumeAll();
+ ATRACE_END();
uint64_t pause_end = NanoTime();
pause_times_.push_back(pause_end - pause_start);
} else {
@@ -82,9 +89,11 @@
bool done = false;
while (!done) {
uint64_t pause_start = NanoTime();
+ ATRACE_BEGIN("Application threads suspended");
thread_list->SuspendAll();
done = HandleDirtyObjectsPhase();
thread_list->ResumeAll();
+ ATRACE_END();
uint64_t pause_end = NanoTime();
pause_times_.push_back(pause_end - pause_start);
}
diff --git a/src/gc/heap.cc b/src/gc/heap.cc
index 34c0b5c..9ec1f21 100644
--- a/src/gc/heap.cc
+++ b/src/gc/heap.cc
@@ -16,6 +16,8 @@
#include "heap.h"
+#define ATRACE_TAG ATRACE_TAG_DALVIK
+#include <cutils/trace.h>
#include <sys/types.h>
#include <sys/wait.h>
@@ -1121,6 +1123,19 @@
collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCause gc_cause,
bool clear_soft_references) {
Thread* self = Thread::Current();
+
+ switch (gc_cause) {
+ case kGcCauseForAlloc:
+ ATRACE_BEGIN("GC (alloc)");
+ break;
+ case kGcCauseBackground:
+ ATRACE_BEGIN("GC (background)");
+ break;
+ case kGcCauseExplicit:
+ ATRACE_BEGIN("GC (explicit)");
+ break;
+ }
+
ScopedThreadStateChange tsc(self, kWaitingPerformingGc);
Locks::mutator_lock_->AssertNotHeld(self);
@@ -1234,6 +1249,7 @@
gc_complete_cond_->Broadcast(self);
}
// Inform DDMS that a GC completed.
+ ATRACE_END();
Dbg::GcDidFinish();
return gc_type;
}
@@ -1632,6 +1648,7 @@
collector::GcType Heap::WaitForConcurrentGcToComplete(Thread* self) {
collector::GcType last_gc_type = collector::kGcTypeNone;
if (concurrent_gc_) {
+ ATRACE_BEGIN("GC: Wait For Concurrent");
bool do_wait;
uint64_t wait_start = NanoTime();
{
@@ -1656,6 +1673,7 @@
LOG(INFO) << "WaitForConcurrentGcToComplete blocked for " << PrettyDuration(wait_time);
}
}
+ ATRACE_END();
}
return last_gc_type;
}
diff --git a/src/thread.cc b/src/thread.cc
index 2deb7a5..d6bd8a4 100644
--- a/src/thread.cc
+++ b/src/thread.cc
@@ -14,8 +14,11 @@
* limitations under the License.
*/
+#define ATRACE_TAG ATRACE_TAG_DALVIK
+
#include "thread.h"
+#include <cutils/trace.h>
#include <pthread.h>
#include <signal.h>
#include <sys/resource.h>
@@ -574,6 +577,13 @@
}
}
+void Thread::RunCheckpointFunction() {
+ CHECK(checkpoint_function_ != NULL);
+ ATRACE_BEGIN("Checkpoint function");
+ checkpoint_function_->Run(this);
+ ATRACE_END();
+}
+
bool Thread::RequestCheckpoint(Closure* function) {
CHECK(!ReadFlag(kCheckpointRequest)) << "Already have a pending checkpoint request";
checkpoint_function_ = function;
@@ -589,10 +599,12 @@
void Thread::FullSuspendCheck() {
VLOG(threads) << this << " self-suspending";
+ ATRACE_BEGIN("Full suspend check");
// Make thread appear suspended to other threads, release mutator_lock_.
TransitionFromRunnableToSuspended(kSuspended);
// Transition back to runnable noting requests to suspend, re-acquire share on mutator_lock_.
TransitionFromSuspendedToRunnable();
+ ATRACE_END();
VLOG(threads) << this << " self-reviving";
}
diff --git a/src/thread.h b/src/thread.h
index 24987cd..0daf763 100644
--- a/src/thread.h
+++ b/src/thread.h
@@ -554,10 +554,7 @@
held_mutexes_[level] = mutex;
}
- void RunCheckpointFunction() {
- CHECK(checkpoint_function_ != NULL);
- checkpoint_function_->Run(this);
- }
+ void RunCheckpointFunction();
bool ReadFlag(ThreadFlag flag) const {
return (state_and_flags_.as_struct.flags & flag) != 0;