Updates to tracer to log events.
The tracer can now generates traces for ddms or output to a logfile.
Also includes bugfixes to allow stack walking to work properly when
tracing.
Change-Id: I8894272d9a678eeb1d376734f7822daf2ab298e4
diff --git a/src/trace.cc b/src/trace.cc
index 0a41a2e..56e1eac 100644
--- a/src/trace.cc
+++ b/src/trace.cc
@@ -2,13 +2,109 @@
#include "trace.h"
+#include <sys/uio.h>
+
#include "class_linker.h"
+#include "debugger.h"
#include "dex_cache.h"
+#include "object_utils.h"
+#include "os.h"
#include "runtime_support.h"
#include "thread.h"
+static const uint32_t kTraceMethodActionMask = 0x03; // two bits
+static const char kTraceTokenChar = '*';
+static const uint16_t kTraceHeaderLength = 32;
+static const uint32_t kTraceMagicValue = 0x574f4c53;
+static const uint16_t kTraceVersionSingleClock = 2;
+static const uint16_t kTraceVersionDualClock = 3;
+static const uint16_t kTraceRecordSizeSingleClock = 10; // using v2
+static const uint16_t kTraceRecordSizeDualClock = 14; // using v3 with two timestamps
+
+static inline uint32_t TraceMethodId(uint32_t methodValue) {
+ return (methodValue & ~kTraceMethodActionMask);
+}
+static inline uint32_t TraceMethodCombine(uint32_t method, uint8_t traceEvent) {
+ return (method | traceEvent);
+}
+
namespace art {
+// TODO: Replace class statics with singleton instance
+bool Trace::method_tracing_active_ = false;
+std::map<const Method*, const void*> Trace::saved_code_map_;
+std::set<const Method*> Trace::visited_methods_;
+std::map<Thread*, uint64_t> Trace::thread_clock_base_map_;
+uint8_t* Trace::buf_;
+File* Trace::trace_file_;
+bool Trace::direct_to_ddms_ = false;
+int Trace::buffer_size_ = 0;
+uint64_t Trace::start_time_ = 0;
+bool Trace::overflow_ = false;
+uint16_t Trace::trace_version_;
+uint16_t Trace::record_size_;
+volatile int32_t Trace::cur_offset_;
+
+bool UseThreadCpuClock() {
+ // TODO: Allow control over which clock is used
+ return true;
+}
+
+bool UseWallClock() {
+ // TODO: Allow control over which clock is used
+ return true;
+}
+
+void MeasureClockOverhead() {
+ if (UseThreadCpuClock()) {
+ ThreadCpuMicroTime();
+ }
+ if (UseWallClock()) {
+ MicroTime();
+ }
+}
+
+uint32_t GetClockOverhead() {
+ uint64_t start = ThreadCpuMicroTime();
+
+ for (int i = 4000; i > 0; i--) {
+ MeasureClockOverhead();
+ MeasureClockOverhead();
+ MeasureClockOverhead();
+ MeasureClockOverhead();
+ MeasureClockOverhead();
+ MeasureClockOverhead();
+ MeasureClockOverhead();
+ MeasureClockOverhead();
+ }
+
+ uint64_t elapsed = ThreadCpuMicroTime() - start;
+ return uint32_t (elapsed / 32);
+}
+
+void Append2LE(uint8_t* buf, uint16_t val) {
+ *buf++ = (uint8_t) val;
+ *buf++ = (uint8_t) (val >> 8);
+}
+
+void Append4LE(uint8_t* buf, uint32_t val) {
+ *buf++ = (uint8_t) val;
+ *buf++ = (uint8_t) (val >> 8);
+ *buf++ = (uint8_t) (val >> 16);
+ *buf++ = (uint8_t) (val >> 24);
+}
+
+void Append8LE(uint8_t* buf, uint64_t val) {
+ *buf++ = (uint8_t) val;
+ *buf++ = (uint8_t) (val >> 8);
+ *buf++ = (uint8_t) (val >> 16);
+ *buf++ = (uint8_t) (val >> 24);
+ *buf++ = (uint8_t) (val >> 32);
+ *buf++ = (uint8_t) (val >> 40);
+ *buf++ = (uint8_t) (val >> 48);
+ *buf++ = (uint8_t) (val >> 56);
+}
+
#if defined(__arm__)
static bool InstallStubsClassVisitor(Class* klass, void* trace_stub) {
for (size_t i = 0; i < klass->NumDirectMethods(); i++) {
@@ -89,28 +185,30 @@
}
#endif
-bool Trace::method_tracing_active_ = false;
-std::map<const Method*, const void*> Trace::saved_code_map_;
-
void Trace::AddSavedCodeToMap(const Method* method, const void* code) {
+ CHECK(IsMethodTracingActive());
saved_code_map_.insert(std::make_pair(method, code));
}
void Trace::RemoveSavedCodeFromMap(const Method* method) {
+ CHECK(IsMethodTracingActive());
saved_code_map_.erase(method);
}
const void* Trace::GetSavedCodeFromMap(const Method* method) {
+ CHECK(IsMethodTracingActive());
return saved_code_map_.find(method)->second;
}
void Trace::SaveAndUpdateCode(Method* method, const void* new_code) {
+ CHECK(IsMethodTracingActive());
CHECK(GetSavedCodeFromMap(method) == NULL);
AddSavedCodeToMap(method, method->GetCode());
method->SetCode(new_code);
}
void Trace::ResetSavedCode(Method* method) {
+ CHECK(IsMethodTracingActive());
CHECK(GetSavedCodeFromMap(method) != NULL);
method->SetCode(GetSavedCodeFromMap(method));
RemoveSavedCodeFromMap(method);
@@ -127,39 +225,222 @@
void Trace::Start(const char* trace_filename, int trace_fd, int buffer_size, int flags, bool direct_to_ddms) {
LOG(INFO) << "Starting method tracing...";
if (IsMethodTracingActive()) {
- // TODO: Stop the trace, then start it up again instead of returning
- LOG(INFO) << "Trace already in progress, stopping";
+ // TODO: Stop the trace, then start it up again instead of returning.
+ LOG(INFO) << "Trace already in progress, ignoring this request";
return;
}
+ // Suspend all threads.
+ ScopedThreadStateChange tsc(Thread::Current(), Thread::kRunnable);
+ Runtime::Current()->GetThreadList()->SuspendAll(false);
+
+ // Open files and allocate storage.
+ if (!direct_to_ddms) {
+ if (trace_fd < 0) {
+ trace_file_ = OS::OpenFile(trace_filename, true);
+ } else {
+ trace_file_ = OS::FileFromFd("tracefile", trace_fd);
+ }
+ if (trace_file_ == NULL) {
+ PLOG(ERROR) << "Unable to open trace file '" << trace_filename;
+ Thread::Current()->ThrowNewException("Ljava/lang/RuntimeException;",
+ StringPrintf("Unable to open trace file '%s'", trace_filename).c_str());
+ Runtime::Current()->GetThreadList()->ResumeAll(false);
+ return;
+ }
+ }
+ buf_ = new uint8_t[buffer_size]();
+
+ // Populate profiler state.
+ direct_to_ddms_ = direct_to_ddms;
+ buffer_size_ = buffer_size;
+ overflow_ = false;
+ start_time_ = MicroTime();
+
+ if (UseThreadCpuClock() && UseWallClock()) {
+ trace_version_ = kTraceVersionDualClock;
+ record_size_ = kTraceRecordSizeDualClock;
+ } else {
+ trace_version_ = kTraceVersionSingleClock;
+ record_size_ = kTraceRecordSizeSingleClock;
+ }
+
+ saved_code_map_.clear();
+ visited_methods_.clear();
+ thread_clock_base_map_.clear();
+
+ // Set up the beginning of the trace.
+ memset(buf_, 0, kTraceHeaderLength);
+ Append4LE(buf_, kTraceMagicValue);
+ Append2LE(buf_ + 4, trace_version_);
+ Append2LE(buf_ + 6, kTraceHeaderLength);
+ Append8LE(buf_ + 8, start_time_);
+ if (trace_version_ >= kTraceVersionDualClock) {
+ Append2LE(buf_ + 16, record_size_);
+ }
+ cur_offset_ = kTraceHeaderLength;
+
SetMethodTracingActive(true);
+
+ // Install all method tracing stubs.
InstallStubs();
LOG(INFO) << "Method tracing started";
+
+ Runtime::Current()->GetThreadList()->ResumeAll(false);
}
void Trace::Stop() {
LOG(INFO) << "Stopping method tracing...";
if (!IsMethodTracingActive()) {
- LOG(INFO) << "Trace stop requested, but not running";
+ LOG(INFO) << "Trace stop requested, but no trace currently running";
return;
}
+ // Suspend all threads.
+ ScopedThreadStateChange tsc(Thread::Current(), Thread::kRunnable);
+ Runtime::Current()->GetThreadList()->SuspendAll(false);
+
+ // Uninstall all method tracing stubs.
UninstallStubs();
+
SetMethodTracingActive(false);
+
+ // Compute elapsed time.
+ uint64_t elapsed = MicroTime() - start_time_;
+
+ size_t final_offset = cur_offset_;
+ uint32_t clock_overhead = GetClockOverhead();
+
+ GetVisitedMethods(final_offset);
+
+ std::ostringstream os;
+
+ os << StringPrintf("%cversion\n", kTraceTokenChar);
+ os << StringPrintf("%d\n", trace_version_);
+ os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false");
+ if (UseThreadCpuClock()) {
+ if (UseWallClock()) {
+ os << StringPrintf("clock=dual\n");
+ } else {
+ os << StringPrintf("clock=thread-cpu\n");
+ }
+ } else {
+ os << StringPrintf("clock=wall\n");
+ }
+ os << StringPrintf("elapsed-time-usec=%llu\n", elapsed);
+ os << StringPrintf("num-method-calls=%d\n", (final_offset - kTraceHeaderLength) / record_size_);
+ os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead);
+ os << StringPrintf("vm=art\n");
+ os << StringPrintf("%cthreads\n", kTraceTokenChar);
+ DumpThreadList(os);
+ os << StringPrintf("%cmethods\n", kTraceTokenChar);
+ DumpMethodList(os);
+ os << StringPrintf("%cend\n", kTraceTokenChar);
+
+ std::string header(os.str());
+ if (direct_to_ddms_) {
+ struct iovec iov[2];
+ iov[0].iov_base = reinterpret_cast<void*>(const_cast<char*>(header.c_str()));
+ iov[0].iov_len = header.length();
+ iov[1].iov_base = buf_;
+ iov[1].iov_len = final_offset;
+ Dbg::DdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2);
+ } else {
+ if (!trace_file_->WriteFully(header.c_str(), header.length()) ||
+ !trace_file_->WriteFully(buf_, final_offset)) {
+ int err = errno;
+ LOG(ERROR) << "Trace data write failed: " << strerror(err);
+ Thread::Current()->ThrowNewException("Ljava/lang/RuntimeException;",
+ StringPrintf("Trace data write failed: %s", strerror(err)).c_str());
+ }
+ delete trace_file_;
+ }
+
+ delete buf_;
+
LOG(INFO) << "Method tracing stopped";
+
+ Runtime::Current()->GetThreadList()->ResumeAll(false);
+}
+
+void Trace::LogMethodTraceEvent(Thread* self, const Method* method, Trace::TraceEvent event) {
+ if (thread_clock_base_map_.find(self) == thread_clock_base_map_.end()) {
+ uint64_t time = ThreadCpuMicroTime();
+ thread_clock_base_map_.insert(std::make_pair(self, time));
+ }
+
+ // Advance cur_offset_ atomically.
+ int32_t new_offset;
+ int32_t old_offset;
+ do {
+ old_offset = cur_offset_;
+ new_offset = old_offset + record_size_;
+ if (new_offset > buffer_size_) {
+ overflow_ = true;
+ return;
+ }
+ } while (android_atomic_release_cas(old_offset, new_offset, &cur_offset_) != 0);
+
+ uint32_t method_value = TraceMethodCombine(reinterpret_cast<uint32_t>(method), event);
+
+ // Write data
+ uint8_t* ptr = buf_ + old_offset;
+ Append2LE(ptr, self->GetTid());
+ Append4LE(ptr + 2, method_value);
+ ptr += 6;
+
+ if (UseThreadCpuClock()) {
+ uint64_t thread_clock_base = thread_clock_base_map_.find(self)->second;
+ uint32_t thread_clock_diff = ThreadCpuMicroTime() - thread_clock_base;
+ Append4LE(ptr, thread_clock_diff);
+ ptr += 4;
+ }
+
+ if (UseWallClock()) {
+ uint32_t wall_clock_diff = MicroTime() - start_time_;
+ Append4LE(ptr, wall_clock_diff);
+ }
+}
+
+void Trace::GetVisitedMethods(size_t end_offset) {
+ uint8_t* ptr = buf_ + kTraceHeaderLength;
+ uint8_t* end = buf_ + end_offset;
+
+ while (ptr < end) {
+ uint32_t method_value = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16) | (ptr[5] << 24);
+ Method* method = reinterpret_cast<Method*>(TraceMethodId(method_value));
+ visited_methods_.insert(method);
+ ptr += record_size_;
+ }
+}
+
+void Trace::DumpMethodList(std::ostream& os) {
+ typedef std::set<const Method*>::const_iterator It; // TODO: C++0x auto
+ for (It it = visited_methods_.begin(); it != visited_methods_.end(); ++it) {
+ const Method* method = *it;
+ MethodHelper mh(method);
+ os << StringPrintf("0x%08x\t%s\t%s\t%s\t%s\t%d\n", (int) method,
+ PrettyDescriptor(mh.GetDeclaringClassDescriptor()).c_str(), mh.GetName(),
+ mh.GetSignature().c_str(), mh.GetDeclaringClassSourceFile(),
+ mh.GetLineNumFromNativePC(0));
+ }
+ visited_methods_.clear();
+}
+
+static void DumpThread(Thread* t, void* arg) {
+ std::ostream* os = reinterpret_cast<std::ostream*>(arg);
+ *os << StringPrintf("%d\t%s\n", t->GetTid(), t->GetName()->ToModifiedUtf8().c_str());
+}
+
+void Trace::DumpThreadList(std::ostream& os) {
+ ScopedThreadListLock thread_list_lock;
+ Runtime::Current()->GetThreadList()->ForEach(DumpThread, &os);
}
void Trace::InstallStubs() {
#if defined(__arm__)
- {
- ScopedThreadStateChange tsc(Thread::Current(), Thread::kRunnable);
- Runtime::Current()->GetThreadList()->SuspendAll(false);
- }
-
void* trace_stub = reinterpret_cast<void*>(art_trace_entry_from_code);
Runtime::Current()->GetClassLinker()->VisitClasses(InstallStubsClassVisitor, trace_stub);
-
- Runtime::Current()->GetThreadList()->ResumeAll(false);
#else
UNIMPLEMENTED(WARNING);
#endif
@@ -167,11 +448,6 @@
void Trace::UninstallStubs() {
#if defined(__arm__)
- {
- ScopedThreadStateChange tsc(Thread::Current(), Thread::kRunnable);
- Runtime::Current()->GetThreadList()->SuspendAll(false);
- }
-
void* trace_stub = reinterpret_cast<void*>(art_trace_entry_from_code);
Runtime::Current()->GetClassLinker()->VisitClasses(UninstallStubsClassVisitor, trace_stub);
@@ -180,8 +456,6 @@
ScopedThreadListLock thread_list_lock;
Runtime::Current()->GetThreadList()->ForEach(TraceRestoreStack, NULL);
}
-
- Runtime::Current()->GetThreadList()->ResumeAll(false);
#else
UNIMPLEMENTED(WARNING);
#endif