Interpreter entries and instrumentation as a listener.
Make the instrumentation responsible for whether we want method entry/exit
stubs, and allow it to use interpreter entry stubs when instruction by
instruction instrumentation is required. Improve deoptimization so more JDWP
test cases are passing.
Refactor exception debug posting, in particular improve reporting in the
interpreter. Improve class linker exception throwing so that broken dex files
are more likely to be reported. Fixes the performance issue Bug: 8410519.
Fix some error reporting lock level errors for the large object space. Make
fast object verification faster.
Add some debug mode robustness to finding dex PCs in GC maps.
Add printf attributes to JniAbortF and fix errors.
Expand run-test 044 to test return behaviors and fix issues with not throwing
appropriate exceptions for proxies.
Ensure causes are reported with a class linker NoClassDefFoundError and JNI
NoSuchFieldError.
Remove unused debugMe and updateDebuggerFromCode.
There's a minor sizing tweak to the arg array builder, and an extra reference
array check in the interpreter.
Some clean-up of trace code.
Fix reg type cache destructor if it is called after the reg type cache is
shutdown (as is the case in oatdump).
Change-Id: I6519c7b35df77f978d011999354c864f4918e8ce
diff --git a/src/trace.cc b/src/trace.cc
index 859f523..3293290 100644
--- a/src/trace.cc
+++ b/src/trace.cc
@@ -20,6 +20,7 @@
#include "base/unix_file/fd_file.h"
#include "class_linker.h"
+#include "common_throws.h"
#include "debugger.h"
#include "dex_file-inl.h"
#include "instrumentation.h"
@@ -73,7 +74,14 @@
//
// All values are stored in little-endian order.
-static const uint32_t kTraceMethodActionMask = 0x03; // two bits
+enum TraceAction {
+ kTraceMethodEnter = 0x00, // method entry
+ kTraceMethodExit = 0x01, // method exit
+ kTraceUnroll = 0x02, // method exited by exception unrolling
+ // 0x03 currently unused
+ kTraceMethodActionMask = 0x03, // two bits
+};
+
static const char kTraceTokenChar = '*';
static const uint16_t kTraceHeaderLength = 32;
static const uint32_t kTraceMagicValue = 0x574f4c53;
@@ -82,34 +90,57 @@
static const uint16_t kTraceRecordSizeSingleClock = 10; // using v2
static const uint16_t kTraceRecordSizeDualClock = 14; // using v3 with two timestamps
-static ProfilerClockSource gDefaultTraceClockSource = kProfilerClockSourceDual;
+#if defined(HAVE_POSIX_CLOCKS)
+ProfilerClockSource Trace::default_clock_source_ = kProfilerClockSourceDual;
+#else
+ProfilerClockSource Trace::default_clock_source_ = kProfilerClockSourceWall;
+#endif
-static inline uint32_t TraceMethodId(uint32_t methodValue) {
- return (methodValue & ~kTraceMethodActionMask);
+Trace* Trace::the_trace_ = NULL;
+
+static mirror::AbstractMethod* DecodeTraceMethodId(uint32_t tmid) {
+ return reinterpret_cast<mirror::AbstractMethod*>(tmid & ~kTraceMethodActionMask);
}
-static inline uint32_t TraceMethodCombine(uint32_t method, uint8_t traceEvent) {
- return (method | traceEvent);
+static TraceAction DecodeTraceAction(uint32_t tmid) {
+ return static_cast<TraceAction>(tmid & kTraceMethodActionMask);
+}
+
+static uint32_t EncodeTraceMethodAndAction(const mirror::AbstractMethod* method,
+ TraceAction action) {
+ uint32_t tmid = reinterpret_cast<uint32_t>(method) | action;
+ DCHECK_EQ(method, DecodeTraceMethodId(tmid));
+ return tmid;
}
void Trace::SetDefaultClockSource(ProfilerClockSource clock_source) {
- gDefaultTraceClockSource = clock_source;
+#if defined(HAVE_POSIX_CLOCKS)
+ default_clock_source_ = clock_source;
+#else
+ if (clock_source != kProfilerClockSourceWall) {
+ LOG(WARNING) << "Ignoring tracing request to use ";
+ }
+#endif
+}
+
+static uint16_t GetTraceVersion(ProfilerClockSource clock_source) {
+ return (clock_source == kProfilerClockSourceDual) ? kTraceVersionDualClock
+ : kTraceVersionSingleClock;
+}
+
+static uint16_t GetRecordSize(ProfilerClockSource clock_source) {
+ return (clock_source == kProfilerClockSourceDual) ? kTraceRecordSizeDualClock
+ : kTraceRecordSizeSingleClock;
}
bool Trace::UseThreadCpuClock() {
-#if defined(HAVE_POSIX_CLOCKS)
- return clock_source_ != kProfilerClockSourceWall;
-#else
- return false;
-#endif
+ return (clock_source_ == kProfilerClockSourceThreadCpu) ||
+ (clock_source_ == kProfilerClockSourceDual);
}
bool Trace::UseWallClock() {
-#if defined(HAVE_POSIX_CLOCKS)
- return clock_source_ != kProfilerClockSourceThreadCpu;
-#else
- return true;
-#endif
+ return (clock_source_ == kProfilerClockSourceWall) ||
+ (clock_source_ == kProfilerClockSourceDual);
}
static void MeasureClockOverhead(Trace* trace) {
@@ -165,109 +196,129 @@
*buf++ = (uint8_t) (val >> 56);
}
-Trace::Trace(File* trace_file, int buffer_size, int flags)
- : trace_file_(trace_file), buf_(new uint8_t[buffer_size]()), flags_(flags),
- clock_source_(gDefaultTraceClockSource), overflow_(false),
- buffer_size_(buffer_size), start_time_(0), trace_version_(0), record_size_(0), cur_offset_(0) {
-}
-
-void Trace::Start(const char* trace_filename, int trace_fd, int buffer_size, int flags, bool direct_to_ddms) {
- if (Runtime::Current()->IsMethodTracingActive()) {
- LOG(INFO) << "Trace already in progress, ignoring this request";
- return;
+void Trace::Start(const char* trace_filename, int trace_fd, int buffer_size, int flags,
+ bool direct_to_ddms) {
+ Thread* self = Thread::Current();
+ {
+ MutexLock mu(self, *Locks::trace_lock_);
+ if (the_trace_ != NULL) {
+ LOG(ERROR) << "Trace already in progress, ignoring this request";
+ return;
+ }
}
-
- Runtime::Current()->GetThreadList()->SuspendAll();
+ Runtime* runtime = Runtime::Current();
+ runtime->GetThreadList()->SuspendAll();
// Open trace file if not going directly to ddms.
- File* trace_file = NULL;
+ UniquePtr<File> trace_file;
if (!direct_to_ddms) {
if (trace_fd < 0) {
- trace_file = OS::OpenFile(trace_filename, true);
+ trace_file.reset(OS::OpenFile(trace_filename, true));
} else {
- trace_file = new File(trace_fd, "tracefile");
+ trace_file.reset(new File(trace_fd, "tracefile"));
trace_file->DisableAutoClose();
}
- if (trace_file == NULL) {
+ if (trace_file.get() == 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();
+ runtime->GetThreadList()->ResumeAll();
+ ScopedObjectAccess soa(self);
+ ThrowRuntimeException("Unable to open trace file '%s'", trace_filename);
return;
}
}
// Create Trace object.
- Trace* tracer(new Trace(trace_file, buffer_size, flags));
+ {
+ MutexLock mu(self, *Locks::trace_lock_);
+ if(the_trace_ != NULL) {
+ LOG(ERROR) << "Trace already in progress, ignoring this request";
+ } else {
+ the_trace_ = new Trace(trace_file.release(), buffer_size, flags);
- // Enable count of allocs if specified in the flags.
- if ((flags && kTraceCountAllocs) != 0) {
- Runtime::Current()->SetStatsEnabled(true);
+ // Enable count of allocs if specified in the flags.
+ if ((flags && kTraceCountAllocs) != 0) {
+ runtime->SetStatsEnabled(true);
+ }
+
+ runtime->GetInstrumentation()->AddListener(the_trace_,
+ instrumentation::Instrumentation::kMethodEntered |
+ instrumentation::Instrumentation::kMethodExited |
+ instrumentation::Instrumentation::kMethodUnwind);
+ }
}
-
- Runtime::Current()->EnableMethodTracing(tracer);
- tracer->BeginTracing();
-
- Runtime::Current()->GetThreadList()->ResumeAll();
+ runtime->GetThreadList()->ResumeAll();
}
void Trace::Stop() {
- if (!Runtime::Current()->IsMethodTracingActive()) {
- LOG(INFO) << "Trace stop requested, but no trace currently running";
- return;
+ Runtime* runtime = Runtime::Current();
+ runtime->GetThreadList()->SuspendAll();
+ Trace* the_trace = NULL;
+ {
+ MutexLock mu(Thread::Current(), *Locks::trace_lock_);
+ if (the_trace_ == NULL) {
+ LOG(ERROR) << "Trace stop requested, but no trace currently running";
+ } else {
+ the_trace = the_trace_;
+ the_trace_ = NULL;
+ }
}
-
- Runtime::Current()->GetThreadList()->SuspendAll();
-
- Runtime::Current()->GetInstrumentation()->GetTrace()->FinishTracing();
- Runtime::Current()->DisableMethodTracing();
-
- Runtime::Current()->GetThreadList()->ResumeAll();
+ if (the_trace != NULL) {
+ the_trace->FinishTracing();
+ runtime->GetInstrumentation()->RemoveListener(the_trace,
+ instrumentation::Instrumentation::kMethodEntered |
+ instrumentation::Instrumentation::kMethodExited |
+ instrumentation::Instrumentation::kMethodUnwind);
+ delete the_trace;
+ }
+ runtime->GetThreadList()->ResumeAll();
}
void Trace::Shutdown() {
- if (!Runtime::Current()->IsMethodTracingActive()) {
- LOG(INFO) << "Trace shutdown requested, but no trace currently running";
- return;
+ if (IsMethodTracingActive()) {
+ Stop();
}
- Runtime::Current()->GetInstrumentation()->GetTrace()->FinishTracing();
- Runtime::Current()->DisableMethodTracing();
}
-void Trace::BeginTracing() {
- // Set the start time of tracing.
- start_time_ = MicroTime();
+bool Trace::IsMethodTracingActive() {
+ MutexLock mu(Thread::Current(), *Locks::trace_lock_);
+ return the_trace_ != NULL;
+}
- // Set trace version and record size.
- if (UseThreadCpuClock() && UseWallClock()) {
- trace_version_ = kTraceVersionDualClock;
- record_size_ = kTraceRecordSizeDualClock;
- } else {
- trace_version_ = kTraceVersionSingleClock;
- record_size_ = kTraceRecordSizeSingleClock;
- }
-
+Trace::Trace(File* trace_file, int buffer_size, int flags)
+ : trace_file_(trace_file), buf_(new uint8_t[buffer_size]()), flags_(flags),
+ clock_source_(default_clock_source_), buffer_size_(buffer_size), start_time_(MicroTime()),
+ cur_offset_(0), overflow_(false) {
// Set up the beginning of the trace.
+ uint16_t trace_version = GetTraceVersion(clock_source_);
memset(buf_.get(), 0, kTraceHeaderLength);
Append4LE(buf_.get(), kTraceMagicValue);
- Append2LE(buf_.get() + 4, trace_version_);
+ Append2LE(buf_.get() + 4, trace_version);
Append2LE(buf_.get() + 6, kTraceHeaderLength);
Append8LE(buf_.get() + 8, start_time_);
- if (trace_version_ >= kTraceVersionDualClock) {
- Append2LE(buf_.get() + 16, record_size_);
+ if (trace_version >= kTraceVersionDualClock) {
+ uint16_t record_size = GetRecordSize(clock_source_);
+ Append2LE(buf_.get() + 16, record_size);
}
// Update current offset.
cur_offset_ = kTraceHeaderLength;
+}
- // Install all method tracing stubs.
- Runtime::Current()->GetInstrumentation()->InstallStubs();
+static void DumpBuf(uint8_t* buf, size_t buf_size, ProfilerClockSource clock_source)
+ SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
+ uint8_t* ptr = buf + kTraceHeaderLength;
+ uint8_t* end = buf + buf_size;
+
+ while (ptr < end) {
+ uint32_t tmid = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16) | (ptr[5] << 24);
+ mirror::AbstractMethod* method = DecodeTraceMethodId(tmid);
+ TraceAction action = DecodeTraceAction(tmid);
+ LOG(INFO) << PrettyMethod(method) << " " << static_cast<int>(action);
+ ptr += GetRecordSize(clock_source);
+ }
}
void Trace::FinishTracing() {
- // Uninstall all method tracing stubs.
- Runtime::Current()->GetInstrumentation()->UninstallStubs();
-
// Compute elapsed time.
uint64_t elapsed = MicroTime() - start_time_;
@@ -278,12 +329,13 @@
Runtime::Current()->SetStatsEnabled(false);
}
- GetVisitedMethods(final_offset);
+ std::set<mirror::AbstractMethod*> visited_methods;
+ GetVisitedMethods(final_offset, &visited_methods);
std::ostringstream os;
os << StringPrintf("%cversion\n", kTraceTokenChar);
- os << StringPrintf("%d\n", trace_version_);
+ os << StringPrintf("%d\n", GetTraceVersion(clock_source_));
os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false");
if (UseThreadCpuClock()) {
if (UseWallClock()) {
@@ -295,7 +347,8 @@
os << StringPrintf("clock=wall\n");
}
os << StringPrintf("elapsed-time-usec=%llu\n", elapsed);
- os << StringPrintf("num-method-calls=%zd\n", (final_offset - kTraceHeaderLength) / record_size_);
+ size_t num_records = (final_offset - kTraceHeaderLength) / GetRecordSize(clock_source_);
+ os << StringPrintf("num-method-calls=%zd\n", num_records);
os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead);
os << StringPrintf("vm=art\n");
if ((flags_ & kTraceCountAllocs) != 0) {
@@ -306,7 +359,7 @@
os << StringPrintf("%cthreads\n", kTraceTokenChar);
DumpThreadList(os);
os << StringPrintf("%cmethods\n", kTraceTokenChar);
- DumpMethodList(os);
+ DumpMethodList(os, visited_methods);
os << StringPrintf("%cend\n", kTraceTokenChar);
std::string header(os.str());
@@ -317,74 +370,128 @@
iov[1].iov_base = buf_.get();
iov[1].iov_len = final_offset;
Dbg::DdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2);
+ const bool kDumpTraceInfo = false;
+ if (kDumpTraceInfo) {
+ LOG(INFO) << "Trace sent:\n" << header;
+ DumpBuf(buf_.get(), final_offset, clock_source_);
+ }
} else {
if (!trace_file_->WriteFully(header.c_str(), header.length()) ||
!trace_file_->WriteFully(buf_.get(), final_offset)) {
std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno)));
PLOG(ERROR) << detail;
- Thread::Current()->ThrowNewException("Ljava/lang/RuntimeException;", detail.c_str());
+ ThrowRuntimeException("%s", detail.c_str());
}
}
}
-void Trace::LogMethodTraceEvent(Thread* self, const mirror::AbstractMethod* method,
- Trace::TraceEvent event) {
- if (thread_clock_base_map_.find(self) == thread_clock_base_map_.end()) {
- uint64_t time = ThreadCpuMicroTime();
- thread_clock_base_map_.Put(self, time);
- }
+void Trace::DexPcMoved(Thread* thread, mirror::Object* this_object,
+ const mirror::AbstractMethod* method, uint32_t new_dex_pc) {
+ // We're not recorded to listen to this kind of event, so complain.
+ LOG(ERROR) << "Unexpected dex PC event in tracing " << PrettyMethod(method) << " " << new_dex_pc;
+};
+void Trace::MethodEntered(Thread* thread, mirror::Object* this_object,
+ const mirror::AbstractMethod* method, uint32_t dex_pc) {
+ LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodEntered);
+}
+
+void Trace::MethodExited(Thread* thread, mirror::Object* this_object,
+ const mirror::AbstractMethod* method, uint32_t dex_pc,
+ const JValue& return_value) {
+ UNUSED(return_value);
+ LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodExited);
+}
+
+void Trace::MethodUnwind(Thread* thread, const mirror::AbstractMethod* method, uint32_t dex_pc) {
+ LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodUnwind);
+}
+
+void Trace::ExceptionCaught(Thread* thread, const ThrowLocation& throw_location,
+ mirror::AbstractMethod* catch_method, uint32_t catch_dex_pc,
+ mirror::Throwable* exception_object)
+ SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
+ LOG(ERROR) << "Unexpected exception caught event in tracing";
+}
+
+void Trace::LogMethodTraceEvent(Thread* thread, const mirror::AbstractMethod* method,
+ instrumentation::Instrumentation::InstrumentationEvent event) {
// Advance cur_offset_ atomically.
int32_t new_offset;
int32_t old_offset;
do {
old_offset = cur_offset_;
- new_offset = old_offset + record_size_;
+ new_offset = old_offset + GetRecordSize(clock_source_);
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);
+ TraceAction action = kTraceMethodEnter;
+ switch (event) {
+ case instrumentation::Instrumentation::kMethodEntered:
+ action = kTraceMethodEnter;
+ break;
+ case instrumentation::Instrumentation::kMethodExited:
+ action = kTraceMethodExit;
+ break;
+ case instrumentation::Instrumentation::kMethodUnwind:
+ action = kTraceUnroll;
+ break;
+ default:
+ UNIMPLEMENTED(FATAL) << "Unexpected event: " << event;
+ }
+
+ uint32_t method_value = EncodeTraceMethodAndAction(method, action);
// Write data
uint8_t* ptr = buf_.get() + old_offset;
- Append2LE(ptr, self->GetTid());
+ Append2LE(ptr, thread->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;
+ // TODO: this isn't vaguely thread safe.
+ SafeMap<Thread*, uint64_t>::iterator it = thread_clock_base_map_.find(thread);
+ uint32_t thread_clock_diff = 0;
+ if (UNLIKELY(it == thread_clock_base_map_.end())) {
+ // First event, the diff is 0, record the base time in the map.
+ uint64_t time = ThreadCpuMicroTime();
+ thread_clock_base_map_.Put(thread, time);
+ } else {
+ uint64_t thread_clock_base = it->second;
+ 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) {
+void Trace::GetVisitedMethods(size_t buf_size,
+ std::set<mirror::AbstractMethod*>* visited_methods) {
uint8_t* ptr = buf_.get() + kTraceHeaderLength;
- uint8_t* end = buf_.get() + end_offset;
+ uint8_t* end = buf_.get() + buf_size;
while (ptr < end) {
- uint32_t method_value = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16) | (ptr[5] << 24);
- mirror::AbstractMethod* method =
- reinterpret_cast<mirror::AbstractMethod*>(TraceMethodId(method_value));
- visited_methods_.insert(method);
- ptr += record_size_;
+ uint32_t tmid = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16) | (ptr[5] << 24);
+ mirror::AbstractMethod* method = DecodeTraceMethodId(tmid);
+ visited_methods->insert(method);
+ ptr += GetRecordSize(clock_source_);
}
}
-void Trace::DumpMethodList(std::ostream& os) {
- typedef std::set<const mirror::AbstractMethod*>::const_iterator It; // TODO: C++0x auto
- for (It it = visited_methods_.begin(); it != visited_methods_.end(); ++it) {
- const mirror::AbstractMethod* method = *it;
- MethodHelper mh(method);
+void Trace::DumpMethodList(std::ostream& os,
+ const std::set<mirror::AbstractMethod*>& visited_methods) {
+ typedef std::set<mirror::AbstractMethod*>::const_iterator It; // TODO: C++0x auto
+ MethodHelper mh;
+ for (It it = visited_methods.begin(); it != visited_methods.end(); ++it) {
+ mirror::AbstractMethod* method = *it;
+ mh.ChangeMethod(method);
os << StringPrintf("%p\t%s\t%s\t%s\t%s\n", method,
PrettyDescriptor(mh.GetDeclaringClassDescriptor()).c_str(), mh.GetName(),
mh.GetSignature().c_str(), mh.GetDeclaringClassSourceFile());