diff options
| -rw-r--r-- | runtime/trace.cc | 111 | ||||
| -rw-r--r-- | runtime/trace.h | 24 | ||||
| -rw-r--r-- | test/2246-trace-v2/dump_trace.cc | 79 |
3 files changed, 143 insertions, 71 deletions
diff --git a/runtime/trace.cc b/runtime/trace.cc index bb65dda867..dd14e323c3 100644 --- a/runtime/trace.cc +++ b/runtime/trace.cc @@ -87,7 +87,7 @@ static const int kSummaryHeaderV2 = 3; static const uint16_t kTraceHeaderLengthV2 = 32; static const uint16_t kTraceRecordSizeSingleClockV2 = 6; static const uint16_t kTraceRecordSizeDualClockV2 = kTraceRecordSizeSingleClockV2 + 2; -static const uint16_t kEntryHeaderSizeSingleClockV2 = 17; +static const uint16_t kEntryHeaderSizeSingleClockV2 = 21; static const uint16_t kEntryHeaderSizeDualClockV2 = kEntryHeaderSizeSingleClockV2 + 4; static const uint16_t kTraceVersionSingleClockV2 = 4; @@ -276,7 +276,7 @@ class TraceWriterTask final : public SelfDeletingTask { void Run(Thread* self ATTRIBUTE_UNUSED) override { std::unordered_map<ArtMethod*, std::string> method_infos; - { + if (trace_writer_->GetTraceFormatVersion() == Trace::kFormatV1) { ScopedObjectAccess soa(Thread::Current()); trace_writer_->PreProcessTraceForMethodInfos(buffer_, cur_offset_, method_infos); } @@ -521,6 +521,51 @@ void* Trace::RunSamplingThread(void* arg) { return nullptr; } +// Visitor used to record all methods currently loaded in the runtime. This is done at the start of +// method tracing. +class RecordMethodInfoClassVisitor : public ClassVisitor { + public: + explicit RecordMethodInfoClassVisitor(Trace* trace) : trace_(trace) {} + + bool operator()(ObjPtr<mirror::Class> klass) override REQUIRES(Locks::mutator_lock_) { + trace_->GetTraceWriter()->RecordMethodInfo(klass.Ptr()); + return true; // Visit all classes. + } + + private: + Trace* const trace_; +}; + +void Trace::ClassPrepare([[maybe_unused]] Handle<mirror::Class> temp_klass, + Handle<mirror::Class> klass) { + MutexLock mu(Thread::Current(), *Locks::trace_lock_); + if (the_trace_ == nullptr) { + return; + } + the_trace_->GetTraceWriter()->RecordMethodInfo(klass.Get()); +} + +void TraceWriter::RecordMethodInfo(mirror::Class* klass) { + // For the v1 format, we record methods when we first execute them. + if (trace_format_version_ == Trace::kFormatV1) { + return; + } + + MutexLock mu(Thread::Current(), tracing_lock_); + for (ArtMethod& method : klass->GetMethods(kRuntimePointerSize)) { + if (!method.IsInvokable()) { + continue; + } + + uint64_t method_id = reinterpret_cast<uint64_t>(&method); + if (trace_output_mode_ == TraceOutputMode::kStreaming) { + // Record the entry in the file for streaming output mode. For + // non-streaming case all information is logged at the end of tracing. + RecordMethodInfo(GetMethodInfoLine(&method), method_id); + } + } +} + void Trace::Start(const char* trace_filename, size_t buffer_size, int flags, @@ -629,6 +674,10 @@ void Trace::Start(std::unique_ptr<File>&& trace_file_in, } else { enable_stats = (flags & kTraceCountAllocs) != 0; the_trace_ = new Trace(trace_file.release(), buffer_size, flags, output_mode, trace_mode); + // Record all the methods that are currently loaded. We log all methods when any new class is + // loaded. This will allow us to process the trace entries without requiring a mutator lock. + RecordMethodInfoClassVisitor visitor(the_trace_); + runtime->GetClassLinker()->VisitClasses(&visitor); if (trace_mode == TraceMode::kSampling) { CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread, reinterpret_cast<void*>(interval_us)), @@ -654,6 +703,8 @@ void Trace::Start(std::unique_ptr<File>&& trace_file_in, // user space. Seem comment in GetTimestamp for more details. is_fast_trace = false; #endif + // Add ClassLoadCallback to record methods on class load. + runtime->GetRuntimeCallbacks()->AddClassLoadCallback(the_trace_); runtime->GetInstrumentation()->AddListener( the_trace_, instrumentation::Instrumentation::kMethodEntered | @@ -719,13 +770,14 @@ void Trace::StopTracing(bool flush_entries) { // user space. Seem comment in GetTimestamp for more details. is_fast_trace = false; #endif - runtime->GetInstrumentation()->RemoveListener( - the_trace, - instrumentation::Instrumentation::kMethodEntered | - instrumentation::Instrumentation::kMethodExited | - instrumentation::Instrumentation::kMethodUnwind, - is_fast_trace); - runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey); + runtime->GetRuntimeCallbacks()->RemoveClassLoadCallback(the_trace_); + runtime->GetInstrumentation()->RemoveListener( + the_trace, + instrumentation::Instrumentation::kMethodEntered | + instrumentation::Instrumentation::kMethodExited | + instrumentation::Instrumentation::kMethodUnwind, + is_fast_trace); + runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey); } // Flush thread specific buffer from all threads before resetting the_trace_ to nullptr. @@ -1257,11 +1309,11 @@ void TraceWriter::PreProcessTraceForMethodInfos( } } -void TraceWriter::RecordMethodInfo(const std::string& method_info_line, uint32_t method_id) { +void TraceWriter::RecordMethodInfo(const std::string& method_info_line, uint64_t method_id) { // Write a special block with the name. std::string method_line; size_t header_size; - static constexpr size_t kMaxMethodNameHeaderSize = 7; + static constexpr size_t kMaxMethodNameHeaderSize = 11; uint8_t method_header[kMaxMethodNameHeaderSize]; uint16_t method_line_length = static_cast<uint16_t>(method_line.length()); DCHECK(method_line.length() < (1 << 16)); @@ -1279,9 +1331,9 @@ void TraceWriter::RecordMethodInfo(const std::string& method_info_line, uint32_t method_line = method_info_line; method_line_length = static_cast<uint16_t>(method_line.length()); method_header[0] = kMethodInfoHeaderV2; - Append4LE(method_header + 1, method_id); - Append2LE(method_header + 5, method_line_length); - header_size = 7; + Append8LE(method_header + 1, method_id); + Append2LE(method_header + 9, method_line_length); + header_size = 11; } const uint8_t* ptr = reinterpret_cast<const uint8_t*>(method_line.c_str()); @@ -1376,7 +1428,9 @@ void TraceWriter::FlushBuffer(Thread* thread, bool is_sync, bool release) { if (is_sync || thread_pool_ == nullptr) { std::unordered_map<ArtMethod*, std::string> method_infos; - PreProcessTraceForMethodInfos(method_trace_entries, *current_offset, method_infos); + if (trace_format_version_ == Trace::kFormatV1) { + PreProcessTraceForMethodInfos(method_trace_entries, *current_offset, method_infos); + } FlushBuffer(method_trace_entries, *current_offset, tid, method_infos); // This is a synchronous flush, so no need to allocate a new buffer. This is used either @@ -1474,7 +1528,6 @@ void TraceWriter::FlushEntriesFormatV1( void TraceWriter::FlushEntriesFormatV2( uintptr_t* method_trace_entries, size_t tid, - const std::unordered_map<ArtMethod*, std::string>& method_infos, size_t num_records, size_t* current_index, uint8_t* init_buffer_ptr) { @@ -1483,7 +1536,7 @@ void TraceWriter::FlushEntriesFormatV2( size_t num_entries = GetNumEntries(clock_source_); uint32_t prev_wall_timestamp = 0; uint32_t prev_thread_timestamp = 0; - int32_t init_method_action_encoding = 0; + uint64_t prev_method_action_encoding = 0; bool is_first_entry = true; uint8_t* current_buffer_ptr = init_buffer_ptr; uint32_t header_size = (clock_source_ == TraceClockSource::kDual) ? kEntryHeaderSizeDualClockV2 : @@ -1501,17 +1554,13 @@ void TraceWriter::FlushEntriesFormatV2( // On 64-bit this means method ids would use 8 bytes but that is okay since we only encode the // full method id in the header and then encode the diff against the method id in the header. // The diff is usually expected to be small. - auto [method_id, is_new_method] = GetMethodEncoding(record.method); - if (is_new_method && trace_output_mode_ == TraceOutputMode::kStreaming) { - RecordMethodInfo(method_infos.find(record.method)->second, method_id); - } - DCHECK(method_id < (1 << (31 - TraceActionBits))); - uint32_t method_action_encoding = (method_id << TraceActionBits) | record.action; + uint64_t method_id = reinterpret_cast<uintptr_t>(record.method); + uint64_t method_action_encoding = method_id | record.action; if (is_first_entry) { prev_wall_timestamp = record.wall_clock_time; prev_thread_timestamp = record.thread_cpu_time; - init_method_action_encoding = method_action_encoding; + prev_method_action_encoding = method_action_encoding; is_first_entry = false; EncodeEventBlockHeader(init_buffer_ptr, @@ -1522,8 +1571,9 @@ void TraceWriter::FlushEntriesFormatV2( num_records); current_buffer_ptr += header_size; } else { - current_buffer_ptr = EncodeSignedLeb128(current_buffer_ptr, - (method_action_encoding - init_method_action_encoding)); + int64_t method_diff = method_action_encoding - prev_method_action_encoding; + current_buffer_ptr = EncodeSignedLeb128(current_buffer_ptr, method_diff); + prev_method_action_encoding = method_action_encoding; if (has_wall_clock) { current_buffer_ptr = @@ -1581,8 +1631,7 @@ void TraceWriter::FlushBuffer(uintptr_t* method_trace_entries, FlushEntriesFormatV1( method_trace_entries, tid, method_infos, current_offset, ¤t_index, buffer_ptr); } else { - FlushEntriesFormatV2( - method_trace_entries, tid, method_infos, num_records, ¤t_index, buffer_ptr); + FlushEntriesFormatV2(method_trace_entries, tid, num_records, ¤t_index, buffer_ptr); } if (trace_output_mode_ == TraceOutputMode::kStreaming) { @@ -1681,14 +1730,14 @@ void TraceWriter::EncodeEventEntry(uint8_t* ptr, void TraceWriter::EncodeEventBlockHeader(uint8_t* ptr, uint32_t thread_id, - uint32_t init_method_index, + uint64_t init_method_index, uint32_t init_thread_clock, uint32_t init_wall_clock, uint16_t num_records) { ptr[0] = kEntryHeaderV2; Append4LE(ptr + 1, thread_id); - Append4LE(ptr + 5, init_method_index); - ptr += 9; + Append8LE(ptr + 5, init_method_index); + ptr += 13; if (UseThreadCpuClock(clock_source_)) { Append4LE(ptr, init_thread_clock); diff --git a/runtime/trace.h b/runtime/trace.h index 227955ff2d..baa8e20259 100644 --- a/runtime/trace.h +++ b/runtime/trace.h @@ -32,6 +32,7 @@ #include "base/mutex.h" #include "base/os.h" #include "base/safe_map.h" +#include "class_linker.h" #include "instrumentation.h" #include "runtime_globals.h" #include "thread_pool.h" @@ -192,6 +193,9 @@ class TraceWriter { // thread. void RecordThreadInfo(Thread* thread) REQUIRES(!tracing_lock_); + // Records information about all methods in the newly loaded class. + void RecordMethodInfo(mirror::Class* klass) REQUIRES_SHARED(Locks::mutator_lock_); + bool HasOverflow() { return overflow_; } TraceOutputMode GetOutputMode() { return trace_output_mode_; } size_t GetBufferSize() { return buffer_size_; } @@ -212,6 +216,8 @@ class TraceWriter { // buffer and assign parts of it for each thread. int GetMethodTraceIndex(uintptr_t* current_buffer); + int GetTraceFormatVersion() { return trace_format_version_; } + private: void ReadValuesFromRecord(uintptr_t* method_trace_entries, size_t record_index, @@ -221,7 +227,6 @@ class TraceWriter { void FlushEntriesFormatV2(uintptr_t* method_trace_entries, size_t tid, - const std::unordered_map<ArtMethod*, std::string>& method_infos, size_t num_records, size_t* current_index, uint8_t* init_buffer_ptr) REQUIRES(tracing_lock_); @@ -249,7 +254,7 @@ class TraceWriter { // Helper function to record method information when processing the events. These are used by // streaming output mode. Non-streaming modes dump the methods and threads list at the end of // tracing. - void RecordMethodInfo(const std::string& method_line, uint32_t method_id) REQUIRES(tracing_lock_); + void RecordMethodInfo(const std::string& method_line, uint64_t method_id) REQUIRES(tracing_lock_); // Encodes the trace event. This assumes that there is enough space reserved to encode the entry. void EncodeEventEntry(uint8_t* ptr, @@ -263,7 +268,7 @@ class TraceWriter { // encode the entry. void EncodeEventBlockHeader(uint8_t* ptr, uint32_t thread_id, - uint32_t method_index, + uint64_t method_index, uint32_t init_thread_clock_time, uint32_t init_wall_clock_time, uint16_t num_records) REQUIRES(tracing_lock_); @@ -351,7 +356,7 @@ class TraceWriter { // Class for recording event traces. Trace data is either collected // synchronously during execution (TracingMode::kMethodTracingActive), // or by a separate sampling thread (TracingMode::kSampleProfilingActive). -class Trace final : public instrumentation::InstrumentationListener { +class Trace final : public instrumentation::InstrumentationListener, public ClassLoadCallback { public: enum TraceFlag { kTraceCountAllocs = 0x001, @@ -456,6 +461,12 @@ class Trace final : public instrumentation::InstrumentationListener { void WatchedFramePop(Thread* thread, const ShadowFrame& frame) REQUIRES_SHARED(Locks::mutator_lock_) override; + // ClassLoadCallback implementation + void ClassLoad([[maybe_unused]] Handle<mirror::Class> klass) + REQUIRES_SHARED(Locks::mutator_lock_) override {} + void ClassPrepare(Handle<mirror::Class> temp_klass, Handle<mirror::Class> klass) + REQUIRES_SHARED(Locks::mutator_lock_) override; + TraceClockSource GetClockSource() { return clock_source_; } // Reuse an old stack trace if it exists, otherwise allocate a new one. @@ -472,6 +483,11 @@ class Trace final : public instrumentation::InstrumentationListener { // Used by class linker to prevent class unloading. static bool IsTracingEnabled() REQUIRES(!Locks::trace_lock_); + // Callback for each class prepare event to record information about the newly created methods. + static void ClassPrepare(Handle<mirror::Class> klass) REQUIRES_SHARED(Locks::mutator_lock_); + + TraceWriter* GetTraceWriter() { return trace_writer_.get(); } + private: Trace(File* trace_file, size_t buffer_size, diff --git a/test/2246-trace-v2/dump_trace.cc b/test/2246-trace-v2/dump_trace.cc index 66192798f5..c7eea0ddd5 100644 --- a/test/2246-trace-v2/dump_trace.cc +++ b/test/2246-trace-v2/dump_trace.cc @@ -45,22 +45,27 @@ static const std::string_view ignored_methods_list[] = { "java.lang.ref.ReferenceQueue add (Ljava/lang/ref/Reference;)V ReferenceQueue.java" }; -int ReadNumber(int num_bytes, uint8_t* header) { - int number = 0; +uint64_t ReadNumber(int num_bytes, uint8_t* header) { + uint64_t number = 0; for (int i = 0; i < num_bytes; i++) { - number += header[i] << (i * 8); + uint64_t c = header[i]; + number += c << (i * 8); } return number; } -bool ProcessThreadOrMethodInfo(std::unique_ptr<File>& file, std::map<int, std::string>& name_map) { - uint8_t header[6]; - if (!file->ReadFully(&header, sizeof(header))) { +bool ProcessThreadOrMethodInfo(std::unique_ptr<File>& file, + std::map<uint64_t, std::string>& name_map, + bool is_method) { + uint8_t header[10]; + uint8_t header_length = is_method ? 10 : 6; + if (!file->ReadFully(&header, header_length)) { printf("Couldn't read header\n"); return false; } - int id = ReadNumber(4, header); - int length = ReadNumber(2, header + 4); + uint8_t num_bytes_for_id = is_method ? 8 : 4; + uint64_t id = ReadNumber(num_bytes_for_id, header); + int length = ReadNumber(2, header + num_bytes_for_id); char* name = new char[length]; if (!file->ReadFully(name, length)) { @@ -135,22 +140,22 @@ void PrintTraceEntry(const std::string& thread_name, } bool ProcessTraceEntries(std::unique_ptr<File>& file, - std::map<int, int>& current_depth_map, - std::map<int, std::string>& thread_map, - std::map<int, std::string>& method_map, + std::map<int64_t, int>& current_depth_map, + std::map<uint64_t, std::string>& thread_map, + std::map<uint64_t, std::string>& method_map, bool is_dual_clock, const char* thread_name_filter, - std::map<int, std::string>& ignored_method_map, - std::map<int, int>& ignored_method_depth_map) { - uint8_t header[20]; - int header_size = is_dual_clock ? 20 : 16; + std::map<uint64_t, std::string>& ignored_method_map, + std::map<int64_t, int>& ignored_method_depth_map) { + uint8_t header[24]; + int header_size = is_dual_clock ? 24 : 20; if (!file->ReadFully(header, header_size)) { return false; } uint32_t thread_id = ReadNumber(4, header); - uint32_t method_value = ReadNumber(4, header + 4); - int offset = 8; + uint64_t method_value = ReadNumber(8, header + 4); + int offset = 12; if (is_dual_clock) { // Read timestamp. ReadNumber(4, header + offset); @@ -169,8 +174,8 @@ bool ProcessTraceEntries(std::unique_ptr<File>& file, } const uint8_t* current_buffer_ptr = buffer; - int32_t method_id = method_value >> kTraceActionBits; uint8_t event_type = method_value & 0x3; + uint64_t method_id = (method_value >> kTraceActionBits) << kTraceActionBits; int current_depth = 0; if (current_depth_map.find(thread_id) != current_depth_map.end()) { // Get the current call stack depth. If it is the first method we are seeing on this thread @@ -188,7 +193,7 @@ bool ProcessTraceEntries(std::unique_ptr<File>& file, std::string thread_name = thread_map[thread_id]; bool print_thread_events = (thread_name.compare(thread_name_filter) == 0); if (method_map.find(method_id) == method_map.end()) { - LOG(FATAL) << "No entry for init method " << method_id; + LOG(FATAL) << "No entry for init method " << std::hex << method_id << " " << method_value; } if (print_thread_events) { PrintTraceEntry(thread_name, @@ -198,15 +203,20 @@ bool ProcessTraceEntries(std::unique_ptr<File>& file, ignored_method, &ignored_method_depth); } + int64_t prev_method_value = method_value; for (int i = 0; i < num_records; i++) { - int32_t diff = 0; - bool success = DecodeSignedLeb128Checked(¤t_buffer_ptr, buffer + total_size - 1, &diff); - if (!success) { + int64_t diff = 0; + auto buffer_ptr = current_buffer_ptr; + if (!DecodeSignedLeb128Checked(¤t_buffer_ptr, buffer + total_size - 1, &diff)) { LOG(FATAL) << "Reading past the buffer???"; } - int32_t curr_method_value = method_value + diff; - method_id = curr_method_value >> kTraceActionBits; + int64_t curr_method_value = prev_method_value + diff; + prev_method_value = curr_method_value; event_type = curr_method_value & 0x3; + method_id = (curr_method_value >> kTraceActionBits) << kTraceActionBits; + if (method_map.find(method_id) == method_map.end()) { + LOG(FATAL) << "No entry for method " << std::hex << method_id; + } if (print_thread_events) { PrintTraceEntry(thread_name, method_map[method_id], @@ -235,11 +245,11 @@ extern "C" JNIEXPORT void JNICALL Java_Main_dumpTrace(JNIEnv* env, jstring threadName) { const char* file_name = env->GetStringUTFChars(fileName, nullptr); const char* thread_name = env->GetStringUTFChars(threadName, nullptr); - std::map<int, std::string> thread_map; - std::map<int, std::string> method_map; - std::map<int, std::string> ignored_method_map; - std::map<int, int> current_depth_map; - std::map<int, int> ignored_method_depth_map; + std::map<uint64_t, std::string> thread_map; + std::map<uint64_t, std::string> method_map; + std::map<uint64_t, std::string> ignored_method_map; + std::map<int64_t, int> current_depth_map; + std::map<int64_t, int> ignored_method_depth_map; std::unique_ptr<File> file(OS::OpenFileForReading(file_name)); if (file == nullptr) { @@ -248,8 +258,7 @@ extern "C" JNIEXPORT void JNICALL Java_Main_dumpTrace(JNIEnv* env, } uint8_t header[32]; - const bool success = file->ReadFully(&header, sizeof(header)); - if (!success) { + if (!file->ReadFully(&header, sizeof(header))) { printf("Couldn't read header\n"); return; } @@ -259,9 +268,7 @@ extern "C" JNIEXPORT void JNICALL Java_Main_dumpTrace(JNIEnv* env, return; } int version = ReadNumber(2, header + 4); - if (success) { - printf("version=%0x\n", version); - } + printf("version=%0x\n", version); bool is_dual_clock = (version == kVersionDualClock); bool has_entries = true; @@ -272,12 +279,12 @@ extern "C" JNIEXPORT void JNICALL Java_Main_dumpTrace(JNIEnv* env, } switch (entry_header) { case kThreadInfo: - if (!ProcessThreadOrMethodInfo(file, thread_map)) { + if (!ProcessThreadOrMethodInfo(file, thread_map, /*is_method=*/false)) { has_entries = false; } break; case kMethodInfo: - if (!ProcessThreadOrMethodInfo(file, method_map)) { + if (!ProcessThreadOrMethodInfo(file, method_map, /*is_method=*/true)) { has_entries = false; } break; |