| /* | |
| * Copyright (C) 2011 The Android Open Source Project | |
| * | |
| * Licensed under the Apache License, Version 2.0 (the "License"); | |
| * you may not use this file except in compliance with the License. | |
| * You may obtain a copy of the License at | |
| * | |
| * http://www.apache.org/licenses/LICENSE-2.0 | |
| * | |
| * Unless required by applicable law or agreed to in writing, software | |
| * distributed under the License is distributed on an "AS IS" BASIS, | |
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | |
| * See the License for the specific language governing permissions and | |
| * limitations under the License. | |
| */ | |
| #include "trace.h" | |
| #include <sys/uio.h> | |
| #include <unistd.h> | |
| #include "android-base/macros.h" | |
| #include "android-base/stringprintf.h" | |
| #include "art_method-inl.h" | |
| #include "base/casts.h" | |
| #include "base/leb128.h" | |
| #include "base/os.h" | |
| #include "base/pointer_size.h" | |
| #include "base/stl_util.h" | |
| #include "base/systrace.h" | |
| #include "base/time_utils.h" | |
| #include "base/unix_file/fd_file.h" | |
| #include "base/utils.h" | |
| #include "class_linker.h" | |
| #include "com_android_art_flags.h" | |
| #include "common_throws.h" | |
| #include "debugger.h" | |
| #include "dex/descriptors_names.h" | |
| #include "dex/dex_file-inl.h" | |
| #include "entrypoints/quick/quick_entrypoints.h" | |
| #include "gc/scoped_gc_critical_section.h" | |
| #include "instrumentation.h" | |
| #include "jit/jit.h" | |
| #include "jit/jit_code_cache.h" | |
| #include "mirror/class-inl.h" | |
| #include "mirror/dex_cache-inl.h" | |
| #include "mirror/object-inl.h" | |
| #include "mirror/object_array-inl.h" | |
| #include "nativehelper/scoped_local_ref.h" | |
| #include "scoped_thread_state_change-inl.h" | |
| #include "stack.h" | |
| #include "thread.h" | |
| #include "thread_list.h" | |
| #include "trace_common.h" | |
| #include "trace_profile.h" | |
| namespace art_flags = com::android::art::flags; | |
| namespace art HIDDEN { | |
| struct MethodTraceRecord { | |
| ArtMethod* method; | |
| TraceAction action; | |
| uint64_t wall_clock_time; | |
| uint64_t thread_cpu_time; | |
| }; | |
| using android::base::StringPrintf; | |
| static constexpr size_t TraceActionBits = MinimumBitsToStore( | |
| static_cast<size_t>(kTraceMethodActionMask)); | |
| static constexpr uint8_t kOpNewMethod = 1U; | |
| static constexpr uint8_t kOpNewThread = 2U; | |
| static constexpr uint8_t kOpTraceSummary = 3U; | |
| 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 const size_t kNumTracePoolBuffers = 32; | |
| static constexpr size_t kMinBufSize = 18U; // Trace header is up to 18B. | |
| // Size of per-thread buffer size. The value is chosen arbitrarily. This value | |
| // should be greater than kMinBufSize. | |
| static constexpr size_t kPerThreadBufSize = 512 * 1024; | |
| static_assert(kPerThreadBufSize > kMinBufSize); | |
| // On average we need 12 bytes for encoding an entry. We typically use two | |
| // entries in per-thread buffer, the scaling factor is 6. | |
| static constexpr size_t kScalingFactorEncodedEntries = 6; | |
| // The key identifying the tracer to update instrumentation. | |
| static constexpr const char* kTracerInstrumentationKey = "Tracer"; | |
| double TimestampCounter::tsc_to_nanosec_scaling_factor = -1; | |
| Trace* Trace::the_trace_ = nullptr; | |
| pthread_t Trace::sampling_pthread_ = 0U; | |
| std::unique_ptr<std::vector<ArtMethod*>> Trace::temp_stack_trace_; | |
| static TraceAction DecodeTraceAction(uint32_t tmid) { | |
| return static_cast<TraceAction>(tmid & kTraceMethodActionMask); | |
| } | |
| namespace { | |
| TraceClockSource GetClockSourceFromFlags(int flags) { | |
| bool need_wall = flags & Trace::TraceFlag::kTraceClockSourceWallClock; | |
| bool need_thread_cpu = flags & Trace::TraceFlag::kTraceClockSourceThreadCpu; | |
| if (need_wall && need_thread_cpu) { | |
| return TraceClockSource::kDual; | |
| } else if (need_wall) { | |
| return TraceClockSource::kWall; | |
| } else if (need_thread_cpu) { | |
| return TraceClockSource::kThreadCpu; | |
| } else { | |
| return kDefaultTraceClockSource; | |
| } | |
| } | |
| int GetTraceFormatVersionFromFlags(int flags) { | |
| int version = (flags & Trace::kTraceFormatVersionFlagMask) >> Trace::kTraceFormatVersionShift; | |
| return version; | |
| } | |
| } // namespace | |
| // Temporary code for debugging b/342768977 | |
| int num_trace_starts_ GUARDED_BY(Locks::trace_lock_); | |
| int num_trace_stops_initiated_ GUARDED_BY(Locks::trace_lock_); | |
| std::atomic<int> num_trace_stops_finished_; | |
| std::string Trace::GetDebugInformation() { | |
| MutexLock mu(Thread::Current(), *Locks::trace_lock_); | |
| std::stringstream debug_info; | |
| debug_info << "start:" << num_trace_starts_ << "stop:" << num_trace_stops_initiated_ << "done:" | |
| << num_trace_stops_finished_ << "trace:" << the_trace_; | |
| return debug_info.str(); | |
| } | |
| bool TraceWriter::HasMethodEncoding(ArtMethod* method) { | |
| return art_method_id_map_.find(method) != art_method_id_map_.end(); | |
| } | |
| std::pair<uint32_t, bool> TraceWriter::GetMethodEncoding(ArtMethod* method) { | |
| auto it = art_method_id_map_.find(method); | |
| if (it != art_method_id_map_.end()) { | |
| return std::pair<uint32_t, bool>(it->second, false); | |
| } else { | |
| uint32_t idx = current_method_index_; | |
| art_method_id_map_.emplace(method, idx); | |
| current_method_index_++; | |
| return std::pair<uint32_t, bool>(idx, true); | |
| } | |
| } | |
| uint16_t TraceWriter::GetThreadEncoding(pid_t thread_id) { | |
| auto it = thread_id_map_.find(thread_id); | |
| if (it != thread_id_map_.end()) { | |
| return it->second; | |
| } | |
| uint16_t idx = current_thread_index_; | |
| thread_id_map_.emplace(thread_id, current_thread_index_); | |
| DCHECK_LT(current_thread_index_, (1 << 16) - 2); | |
| current_thread_index_++; | |
| return idx; | |
| } | |
| class TraceWriterTask : public SelfDeletingTask { | |
| public: | |
| TraceWriterTask( | |
| TraceWriter* trace_writer, int index, uintptr_t* buffer, size_t cur_offset, size_t thread_id) | |
| : trace_writer_(trace_writer), | |
| index_(index), | |
| buffer_(buffer), | |
| cur_offset_(cur_offset), | |
| thread_id_(thread_id) {} | |
| void Run(Thread* self ATTRIBUTE_UNUSED) override { | |
| ProcessBuffer(buffer_, cur_offset_, thread_id_); | |
| if (index_ == -1) { | |
| // This was a temporary buffer we allocated since there are no free buffers and it wasn't | |
| // safe to wait for one. This should only happen when we have fewer buffers than the number | |
| // of threads. | |
| delete[] buffer_; | |
| } | |
| trace_writer_->ReleaseBuffer(index_); | |
| } | |
| virtual void ProcessBuffer(uintptr_t* buffer, size_t cur_offset, size_t thread_id) = 0; | |
| TraceWriter* GetTraceWriter() { return trace_writer_; } | |
| private: | |
| TraceWriter* trace_writer_; | |
| int index_; | |
| uintptr_t* buffer_; | |
| size_t cur_offset_; | |
| size_t thread_id_; | |
| }; | |
| class TraceEntriesWriterTask final : public TraceWriterTask { | |
| public: | |
| TraceEntriesWriterTask( | |
| TraceWriter* trace_writer, int index, uintptr_t* buffer, size_t cur_offset, size_t tid) | |
| : TraceWriterTask(trace_writer, index, buffer, cur_offset, tid) {} | |
| void ProcessBuffer(uintptr_t* buffer, size_t cur_offset, size_t thread_id) override { | |
| std::unordered_map<ArtMethod*, std::string> method_infos; | |
| TraceWriter* trace_writer = GetTraceWriter(); | |
| if (trace_writer->GetTraceFormatVersion() == Trace::kFormatV1) { | |
| ScopedObjectAccess soa(Thread::Current()); | |
| trace_writer->PreProcessTraceForMethodInfos(buffer, cur_offset, method_infos); | |
| } | |
| trace_writer->FlushBuffer(buffer, cur_offset, thread_id, method_infos); | |
| } | |
| }; | |
| class MethodInfoWriterTask final : public TraceWriterTask { | |
| public: | |
| MethodInfoWriterTask(TraceWriter* trace_writer, int index, uintptr_t* buffer, size_t cur_offset) | |
| : TraceWriterTask(trace_writer, index, buffer, cur_offset, 0) {} | |
| void ProcessBuffer(uintptr_t* buffer, | |
| size_t cur_offset, | |
| [[maybe_unused]] size_t thread_id) override { | |
| GetTraceWriter()->WriteToFile(reinterpret_cast<uint8_t*>(buffer), cur_offset); | |
| } | |
| }; | |
| std::vector<ArtMethod*>* Trace::AllocStackTrace() { | |
| return (temp_stack_trace_.get() != nullptr) ? temp_stack_trace_.release() : | |
| new std::vector<ArtMethod*>(); | |
| } | |
| void Trace::FreeStackTrace(std::vector<ArtMethod*>* stack_trace) { | |
| stack_trace->clear(); | |
| temp_stack_trace_.reset(stack_trace); | |
| } | |
| static uint16_t GetTraceVersion(TraceClockSource clock_source, int version) { | |
| if (version == Trace::kFormatV1) { | |
| return (clock_source == TraceClockSource::kDual) ? kTraceVersionDualClock : | |
| kTraceVersionSingleClock; | |
| } else { | |
| return (clock_source == TraceClockSource::kDual) ? kTraceVersionDualClockV2 : | |
| kTraceVersionSingleClockV2; | |
| } | |
| } | |
| static uint16_t GetRecordSize(TraceClockSource clock_source, int version) { | |
| if (version == Trace::kFormatV1) { | |
| return (clock_source == TraceClockSource::kDual) ? kTraceRecordSizeDualClock : | |
| kTraceRecordSizeSingleClock; | |
| } else { | |
| return (clock_source == TraceClockSource::kDual) ? kMaxTraceRecordSizeDualClockV2 | |
| : kMaxTraceRecordSizeSingleClockV2; | |
| } | |
| } | |
| static uint16_t GetNumEntries(TraceClockSource clock_source) { | |
| return (clock_source == TraceClockSource::kDual) ? kNumEntriesForDualClock | |
| : kNumEntriesForWallClock; | |
| } | |
| bool UseThreadCpuClock(TraceClockSource clock_source) { | |
| return (clock_source == TraceClockSource::kThreadCpu) || | |
| (clock_source == TraceClockSource::kDual); | |
| } | |
| bool UseWallClock(TraceClockSource clock_source) { | |
| return (clock_source == TraceClockSource::kWall) || (clock_source == TraceClockSource::kDual); | |
| } | |
| bool UseFastTraceListeners(TraceClockSource clock_source) { | |
| // Thread cpu clocks needs a kernel call, so we don't directly support them in JITed code. | |
| bool is_fast_trace = !UseThreadCpuClock(clock_source); | |
| #if defined(__arm__) | |
| // On ARM 32 bit, we don't always have access to the timestamp counters from | |
| // user space. See comment in TimestampCounter::GetTimestamp for more details. | |
| is_fast_trace = false; | |
| #endif | |
| return is_fast_trace; | |
| } | |
| void Trace::MeasureClockOverhead() { | |
| if (UseThreadCpuClock(clock_source_)) { | |
| Thread::Current()->GetCpuNanoTime(); | |
| } | |
| if (UseWallClock(clock_source_)) { | |
| TimestampCounter::GetTimestamp(); | |
| } | |
| } | |
| // Compute an average time taken to measure clocks. | |
| uint64_t Trace::GetClockOverheadNanoSeconds() { | |
| Thread* self = Thread::Current(); | |
| uint64_t start = self->GetCpuNanoTime(); | |
| const uint64_t numIter = 4000; | |
| for (int i = numIter; i > 0; i--) { | |
| MeasureClockOverhead(); | |
| MeasureClockOverhead(); | |
| MeasureClockOverhead(); | |
| MeasureClockOverhead(); | |
| MeasureClockOverhead(); | |
| MeasureClockOverhead(); | |
| MeasureClockOverhead(); | |
| MeasureClockOverhead(); | |
| } | |
| uint64_t elapsed_ns = self->GetCpuNanoTime() - start; | |
| return elapsed_ns / (numIter * 8); | |
| } | |
| static void GetSample(Thread* thread, void* arg) REQUIRES_SHARED(Locks::mutator_lock_) { | |
| std::vector<ArtMethod*>* const stack_trace = Trace::AllocStackTrace(); | |
| StackVisitor::WalkStack( | |
| [&](const art::StackVisitor* stack_visitor) REQUIRES_SHARED(Locks::mutator_lock_) { | |
| ArtMethod* m = stack_visitor->GetMethod(); | |
| // Ignore runtime frames (in particular callee save). | |
| if (!m->IsRuntimeMethod()) { | |
| stack_trace->push_back(m); | |
| } | |
| return true; | |
| }, | |
| thread, | |
| /* context= */ nullptr, | |
| art::StackVisitor::StackWalkKind::kIncludeInlinedFrames); | |
| Trace* the_trace = reinterpret_cast<Trace*>(arg); | |
| the_trace->CompareAndUpdateStackTrace(thread, stack_trace); | |
| } | |
| static void ClearThreadStackTraceAndClockBase(Thread* thread, [[maybe_unused]] void* arg) { | |
| thread->SetTraceClockBase(0); | |
| std::vector<ArtMethod*>* stack_trace = thread->GetStackTraceSample(); | |
| thread->SetStackTraceSample(nullptr); | |
| delete stack_trace; | |
| } | |
| void Trace::CompareAndUpdateStackTrace(Thread* thread, | |
| std::vector<ArtMethod*>* stack_trace) { | |
| CHECK_EQ(pthread_self(), sampling_pthread_); | |
| std::vector<ArtMethod*>* old_stack_trace = thread->GetStackTraceSample(); | |
| // Update the thread's stack trace sample. | |
| thread->SetStackTraceSample(stack_trace); | |
| // Read timer clocks to use for all events in this trace. | |
| uint64_t thread_clock_diff = 0; | |
| uint64_t timestamp_counter = 0; | |
| ReadClocks(thread, &thread_clock_diff, ×tamp_counter); | |
| if (old_stack_trace == nullptr) { | |
| // If there's no previous stack trace sample for this thread, log an entry event for all | |
| // methods in the trace. | |
| for (auto rit = stack_trace->rbegin(); rit != stack_trace->rend(); ++rit) { | |
| LogMethodTraceEvent(thread, *rit, kTraceMethodEnter, thread_clock_diff, timestamp_counter); | |
| } | |
| } else { | |
| // If there's a previous stack trace for this thread, diff the traces and emit entry and exit | |
| // events accordingly. | |
| auto old_rit = old_stack_trace->rbegin(); | |
| auto rit = stack_trace->rbegin(); | |
| // Iterate bottom-up over both traces until there's a difference between them. | |
| while (old_rit != old_stack_trace->rend() && rit != stack_trace->rend() && *old_rit == *rit) { | |
| old_rit++; | |
| rit++; | |
| } | |
| // Iterate top-down over the old trace until the point where they differ, emitting exit events. | |
| for (auto old_it = old_stack_trace->begin(); old_it != old_rit.base(); ++old_it) { | |
| LogMethodTraceEvent(thread, *old_it, kTraceMethodExit, thread_clock_diff, timestamp_counter); | |
| } | |
| // Iterate bottom-up over the new trace from the point where they differ, emitting entry events. | |
| for (; rit != stack_trace->rend(); ++rit) { | |
| LogMethodTraceEvent(thread, *rit, kTraceMethodEnter, thread_clock_diff, timestamp_counter); | |
| } | |
| FreeStackTrace(old_stack_trace); | |
| } | |
| } | |
| void* Trace::RunSamplingThread(void* arg) { | |
| Runtime* runtime = Runtime::Current(); | |
| intptr_t interval_us = reinterpret_cast<intptr_t>(arg); | |
| CHECK_GE(interval_us, 0); | |
| CHECK(runtime->AttachCurrentThread("Sampling Profiler", true, runtime->GetSystemThreadGroup(), | |
| !runtime->IsAotCompiler())); | |
| while (true) { | |
| usleep(interval_us); | |
| ScopedTrace trace("Profile sampling"); | |
| Thread* self = Thread::Current(); | |
| Trace* the_trace; | |
| { | |
| MutexLock mu(self, *Locks::trace_lock_); | |
| the_trace = the_trace_; | |
| if (the_trace_->stop_tracing_) { | |
| break; | |
| } | |
| } | |
| { | |
| // Avoid a deadlock between a thread doing garbage collection | |
| // and the profile sampling thread, by blocking GC when sampling | |
| // thread stacks (see b/73624630). | |
| gc::ScopedGCCriticalSection gcs(self, | |
| art::gc::kGcCauseInstrumentation, | |
| art::gc::kCollectorTypeInstrumentation); | |
| ScopedSuspendAll ssa(__FUNCTION__); | |
| MutexLock mu(self, *Locks::thread_list_lock_); | |
| runtime->GetThreadList()->ForEach(GetSample, the_trace); | |
| } | |
| } | |
| runtime->DetachCurrentThread(); | |
| 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), offset_(0), buffer_(nullptr) {} | |
| bool operator()(ObjPtr<mirror::Class> klass) override REQUIRES(Locks::mutator_lock_) { | |
| // We use a buffer to aggregate method infos from different classes to avoid multiple small | |
| // writes to the file. The RecordMethodInfo handles the overflows by enqueueing a task to | |
| // flush the old buffer and allocates a new buffer. | |
| trace_->GetTraceWriter()->RecordMethodInfoV2(klass.Ptr(), &buffer_, &offset_); | |
| return true; // Visit all classes. | |
| } | |
| void FlushBuffer() REQUIRES_SHARED(Locks::mutator_lock_) { | |
| // Flushes any data in the buffer to the file. Called at the end of visit to write any | |
| // remaining data to the file. | |
| trace_->GetTraceWriter()->AddMethodInfoWriteTask( | |
| buffer_, offset_, Thread::Current()->GetTid(), true); | |
| } | |
| private: | |
| Trace* const trace_; | |
| // Use a buffer to aggregate method infos of all classes to avoid multiple smaller writes to file. | |
| size_t offset_ = 0; | |
| uint8_t* buffer_ = nullptr; | |
| }; | |
| 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; | |
| } | |
| size_t offset = 0; | |
| size_t tid = Thread::Current()->GetTid(); | |
| uint8_t* buffer = nullptr; | |
| // Write the method infos of the newly loaded class. | |
| the_trace_->GetTraceWriter()->RecordMethodInfoV2(klass.Get(), &buffer, &offset); | |
| the_trace_->GetTraceWriter()->AddMethodInfoWriteTask(buffer, offset, tid, true); | |
| } | |
| uint8_t* TraceWriter::AddMethodInfoWriteTask(uint8_t* buffer, | |
| size_t offset, | |
| size_t tid, | |
| bool release) { | |
| int old_index = GetMethodTraceIndex(reinterpret_cast<uintptr_t*>(buffer)); | |
| uintptr_t* new_buf = nullptr; | |
| thread_pool_->AddTask( | |
| Thread::Current(), | |
| new MethodInfoWriterTask(this, old_index, reinterpret_cast<uintptr_t*>(buffer), offset)); | |
| if (!release) { | |
| new_buf = AcquireTraceBuffer(tid); | |
| } | |
| return reinterpret_cast<uint8_t*>(new_buf); | |
| } | |
| void TraceWriter::WriteToFile(uint8_t* buffer, size_t offset) { | |
| MutexLock mu(Thread::Current(), trace_writer_lock_); | |
| if (!trace_file_->WriteFully(buffer, offset)) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| } | |
| void TraceWriter::RecordMethodInfoV2(mirror::Class* klass, uint8_t** buffer, size_t* offset) { | |
| // For the v1 format, we record methods when we first execute them. | |
| DCHECK_EQ(trace_format_version_, Trace::kFormatV2); | |
| auto methods = klass->GetMethods(kRuntimePointerSize); | |
| if (methods.empty()) { | |
| return; | |
| } | |
| size_t tid = Thread::Current()->GetTid(); | |
| size_t buffer_size = kPerThreadBufSize * sizeof(uintptr_t); | |
| size_t index = *offset; | |
| uint8_t* buf = *buffer; | |
| if (buf == nullptr) { | |
| buf = reinterpret_cast<uint8_t*>(AcquireTraceBuffer(tid)); | |
| } | |
| std::string class_name_current = klass->PrettyDescriptor(); | |
| const char* source_file_current = klass->GetSourceFile(); | |
| if (source_file_current == nullptr) { | |
| // Generated classes have no source file. | |
| source_file_current = ""; | |
| } | |
| for (ArtMethod& method : klass->GetMethods(kRuntimePointerSize)) { | |
| if (!method.IsInvokable()) { | |
| continue; | |
| } | |
| std::string class_name; | |
| const char* source_file; | |
| if (method.IsCopied()) { | |
| // For copied methods use method's declaring class which may not be the current class. | |
| class_name = method.GetDeclaringClass()->PrettyDescriptor(); | |
| source_file = method.GetDeclaringClass()->GetSourceFile(); | |
| } else { | |
| DCHECK(klass == method.GetDeclaringClass()); | |
| class_name = class_name_current; | |
| source_file = source_file_current; | |
| } | |
| int class_name_len = class_name.length(); | |
| int source_file_len = strlen(source_file); | |
| uint64_t method_id = reinterpret_cast<uint64_t>(&method); | |
| // TODO(mythria): Change how we report method infos in V2 to reduce the | |
| // repetition of the information about class and the source file. | |
| const char* name = method.GetName(); | |
| int name_len = strlen(name); | |
| std::string signature = method.GetSignature().ToString(); | |
| int signature_len = signature.length(); | |
| // We need 3 tabs in between and a \n at the end and hence 4 additional characters. | |
| int method_info_length = class_name_len + name_len + signature_len + source_file_len + 4; | |
| // 1 byte header + 8 bytes method id + 2 bytes method_info_length | |
| int header_length = 11; | |
| if (index + header_length + method_info_length >= buffer_size) { | |
| buf = AddMethodInfoWriteTask(buf, index, tid, false); | |
| index = 0; | |
| } | |
| // Write the header to the buffer | |
| buf[index] = kMethodInfoHeaderV2; | |
| Append8LE(buf + index + 1, method_id); | |
| Append2LE(buf + index + 9, method_info_length); | |
| index += header_length; | |
| // Copy method line into the buffer | |
| memcpy(buf + index, class_name.c_str(), class_name_len); | |
| buf[index + class_name_len] = '\t'; | |
| index += class_name_len + 1; | |
| memcpy(buf + index, name, name_len); | |
| buf[index + name_len] = '\t'; | |
| index += name_len + 1; | |
| memcpy(buf + index, signature.c_str(), signature_len); | |
| buf[index + signature_len] = '\t'; | |
| index += signature_len + 1; | |
| memcpy(buf + index, source_file, source_file_len); | |
| buf[index + source_file_len] = '\n'; | |
| index += source_file_len + 1; | |
| } | |
| *offset = index; | |
| *buffer = buf; | |
| } | |
| void Trace::Start(const char* trace_filename, | |
| size_t buffer_size, | |
| int flags, | |
| TraceOutputMode output_mode, | |
| TraceMode trace_mode, | |
| int interval_us) { | |
| std::unique_ptr<File> file(OS::CreateEmptyFileWriteOnly(trace_filename)); | |
| if (file == nullptr) { | |
| std::string msg = android::base::StringPrintf("Unable to open trace file '%s'", trace_filename); | |
| PLOG(ERROR) << msg; | |
| ScopedObjectAccess soa(Thread::Current()); | |
| Thread::Current()->ThrowNewException("Ljava/lang/RuntimeException;", msg.c_str()); | |
| return; | |
| } | |
| Start(std::move(file), buffer_size, flags, output_mode, trace_mode, interval_us); | |
| } | |
| void Trace::Start(int trace_fd, | |
| size_t buffer_size, | |
| int flags, | |
| TraceOutputMode output_mode, | |
| TraceMode trace_mode, | |
| int interval_us) { | |
| if (trace_fd < 0) { | |
| std::string msg = android::base::StringPrintf("Unable to start tracing with invalid fd %d", | |
| trace_fd); | |
| LOG(ERROR) << msg; | |
| ScopedObjectAccess soa(Thread::Current()); | |
| Thread::Current()->ThrowNewException("Ljava/lang/RuntimeException;", msg.c_str()); | |
| return; | |
| } | |
| std::unique_ptr<File> file(new File(trace_fd, /* path= */ "tracefile", /* check_usage= */ true)); | |
| Start(std::move(file), buffer_size, flags, output_mode, trace_mode, interval_us); | |
| } | |
| void Trace::StartDDMS(size_t buffer_size, | |
| int flags, | |
| TraceMode trace_mode, | |
| int interval_us) { | |
| Start(std::unique_ptr<File>(), | |
| buffer_size, | |
| flags, | |
| TraceOutputMode::kDDMS, | |
| trace_mode, | |
| interval_us); | |
| } | |
| void Trace::Start(std::unique_ptr<File>&& trace_file_in, | |
| size_t buffer_size, | |
| int flags, | |
| TraceOutputMode output_mode, | |
| TraceMode trace_mode, | |
| int interval_us) { | |
| // We own trace_file now and are responsible for closing it. To account for error situations, use | |
| // a specialized unique_ptr to ensure we close it on the way out (if it hasn't been passed to a | |
| // Trace instance). | |
| auto deleter = [](File* file) { | |
| if (file != nullptr) { | |
| file->MarkUnchecked(); // Don't deal with flushing requirements. | |
| [[maybe_unused]] int result = file->Close(); | |
| delete file; | |
| } | |
| }; | |
| std::unique_ptr<File, decltype(deleter)> trace_file(trace_file_in.release(), deleter); | |
| Thread* self = Thread::Current(); | |
| { | |
| MutexLock mu(self, *Locks::trace_lock_); | |
| if (the_trace_ != nullptr) { | |
| LOG(ERROR) << "Trace already in progress, ignoring this request"; | |
| return; | |
| } | |
| } | |
| // Check interval if sampling is enabled | |
| if (trace_mode == TraceMode::kSampling && interval_us <= 0) { | |
| LOG(ERROR) << "Invalid sampling interval: " << interval_us; | |
| ScopedObjectAccess soa(self); | |
| ThrowRuntimeException("Invalid sampling interval: %d", interval_us); | |
| return; | |
| } | |
| // Initialize the frequency of timestamp counter updates here. This is needed | |
| // to get wallclock time from timestamp counter values. | |
| TimestampCounter::InitializeTimestampCounters(); | |
| Runtime* runtime = Runtime::Current(); | |
| // Enable count of allocs if specified in the flags. | |
| bool enable_stats = false; | |
| // Create Trace object. | |
| { | |
| // Suspend JIT here since we are switching runtime to debuggable. Debuggable runtimes cannot use | |
| // JITed code from before so we need to invalidated all JITed code here. Enter suspend JIT scope | |
| // to prevent any races with ongoing JIT compilations. | |
| jit::ScopedJitSuspend suspend_jit; | |
| // Required since EnableMethodTracing calls ConfigureStubs which visits class linker classes. | |
| gc::ScopedGCCriticalSection gcs(self, | |
| gc::kGcCauseInstrumentation, | |
| gc::kCollectorTypeInstrumentation); | |
| ScopedSuspendAll ssa(__FUNCTION__); | |
| MutexLock mu(self, *Locks::trace_lock_); | |
| if (TraceProfiler::IsTraceProfileInProgress()) { | |
| LOG(ERROR) << "On-demand profile in progress, ignoring this request"; | |
| return; | |
| } | |
| if (Trace::IsTracingEnabledLocked()) { | |
| LOG(ERROR) << "Trace already in progress, ignoring this request"; | |
| return; | |
| } | |
| enable_stats = (flags & kTraceCountAllocs) != 0; | |
| bool is_trace_format_v2 = GetTraceFormatVersionFromFlags(flags) == Trace::kFormatV2; | |
| the_trace_ = new Trace(trace_file.release(), buffer_size, flags, output_mode, trace_mode); | |
| num_trace_starts_++; | |
| if (is_trace_format_v2) { | |
| // 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); | |
| visitor.FlushBuffer(); | |
| } | |
| if (trace_mode == TraceMode::kSampling) { | |
| CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread, | |
| reinterpret_cast<void*>(interval_us)), | |
| "Sampling profiler thread"); | |
| the_trace_->interval_us_ = interval_us; | |
| } else { | |
| if (!runtime->IsJavaDebuggable()) { | |
| art::jit::Jit* jit = runtime->GetJit(); | |
| if (jit != nullptr) { | |
| jit->GetCodeCache()->InvalidateAllCompiledCode(); | |
| jit->GetCodeCache()->TransitionToDebuggable(); | |
| jit->GetJitCompiler()->SetDebuggableCompilerOption(true); | |
| } | |
| runtime->SetRuntimeDebugState(art::Runtime::RuntimeDebugState::kJavaDebuggable); | |
| runtime->GetInstrumentation()->UpdateEntrypointsForDebuggable(); | |
| runtime->DeoptimizeBootImage(); | |
| } | |
| if (is_trace_format_v2) { | |
| // Add ClassLoadCallback to record methods on class load. | |
| runtime->GetRuntimeCallbacks()->AddClassLoadCallback(the_trace_); | |
| } | |
| runtime->GetInstrumentation()->AddListener( | |
| the_trace_, | |
| instrumentation::Instrumentation::kMethodEntered | | |
| instrumentation::Instrumentation::kMethodExited | | |
| instrumentation::Instrumentation::kMethodUnwind, | |
| UseFastTraceListeners(the_trace_->GetClockSource())); | |
| runtime->GetInstrumentation()->EnableMethodTracing(kTracerInstrumentationKey, | |
| the_trace_, | |
| /*needs_interpreter=*/false); | |
| } | |
| } | |
| // Can't call this when holding the mutator lock. | |
| if (enable_stats) { | |
| runtime->SetStatsEnabled(true); | |
| } | |
| } | |
| void Trace::StopTracing(bool flush_entries) { | |
| Runtime* const runtime = Runtime::Current(); | |
| Thread* const self = Thread::Current(); | |
| pthread_t sampling_pthread = 0U; | |
| { | |
| MutexLock mu(self, *Locks::trace_lock_); | |
| num_trace_stops_initiated_++; | |
| if (the_trace_ == nullptr || the_trace_->stop_tracing_) { | |
| LOG(ERROR) << "Trace stop requested, but no trace currently running or trace is being" | |
| << " stopped concurrently on another thread"; | |
| return; | |
| } | |
| // Tell sampling_pthread_ to stop tracing. | |
| the_trace_->stop_tracing_ = true; | |
| sampling_pthread = sampling_pthread_; | |
| } | |
| // Make sure that we join before we delete the trace since we don't want to have | |
| // the sampling thread access a stale pointer. This finishes since the sampling thread exits when | |
| // the_trace_ is null. | |
| if (sampling_pthread != 0U) { | |
| CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, nullptr), "sampling thread shutdown"); | |
| } | |
| // Wakeup any threads waiting for a buffer and abort allocating a buffer. | |
| the_trace_->trace_writer_->StopTracing(); | |
| // Make a copy of the_trace_, so it can be flushed later. We want to reset | |
| // the_trace_ to nullptr in suspend all scope to prevent any races | |
| Trace* the_trace = the_trace_; | |
| bool stop_alloc_counting = (the_trace->flags_ & Trace::kTraceCountAllocs) != 0; | |
| // Stop the trace sources adding more entries to the trace buffer and synchronise stores. | |
| { | |
| gc::ScopedGCCriticalSection gcs( | |
| self, gc::kGcCauseInstrumentation, gc::kCollectorTypeInstrumentation); | |
| jit::ScopedJitSuspend suspend_jit; | |
| ScopedSuspendAll ssa(__FUNCTION__); | |
| if (the_trace->trace_mode_ == TraceMode::kSampling) { | |
| MutexLock mu(self, *Locks::thread_list_lock_); | |
| runtime->GetThreadList()->ForEach(ClearThreadStackTraceAndClockBase, nullptr); | |
| } else { | |
| runtime->GetRuntimeCallbacks()->RemoveClassLoadCallback(the_trace_); | |
| runtime->GetInstrumentation()->RemoveListener( | |
| the_trace, | |
| instrumentation::Instrumentation::kMethodEntered | | |
| instrumentation::Instrumentation::kMethodExited | | |
| instrumentation::Instrumentation::kMethodUnwind, | |
| UseFastTraceListeners(the_trace_->GetClockSource())); | |
| runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey); | |
| } | |
| // Flush thread specific buffer from all threads before resetting the_trace_ to nullptr. | |
| // We also flush the buffer when destroying a thread which expects the_trace_ to be valid so | |
| // make sure that the per-thread buffer is reset before resetting the_trace_. | |
| { | |
| MutexLock mu(self, *Locks::trace_lock_); | |
| MutexLock tl_lock(Thread::Current(), *Locks::thread_list_lock_); | |
| // Flush the per-thread buffers and reset the trace inside the trace_lock_ to avoid any | |
| // race if the thread is detaching and trying to flush the buffer too. Since we hold the | |
| // trace_lock_ both here and when flushing on a thread detach only one of them will succeed | |
| // in actually flushing the buffer. | |
| for (Thread* thread : Runtime::Current()->GetThreadList()->GetList()) { | |
| if (thread->GetMethodTraceBuffer() != nullptr) { | |
| // We may have pending requests to flush the data. So just enqueue a | |
| // request to flush the current buffer so all the requests are | |
| // processed in order. | |
| the_trace->trace_writer_->FlushBuffer( | |
| thread, /* is_sync= */ false, /* free_buffer= */ true); | |
| } | |
| } | |
| the_trace_ = nullptr; | |
| sampling_pthread_ = 0U; | |
| } | |
| } | |
| // At this point, code may read buf_ as its writers are shutdown | |
| // and the ScopedSuspendAll above has ensured all stores to buf_ | |
| // are now visible. | |
| the_trace->trace_writer_->FinishTracing(the_trace->flags_, flush_entries); | |
| delete the_trace; | |
| num_trace_stops_finished_++; | |
| if (stop_alloc_counting) { | |
| // Can be racy since SetStatsEnabled is not guarded by any locks. | |
| runtime->SetStatsEnabled(false); | |
| } | |
| } | |
| void Trace::RemoveListeners() { | |
| Thread* self = Thread::Current(); | |
| // This is expected to be called in SuspendAll scope. | |
| DCHECK(Locks::mutator_lock_->IsExclusiveHeld(self)); | |
| MutexLock mu(self, *Locks::trace_lock_); | |
| Runtime* runtime = Runtime::Current(); | |
| runtime->GetRuntimeCallbacks()->RemoveClassLoadCallback(the_trace_); | |
| runtime->GetInstrumentation()->RemoveListener( | |
| the_trace_, | |
| instrumentation::Instrumentation::kMethodEntered | | |
| instrumentation::Instrumentation::kMethodExited | | |
| instrumentation::Instrumentation::kMethodUnwind, | |
| UseFastTraceListeners(the_trace_->GetClockSource())); | |
| } | |
| void Trace::FlushThreadBuffer(Thread* self) { | |
| MutexLock mu(self, *Locks::trace_lock_); | |
| // Check if we still need to flush inside the trace_lock_. If we are stopping tracing it is | |
| // possible we already deleted the trace and flushed the buffer too. | |
| if (the_trace_ == nullptr) { | |
| if (art_flags::always_enable_profile_code()) { | |
| TraceProfiler::ReleaseThreadBuffer(self); | |
| } | |
| DCHECK_EQ(self->GetMethodTraceBuffer(), nullptr); | |
| return; | |
| } | |
| the_trace_->trace_writer_->FlushBuffer(self, /* is_sync= */ false, /* free_buffer= */ true); | |
| } | |
| void Trace::ReleaseThreadBuffer(Thread* self) { | |
| MutexLock mu(self, *Locks::trace_lock_); | |
| // Check if we still need to flush inside the trace_lock_. If we are stopping tracing it is | |
| // possible we already deleted the trace and flushed the buffer too. | |
| if (the_trace_ == nullptr) { | |
| if (art_flags::always_enable_profile_code()) { | |
| TraceProfiler::ReleaseThreadBuffer(self); | |
| } | |
| DCHECK_EQ(self->GetMethodTraceBuffer(), nullptr); | |
| return; | |
| } | |
| the_trace_->trace_writer_->ReleaseBufferForThread(self); | |
| self->SetMethodTraceBuffer(nullptr, 0); | |
| } | |
| void Trace::Abort() { | |
| // Do not write anything anymore. | |
| StopTracing(/* flush_entries= */ false); | |
| } | |
| void Trace::Stop() { | |
| // Finish writing. | |
| StopTracing(/* flush_entries= */ true); | |
| } | |
| void Trace::Shutdown() { | |
| if (GetMethodTracingMode() != kTracingInactive) { | |
| Stop(); | |
| } | |
| } | |
| TracingMode Trace::GetMethodTracingMode() { | |
| MutexLock mu(Thread::Current(), *Locks::trace_lock_); | |
| if (the_trace_ == nullptr) { | |
| return kTracingInactive; | |
| } else { | |
| switch (the_trace_->trace_mode_) { | |
| case TraceMode::kSampling: | |
| return kSampleProfilingActive; | |
| case TraceMode::kMethodTracing: | |
| return kMethodTracingActive; | |
| } | |
| LOG(FATAL) << "Unreachable"; | |
| UNREACHABLE(); | |
| } | |
| } | |
| TraceWriter::TraceWriter(File* trace_file, | |
| TraceOutputMode output_mode, | |
| TraceClockSource clock_source, | |
| size_t buffer_size, | |
| int num_trace_buffers, | |
| int trace_format_version, | |
| uint64_t clock_overhead_ns) | |
| : trace_file_(trace_file), | |
| trace_output_mode_(output_mode), | |
| clock_source_(clock_source), | |
| buf_(new uint8_t[std::max(kMinBufSize, buffer_size)]()), | |
| buffer_size_(std::max(kMinBufSize, buffer_size)), | |
| trace_format_version_(trace_format_version), | |
| start_time_(TimestampCounter::GetNanoTime(TimestampCounter::GetTimestamp())), | |
| overflow_(false), | |
| num_records_(0), | |
| clock_overhead_ns_(clock_overhead_ns), | |
| owner_tids_(num_trace_buffers), | |
| buffer_pool_lock_("tracing buffer pool lock", kDefaultMutexLevel), | |
| buffer_available_("buffer available condition", buffer_pool_lock_), | |
| num_waiters_zero_cond_("Num waiters zero", buffer_pool_lock_), | |
| num_waiters_for_buffer_(0), | |
| trace_writer_lock_("trace writer lock", LockLevel::kTracingStreamingLock) { | |
| // We initialize the start_time_ from the timestamp counter. This may not match | |
| // with the monotonic timer but we only use this time to calculate the elapsed | |
| // time from this point which should be the same for both cases. | |
| // We record monotonic time at the start of the trace, because Android Studio | |
| // fetches the monotonic timer from other places and matches these times to | |
| // construct a cpu profile. See b/318052824 for more context. | |
| uint64_t start_time_monotonic = | |
| start_time_ + (NanoTime() - TimestampCounter::GetNanoTime(TimestampCounter::GetTimestamp())); | |
| uint16_t trace_version = GetTraceVersion(clock_source_, trace_format_version_); | |
| if (output_mode == TraceOutputMode::kStreaming) { | |
| trace_version |= 0xF0U; | |
| } | |
| // Set up the beginning of the trace. | |
| if (trace_format_version_ == Trace::kFormatV1) { | |
| memset(buf_.get(), 0, kTraceHeaderLength); | |
| Append4LE(buf_.get(), kTraceMagicValue); | |
| Append2LE(buf_.get() + 4, trace_version); | |
| Append2LE(buf_.get() + 6, kTraceHeaderLength); | |
| // Use microsecond precision for V1 format. | |
| Append8LE(buf_.get() + 8, (start_time_monotonic / 1000)); | |
| if (trace_version >= kTraceVersionDualClock) { | |
| uint16_t record_size = GetRecordSize(clock_source_, trace_format_version_); | |
| Append2LE(buf_.get() + 16, record_size); | |
| } | |
| static_assert(18 <= kMinBufSize, "Minimum buffer size not large enough for trace header"); | |
| cur_offset_ = kTraceHeaderLength; | |
| } else { | |
| memset(buf_.get(), 0, kTraceHeaderLengthV2); | |
| Append4LE(buf_.get(), kTraceMagicValue); | |
| Append2LE(buf_.get() + 4, trace_version); | |
| Append8LE(buf_.get() + 6, start_time_monotonic); | |
| cur_offset_ = kTraceHeaderLengthV2; | |
| } | |
| if (output_mode == TraceOutputMode::kStreaming || trace_format_version_ == Trace::kFormatV2) { | |
| // Flush the header information to the file. We use a per thread buffer, so | |
| // it is easier to just write the header information directly to file. | |
| if (!trace_file_->WriteFully(buf_.get(), kTraceHeaderLength)) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| cur_offset_ = 0; | |
| } | |
| // Thread index of 0 is a special identifier used to distinguish between trace | |
| // event entries and thread / method info entries. | |
| current_thread_index_ = 1; | |
| // Don't create threadpool for a zygote. This would cause slowdown when forking because we need | |
| // to stop and start this thread pool. Method tracing on zygote isn't a frequent use case and | |
| // it is okay to flush on the main thread in such cases. | |
| if (!Runtime::Current()->IsZygote()) { | |
| thread_pool_.reset(TraceWriterThreadPool::Create("Trace writer pool")); | |
| thread_pool_->StartWorkers(Thread::Current()); | |
| } | |
| // Initialize the pool of per-thread buffers. | |
| InitializeTraceBuffers(); | |
| } | |
| Trace::Trace(File* trace_file, | |
| size_t buffer_size, | |
| int flags, | |
| TraceOutputMode output_mode, | |
| TraceMode trace_mode) | |
| : flags_(flags), | |
| trace_mode_(trace_mode), | |
| clock_source_(GetClockSourceFromFlags(flags)), | |
| interval_us_(0), | |
| stop_tracing_(false) { | |
| CHECK_IMPLIES(trace_file == nullptr, output_mode == TraceOutputMode::kDDMS); | |
| int trace_format_version = GetTraceFormatVersionFromFlags(flags_); | |
| // In streaming mode, we only need a buffer big enough to store data per each | |
| // thread buffer. In non-streaming mode this is specified by the user and we | |
| // stop tracing when the buffer is full. | |
| size_t buf_size = (output_mode == TraceOutputMode::kStreaming) ? | |
| kPerThreadBufSize * kScalingFactorEncodedEntries : | |
| buffer_size; | |
| trace_writer_.reset(new TraceWriter(trace_file, | |
| output_mode, | |
| clock_source_, | |
| buf_size, | |
| kNumTracePoolBuffers, | |
| trace_format_version, | |
| GetClockOverheadNanoSeconds())); | |
| } | |
| std::string TraceWriter::CreateSummary(int flags) { | |
| std::ostringstream os; | |
| // Compute elapsed time. | |
| uint64_t elapsed = TimestampCounter::GetNanoTime(TimestampCounter::GetTimestamp()) - start_time_; | |
| os << StringPrintf("%cversion\n", kTraceTokenChar); | |
| os << StringPrintf("%d\n", GetTraceVersion(clock_source_, trace_format_version_)); | |
| os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false"); | |
| if (UseThreadCpuClock(clock_source_)) { | |
| if (UseWallClock(clock_source_)) { | |
| os << StringPrintf("clock=dual\n"); | |
| } else { | |
| os << StringPrintf("clock=thread-cpu\n"); | |
| } | |
| } else { | |
| os << StringPrintf("clock=wall\n"); | |
| } | |
| if (trace_format_version_ == Trace::kFormatV1) { | |
| os << StringPrintf("elapsed-time-usec=%" PRIu64 "\n", elapsed / 1000); | |
| } else { | |
| os << StringPrintf("elapsed-time-nsec=%" PRIu64 "\n", elapsed); | |
| } | |
| if (trace_output_mode_ != TraceOutputMode::kStreaming) { | |
| os << StringPrintf("num-method-calls=%zd\n", num_records_); | |
| } | |
| os << StringPrintf("clock-call-overhead-nsec=%" PRIu64 "\n", clock_overhead_ns_); | |
| os << StringPrintf("vm=art\n"); | |
| os << StringPrintf("pid=%d\n", getpid()); | |
| if ((flags & Trace::kTraceCountAllocs) != 0) { | |
| os << "alloc-count=" << Runtime::Current()->GetStat(KIND_ALLOCATED_OBJECTS) << "\n"; | |
| os << "alloc-size=" << Runtime::Current()->GetStat(KIND_ALLOCATED_BYTES) << "\n"; | |
| os << "gc-count=" << Runtime::Current()->GetStat(KIND_GC_INVOCATIONS) << "\n"; | |
| } | |
| if (trace_format_version_ == Trace::kFormatV1) { | |
| os << StringPrintf("%cthreads\n", kTraceTokenChar); | |
| DumpThreadList(os); | |
| os << StringPrintf("%cmethods\n", kTraceTokenChar); | |
| DumpMethodList(os); | |
| } | |
| os << StringPrintf("%cend\n", kTraceTokenChar); | |
| return os.str(); | |
| } | |
| void TraceWriter::FinishTracing(int flags, bool flush_entries) { | |
| Thread* self = Thread::Current(); | |
| if (!flush_entries) { | |
| // This is only called from the child process post fork to abort the trace. | |
| // We shouldn't have any workers in the thread pool here. | |
| DCHECK_EQ(thread_pool_, nullptr); | |
| trace_file_->MarkUnchecked(); // Do not trigger guard. | |
| if (trace_file_->Close() != 0) { | |
| PLOG(ERROR) << "Could not close trace file."; | |
| } | |
| return; | |
| } | |
| if (thread_pool_ != nullptr) { | |
| // Wait for any workers to be created. If we are stopping tracing as a part of runtime | |
| // shutdown, any unstarted workers can create problems if they try attaching while shutting | |
| // down. | |
| thread_pool_->WaitForWorkersToBeCreated(); | |
| // Wait for any outstanding writer tasks to finish. Let the thread pool worker finish the | |
| // tasks to avoid any re-ordering when processing tasks. | |
| thread_pool_->Wait(self, /* do_work= */ false, /* may_hold_locks= */ true); | |
| DCHECK_EQ(thread_pool_->GetTaskCount(self), 0u); | |
| thread_pool_->StopWorkers(self); | |
| } | |
| size_t final_offset = 0; | |
| if (trace_output_mode_ != TraceOutputMode::kStreaming) { | |
| MutexLock mu(Thread::Current(), trace_writer_lock_); | |
| final_offset = cur_offset_; | |
| } | |
| std::string summary = CreateSummary(flags); | |
| if (trace_format_version_ == Trace::kFormatV1) { | |
| if (trace_output_mode_ == TraceOutputMode::kStreaming) { | |
| DCHECK_NE(trace_file_.get(), nullptr); | |
| // It is expected that this method is called when all other threads are suspended, so there | |
| // cannot be any writes to trace_file_ after finish tracing. | |
| // Write a special token to mark the end of trace records and the start of | |
| // trace summary. | |
| uint8_t buf[7]; | |
| Append2LE(buf, 0); | |
| buf[2] = kOpTraceSummary; | |
| Append4LE(buf + 3, static_cast<uint32_t>(summary.length())); | |
| // Write the trace summary. The summary is identical to the file header when | |
| // the output mode is not streaming (except for methods). | |
| if (!trace_file_->WriteFully(buf, sizeof(buf)) || | |
| !trace_file_->WriteFully(summary.c_str(), summary.length())) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| } else if (trace_output_mode_ == TraceOutputMode::kFile) { | |
| DCHECK_NE(trace_file_.get(), nullptr); | |
| if (!trace_file_->WriteFully(summary.c_str(), summary.length()) || | |
| !trace_file_->WriteFully(buf_.get(), final_offset)) { | |
| std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno))); | |
| PLOG(ERROR) << detail; | |
| ThrowRuntimeException("%s", detail.c_str()); | |
| } | |
| } else { | |
| DCHECK_EQ(trace_file_.get(), nullptr); | |
| DCHECK(trace_output_mode_ == TraceOutputMode::kDDMS); | |
| std::vector<uint8_t> data; | |
| data.resize(summary.length() + final_offset); | |
| memcpy(data.data(), summary.c_str(), summary.length()); | |
| memcpy(data.data() + summary.length(), buf_.get(), final_offset); | |
| Runtime::Current()->GetRuntimeCallbacks()->DdmPublishChunk(CHUNK_TYPE("MPSE"), | |
| ArrayRef<const uint8_t>(data)); | |
| } | |
| } else { | |
| DCHECK(trace_format_version_ == Trace::kFormatV2); | |
| DCHECK(trace_output_mode_ != TraceOutputMode::kDDMS); | |
| if (trace_output_mode_ == TraceOutputMode::kFile) { | |
| if (!trace_file_->WriteFully(buf_.get(), final_offset)) { | |
| PLOG(WARNING) << "Failed to write trace output"; | |
| } | |
| } | |
| // Write the summary packet | |
| uint8_t buf[3]; | |
| buf[0] = kSummaryHeaderV2; | |
| Append2LE(buf + 1, static_cast<uint32_t>(summary.length())); | |
| // Write the trace summary. Reports information about tracing mode, number of records and | |
| // clock overhead in plain text format. | |
| if (!trace_file_->WriteFully(buf, sizeof(buf)) || | |
| !trace_file_->WriteFully(summary.c_str(), summary.length())) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| } | |
| if (trace_file_.get() != nullptr) { | |
| // Do not try to erase, so flush and close explicitly. | |
| if (trace_file_->Flush() != 0) { | |
| PLOG(WARNING) << "Could not flush trace file."; | |
| } | |
| if (trace_file_->Close() != 0) { | |
| PLOG(ERROR) << "Could not close trace file."; | |
| } | |
| } | |
| } | |
| void Trace::DexPcMoved([[maybe_unused]] Thread* thread, | |
| [[maybe_unused]] Handle<mirror::Object> this_object, | |
| ArtMethod* 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 " << ArtMethod::PrettyMethod(method) | |
| << " " << new_dex_pc; | |
| } | |
| void Trace::FieldRead([[maybe_unused]] Thread* thread, | |
| [[maybe_unused]] Handle<mirror::Object> this_object, | |
| ArtMethod* method, | |
| uint32_t dex_pc, | |
| [[maybe_unused]] ArtField* field) REQUIRES_SHARED(Locks::mutator_lock_) { | |
| // We're not recorded to listen to this kind of event, so complain. | |
| LOG(ERROR) << "Unexpected field read event in tracing " << ArtMethod::PrettyMethod(method) | |
| << " " << dex_pc; | |
| } | |
| void Trace::FieldWritten([[maybe_unused]] Thread* thread, | |
| [[maybe_unused]] Handle<mirror::Object> this_object, | |
| ArtMethod* method, | |
| uint32_t dex_pc, | |
| [[maybe_unused]] ArtField* field, | |
| [[maybe_unused]] const JValue& field_value) | |
| REQUIRES_SHARED(Locks::mutator_lock_) { | |
| // We're not recorded to listen to this kind of event, so complain. | |
| LOG(ERROR) << "Unexpected field write event in tracing " << ArtMethod::PrettyMethod(method) | |
| << " " << dex_pc; | |
| } | |
| void Trace::MethodEntered(Thread* thread, ArtMethod* method) { | |
| uint64_t thread_clock_diff = 0; | |
| uint64_t timestamp_counter = 0; | |
| ReadClocks(thread, &thread_clock_diff, ×tamp_counter); | |
| LogMethodTraceEvent(thread, method, kTraceMethodEnter, thread_clock_diff, timestamp_counter); | |
| } | |
| void Trace::MethodExited(Thread* thread, | |
| ArtMethod* method, | |
| [[maybe_unused]] instrumentation::OptionalFrame frame, | |
| [[maybe_unused]] JValue& return_value) { | |
| uint64_t thread_clock_diff = 0; | |
| uint64_t timestamp_counter = 0; | |
| ReadClocks(thread, &thread_clock_diff, ×tamp_counter); | |
| LogMethodTraceEvent(thread, method, kTraceMethodExit, thread_clock_diff, timestamp_counter); | |
| } | |
| void Trace::MethodUnwind(Thread* thread, ArtMethod* method, [[maybe_unused]] uint32_t dex_pc) { | |
| uint64_t thread_clock_diff = 0; | |
| uint64_t timestamp_counter = 0; | |
| ReadClocks(thread, &thread_clock_diff, ×tamp_counter); | |
| LogMethodTraceEvent(thread, method, kTraceUnroll, thread_clock_diff, timestamp_counter); | |
| } | |
| void Trace::ExceptionThrown([[maybe_unused]] Thread* thread, | |
| [[maybe_unused]] Handle<mirror::Throwable> exception_object) | |
| REQUIRES_SHARED(Locks::mutator_lock_) { | |
| LOG(ERROR) << "Unexpected exception thrown event in tracing"; | |
| } | |
| void Trace::ExceptionHandled([[maybe_unused]] Thread* thread, | |
| [[maybe_unused]] Handle<mirror::Throwable> exception_object) | |
| REQUIRES_SHARED(Locks::mutator_lock_) { | |
| LOG(ERROR) << "Unexpected exception thrown event in tracing"; | |
| } | |
| void Trace::Branch(Thread* /*thread*/, ArtMethod* method, | |
| uint32_t /*dex_pc*/, int32_t /*dex_pc_offset*/) | |
| REQUIRES_SHARED(Locks::mutator_lock_) { | |
| LOG(ERROR) << "Unexpected branch event in tracing" << ArtMethod::PrettyMethod(method); | |
| } | |
| void Trace::WatchedFramePop([[maybe_unused]] Thread* self, | |
| [[maybe_unused]] const ShadowFrame& frame) { | |
| LOG(ERROR) << "Unexpected WatchedFramePop event in tracing"; | |
| } | |
| void Trace::ReadClocks(Thread* thread, uint64_t* thread_clock_diff, uint64_t* timestamp_counter) { | |
| if (UseThreadCpuClock(clock_source_)) { | |
| uint64_t clock_base = thread->GetTraceClockBase(); | |
| if (UNLIKELY(clock_base == 0)) { | |
| // First event, record the base time in the map. | |
| uint64_t time = thread->GetCpuNanoTime(); | |
| thread->SetTraceClockBase(time); | |
| } else { | |
| *thread_clock_diff = thread->GetCpuNanoTime() - clock_base; | |
| } | |
| } | |
| if (UseWallClock(clock_source_)) { | |
| *timestamp_counter = TimestampCounter::GetTimestamp(); | |
| } | |
| } | |
| std::string TraceWriter::GetMethodLine(const std::string& method_line, uint32_t method_index) { | |
| return StringPrintf("%#x\t%s", (method_index << TraceActionBits), method_line.c_str()); | |
| } | |
| void TraceWriter::RecordThreadInfo(Thread* thread) { | |
| // This is the first event from this thread, so first record information about the thread. | |
| std::string thread_name; | |
| thread->GetThreadName(thread_name); | |
| // In tests, we destroy VM after already detaching the current thread. We re-attach the current | |
| // thread again as a "Shutdown thread" during the process of shutting down. So don't record | |
| // information about shutdown threads since it overwrites the actual thread_name. | |
| if (thread_name.compare("Shutdown thread") == 0) { | |
| return; | |
| } | |
| MutexLock mu(Thread::Current(), trace_writer_lock_); | |
| if (trace_format_version_ == Trace::kFormatV1 && | |
| trace_output_mode_ != TraceOutputMode::kStreaming) { | |
| threads_list_.Overwrite(GetThreadEncoding(thread->GetTid()), thread_name); | |
| return; | |
| } | |
| static constexpr size_t kThreadNameHeaderSize = 7; | |
| uint8_t header[kThreadNameHeaderSize]; | |
| if (trace_format_version_ == Trace::kFormatV1) { | |
| Append2LE(header, 0); | |
| header[2] = kOpNewThread; | |
| Append2LE(header + 3, GetThreadEncoding(thread->GetTid())); | |
| } else { | |
| header[0] = kThreadInfoHeaderV2; | |
| Append4LE(header + 1, thread->GetTid()); | |
| } | |
| DCHECK(thread_name.length() < (1 << 16)); | |
| Append2LE(header + 5, static_cast<uint16_t>(thread_name.length())); | |
| if (!trace_file_->WriteFully(header, kThreadNameHeaderSize) || | |
| !trace_file_->WriteFully(reinterpret_cast<const uint8_t*>(thread_name.c_str()), | |
| thread_name.length())) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| } | |
| void TraceWriter::PreProcessTraceForMethodInfos( | |
| uintptr_t* method_trace_entries, | |
| size_t current_offset, | |
| std::unordered_map<ArtMethod*, std::string>& method_infos) { | |
| // Compute the method infos before we process the entries. We don't want to assign an encoding | |
| // for the method here. The expectation is that once we assign a method id we write it to the | |
| // file before any other thread can see the method id. So we should assign method encoding while | |
| // holding the trace_writer_lock_ and not release it till we flush the method info to the file. We | |
| // don't want to flush entries to file while holding the mutator lock. We need the mutator lock to | |
| // get method info. So we just precompute method infos without assigning a method encoding here. | |
| // There may be a race and multiple threads computing the method info but only one of them would | |
| // actually put into the method_id_map_. | |
| MutexLock mu(Thread::Current(), trace_writer_lock_); | |
| size_t num_entries = GetNumEntries(clock_source_); | |
| DCHECK_EQ((kPerThreadBufSize - current_offset) % num_entries, 0u); | |
| for (size_t entry_index = kPerThreadBufSize; entry_index != current_offset;) { | |
| entry_index -= num_entries; | |
| uintptr_t method_and_action = method_trace_entries[entry_index]; | |
| ArtMethod* method = reinterpret_cast<ArtMethod*>(method_and_action & kMaskTraceAction); | |
| if (!HasMethodEncoding(method) && method_infos.find(method) == method_infos.end()) { | |
| method_infos.emplace(method, GetMethodInfoLine(method)); | |
| } | |
| } | |
| } | |
| void TraceWriter::RecordMethodInfoV1(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 kMethodNameHeaderSize = 5; | |
| DCHECK_LT(kMethodNameHeaderSize, kPerThreadBufSize); | |
| uint8_t method_header[kMethodNameHeaderSize]; | |
| uint16_t method_line_length = static_cast<uint16_t>(method_line.length()); | |
| DCHECK(method_line.length() < (1 << 16)); | |
| // Write a special block with the name. | |
| Append2LE(method_header, 0); | |
| method_header[2] = kOpNewMethod; | |
| method_line = GetMethodLine(method_info_line, method_id); | |
| method_line_length = static_cast<uint16_t>(method_line.length()); | |
| Append2LE(method_header + 3, method_line_length); | |
| header_size = kMethodNameHeaderSize; | |
| const uint8_t* ptr = reinterpret_cast<const uint8_t*>(method_line.c_str()); | |
| if (!trace_file_->WriteFully(method_header, header_size) || | |
| !trace_file_->WriteFully(ptr, method_line_length)) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| } | |
| void TraceWriter::FlushAllThreadBuffers() { | |
| ScopedThreadStateChange stsc(Thread::Current(), ThreadState::kSuspended); | |
| ScopedSuspendAll ssa(__FUNCTION__); | |
| { | |
| MutexLock mu(Thread::Current(), *Locks::thread_list_lock_); | |
| for (Thread* thread : Runtime::Current()->GetThreadList()->GetList()) { | |
| if (thread->GetMethodTraceBuffer() != nullptr) { | |
| FlushBuffer(thread, /* is_sync= */ true, /* free_buffer= */ false); | |
| // We cannot flush anynore data, so just break. | |
| if (overflow_) { | |
| break; | |
| } | |
| } | |
| } | |
| } | |
| Trace::RemoveListeners(); | |
| return; | |
| } | |
| uintptr_t* TraceWriter::PrepareBufferForNewEntries(Thread* thread) { | |
| if (trace_output_mode_ == TraceOutputMode::kStreaming) { | |
| // In streaming mode, just flush the per-thread buffer and reuse the | |
| // existing buffer for new entries. | |
| FlushBuffer(thread, /* is_sync= */ false, /* free_buffer= */ false); | |
| DCHECK_EQ(overflow_, false); | |
| } else { | |
| // For non-streaming mode, flush all the threads to check if we have space in the common | |
| // buffer to record any future events. | |
| FlushAllThreadBuffers(); | |
| } | |
| if (overflow_) { | |
| return nullptr; | |
| } | |
| return thread->GetMethodTraceBuffer(); | |
| } | |
| void TraceWriter::InitializeTraceBuffers() { | |
| for (size_t i = 0; i < owner_tids_.size(); i++) { | |
| owner_tids_[i].store(0); | |
| } | |
| trace_buffer_.reset(new uintptr_t[kPerThreadBufSize * owner_tids_.size()]); | |
| CHECK(trace_buffer_.get() != nullptr); | |
| } | |
| uintptr_t* TraceWriter::AcquireTraceBuffer(size_t tid) { | |
| Thread* self = Thread::Current(); | |
| // Fast path, check if there is a free buffer in the pool | |
| for (size_t index = 0; index < owner_tids_.size(); index++) { | |
| size_t owner = 0; | |
| if (owner_tids_[index].compare_exchange_strong(owner, tid)) { | |
| return trace_buffer_.get() + index * kPerThreadBufSize; | |
| } | |
| } | |
| // Increment a counter so we know how many threads are potentially suspended in the tracing code. | |
| // We need this when stopping tracing. We need to wait for all these threads to finish executing | |
| // this code so we can safely delete the trace related data. | |
| num_waiters_for_buffer_.fetch_add(1); | |
| uintptr_t* buffer = nullptr; | |
| // If finish_tracing_ is set to true we shouldn't suspend ourselves. So check for finish_tracing_ | |
| // before the thread suspension. As an example, consider the following: | |
| // T2 is looking for a free buffer in the loop above | |
| // T1 calls stop tracing -> Sets finish_tracing_ to true -> Checks that there are no waiters -> | |
| // Waiting to suspend all threads. | |
| // T2 doesn't find a buffer. | |
| // If T2 suspends before checking for finish_tracing_ there is a possibility T1 succeeds entering | |
| // SuspendAllScope while thread T2 is still in the TraceWriter code. | |
| // To avoid this, we increment the num_waiters_for_buffer and then check for finish_tracing | |
| // before suspending the thread. StopTracing sets finish_tracing_ to true first and then checks | |
| // for num_waiters_for_buffer. Both these are atomic variables and we use sequential consistency | |
| // (acquire for load and release for stores), so all threads see the updates for these variables | |
| // in the same order. That ensures we don't suspend in the tracing logic after Trace::StopTracing | |
| // has returned. This is required so that we can safely delete tracing data. | |
| if (self->IsThreadSuspensionAllowable() && !finish_tracing_.load()) { | |
| ScopedThreadSuspension sts(self, ThreadState::kSuspended); | |
| while (1) { | |
| MutexLock mu(self, buffer_pool_lock_); | |
| // Tracing is being stopped, so don't wait for a free buffer. Just return early. | |
| if (finish_tracing_.load()) { | |
| break; | |
| } | |
| // Check if there's a free buffer in the pool | |
| for (size_t index = 0; index < owner_tids_.size(); index++) { | |
| size_t owner = 0; | |
| if (owner_tids_[index].compare_exchange_strong(owner, tid)) { | |
| buffer = trace_buffer_.get() + index * kPerThreadBufSize; | |
| break; | |
| } | |
| } | |
| // Found a buffer | |
| if (buffer != nullptr) { | |
| break; | |
| } | |
| if (thread_pool_ == nullptr || | |
| (thread_pool_->GetTaskCount(self) < num_waiters_for_buffer_.load())) { | |
| // We have fewer buffers than active threads, just allocate a new one. | |
| break; | |
| } | |
| buffer_available_.WaitHoldingLocks(self); | |
| } | |
| } | |
| // The thread is no longer in the suspend scope, so decrement the counter. | |
| num_waiters_for_buffer_.fetch_sub(1); | |
| if (num_waiters_for_buffer_.load() == 0 && finish_tracing_.load()) { | |
| MutexLock mu(self, buffer_pool_lock_); | |
| num_waiters_zero_cond_.Broadcast(self); | |
| } | |
| if (buffer == nullptr) { | |
| // Allocate a new buffer. We either don't want to wait or have too few buffers. | |
| buffer = new uintptr_t[kPerThreadBufSize]; | |
| CHECK(buffer != nullptr); | |
| } | |
| return buffer; | |
| } | |
| void TraceWriter::StopTracing() { | |
| Thread* self = Thread::Current(); | |
| MutexLock mu(self, buffer_pool_lock_); | |
| finish_tracing_.store(true); | |
| while (num_waiters_for_buffer_.load() != 0) { | |
| buffer_available_.Broadcast(self); | |
| num_waiters_zero_cond_.WaitHoldingLocks(self); | |
| } | |
| } | |
| void TraceWriter::ReleaseBuffer(int index) { | |
| // Only the trace_writer_ thread can release the buffer. | |
| MutexLock mu(Thread::Current(), buffer_pool_lock_); | |
| if (index != -1) { | |
| owner_tids_[index].store(0); | |
| } | |
| buffer_available_.Signal(Thread::Current()); | |
| } | |
| void TraceWriter::ReleaseBufferForThread(Thread* self) { | |
| uintptr_t* buffer = self->GetMethodTraceBuffer(); | |
| int index = GetMethodTraceIndex(buffer); | |
| if (index == -1) { | |
| delete[] buffer; | |
| } else { | |
| ReleaseBuffer(index); | |
| } | |
| } | |
| int TraceWriter::GetMethodTraceIndex(uintptr_t* current_buffer) { | |
| if (current_buffer < trace_buffer_.get() || | |
| current_buffer > trace_buffer_.get() + (owner_tids_.size() - 1) * kPerThreadBufSize) { | |
| // This was the temporary buffer we allocated. | |
| return -1; | |
| } | |
| return (current_buffer - trace_buffer_.get()) / kPerThreadBufSize; | |
| } | |
| void TraceWriter::FlushBuffer(Thread* thread, bool is_sync, bool release) { | |
| uintptr_t* method_trace_entries = thread->GetMethodTraceBuffer(); | |
| uintptr_t** current_entry_ptr = thread->GetTraceBufferCurrEntryPtr(); | |
| size_t current_offset = *current_entry_ptr - method_trace_entries; | |
| size_t tid = thread->GetTid(); | |
| DCHECK(method_trace_entries != nullptr); | |
| if (is_sync || thread_pool_ == nullptr) { | |
| std::unordered_map<ArtMethod*, std::string> 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 | |
| // when the tracing has finished or in non-streaming mode. | |
| // Just reset the buffer pointer to the initial value, so we can reuse the same buffer. | |
| if (release) { | |
| thread->SetMethodTraceBuffer(nullptr, 0); | |
| } else { | |
| thread->SetMethodTraceBufferCurrentEntry(kPerThreadBufSize); | |
| } | |
| } else { | |
| int old_index = GetMethodTraceIndex(method_trace_entries); | |
| // The TraceWriterTask takes the ownership of the buffer and releases the buffer once the | |
| // entries are flushed. | |
| thread_pool_->AddTask( | |
| Thread::Current(), | |
| new TraceEntriesWriterTask(this, old_index, method_trace_entries, current_offset, tid)); | |
| if (release) { | |
| thread->SetMethodTraceBuffer(nullptr, 0); | |
| } else { | |
| thread->SetMethodTraceBuffer(AcquireTraceBuffer(tid), kPerThreadBufSize); | |
| } | |
| } | |
| return; | |
| } | |
| void TraceWriter::ReadValuesFromRecord(uintptr_t* method_trace_entries, | |
| size_t record_index, | |
| MethodTraceRecord& record, | |
| bool has_thread_cpu_clock, | |
| bool has_wall_clock) { | |
| uintptr_t method_and_action = method_trace_entries[record_index++]; | |
| record.method = reinterpret_cast<ArtMethod*>(method_and_action & kMaskTraceAction); | |
| CHECK(record.method != nullptr); | |
| record.action = DecodeTraceAction(method_and_action); | |
| record.thread_cpu_time = 0; | |
| record.wall_clock_time = 0; | |
| if (has_thread_cpu_clock) { | |
| record.thread_cpu_time = method_trace_entries[record_index++]; | |
| if (art::kRuntimePointerSize == PointerSize::k32) { | |
| // On 32-bit architectures threadcputime is stored as two 32-bit values. | |
| uint64_t high_bits = method_trace_entries[record_index++]; | |
| record.thread_cpu_time = (high_bits << 32 | record.thread_cpu_time); | |
| } | |
| } | |
| if (has_wall_clock) { | |
| uint64_t timestamp = method_trace_entries[record_index++]; | |
| if (art::kRuntimePointerSize == PointerSize::k32) { | |
| // On 32-bit architectures timestamp is stored as two 32-bit values. | |
| uint64_t high_timestamp = method_trace_entries[record_index++]; | |
| timestamp = (high_timestamp << 32 | timestamp); | |
| } | |
| record.wall_clock_time = TimestampCounter::GetNanoTime(timestamp) - start_time_; | |
| } | |
| } | |
| size_t TraceWriter::FlushEntriesFormatV1( | |
| uintptr_t* method_trace_entries, | |
| size_t tid, | |
| const std::unordered_map<ArtMethod*, std::string>& method_infos, | |
| size_t end_offset, | |
| size_t num_records) { | |
| size_t buffer_index = 0; | |
| uint8_t* buffer_ptr = buf_.get(); | |
| const size_t record_size = GetRecordSize(clock_source_, trace_format_version_); | |
| DCHECK_LT(record_size, kPerThreadBufSize); | |
| if (trace_output_mode_ != TraceOutputMode::kStreaming) { | |
| // In non-streaming mode we only flush to file at the end, so retain the earlier data. If the | |
| // buffer is full we don't process any more entries. | |
| buffer_index = cur_offset_; | |
| // Check if there is sufficient space in the buffer for non-streaming case. If not return early. | |
| // In FormatV1, the encoding of events is fixed size, so we can determine the amount of buffer | |
| // space required. | |
| if (cur_offset_ + record_size * num_records >= buffer_size_) { | |
| overflow_ = true; | |
| return 0; | |
| } | |
| } | |
| uint16_t thread_id = GetThreadEncoding(tid); | |
| bool has_thread_cpu_clock = UseThreadCpuClock(clock_source_); | |
| bool has_wall_clock = UseWallClock(clock_source_); | |
| size_t num_entries = GetNumEntries(clock_source_); | |
| for (size_t entry_index = kPerThreadBufSize; entry_index != end_offset;) { | |
| entry_index -= num_entries; | |
| MethodTraceRecord record; | |
| ReadValuesFromRecord( | |
| method_trace_entries, entry_index, record, has_thread_cpu_clock, has_wall_clock); | |
| auto [method_id, is_new_method] = GetMethodEncoding(record.method); | |
| if (is_new_method && trace_output_mode_ == TraceOutputMode::kStreaming) { | |
| RecordMethodInfoV1(method_infos.find(record.method)->second, method_id); | |
| } | |
| DCHECK_LT(buffer_index + record_size, buffer_size_); | |
| EncodeEventEntry(buffer_ptr + buffer_index, | |
| thread_id, | |
| method_id, | |
| record.action, | |
| record.thread_cpu_time, | |
| record.wall_clock_time); | |
| buffer_index += record_size; | |
| } | |
| if (trace_output_mode_ == TraceOutputMode::kStreaming) { | |
| // Flush the contents of buffer to file. | |
| if (!trace_file_->WriteFully(buffer_ptr, buffer_index)) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| } else { | |
| // In non-streaming mode, we keep the data in the buffer and write to the | |
| // file when tracing has stopped. Just update the offset of the buffer. | |
| cur_offset_ = buffer_index; | |
| } | |
| return num_records; | |
| } | |
| size_t TraceWriter::FlushEntriesFormatV2(uintptr_t* method_trace_entries, | |
| size_t tid, | |
| size_t num_records) { | |
| uint8_t* init_buffer_ptr = buf_.get(); | |
| uint8_t* end_buffer_ptr = buf_.get() + buffer_size_; | |
| if (trace_output_mode_ != TraceOutputMode::kStreaming) { | |
| // In non-streaming mode we only flush to file at the end, so retain the earlier data. If the | |
| // buffer is full we don't process any more entries. | |
| init_buffer_ptr = buf_.get() + cur_offset_; | |
| } | |
| uint8_t* current_buffer_ptr = init_buffer_ptr; | |
| bool has_thread_cpu_clock = UseThreadCpuClock(clock_source_); | |
| bool has_wall_clock = UseWallClock(clock_source_); | |
| size_t num_entries = GetNumEntries(clock_source_); | |
| uint64_t prev_wall_timestamp = 0; | |
| uint64_t prev_thread_timestamp = 0; | |
| uint64_t prev_method_action_encoding = 0; | |
| size_t entry_index = kPerThreadBufSize; | |
| size_t curr_record_index = 0; | |
| const int max_record_size = GetRecordSize(clock_source_, trace_format_version_); | |
| while (curr_record_index < num_records) { | |
| current_buffer_ptr = init_buffer_ptr + kEntryHeaderSizeV2; | |
| for (; curr_record_index < num_records; curr_record_index++) { | |
| // Don't process more entries if the buffer doesn't have sufficient space. | |
| if (end_buffer_ptr - current_buffer_ptr < max_record_size) { | |
| break; | |
| } | |
| entry_index -= num_entries; | |
| MethodTraceRecord record; | |
| ReadValuesFromRecord( | |
| method_trace_entries, entry_index, record, has_thread_cpu_clock, has_wall_clock); | |
| uint64_t method_id = reinterpret_cast<uintptr_t>(record.method); | |
| uint64_t method_action_encoding = method_id | record.action; | |
| 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 = EncodeUnsignedLeb128(current_buffer_ptr, | |
| (record.wall_clock_time - prev_wall_timestamp)); | |
| prev_wall_timestamp = record.wall_clock_time; | |
| } | |
| if (has_thread_cpu_clock) { | |
| current_buffer_ptr = EncodeUnsignedLeb128(current_buffer_ptr, | |
| (record.thread_cpu_time - prev_thread_timestamp)); | |
| prev_thread_timestamp = record.thread_cpu_time; | |
| } | |
| } | |
| uint32_t size = current_buffer_ptr - (init_buffer_ptr + kEntryHeaderSizeV2); | |
| EncodeEventBlockHeader(init_buffer_ptr, tid, curr_record_index, size); | |
| if (trace_output_mode_ != TraceOutputMode::kStreaming) { | |
| if (curr_record_index < num_records) { | |
| overflow_ = true; | |
| } | |
| // In non-streaming mode, we keep the data in the buffer and write to the | |
| // file when tracing has stopped. Just update the offset of the buffer. | |
| cur_offset_ += (current_buffer_ptr - init_buffer_ptr); | |
| return curr_record_index; | |
| } else { | |
| // Flush the contents of the buffer to the file. | |
| if (!trace_file_->WriteFully(init_buffer_ptr, current_buffer_ptr - init_buffer_ptr)) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| } | |
| } | |
| return num_records; | |
| } | |
| void TraceWriter::FlushBuffer(uintptr_t* method_trace_entries, | |
| size_t current_offset, | |
| size_t tid, | |
| const std::unordered_map<ArtMethod*, std::string>& method_infos) { | |
| // Take a trace_writer_lock_ to serialize writes across threads. We also need to allocate a unique | |
| // method id for each method. We do that by maintaining a map from id to method for each newly | |
| // seen method. trace_writer_lock_ is required to serialize these. | |
| MutexLock mu(Thread::Current(), trace_writer_lock_); | |
| size_t current_index = 0; | |
| uint8_t* buffer_ptr = buf_.get(); | |
| size_t buffer_size = buffer_size_; | |
| size_t num_entries = GetNumEntries(clock_source_); | |
| size_t num_records = (kPerThreadBufSize - current_offset) / num_entries; | |
| DCHECK_EQ((kPerThreadBufSize - current_offset) % num_entries, 0u); | |
| int num_records_written = 0; | |
| if (trace_format_version_ == Trace::kFormatV1) { | |
| num_records_written = | |
| FlushEntriesFormatV1(method_trace_entries, tid, method_infos, current_offset, num_records); | |
| } else { | |
| num_records_written = FlushEntriesFormatV2(method_trace_entries, tid, num_records); | |
| } | |
| num_records_ += num_records_written; | |
| return; | |
| } | |
| void Trace::LogMethodTraceEvent(Thread* thread, | |
| ArtMethod* method, | |
| TraceAction action, | |
| uint64_t thread_clock_diff, | |
| uint64_t timestamp_counter) { | |
| // This method is called in both tracing modes (method and sampling). In sampling mode, this | |
| // method is only called by the sampling thread. In method tracing mode, it can be called | |
| // concurrently. | |
| uintptr_t* method_trace_buffer = thread->GetMethodTraceBuffer(); | |
| uintptr_t** current_entry_ptr = thread->GetTraceBufferCurrEntryPtr(); | |
| // Initialize the buffer lazily. It's just simpler to keep the creation at one place. | |
| if (method_trace_buffer == nullptr) { | |
| method_trace_buffer = trace_writer_->AcquireTraceBuffer(thread->GetTid()); | |
| DCHECK(method_trace_buffer != nullptr); | |
| thread->SetMethodTraceBuffer(method_trace_buffer, kPerThreadBufSize); | |
| trace_writer_->RecordThreadInfo(thread); | |
| } | |
| if (trace_writer_->HasOverflow()) { | |
| // In non-streaming modes, we stop recoding events once the buffer is full. Just reset the | |
| // index, so we don't go to runtime for each method. | |
| thread->SetMethodTraceBufferCurrentEntry(kPerThreadBufSize); | |
| return; | |
| } | |
| size_t required_entries = GetNumEntries(clock_source_); | |
| if (*current_entry_ptr - required_entries < method_trace_buffer) { | |
| // This returns nullptr in non-streaming mode if there's an overflow and we cannot record any | |
| // more entries. In streaming mode, it returns nullptr if it fails to allocate a new buffer. | |
| method_trace_buffer = trace_writer_->PrepareBufferForNewEntries(thread); | |
| if (method_trace_buffer == nullptr) { | |
| thread->SetMethodTraceBufferCurrentEntry(kPerThreadBufSize); | |
| return; | |
| } | |
| } | |
| *current_entry_ptr = *current_entry_ptr - required_entries; | |
| // Record entry in per-thread trace buffer. | |
| int entry_index = 0; | |
| uintptr_t* current_entry = *current_entry_ptr; | |
| // Ensure we always use the non-obsolete version of the method so that entry/exit events have the | |
| // same pointer value. | |
| method = method->GetNonObsoleteMethod(); | |
| current_entry[entry_index++] = reinterpret_cast<uintptr_t>(method) | action; | |
| if (UseThreadCpuClock(clock_source_)) { | |
| if (art::kRuntimePointerSize == PointerSize::k32) { | |
| // On 32-bit architectures store threadcputimer as two 32-bit values. | |
| current_entry[entry_index++] = static_cast<uint32_t>(thread_clock_diff); | |
| current_entry[entry_index++] = thread_clock_diff >> 32; | |
| } else { | |
| current_entry[entry_index++] = thread_clock_diff; | |
| } | |
| } | |
| if (UseWallClock(clock_source_)) { | |
| if (art::kRuntimePointerSize == PointerSize::k32) { | |
| // On 32-bit architectures store timestamp counter as two 32-bit values. | |
| current_entry[entry_index++] = static_cast<uint32_t>(timestamp_counter); | |
| current_entry[entry_index++] = timestamp_counter >> 32; | |
| } else { | |
| current_entry[entry_index++] = timestamp_counter; | |
| } | |
| } | |
| } | |
| void TraceWriter::EncodeEventEntry(uint8_t* ptr, | |
| uint16_t thread_id, | |
| uint32_t method_index, | |
| TraceAction action, | |
| uint64_t thread_clock_diff, | |
| uint64_t wall_clock_diff) { | |
| static constexpr size_t kPacketSize = 14U; // The maximum size of data in a packet. | |
| DCHECK(method_index < (1 << (32 - TraceActionBits))); | |
| uint32_t method_value = (method_index << TraceActionBits) | action; | |
| Append2LE(ptr, thread_id); | |
| Append4LE(ptr + 2, method_value); | |
| ptr += 6; | |
| static constexpr uint64_t ns_to_us = 1000; | |
| uint32_t thread_clock_diff_us = thread_clock_diff / ns_to_us; | |
| uint32_t wall_clock_diff_us = wall_clock_diff / ns_to_us; | |
| if (UseThreadCpuClock(clock_source_)) { | |
| Append4LE(ptr, thread_clock_diff_us); | |
| ptr += 4; | |
| } | |
| if (UseWallClock(clock_source_)) { | |
| Append4LE(ptr, wall_clock_diff_us); | |
| } | |
| static_assert(kPacketSize == 2 + 4 + 4 + 4, "Packet size incorrect."); | |
| } | |
| void TraceWriter::EncodeEventBlockHeader(uint8_t* ptr, | |
| uint32_t thread_id, | |
| uint32_t num_records, | |
| uint32_t size) { | |
| ptr[0] = kEntryHeaderV2; | |
| Append4LE(ptr + 1, thread_id); | |
| // This specifies the total number of records encoded in the block using lebs. | |
| DCHECK_LT(num_records, 1u << 24); | |
| Append3LE(ptr + 5, num_records); | |
| Append4LE(ptr + 8, size); | |
| } | |
| void TraceWriter::EnsureSpace(uint8_t* buffer, | |
| size_t* current_index, | |
| size_t buffer_size, | |
| size_t required_size) { | |
| if (*current_index + required_size < buffer_size) { | |
| return; | |
| } | |
| if (!trace_file_->WriteFully(buffer, *current_index)) { | |
| PLOG(WARNING) << "Failed streaming a tracing event."; | |
| } | |
| *current_index = 0; | |
| } | |
| void TraceWriter::DumpMethodList(std::ostream& os) { | |
| MutexLock mu(Thread::Current(), trace_writer_lock_); | |
| for (auto const& entry : art_method_id_map_) { | |
| os << GetMethodLine(GetMethodInfoLine(entry.first), entry.second); | |
| } | |
| } | |
| void TraceWriter::DumpThreadList(std::ostream& os) { | |
| MutexLock mu(Thread::Current(), trace_writer_lock_); | |
| for (const auto& it : threads_list_) { | |
| os << it.first << "\t" << it.second << "\n"; | |
| } | |
| } | |
| TraceOutputMode Trace::GetOutputMode() { | |
| MutexLock mu(Thread::Current(), *Locks::trace_lock_); | |
| CHECK(the_trace_ != nullptr) << "Trace output mode requested, but no trace currently running"; | |
| return the_trace_->trace_writer_->GetOutputMode(); | |
| } | |
| Trace::TraceMode Trace::GetMode() { | |
| MutexLock mu(Thread::Current(), *Locks::trace_lock_); | |
| CHECK(the_trace_ != nullptr) << "Trace mode requested, but no trace currently running"; | |
| return the_trace_->trace_mode_; | |
| } | |
| int Trace::GetFlags() { | |
| MutexLock mu(Thread::Current(), *Locks::trace_lock_); | |
| CHECK(the_trace_ != nullptr) << "Trace flags requested, but no trace currently running"; | |
| return the_trace_->flags_; | |
| } | |
| int Trace::GetIntervalInMillis() { | |
| MutexLock mu(Thread::Current(), *Locks::trace_lock_); | |
| CHECK(the_trace_ != nullptr) << "Trace interval requested, but no trace currently running"; | |
| return the_trace_->interval_us_; | |
| } | |
| size_t Trace::GetBufferSize() { | |
| MutexLock mu(Thread::Current(), *Locks::trace_lock_); | |
| CHECK(the_trace_ != nullptr) << "Trace buffer size requested, but no trace currently running"; | |
| return the_trace_->trace_writer_->GetBufferSize(); | |
| } | |
| bool Trace::IsTracingEnabled() { | |
| MutexLock mu(Thread::Current(), *Locks::trace_lock_); | |
| return the_trace_ != nullptr; | |
| } | |
| bool Trace::IsTracingEnabledLocked() { | |
| return the_trace_ != nullptr; | |
| } | |
| } // namespace art |