1 /*
2 * Copyright (C) 2011 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "trace.h"
18
19 #include <sys/uio.h>
20 #include <unistd.h>
21
22 #include "android-base/macros.h"
23 #include "android-base/stringprintf.h"
24 #include "art_method-inl.h"
25 #include "base/casts.h"
26 #include "base/leb128.h"
27 #include "base/os.h"
28 #include "base/pointer_size.h"
29 #include "base/stl_util.h"
30 #include "base/systrace.h"
31 #include "base/time_utils.h"
32 #include "base/unix_file/fd_file.h"
33 #include "base/utils.h"
34 #include "class_linker.h"
35 #include "common_throws.h"
36 #include "com_android_art_flags.h"
37 #include "debugger.h"
38 #include "dex/descriptors_names.h"
39 #include "dex/dex_file-inl.h"
40 #include "entrypoints/quick/quick_entrypoints.h"
41 #include "gc/scoped_gc_critical_section.h"
42 #include "instrumentation.h"
43 #include "jit/jit.h"
44 #include "jit/jit_code_cache.h"
45 #include "mirror/class-inl.h"
46 #include "mirror/dex_cache-inl.h"
47 #include "mirror/object-inl.h"
48 #include "mirror/object_array-inl.h"
49 #include "nativehelper/scoped_local_ref.h"
50 #include "scoped_thread_state_change-inl.h"
51 #include "stack.h"
52 #include "thread.h"
53 #include "thread_list.h"
54 #include "trace_profile.h"
55
56 namespace art_flags = com::android::art::flags;
57
58 namespace art HIDDEN {
59
60 struct MethodTraceRecord {
61 ArtMethod* method;
62 TraceAction action;
63 uint32_t wall_clock_time;
64 uint32_t thread_cpu_time;
65 };
66
67 using android::base::StringPrintf;
68
69 static constexpr size_t TraceActionBits = MinimumBitsToStore(
70 static_cast<size_t>(kTraceMethodActionMask));
71 static constexpr uint8_t kOpNewMethod = 1U;
72 static constexpr uint8_t kOpNewThread = 2U;
73 static constexpr uint8_t kOpTraceSummary = 3U;
74
75 static const char kTraceTokenChar = '*';
76 static const uint16_t kTraceHeaderLength = 32;
77 static const uint32_t kTraceMagicValue = 0x574f4c53;
78 static const uint16_t kTraceVersionSingleClock = 2;
79 static const uint16_t kTraceVersionDualClock = 3;
80 static const uint16_t kTraceRecordSizeSingleClock = 10; // using v2
81 static const uint16_t kTraceRecordSizeDualClock = 14; // using v3 with two timestamps
82 static const size_t kNumTracePoolBuffers = 32;
83
84
85 static constexpr size_t kMinBufSize = 18U; // Trace header is up to 18B.
86 // Size of per-thread buffer size. The value is chosen arbitrarily. This value
87 // should be greater than kMinBufSize.
88 static constexpr size_t kPerThreadBufSize = 512 * 1024;
89 static_assert(kPerThreadBufSize > kMinBufSize);
90 // On average we need 12 bytes for encoding an entry. We typically use two
91 // entries in per-thread buffer, the scaling factor is 6.
92 static constexpr size_t kScalingFactorEncodedEntries = 6;
93
94 // The key identifying the tracer to update instrumentation.
95 static constexpr const char* kTracerInstrumentationKey = "Tracer";
96
97 Trace* Trace::the_trace_ = nullptr;
98 pthread_t Trace::sampling_pthread_ = 0U;
99 std::unique_ptr<std::vector<ArtMethod*>> Trace::temp_stack_trace_;
100
101
DecodeTraceAction(uint32_t tmid)102 static TraceAction DecodeTraceAction(uint32_t tmid) {
103 return static_cast<TraceAction>(tmid & kTraceMethodActionMask);
104 }
105
106 namespace {
107 // Scaling factor to convert timestamp counter into wall clock time reported in micro seconds.
108 // This is initialized at the start of tracing using the timestamp counter update frequency.
109 // See InitializeTimestampCounters for more details.
110 double tsc_to_microsec_scaling_factor = -1.0;
111
GetTimestamp()112 uint64_t GetTimestamp() {
113 uint64_t t = 0;
114 #if defined(__arm__)
115 // On ARM 32 bit, we don't always have access to the timestamp counters from user space. There is
116 // no easy way to check if it is safe to read the timestamp counters. There is HWCAP_EVTSTRM which
117 // is set when generic timer is available but not necessarily from the user space. Kernel disables
118 // access to generic timer when there are known problems on the target CPUs. Sometimes access is
119 // disabled only for 32-bit processes even when 64-bit processes can accesses the timer from user
120 // space. These are not reflected in the HWCAP_EVTSTRM capability.So just fallback to
121 // clock_gettime on these processes. See b/289178149 for more discussion.
122 t = MicroTime();
123 #elif defined(__aarch64__)
124 // See Arm Architecture Registers Armv8 section System Registers
125 asm volatile("mrs %0, cntvct_el0" : "=r"(t));
126 #elif defined(__i386__) || defined(__x86_64__)
127 // rdtsc returns two 32-bit values in rax and rdx even on 64-bit architectures.
128 unsigned int lo, hi;
129 asm volatile("rdtsc" : "=a"(lo), "=d"(hi));
130 t = (static_cast<uint64_t>(hi) << 32) | lo;
131 #elif defined(__riscv)
132 asm volatile("rdtime %0" : "=r"(t));
133 #else
134 t = MicroTime();
135 #endif
136 return t;
137 }
138
139 #if defined(__i386__) || defined(__x86_64__) || defined(__aarch64__)
140 // Here we compute the scaling factor by sleeping for a millisecond. Alternatively, we could
141 // generate raw timestamp counter and also time using clock_gettime at the start and the end of the
142 // trace. We can compute the frequency of timestamp counter upadtes in the post processing step
143 // using these two samples. However, that would require a change in Android Studio which is the main
144 // consumer of these profiles. For now, just compute the frequency of tsc updates here.
computeScalingFactor()145 double computeScalingFactor() {
146 uint64_t start = MicroTime();
147 uint64_t start_tsc = GetTimestamp();
148 // Sleep for one millisecond.
149 usleep(1000);
150 uint64_t diff_tsc = GetTimestamp() - start_tsc;
151 uint64_t diff_time = MicroTime() - start;
152 double scaling_factor = static_cast<double>(diff_time) / diff_tsc;
153 DCHECK(scaling_factor > 0.0) << scaling_factor;
154 return scaling_factor;
155 }
156 #endif
157
158 #if defined(__i386__) || defined(__x86_64__)
GetScalingFactorForX86()159 double GetScalingFactorForX86() {
160 uint32_t eax, ebx, ecx;
161 asm volatile("cpuid" : "=a"(eax), "=b"(ebx), "=c"(ecx) : "a"(0x0), "c"(0));
162 if (eax < 0x15) {
163 // There is no 15H - Timestamp counter and core crystal clock information
164 // leaf. Just compute the frequency.
165 return computeScalingFactor();
166 }
167
168 // From Intel architecture-instruction-set-extensions-programming-reference:
169 // EBX[31:0]/EAX[31:0] indicates the ratio of the TSC frequency and the
170 // core crystal clock frequency.
171 // If EBX[31:0] is 0, the TSC and "core crystal clock" ratio is not enumerated.
172 // If ECX is 0, the nominal core crystal clock frequency is not enumerated.
173 // "TSC frequency" = "core crystal clock frequency" * EBX/EAX.
174 // The core crystal clock may differ from the reference clock, bus clock, or core clock
175 // frequencies.
176 // EAX Bits 31 - 00: An unsigned integer which is the denominator of the
177 // TSC/"core crystal clock" ratio.
178 // EBX Bits 31 - 00: An unsigned integer which is the numerator of the
179 // TSC/"core crystal clock" ratio.
180 // ECX Bits 31 - 00: An unsigned integer which is the nominal frequency of the core
181 // crystal clock in Hz.
182 // EDX Bits 31 - 00: Reserved = 0.
183 asm volatile("cpuid" : "=a"(eax), "=b"(ebx), "=c"(ecx) : "a"(0x15), "c"(0));
184 if (ebx == 0 || ecx == 0) {
185 return computeScalingFactor();
186 }
187 double coreCrystalFreq = ecx;
188 // frequency = coreCrystalFreq * (ebx / eax)
189 // scaling_factor = seconds_to_microseconds / frequency
190 // = seconds_to_microseconds * eax / (coreCrystalFreq * ebx)
191 double seconds_to_microseconds = 1000 * 1000;
192 double scaling_factor = (seconds_to_microseconds * eax) / (coreCrystalFreq * ebx);
193 return scaling_factor;
194 }
195 #endif
196
InitializeTimestampCounters()197 void InitializeTimestampCounters() {
198 // It is sufficient to initialize this once for the entire execution. Just return if it is
199 // already initialized.
200 if (tsc_to_microsec_scaling_factor > 0.0) {
201 return;
202 }
203
204 #if defined(__arm__)
205 // On ARM 32 bit, we don't always have access to the timestamp counters from
206 // user space. Seem comment in GetTimestamp for more details.
207 tsc_to_microsec_scaling_factor = 1.0;
208 #elif defined(__aarch64__)
209 double seconds_to_microseconds = 1000 * 1000;
210 uint64_t freq = 0;
211 // See Arm Architecture Registers Armv8 section System Registers
212 asm volatile("mrs %0, cntfrq_el0" : "=r"(freq));
213 if (freq == 0) {
214 // It is expected that cntfrq_el0 is correctly setup during system initialization but some
215 // devices don't do this. In such cases fall back to computing the frequency. See b/315139000.
216 tsc_to_microsec_scaling_factor = computeScalingFactor();
217 } else {
218 tsc_to_microsec_scaling_factor = seconds_to_microseconds / static_cast<double>(freq);
219 }
220 #elif defined(__i386__) || defined(__x86_64__)
221 tsc_to_microsec_scaling_factor = GetScalingFactorForX86();
222 #else
223 tsc_to_microsec_scaling_factor = 1.0;
224 #endif
225 }
226
GetMicroTime(uint64_t counter)227 ALWAYS_INLINE uint64_t GetMicroTime(uint64_t counter) {
228 DCHECK(tsc_to_microsec_scaling_factor > 0.0) << tsc_to_microsec_scaling_factor;
229 return tsc_to_microsec_scaling_factor * counter;
230 }
231
GetClockSourceFromFlags(int flags)232 TraceClockSource GetClockSourceFromFlags(int flags) {
233 bool need_wall = flags & Trace::TraceFlag::kTraceClockSourceWallClock;
234 bool need_thread_cpu = flags & Trace::TraceFlag::kTraceClockSourceThreadCpu;
235 if (need_wall && need_thread_cpu) {
236 return TraceClockSource::kDual;
237 } else if (need_wall) {
238 return TraceClockSource::kWall;
239 } else if (need_thread_cpu) {
240 return TraceClockSource::kThreadCpu;
241 } else {
242 return kDefaultTraceClockSource;
243 }
244 }
245
GetTraceFormatVersionFromFlags(int flags)246 int GetTraceFormatVersionFromFlags(int flags) {
247 int version = (flags & Trace::kTraceFormatVersionFlagMask) >> Trace::kTraceFormatVersionShift;
248 return version;
249 }
250
251 } // namespace
252
253 // Temporary code for debugging b/342768977
254 int num_trace_starts_ GUARDED_BY(Locks::trace_lock_);
255 int num_trace_stops_initiated_ GUARDED_BY(Locks::trace_lock_);
256 std::atomic<int> num_trace_stops_finished_;
GetDebugInformation()257 std::string Trace::GetDebugInformation() {
258 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
259 std::stringstream debug_info;
260 debug_info << "start:" << num_trace_starts_ << "stop:" << num_trace_stops_initiated_ << "done:"
261 << num_trace_stops_finished_ << "trace:" << the_trace_;
262 return debug_info.str();
263 }
264
HasMethodEncoding(ArtMethod * method)265 bool TraceWriter::HasMethodEncoding(ArtMethod* method) {
266 return art_method_id_map_.find(method) != art_method_id_map_.end();
267 }
268
GetMethodEncoding(ArtMethod * method)269 std::pair<uint32_t, bool> TraceWriter::GetMethodEncoding(ArtMethod* method) {
270 auto it = art_method_id_map_.find(method);
271 if (it != art_method_id_map_.end()) {
272 return std::pair<uint32_t, bool>(it->second, false);
273 } else {
274 uint32_t idx = current_method_index_;
275 art_method_id_map_.emplace(method, idx);
276 current_method_index_++;
277 return std::pair<uint32_t, bool>(idx, true);
278 }
279 }
280
GetThreadEncoding(pid_t thread_id)281 uint16_t TraceWriter::GetThreadEncoding(pid_t thread_id) {
282 auto it = thread_id_map_.find(thread_id);
283 if (it != thread_id_map_.end()) {
284 return it->second;
285 }
286
287 uint16_t idx = current_thread_index_;
288 thread_id_map_.emplace(thread_id, current_thread_index_);
289 DCHECK_LT(current_thread_index_, (1 << 16) - 2);
290 current_thread_index_++;
291 return idx;
292 }
293
294 class TraceWriterTask : public SelfDeletingTask {
295 public:
TraceWriterTask(TraceWriter * trace_writer,int index,uintptr_t * buffer,size_t cur_offset,size_t thread_id)296 TraceWriterTask(
297 TraceWriter* trace_writer, int index, uintptr_t* buffer, size_t cur_offset, size_t thread_id)
298 : trace_writer_(trace_writer),
299 index_(index),
300 buffer_(buffer),
301 cur_offset_(cur_offset),
302 thread_id_(thread_id) {}
303
Run(Thread * self ATTRIBUTE_UNUSED)304 void Run(Thread* self ATTRIBUTE_UNUSED) override {
305 ProcessBuffer(buffer_, cur_offset_, thread_id_);
306 if (index_ == -1) {
307 // This was a temporary buffer we allocated since there are no free buffers and it wasn't
308 // safe to wait for one. This should only happen when we have fewer buffers than the number
309 // of threads.
310 delete[] buffer_;
311 }
312 trace_writer_->ReleaseBuffer(index_);
313 }
314
315 virtual void ProcessBuffer(uintptr_t* buffer, size_t cur_offset, size_t thread_id) = 0;
316
GetTraceWriter()317 TraceWriter* GetTraceWriter() { return trace_writer_; }
318
319 private:
320 TraceWriter* trace_writer_;
321 int index_;
322 uintptr_t* buffer_;
323 size_t cur_offset_;
324 size_t thread_id_;
325 };
326
327 class TraceEntriesWriterTask final : public TraceWriterTask {
328 public:
TraceEntriesWriterTask(TraceWriter * trace_writer,int index,uintptr_t * buffer,size_t cur_offset,size_t tid)329 TraceEntriesWriterTask(
330 TraceWriter* trace_writer, int index, uintptr_t* buffer, size_t cur_offset, size_t tid)
331 : TraceWriterTask(trace_writer, index, buffer, cur_offset, tid) {}
332
ProcessBuffer(uintptr_t * buffer,size_t cur_offset,size_t thread_id)333 void ProcessBuffer(uintptr_t* buffer, size_t cur_offset, size_t thread_id) override {
334 std::unordered_map<ArtMethod*, std::string> method_infos;
335 TraceWriter* trace_writer = GetTraceWriter();
336 if (trace_writer->GetTraceFormatVersion() == Trace::kFormatV1) {
337 ScopedObjectAccess soa(Thread::Current());
338 trace_writer->PreProcessTraceForMethodInfos(buffer, cur_offset, method_infos);
339 }
340 trace_writer->FlushBuffer(buffer, cur_offset, thread_id, method_infos);
341 }
342 };
343
344 class MethodInfoWriterTask final : public TraceWriterTask {
345 public:
MethodInfoWriterTask(TraceWriter * trace_writer,int index,uintptr_t * buffer,size_t cur_offset)346 MethodInfoWriterTask(TraceWriter* trace_writer, int index, uintptr_t* buffer, size_t cur_offset)
347 : TraceWriterTask(trace_writer, index, buffer, cur_offset, 0) {}
348
ProcessBuffer(uintptr_t * buffer,size_t cur_offset,size_t thread_id)349 void ProcessBuffer(uintptr_t* buffer,
350 size_t cur_offset,
351 [[maybe_unused]] size_t thread_id) override {
352 GetTraceWriter()->WriteToFile(reinterpret_cast<uint8_t*>(buffer), cur_offset);
353 }
354 };
355
AllocStackTrace()356 std::vector<ArtMethod*>* Trace::AllocStackTrace() {
357 return (temp_stack_trace_.get() != nullptr) ? temp_stack_trace_.release() :
358 new std::vector<ArtMethod*>();
359 }
360
FreeStackTrace(std::vector<ArtMethod * > * stack_trace)361 void Trace::FreeStackTrace(std::vector<ArtMethod*>* stack_trace) {
362 stack_trace->clear();
363 temp_stack_trace_.reset(stack_trace);
364 }
365
GetTraceVersion(TraceClockSource clock_source,int version)366 static uint16_t GetTraceVersion(TraceClockSource clock_source, int version) {
367 if (version == Trace::kFormatV1) {
368 return (clock_source == TraceClockSource::kDual) ? kTraceVersionDualClock :
369 kTraceVersionSingleClock;
370 } else {
371 return (clock_source == TraceClockSource::kDual) ? kTraceVersionDualClockV2 :
372 kTraceVersionSingleClockV2;
373 }
374 }
375
GetRecordSize(TraceClockSource clock_source,int version)376 static uint16_t GetRecordSize(TraceClockSource clock_source, int version) {
377 if (version == Trace::kFormatV1) {
378 return (clock_source == TraceClockSource::kDual) ? kTraceRecordSizeDualClock :
379 kTraceRecordSizeSingleClock;
380 } else {
381 return (clock_source == TraceClockSource::kDual) ? kTraceRecordSizeDualClockV2 :
382 kTraceRecordSizeSingleClockV2;
383 }
384 }
385
GetNumEntries(TraceClockSource clock_source)386 static uint16_t GetNumEntries(TraceClockSource clock_source) {
387 return (clock_source == TraceClockSource::kDual) ? kNumEntriesForDualClock
388 : kNumEntriesForWallClock;
389 }
390
UseThreadCpuClock(TraceClockSource clock_source)391 bool UseThreadCpuClock(TraceClockSource clock_source) {
392 return (clock_source == TraceClockSource::kThreadCpu) ||
393 (clock_source == TraceClockSource::kDual);
394 }
395
UseWallClock(TraceClockSource clock_source)396 bool UseWallClock(TraceClockSource clock_source) {
397 return (clock_source == TraceClockSource::kWall) || (clock_source == TraceClockSource::kDual);
398 }
399
UseFastTraceListeners(TraceClockSource clock_source)400 bool UseFastTraceListeners(TraceClockSource clock_source) {
401 // Thread cpu clocks needs a kernel call, so we don't directly support them in JITed code.
402 bool is_fast_trace = !UseThreadCpuClock(clock_source);
403 #if defined(__arm__)
404 // On ARM 32 bit, we don't always have access to the timestamp counters from
405 // user space. See comment in GetTimestamp for more details.
406 is_fast_trace = false;
407 #endif
408 return is_fast_trace;
409 }
410
MeasureClockOverhead()411 void Trace::MeasureClockOverhead() {
412 if (UseThreadCpuClock(clock_source_)) {
413 Thread::Current()->GetCpuMicroTime();
414 }
415 if (UseWallClock(clock_source_)) {
416 GetTimestamp();
417 }
418 }
419
420 // Compute an average time taken to measure clocks.
GetClockOverheadNanoSeconds()421 uint32_t Trace::GetClockOverheadNanoSeconds() {
422 Thread* self = Thread::Current();
423 uint64_t start = self->GetCpuMicroTime();
424
425 for (int i = 4000; i > 0; i--) {
426 MeasureClockOverhead();
427 MeasureClockOverhead();
428 MeasureClockOverhead();
429 MeasureClockOverhead();
430 MeasureClockOverhead();
431 MeasureClockOverhead();
432 MeasureClockOverhead();
433 MeasureClockOverhead();
434 }
435
436 uint64_t elapsed_us = self->GetCpuMicroTime() - start;
437 return static_cast<uint32_t>(elapsed_us / 32);
438 }
439
GetSample(Thread * thread,void * arg)440 static void GetSample(Thread* thread, void* arg) REQUIRES_SHARED(Locks::mutator_lock_) {
441 std::vector<ArtMethod*>* const stack_trace = Trace::AllocStackTrace();
442 StackVisitor::WalkStack(
443 [&](const art::StackVisitor* stack_visitor) REQUIRES_SHARED(Locks::mutator_lock_) {
444 ArtMethod* m = stack_visitor->GetMethod();
445 // Ignore runtime frames (in particular callee save).
446 if (!m->IsRuntimeMethod()) {
447 stack_trace->push_back(m);
448 }
449 return true;
450 },
451 thread,
452 /* context= */ nullptr,
453 art::StackVisitor::StackWalkKind::kIncludeInlinedFrames);
454 Trace* the_trace = reinterpret_cast<Trace*>(arg);
455 the_trace->CompareAndUpdateStackTrace(thread, stack_trace);
456 }
457
ClearThreadStackTraceAndClockBase(Thread * thread,void * arg)458 static void ClearThreadStackTraceAndClockBase(Thread* thread, [[maybe_unused]] void* arg) {
459 thread->SetTraceClockBase(0);
460 std::vector<ArtMethod*>* stack_trace = thread->GetStackTraceSample();
461 thread->SetStackTraceSample(nullptr);
462 delete stack_trace;
463 }
464
CompareAndUpdateStackTrace(Thread * thread,std::vector<ArtMethod * > * stack_trace)465 void Trace::CompareAndUpdateStackTrace(Thread* thread,
466 std::vector<ArtMethod*>* stack_trace) {
467 CHECK_EQ(pthread_self(), sampling_pthread_);
468 std::vector<ArtMethod*>* old_stack_trace = thread->GetStackTraceSample();
469 // Update the thread's stack trace sample.
470 thread->SetStackTraceSample(stack_trace);
471 // Read timer clocks to use for all events in this trace.
472 uint32_t thread_clock_diff = 0;
473 uint64_t timestamp_counter = 0;
474 ReadClocks(thread, &thread_clock_diff, ×tamp_counter);
475 if (old_stack_trace == nullptr) {
476 // If there's no previous stack trace sample for this thread, log an entry event for all
477 // methods in the trace.
478 for (auto rit = stack_trace->rbegin(); rit != stack_trace->rend(); ++rit) {
479 LogMethodTraceEvent(thread, *rit, kTraceMethodEnter, thread_clock_diff, timestamp_counter);
480 }
481 } else {
482 // If there's a previous stack trace for this thread, diff the traces and emit entry and exit
483 // events accordingly.
484 auto old_rit = old_stack_trace->rbegin();
485 auto rit = stack_trace->rbegin();
486 // Iterate bottom-up over both traces until there's a difference between them.
487 while (old_rit != old_stack_trace->rend() && rit != stack_trace->rend() && *old_rit == *rit) {
488 old_rit++;
489 rit++;
490 }
491 // Iterate top-down over the old trace until the point where they differ, emitting exit events.
492 for (auto old_it = old_stack_trace->begin(); old_it != old_rit.base(); ++old_it) {
493 LogMethodTraceEvent(thread, *old_it, kTraceMethodExit, thread_clock_diff, timestamp_counter);
494 }
495 // Iterate bottom-up over the new trace from the point where they differ, emitting entry events.
496 for (; rit != stack_trace->rend(); ++rit) {
497 LogMethodTraceEvent(thread, *rit, kTraceMethodEnter, thread_clock_diff, timestamp_counter);
498 }
499 FreeStackTrace(old_stack_trace);
500 }
501 }
502
RunSamplingThread(void * arg)503 void* Trace::RunSamplingThread(void* arg) {
504 Runtime* runtime = Runtime::Current();
505 intptr_t interval_us = reinterpret_cast<intptr_t>(arg);
506 CHECK_GE(interval_us, 0);
507 CHECK(runtime->AttachCurrentThread("Sampling Profiler", true, runtime->GetSystemThreadGroup(),
508 !runtime->IsAotCompiler()));
509
510 while (true) {
511 usleep(interval_us);
512 ScopedTrace trace("Profile sampling");
513 Thread* self = Thread::Current();
514 Trace* the_trace;
515 {
516 MutexLock mu(self, *Locks::trace_lock_);
517 the_trace = the_trace_;
518 if (the_trace_->stop_tracing_) {
519 break;
520 }
521 }
522 {
523 // Avoid a deadlock between a thread doing garbage collection
524 // and the profile sampling thread, by blocking GC when sampling
525 // thread stacks (see b/73624630).
526 gc::ScopedGCCriticalSection gcs(self,
527 art::gc::kGcCauseInstrumentation,
528 art::gc::kCollectorTypeInstrumentation);
529 ScopedSuspendAll ssa(__FUNCTION__);
530 MutexLock mu(self, *Locks::thread_list_lock_);
531 runtime->GetThreadList()->ForEach(GetSample, the_trace);
532 }
533 }
534
535 runtime->DetachCurrentThread();
536 return nullptr;
537 }
538
539 // Visitor used to record all methods currently loaded in the runtime. This is done at the start of
540 // method tracing.
541 class RecordMethodInfoClassVisitor : public ClassVisitor {
542 public:
RecordMethodInfoClassVisitor(Trace * trace)543 explicit RecordMethodInfoClassVisitor(Trace* trace)
544 : trace_(trace), offset_(0), buffer_(nullptr) {}
545
operator ()(ObjPtr<mirror::Class> klass)546 bool operator()(ObjPtr<mirror::Class> klass) override REQUIRES(Locks::mutator_lock_) {
547 // We use a buffer to aggregate method infos from different classes to avoid multiple small
548 // writes to the file. The RecordMethodInfo handles the overflows by enqueueing a task to
549 // flush the old buffer and allocates a new buffer.
550 trace_->GetTraceWriter()->RecordMethodInfoV2(klass.Ptr(), &buffer_, &offset_);
551 return true; // Visit all classes.
552 }
553
FlushBuffer()554 void FlushBuffer() REQUIRES_SHARED(Locks::mutator_lock_) {
555 // Flushes any data in the buffer to the file. Called at the end of visit to write any
556 // remaining data to the file.
557 trace_->GetTraceWriter()->AddMethodInfoWriteTask(
558 buffer_, offset_, Thread::Current()->GetTid(), true);
559 }
560
561 private:
562 Trace* const trace_;
563 // Use a buffer to aggregate method infos of all classes to avoid multiple smaller writes to file.
564 size_t offset_ = 0;
565 uint8_t* buffer_ = nullptr;
566 };
567
ClassPrepare(Handle<mirror::Class> temp_klass,Handle<mirror::Class> klass)568 void Trace::ClassPrepare([[maybe_unused]] Handle<mirror::Class> temp_klass,
569 Handle<mirror::Class> klass) {
570 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
571 if (the_trace_ == nullptr) {
572 return;
573 }
574 size_t offset = 0;
575 size_t tid = Thread::Current()->GetTid();
576 uint8_t* buffer = nullptr;
577 // Write the method infos of the newly loaded class.
578 the_trace_->GetTraceWriter()->RecordMethodInfoV2(klass.Get(), &buffer, &offset);
579 the_trace_->GetTraceWriter()->AddMethodInfoWriteTask(buffer, offset, tid, true);
580 }
581
AddMethodInfoWriteTask(uint8_t * buffer,size_t offset,size_t tid,bool release)582 uint8_t* TraceWriter::AddMethodInfoWriteTask(uint8_t* buffer,
583 size_t offset,
584 size_t tid,
585 bool release) {
586 int old_index = GetMethodTraceIndex(reinterpret_cast<uintptr_t*>(buffer));
587 uintptr_t* new_buf = nullptr;
588 thread_pool_->AddTask(
589 Thread::Current(),
590 new MethodInfoWriterTask(this, old_index, reinterpret_cast<uintptr_t*>(buffer), offset));
591 if (!release) {
592 new_buf = AcquireTraceBuffer(tid);
593 }
594 return reinterpret_cast<uint8_t*>(new_buf);
595 }
596
WriteToFile(uint8_t * buffer,size_t offset)597 void TraceWriter::WriteToFile(uint8_t* buffer, size_t offset) {
598 MutexLock mu(Thread::Current(), trace_writer_lock_);
599 if (!trace_file_->WriteFully(buffer, offset)) {
600 PLOG(WARNING) << "Failed streaming a tracing event.";
601 }
602 }
603
RecordMethodInfoV2(mirror::Class * klass,uint8_t ** buffer,size_t * offset)604 void TraceWriter::RecordMethodInfoV2(mirror::Class* klass, uint8_t** buffer, size_t* offset) {
605 // For the v1 format, we record methods when we first execute them.
606 DCHECK_EQ(trace_format_version_, Trace::kFormatV2);
607
608 auto methods = klass->GetMethods(kRuntimePointerSize);
609 if (methods.empty()) {
610 return;
611 }
612
613 size_t tid = Thread::Current()->GetTid();
614 size_t buffer_size = kPerThreadBufSize * sizeof(uintptr_t);
615 size_t index = *offset;
616 uint8_t* buf = *buffer;
617 if (buf == nullptr) {
618 buf = reinterpret_cast<uint8_t*>(AcquireTraceBuffer(tid));
619 }
620
621 std::string class_name_current = klass->PrettyDescriptor();
622 const char* source_file_current = klass->GetSourceFile();
623 if (source_file_current == nullptr) {
624 // Generated classes have no source file.
625 source_file_current = "";
626 }
627 for (ArtMethod& method : klass->GetMethods(kRuntimePointerSize)) {
628 if (!method.IsInvokable()) {
629 continue;
630 }
631
632 std::string class_name;
633 const char* source_file;
634 if (method.IsCopied()) {
635 // For copied methods use method's declaring class which may not be the current class.
636 class_name = method.GetDeclaringClass()->PrettyDescriptor();
637 source_file = method.GetDeclaringClass()->GetSourceFile();
638 } else {
639 DCHECK(klass == method.GetDeclaringClass());
640 class_name = class_name_current;
641 source_file = source_file_current;
642 }
643 int class_name_len = class_name.length();
644 int source_file_len = strlen(source_file);
645
646 uint64_t method_id = reinterpret_cast<uint64_t>(&method);
647 // TODO(mythria): Change how we report method infos in V2 to reduce the
648 // repetition of the information about class and the source file.
649 const char* name = method.GetName();
650 int name_len = strlen(name);
651 std::string signature = method.GetSignature().ToString();
652 int signature_len = signature.length();
653 // We need 3 tabs in between and a \n at the end and hence 4 additional characters.
654 int method_info_length = class_name_len + name_len + signature_len + source_file_len + 4;
655 // 1 byte header + 8 bytes method id + 2 bytes method_info_length
656 int header_length = 11;
657 if (index + header_length + method_info_length >= buffer_size) {
658 buf = AddMethodInfoWriteTask(buf, index, tid, false);
659 index = 0;
660 }
661 // Write the header to the buffer
662 buf[index] = kMethodInfoHeaderV2;
663 Append8LE(buf + index + 1, method_id);
664 Append2LE(buf + index + 9, method_info_length);
665 index += header_length;
666
667 // Copy method line into the buffer
668 memcpy(buf + index, class_name.c_str(), class_name_len);
669 buf[index + class_name_len] = '\t';
670 index += class_name_len + 1;
671 memcpy(buf + index, name, name_len);
672 buf[index + name_len] = '\t';
673 index += name_len + 1;
674 memcpy(buf + index, signature.c_str(), signature_len);
675 buf[index + signature_len] = '\t';
676 index += signature_len + 1;
677 memcpy(buf + index, source_file, source_file_len);
678 buf[index + source_file_len] = '\n';
679 index += source_file_len + 1;
680 }
681 *offset = index;
682 *buffer = buf;
683 }
684
Start(const char * trace_filename,size_t buffer_size,int flags,TraceOutputMode output_mode,TraceMode trace_mode,int interval_us)685 void Trace::Start(const char* trace_filename,
686 size_t buffer_size,
687 int flags,
688 TraceOutputMode output_mode,
689 TraceMode trace_mode,
690 int interval_us) {
691 std::unique_ptr<File> file(OS::CreateEmptyFileWriteOnly(trace_filename));
692 if (file == nullptr) {
693 std::string msg = android::base::StringPrintf("Unable to open trace file '%s'", trace_filename);
694 PLOG(ERROR) << msg;
695 ScopedObjectAccess soa(Thread::Current());
696 Thread::Current()->ThrowNewException("Ljava/lang/RuntimeException;", msg.c_str());
697 return;
698 }
699 Start(std::move(file), buffer_size, flags, output_mode, trace_mode, interval_us);
700 }
701
Start(int trace_fd,size_t buffer_size,int flags,TraceOutputMode output_mode,TraceMode trace_mode,int interval_us)702 void Trace::Start(int trace_fd,
703 size_t buffer_size,
704 int flags,
705 TraceOutputMode output_mode,
706 TraceMode trace_mode,
707 int interval_us) {
708 if (trace_fd < 0) {
709 std::string msg = android::base::StringPrintf("Unable to start tracing with invalid fd %d",
710 trace_fd);
711 LOG(ERROR) << msg;
712 ScopedObjectAccess soa(Thread::Current());
713 Thread::Current()->ThrowNewException("Ljava/lang/RuntimeException;", msg.c_str());
714 return;
715 }
716 std::unique_ptr<File> file(new File(trace_fd, /* path= */ "tracefile", /* check_usage= */ true));
717 Start(std::move(file), buffer_size, flags, output_mode, trace_mode, interval_us);
718 }
719
StartDDMS(size_t buffer_size,int flags,TraceMode trace_mode,int interval_us)720 void Trace::StartDDMS(size_t buffer_size,
721 int flags,
722 TraceMode trace_mode,
723 int interval_us) {
724 Start(std::unique_ptr<File>(),
725 buffer_size,
726 flags,
727 TraceOutputMode::kDDMS,
728 trace_mode,
729 interval_us);
730 }
731
Start(std::unique_ptr<File> && trace_file_in,size_t buffer_size,int flags,TraceOutputMode output_mode,TraceMode trace_mode,int interval_us)732 void Trace::Start(std::unique_ptr<File>&& trace_file_in,
733 size_t buffer_size,
734 int flags,
735 TraceOutputMode output_mode,
736 TraceMode trace_mode,
737 int interval_us) {
738 // We own trace_file now and are responsible for closing it. To account for error situations, use
739 // a specialized unique_ptr to ensure we close it on the way out (if it hasn't been passed to a
740 // Trace instance).
741 auto deleter = [](File* file) {
742 if (file != nullptr) {
743 file->MarkUnchecked(); // Don't deal with flushing requirements.
744 [[maybe_unused]] int result = file->Close();
745 delete file;
746 }
747 };
748 std::unique_ptr<File, decltype(deleter)> trace_file(trace_file_in.release(), deleter);
749
750 Thread* self = Thread::Current();
751 {
752 MutexLock mu(self, *Locks::trace_lock_);
753 if (the_trace_ != nullptr) {
754 LOG(ERROR) << "Trace already in progress, ignoring this request";
755 return;
756 }
757 }
758
759 // Check interval if sampling is enabled
760 if (trace_mode == TraceMode::kSampling && interval_us <= 0) {
761 LOG(ERROR) << "Invalid sampling interval: " << interval_us;
762 ScopedObjectAccess soa(self);
763 ThrowRuntimeException("Invalid sampling interval: %d", interval_us);
764 return;
765 }
766
767 // Initialize the frequency of timestamp counter updates here. This is needed
768 // to get wallclock time from timestamp counter values.
769 InitializeTimestampCounters();
770
771 Runtime* runtime = Runtime::Current();
772
773 // Enable count of allocs if specified in the flags.
774 bool enable_stats = false;
775
776 // Create Trace object.
777 {
778 // Suspend JIT here since we are switching runtime to debuggable. Debuggable runtimes cannot use
779 // JITed code from before so we need to invalidated all JITed code here. Enter suspend JIT scope
780 // to prevent any races with ongoing JIT compilations.
781 jit::ScopedJitSuspend suspend_jit;
782 // Required since EnableMethodTracing calls ConfigureStubs which visits class linker classes.
783 gc::ScopedGCCriticalSection gcs(self,
784 gc::kGcCauseInstrumentation,
785 gc::kCollectorTypeInstrumentation);
786 ScopedSuspendAll ssa(__FUNCTION__);
787 MutexLock mu(self, *Locks::trace_lock_);
788 if (TraceProfiler::IsTraceProfileInProgress()) {
789 LOG(ERROR) << "On-demand profile in progress, ignoring this request";
790 return;
791 }
792
793 if (Trace::IsTracingEnabledLocked()) {
794 LOG(ERROR) << "Trace already in progress, ignoring this request";
795 return;
796 }
797
798 enable_stats = (flags & kTraceCountAllocs) != 0;
799 bool is_trace_format_v2 = GetTraceFormatVersionFromFlags(flags) == Trace::kFormatV2;
800 the_trace_ = new Trace(trace_file.release(), buffer_size, flags, output_mode, trace_mode);
801 num_trace_starts_++;
802 if (is_trace_format_v2) {
803 // Record all the methods that are currently loaded. We log all methods when any new class
804 // is loaded. This will allow us to process the trace entries without requiring a mutator
805 // lock.
806 RecordMethodInfoClassVisitor visitor(the_trace_);
807 runtime->GetClassLinker()->VisitClasses(&visitor);
808 visitor.FlushBuffer();
809 }
810 if (trace_mode == TraceMode::kSampling) {
811 CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread,
812 reinterpret_cast<void*>(interval_us)),
813 "Sampling profiler thread");
814 the_trace_->interval_us_ = interval_us;
815 } else {
816 if (!runtime->IsJavaDebuggable()) {
817 art::jit::Jit* jit = runtime->GetJit();
818 if (jit != nullptr) {
819 jit->GetCodeCache()->InvalidateAllCompiledCode();
820 jit->GetCodeCache()->TransitionToDebuggable();
821 jit->GetJitCompiler()->SetDebuggableCompilerOption(true);
822 }
823 runtime->SetRuntimeDebugState(art::Runtime::RuntimeDebugState::kJavaDebuggable);
824 runtime->GetInstrumentation()->UpdateEntrypointsForDebuggable();
825 runtime->DeoptimizeBootImage();
826 }
827 if (is_trace_format_v2) {
828 // Add ClassLoadCallback to record methods on class load.
829 runtime->GetRuntimeCallbacks()->AddClassLoadCallback(the_trace_);
830 }
831 runtime->GetInstrumentation()->AddListener(
832 the_trace_,
833 instrumentation::Instrumentation::kMethodEntered |
834 instrumentation::Instrumentation::kMethodExited |
835 instrumentation::Instrumentation::kMethodUnwind,
836 UseFastTraceListeners(the_trace_->GetClockSource()));
837 runtime->GetInstrumentation()->EnableMethodTracing(kTracerInstrumentationKey,
838 the_trace_,
839 /*needs_interpreter=*/false);
840 }
841
842 if (art_flags::always_enable_profile_code()) {
843 // Reset the trace low overhead trace entry points to be a nop.
844 MutexLock thread_list_mutex(self, *Locks::thread_list_lock_);
845 for (Thread* thread : Runtime::Current()->GetThreadList()->GetList()) {
846 thread->UpdateTlsLowOverheadTraceEntrypoints(/*enable= */ false);
847 }
848 }
849 }
850
851 // Can't call this when holding the mutator lock.
852 if (enable_stats) {
853 runtime->SetStatsEnabled(true);
854 }
855 }
856
StopTracing(bool flush_entries)857 void Trace::StopTracing(bool flush_entries) {
858 Runtime* const runtime = Runtime::Current();
859 Thread* const self = Thread::Current();
860
861 pthread_t sampling_pthread = 0U;
862 {
863 MutexLock mu(self, *Locks::trace_lock_);
864 num_trace_stops_initiated_++;
865 if (the_trace_ == nullptr || the_trace_->stop_tracing_) {
866 LOG(ERROR) << "Trace stop requested, but no trace currently running or trace is being"
867 << " stopped concurrently on another thread";
868 return;
869 }
870 // Tell sampling_pthread_ to stop tracing.
871 the_trace_->stop_tracing_ = true;
872 sampling_pthread = sampling_pthread_;
873 }
874
875 // Make sure that we join before we delete the trace since we don't want to have
876 // the sampling thread access a stale pointer. This finishes since the sampling thread exits when
877 // the_trace_ is null.
878 if (sampling_pthread != 0U) {
879 CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, nullptr), "sampling thread shutdown");
880 }
881
882 // Wakeup any threads waiting for a buffer and abort allocating a buffer.
883 the_trace_->trace_writer_->StopTracing();
884
885 // Make a copy of the_trace_, so it can be flushed later. We want to reset
886 // the_trace_ to nullptr in suspend all scope to prevent any races
887 Trace* the_trace = the_trace_;
888 bool stop_alloc_counting = (the_trace->flags_ & Trace::kTraceCountAllocs) != 0;
889 // Stop the trace sources adding more entries to the trace buffer and synchronise stores.
890 {
891 gc::ScopedGCCriticalSection gcs(
892 self, gc::kGcCauseInstrumentation, gc::kCollectorTypeInstrumentation);
893 jit::ScopedJitSuspend suspend_jit;
894 ScopedSuspendAll ssa(__FUNCTION__);
895
896 if (the_trace->trace_mode_ == TraceMode::kSampling) {
897 MutexLock mu(self, *Locks::thread_list_lock_);
898 runtime->GetThreadList()->ForEach(ClearThreadStackTraceAndClockBase, nullptr);
899 } else {
900 runtime->GetRuntimeCallbacks()->RemoveClassLoadCallback(the_trace_);
901 runtime->GetInstrumentation()->RemoveListener(
902 the_trace,
903 instrumentation::Instrumentation::kMethodEntered |
904 instrumentation::Instrumentation::kMethodExited |
905 instrumentation::Instrumentation::kMethodUnwind,
906 UseFastTraceListeners(the_trace_->GetClockSource()));
907 runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey);
908 }
909
910 // Flush thread specific buffer from all threads before resetting the_trace_ to nullptr.
911 // We also flush the buffer when destroying a thread which expects the_trace_ to be valid so
912 // make sure that the per-thread buffer is reset before resetting the_trace_.
913 {
914 MutexLock mu(self, *Locks::trace_lock_);
915 MutexLock tl_lock(Thread::Current(), *Locks::thread_list_lock_);
916 // Flush the per-thread buffers and reset the trace inside the trace_lock_ to avoid any
917 // race if the thread is detaching and trying to flush the buffer too. Since we hold the
918 // trace_lock_ both here and when flushing on a thread detach only one of them will succeed
919 // in actually flushing the buffer.
920 for (Thread* thread : Runtime::Current()->GetThreadList()->GetList()) {
921 if (thread->GetMethodTraceBuffer() != nullptr) {
922 // We may have pending requests to flush the data. So just enqueue a
923 // request to flush the current buffer so all the requests are
924 // processed in order.
925 the_trace->trace_writer_->FlushBuffer(
926 thread, /* is_sync= */ false, /* free_buffer= */ true);
927 }
928
929 if (art_flags::always_enable_profile_code()) {
930 thread->UpdateTlsLowOverheadTraceEntrypoints(/*enable= */ true);
931 }
932 }
933 the_trace_ = nullptr;
934 sampling_pthread_ = 0U;
935 }
936 }
937
938 // At this point, code may read buf_ as its writers are shutdown
939 // and the ScopedSuspendAll above has ensured all stores to buf_
940 // are now visible.
941 the_trace->trace_writer_->FinishTracing(the_trace->flags_, flush_entries);
942 delete the_trace;
943 num_trace_stops_finished_++;
944
945 if (stop_alloc_counting) {
946 // Can be racy since SetStatsEnabled is not guarded by any locks.
947 runtime->SetStatsEnabled(false);
948 }
949 }
950
RemoveListeners()951 void Trace::RemoveListeners() {
952 Thread* self = Thread::Current();
953 // This is expected to be called in SuspendAll scope.
954 DCHECK(Locks::mutator_lock_->IsExclusiveHeld(self));
955 MutexLock mu(self, *Locks::trace_lock_);
956 Runtime* runtime = Runtime::Current();
957 runtime->GetRuntimeCallbacks()->RemoveClassLoadCallback(the_trace_);
958 runtime->GetInstrumentation()->RemoveListener(
959 the_trace_,
960 instrumentation::Instrumentation::kMethodEntered |
961 instrumentation::Instrumentation::kMethodExited |
962 instrumentation::Instrumentation::kMethodUnwind,
963 UseFastTraceListeners(the_trace_->GetClockSource()));
964 }
965
FlushThreadBuffer(Thread * self)966 void Trace::FlushThreadBuffer(Thread* self) {
967 MutexLock mu(self, *Locks::trace_lock_);
968 // Check if we still need to flush inside the trace_lock_. If we are stopping tracing it is
969 // possible we already deleted the trace and flushed the buffer too.
970 if (the_trace_ == nullptr) {
971 if (art_flags::always_enable_profile_code()) {
972 TraceProfiler::ReleaseThreadBuffer(self);
973 }
974 DCHECK_EQ(self->GetMethodTraceBuffer(), nullptr);
975 return;
976 }
977 the_trace_->trace_writer_->FlushBuffer(self, /* is_sync= */ false, /* free_buffer= */ true);
978 }
979
ReleaseThreadBuffer(Thread * self)980 void Trace::ReleaseThreadBuffer(Thread* self) {
981 MutexLock mu(self, *Locks::trace_lock_);
982 // Check if we still need to flush inside the trace_lock_. If we are stopping tracing it is
983 // possible we already deleted the trace and flushed the buffer too.
984 if (the_trace_ == nullptr) {
985 if (art_flags::always_enable_profile_code()) {
986 TraceProfiler::ReleaseThreadBuffer(self);
987 }
988 DCHECK_EQ(self->GetMethodTraceBuffer(), nullptr);
989 return;
990 }
991 the_trace_->trace_writer_->ReleaseBufferForThread(self);
992 self->SetMethodTraceBuffer(nullptr, 0);
993 }
994
Abort()995 void Trace::Abort() {
996 // Do not write anything anymore.
997 StopTracing(/* flush_entries= */ false);
998 }
999
Stop()1000 void Trace::Stop() {
1001 // Finish writing.
1002 StopTracing(/* flush_entries= */ true);
1003 }
1004
Shutdown()1005 void Trace::Shutdown() {
1006 if (GetMethodTracingMode() != kTracingInactive) {
1007 Stop();
1008 }
1009 }
1010
GetMethodTracingMode()1011 TracingMode Trace::GetMethodTracingMode() {
1012 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1013 if (the_trace_ == nullptr) {
1014 return kTracingInactive;
1015 } else {
1016 switch (the_trace_->trace_mode_) {
1017 case TraceMode::kSampling:
1018 return kSampleProfilingActive;
1019 case TraceMode::kMethodTracing:
1020 return kMethodTracingActive;
1021 }
1022 LOG(FATAL) << "Unreachable";
1023 UNREACHABLE();
1024 }
1025 }
1026
TraceWriter(File * trace_file,TraceOutputMode output_mode,TraceClockSource clock_source,size_t buffer_size,int num_trace_buffers,int trace_format_version,uint32_t clock_overhead_ns)1027 TraceWriter::TraceWriter(File* trace_file,
1028 TraceOutputMode output_mode,
1029 TraceClockSource clock_source,
1030 size_t buffer_size,
1031 int num_trace_buffers,
1032 int trace_format_version,
1033 uint32_t clock_overhead_ns)
1034 : trace_file_(trace_file),
1035 trace_output_mode_(output_mode),
1036 clock_source_(clock_source),
1037 buf_(new uint8_t[std::max(kMinBufSize, buffer_size)]()),
1038 buffer_size_(std::max(kMinBufSize, buffer_size)),
1039 trace_format_version_(trace_format_version),
1040 start_time_(GetMicroTime(GetTimestamp())),
1041 overflow_(false),
1042 num_records_(0),
1043 clock_overhead_ns_(clock_overhead_ns),
1044 owner_tids_(num_trace_buffers),
1045 buffer_pool_lock_("tracing buffer pool lock", kDefaultMutexLevel),
1046 buffer_available_("buffer available condition", buffer_pool_lock_),
1047 num_waiters_zero_cond_("Num waiters zero", buffer_pool_lock_),
1048 num_waiters_for_buffer_(0),
1049 trace_writer_lock_("trace writer lock", LockLevel::kTracingStreamingLock) {
1050 // We initialize the start_time_ from the timestamp counter. This may not match
1051 // with the monotonic timer but we only use this time to calculate the elapsed
1052 // time from this point which should be the same for both cases.
1053 // We record monotonic time at the start of the trace, because Android Studio
1054 // fetches the monotonic timer from other places and matches these times to
1055 // construct a cpu profile. See b/318052824 for more context.
1056 uint64_t start_time_monotonic = start_time_ + (MicroTime() - GetMicroTime(GetTimestamp()));
1057 uint16_t trace_version = GetTraceVersion(clock_source_, trace_format_version_);
1058 if (output_mode == TraceOutputMode::kStreaming) {
1059 trace_version |= 0xF0U;
1060 }
1061
1062 // Set up the beginning of the trace.
1063 if (trace_format_version_ == Trace::kFormatV1) {
1064 memset(buf_.get(), 0, kTraceHeaderLength);
1065 Append4LE(buf_.get(), kTraceMagicValue);
1066 Append2LE(buf_.get() + 4, trace_version);
1067 Append2LE(buf_.get() + 6, kTraceHeaderLength);
1068 Append8LE(buf_.get() + 8, start_time_monotonic);
1069 if (trace_version >= kTraceVersionDualClock) {
1070 uint16_t record_size = GetRecordSize(clock_source_, trace_format_version_);
1071 Append2LE(buf_.get() + 16, record_size);
1072 }
1073 static_assert(18 <= kMinBufSize, "Minimum buffer size not large enough for trace header");
1074
1075 cur_offset_ = kTraceHeaderLength;
1076 } else {
1077 memset(buf_.get(), 0, kTraceHeaderLengthV2);
1078 Append4LE(buf_.get(), kTraceMagicValue);
1079 Append2LE(buf_.get() + 4, trace_version);
1080 Append8LE(buf_.get() + 6, start_time_monotonic);
1081 cur_offset_ = kTraceHeaderLengthV2;
1082 }
1083
1084 if (output_mode == TraceOutputMode::kStreaming || trace_format_version_ == Trace::kFormatV2) {
1085 // Flush the header information to the file. We use a per thread buffer, so
1086 // it is easier to just write the header information directly to file.
1087 if (!trace_file_->WriteFully(buf_.get(), kTraceHeaderLength)) {
1088 PLOG(WARNING) << "Failed streaming a tracing event.";
1089 }
1090 cur_offset_ = 0;
1091 }
1092 // Thread index of 0 is a special identifier used to distinguish between trace
1093 // event entries and thread / method info entries.
1094 current_thread_index_ = 1;
1095
1096 // Don't create threadpool for a zygote. This would cause slowdown when forking because we need
1097 // to stop and start this thread pool. Method tracing on zygote isn't a frequent use case and
1098 // it is okay to flush on the main thread in such cases.
1099 if (!Runtime::Current()->IsZygote()) {
1100 thread_pool_.reset(TraceWriterThreadPool::Create("Trace writer pool"));
1101 thread_pool_->StartWorkers(Thread::Current());
1102 }
1103
1104 // Initialize the pool of per-thread buffers.
1105 InitializeTraceBuffers();
1106 }
1107
Trace(File * trace_file,size_t buffer_size,int flags,TraceOutputMode output_mode,TraceMode trace_mode)1108 Trace::Trace(File* trace_file,
1109 size_t buffer_size,
1110 int flags,
1111 TraceOutputMode output_mode,
1112 TraceMode trace_mode)
1113 : flags_(flags),
1114 trace_mode_(trace_mode),
1115 clock_source_(GetClockSourceFromFlags(flags)),
1116 interval_us_(0),
1117 stop_tracing_(false) {
1118 CHECK_IMPLIES(trace_file == nullptr, output_mode == TraceOutputMode::kDDMS);
1119
1120 int trace_format_version = GetTraceFormatVersionFromFlags(flags_);
1121 // In streaming mode, we only need a buffer big enough to store data per each
1122 // thread buffer. In non-streaming mode this is specified by the user and we
1123 // stop tracing when the buffer is full.
1124 size_t buf_size = (output_mode == TraceOutputMode::kStreaming) ?
1125 kPerThreadBufSize * kScalingFactorEncodedEntries :
1126 buffer_size;
1127 trace_writer_.reset(new TraceWriter(trace_file,
1128 output_mode,
1129 clock_source_,
1130 buf_size,
1131 kNumTracePoolBuffers,
1132 trace_format_version,
1133 GetClockOverheadNanoSeconds()));
1134 }
1135
CreateSummary(int flags)1136 std::string TraceWriter::CreateSummary(int flags) {
1137 std::ostringstream os;
1138 // Compute elapsed time.
1139 uint64_t elapsed = GetMicroTime(GetTimestamp()) - start_time_;
1140 os << StringPrintf("%cversion\n", kTraceTokenChar);
1141 os << StringPrintf("%d\n", GetTraceVersion(clock_source_, trace_format_version_));
1142 os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false");
1143 if (UseThreadCpuClock(clock_source_)) {
1144 if (UseWallClock(clock_source_)) {
1145 os << StringPrintf("clock=dual\n");
1146 } else {
1147 os << StringPrintf("clock=thread-cpu\n");
1148 }
1149 } else {
1150 os << StringPrintf("clock=wall\n");
1151 }
1152 os << StringPrintf("elapsed-time-usec=%" PRIu64 "\n", elapsed);
1153 if (trace_output_mode_ != TraceOutputMode::kStreaming) {
1154 os << StringPrintf("num-method-calls=%zd\n", num_records_);
1155 }
1156 os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead_ns_);
1157 os << StringPrintf("vm=art\n");
1158 os << StringPrintf("pid=%d\n", getpid());
1159 if ((flags & Trace::kTraceCountAllocs) != 0) {
1160 os << "alloc-count=" << Runtime::Current()->GetStat(KIND_ALLOCATED_OBJECTS) << "\n";
1161 os << "alloc-size=" << Runtime::Current()->GetStat(KIND_ALLOCATED_BYTES) << "\n";
1162 os << "gc-count=" << Runtime::Current()->GetStat(KIND_GC_INVOCATIONS) << "\n";
1163 }
1164
1165 if (trace_format_version_ == Trace::kFormatV1) {
1166 os << StringPrintf("%cthreads\n", kTraceTokenChar);
1167 DumpThreadList(os);
1168 os << StringPrintf("%cmethods\n", kTraceTokenChar);
1169 DumpMethodList(os);
1170 }
1171 os << StringPrintf("%cend\n", kTraceTokenChar);
1172 return os.str();
1173 }
1174
FinishTracing(int flags,bool flush_entries)1175 void TraceWriter::FinishTracing(int flags, bool flush_entries) {
1176 Thread* self = Thread::Current();
1177
1178 if (!flush_entries) {
1179 // This is only called from the child process post fork to abort the trace.
1180 // We shouldn't have any workers in the thread pool here.
1181 DCHECK_EQ(thread_pool_, nullptr);
1182 trace_file_->MarkUnchecked(); // Do not trigger guard.
1183 if (trace_file_->Close() != 0) {
1184 PLOG(ERROR) << "Could not close trace file.";
1185 }
1186 return;
1187 }
1188
1189 if (thread_pool_ != nullptr) {
1190 // Wait for any workers to be created. If we are stopping tracing as a part of runtime
1191 // shutdown, any unstarted workers can create problems if they try attaching while shutting
1192 // down.
1193 thread_pool_->WaitForWorkersToBeCreated();
1194 // Wait for any outstanding writer tasks to finish. Let the thread pool worker finish the
1195 // tasks to avoid any re-ordering when processing tasks.
1196 thread_pool_->Wait(self, /* do_work= */ false, /* may_hold_locks= */ true);
1197 DCHECK_EQ(thread_pool_->GetTaskCount(self), 0u);
1198 thread_pool_->StopWorkers(self);
1199 }
1200
1201 size_t final_offset = 0;
1202 if (trace_output_mode_ != TraceOutputMode::kStreaming) {
1203 MutexLock mu(Thread::Current(), trace_writer_lock_);
1204 final_offset = cur_offset_;
1205 }
1206
1207 std::string summary = CreateSummary(flags);
1208 if (trace_format_version_ == Trace::kFormatV1) {
1209 if (trace_output_mode_ == TraceOutputMode::kStreaming) {
1210 DCHECK_NE(trace_file_.get(), nullptr);
1211 // It is expected that this method is called when all other threads are suspended, so there
1212 // cannot be any writes to trace_file_ after finish tracing.
1213 // Write a special token to mark the end of trace records and the start of
1214 // trace summary.
1215 uint8_t buf[7];
1216 Append2LE(buf, 0);
1217 buf[2] = kOpTraceSummary;
1218 Append4LE(buf + 3, static_cast<uint32_t>(summary.length()));
1219 // Write the trace summary. The summary is identical to the file header when
1220 // the output mode is not streaming (except for methods).
1221 if (!trace_file_->WriteFully(buf, sizeof(buf)) ||
1222 !trace_file_->WriteFully(summary.c_str(), summary.length())) {
1223 PLOG(WARNING) << "Failed streaming a tracing event.";
1224 }
1225 } else if (trace_output_mode_ == TraceOutputMode::kFile) {
1226 DCHECK_NE(trace_file_.get(), nullptr);
1227 if (!trace_file_->WriteFully(summary.c_str(), summary.length()) ||
1228 !trace_file_->WriteFully(buf_.get(), final_offset)) {
1229 std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno)));
1230 PLOG(ERROR) << detail;
1231 ThrowRuntimeException("%s", detail.c_str());
1232 }
1233 } else {
1234 DCHECK_EQ(trace_file_.get(), nullptr);
1235 DCHECK(trace_output_mode_ == TraceOutputMode::kDDMS);
1236 std::vector<uint8_t> data;
1237 data.resize(summary.length() + final_offset);
1238 memcpy(data.data(), summary.c_str(), summary.length());
1239 memcpy(data.data() + summary.length(), buf_.get(), final_offset);
1240 Runtime::Current()->GetRuntimeCallbacks()->DdmPublishChunk(CHUNK_TYPE("MPSE"),
1241 ArrayRef<const uint8_t>(data));
1242 }
1243 } else {
1244 DCHECK(trace_format_version_ == Trace::kFormatV2);
1245 DCHECK(trace_output_mode_ != TraceOutputMode::kDDMS);
1246
1247 if (trace_output_mode_ == TraceOutputMode::kFile) {
1248 if (!trace_file_->WriteFully(buf_.get(), final_offset)) {
1249 PLOG(WARNING) << "Failed to write trace output";
1250 }
1251 }
1252
1253 // Write the summary packet
1254 uint8_t buf[3];
1255 buf[0] = kSummaryHeaderV2;
1256 Append2LE(buf + 1, static_cast<uint32_t>(summary.length()));
1257 // Write the trace summary. Reports information about tracing mode, number of records and
1258 // clock overhead in plain text format.
1259 if (!trace_file_->WriteFully(buf, sizeof(buf)) ||
1260 !trace_file_->WriteFully(summary.c_str(), summary.length())) {
1261 PLOG(WARNING) << "Failed streaming a tracing event.";
1262 }
1263 }
1264
1265 if (trace_file_.get() != nullptr) {
1266 // Do not try to erase, so flush and close explicitly.
1267 if (trace_file_->Flush() != 0) {
1268 PLOG(WARNING) << "Could not flush trace file.";
1269 }
1270 if (trace_file_->Close() != 0) {
1271 PLOG(ERROR) << "Could not close trace file.";
1272 }
1273 }
1274 }
1275
DexPcMoved(Thread * thread,Handle<mirror::Object> this_object,ArtMethod * method,uint32_t new_dex_pc)1276 void Trace::DexPcMoved([[maybe_unused]] Thread* thread,
1277 [[maybe_unused]] Handle<mirror::Object> this_object,
1278 ArtMethod* method,
1279 uint32_t new_dex_pc) {
1280 // We're not recorded to listen to this kind of event, so complain.
1281 LOG(ERROR) << "Unexpected dex PC event in tracing " << ArtMethod::PrettyMethod(method)
1282 << " " << new_dex_pc;
1283 }
1284
FieldRead(Thread * thread,Handle<mirror::Object> this_object,ArtMethod * method,uint32_t dex_pc,ArtField * field)1285 void Trace::FieldRead([[maybe_unused]] Thread* thread,
1286 [[maybe_unused]] Handle<mirror::Object> this_object,
1287 ArtMethod* method,
1288 uint32_t dex_pc,
1289 [[maybe_unused]] ArtField* field) REQUIRES_SHARED(Locks::mutator_lock_) {
1290 // We're not recorded to listen to this kind of event, so complain.
1291 LOG(ERROR) << "Unexpected field read event in tracing " << ArtMethod::PrettyMethod(method)
1292 << " " << dex_pc;
1293 }
1294
FieldWritten(Thread * thread,Handle<mirror::Object> this_object,ArtMethod * method,uint32_t dex_pc,ArtField * field,const JValue & field_value)1295 void Trace::FieldWritten([[maybe_unused]] Thread* thread,
1296 [[maybe_unused]] Handle<mirror::Object> this_object,
1297 ArtMethod* method,
1298 uint32_t dex_pc,
1299 [[maybe_unused]] ArtField* field,
1300 [[maybe_unused]] const JValue& field_value)
1301 REQUIRES_SHARED(Locks::mutator_lock_) {
1302 // We're not recorded to listen to this kind of event, so complain.
1303 LOG(ERROR) << "Unexpected field write event in tracing " << ArtMethod::PrettyMethod(method)
1304 << " " << dex_pc;
1305 }
1306
MethodEntered(Thread * thread,ArtMethod * method)1307 void Trace::MethodEntered(Thread* thread, ArtMethod* method) {
1308 uint32_t thread_clock_diff = 0;
1309 uint64_t timestamp_counter = 0;
1310 ReadClocks(thread, &thread_clock_diff, ×tamp_counter);
1311 LogMethodTraceEvent(thread, method, kTraceMethodEnter, thread_clock_diff, timestamp_counter);
1312 }
1313
MethodExited(Thread * thread,ArtMethod * method,instrumentation::OptionalFrame frame,JValue & return_value)1314 void Trace::MethodExited(Thread* thread,
1315 ArtMethod* method,
1316 [[maybe_unused]] instrumentation::OptionalFrame frame,
1317 [[maybe_unused]] JValue& return_value) {
1318 uint32_t thread_clock_diff = 0;
1319 uint64_t timestamp_counter = 0;
1320 ReadClocks(thread, &thread_clock_diff, ×tamp_counter);
1321 LogMethodTraceEvent(thread, method, kTraceMethodExit, thread_clock_diff, timestamp_counter);
1322 }
1323
MethodUnwind(Thread * thread,ArtMethod * method,uint32_t dex_pc)1324 void Trace::MethodUnwind(Thread* thread, ArtMethod* method, [[maybe_unused]] uint32_t dex_pc) {
1325 uint32_t thread_clock_diff = 0;
1326 uint64_t timestamp_counter = 0;
1327 ReadClocks(thread, &thread_clock_diff, ×tamp_counter);
1328 LogMethodTraceEvent(thread, method, kTraceUnroll, thread_clock_diff, timestamp_counter);
1329 }
1330
ExceptionThrown(Thread * thread,Handle<mirror::Throwable> exception_object)1331 void Trace::ExceptionThrown([[maybe_unused]] Thread* thread,
1332 [[maybe_unused]] Handle<mirror::Throwable> exception_object)
1333 REQUIRES_SHARED(Locks::mutator_lock_) {
1334 LOG(ERROR) << "Unexpected exception thrown event in tracing";
1335 }
1336
ExceptionHandled(Thread * thread,Handle<mirror::Throwable> exception_object)1337 void Trace::ExceptionHandled([[maybe_unused]] Thread* thread,
1338 [[maybe_unused]] Handle<mirror::Throwable> exception_object)
1339 REQUIRES_SHARED(Locks::mutator_lock_) {
1340 LOG(ERROR) << "Unexpected exception thrown event in tracing";
1341 }
1342
Branch(Thread *,ArtMethod * method,uint32_t,int32_t)1343 void Trace::Branch(Thread* /*thread*/, ArtMethod* method,
1344 uint32_t /*dex_pc*/, int32_t /*dex_pc_offset*/)
1345 REQUIRES_SHARED(Locks::mutator_lock_) {
1346 LOG(ERROR) << "Unexpected branch event in tracing" << ArtMethod::PrettyMethod(method);
1347 }
1348
WatchedFramePop(Thread * self,const ShadowFrame & frame)1349 void Trace::WatchedFramePop([[maybe_unused]] Thread* self,
1350 [[maybe_unused]] const ShadowFrame& frame) {
1351 LOG(ERROR) << "Unexpected WatchedFramePop event in tracing";
1352 }
1353
ReadClocks(Thread * thread,uint32_t * thread_clock_diff,uint64_t * timestamp_counter)1354 void Trace::ReadClocks(Thread* thread, uint32_t* thread_clock_diff, uint64_t* timestamp_counter) {
1355 if (UseThreadCpuClock(clock_source_)) {
1356 uint64_t clock_base = thread->GetTraceClockBase();
1357 if (UNLIKELY(clock_base == 0)) {
1358 // First event, record the base time in the map.
1359 uint64_t time = thread->GetCpuMicroTime();
1360 thread->SetTraceClockBase(time);
1361 } else {
1362 *thread_clock_diff = thread->GetCpuMicroTime() - clock_base;
1363 }
1364 }
1365 if (UseWallClock(clock_source_)) {
1366 *timestamp_counter = GetTimestamp();
1367 }
1368 }
1369
GetMethodLine(const std::string & method_line,uint32_t method_index)1370 std::string TraceWriter::GetMethodLine(const std::string& method_line, uint32_t method_index) {
1371 return StringPrintf("%#x\t%s", (method_index << TraceActionBits), method_line.c_str());
1372 }
1373
GetMethodInfoLine(ArtMethod * method)1374 std::string TraceWriter::GetMethodInfoLine(ArtMethod* method) {
1375 method = method->GetInterfaceMethodIfProxy(kRuntimePointerSize);
1376 return StringPrintf("%s\t%s\t%s\t%s\n",
1377 PrettyDescriptor(method->GetDeclaringClassDescriptor()).c_str(),
1378 method->GetName(),
1379 method->GetSignature().ToString().c_str(),
1380 method->GetDeclaringClassSourceFile());
1381 }
1382
RecordThreadInfo(Thread * thread)1383 void TraceWriter::RecordThreadInfo(Thread* thread) {
1384 // This is the first event from this thread, so first record information about the thread.
1385 std::string thread_name;
1386 thread->GetThreadName(thread_name);
1387
1388 // In tests, we destroy VM after already detaching the current thread. We re-attach the current
1389 // thread again as a "Shutdown thread" during the process of shutting down. So don't record
1390 // information about shutdown threads since it overwrites the actual thread_name.
1391 if (thread_name.compare("Shutdown thread") == 0) {
1392 return;
1393 }
1394
1395 MutexLock mu(Thread::Current(), trace_writer_lock_);
1396 if (trace_format_version_ == Trace::kFormatV1 &&
1397 trace_output_mode_ != TraceOutputMode::kStreaming) {
1398 threads_list_.Overwrite(GetThreadEncoding(thread->GetTid()), thread_name);
1399 return;
1400 }
1401
1402 static constexpr size_t kThreadNameHeaderSize = 7;
1403 uint8_t header[kThreadNameHeaderSize];
1404 if (trace_format_version_ == Trace::kFormatV1) {
1405 Append2LE(header, 0);
1406 header[2] = kOpNewThread;
1407 Append2LE(header + 3, GetThreadEncoding(thread->GetTid()));
1408 } else {
1409 header[0] = kThreadInfoHeaderV2;
1410 Append4LE(header + 1, thread->GetTid());
1411 }
1412 DCHECK(thread_name.length() < (1 << 16));
1413 Append2LE(header + 5, static_cast<uint16_t>(thread_name.length()));
1414
1415 if (!trace_file_->WriteFully(header, kThreadNameHeaderSize) ||
1416 !trace_file_->WriteFully(reinterpret_cast<const uint8_t*>(thread_name.c_str()),
1417 thread_name.length())) {
1418 PLOG(WARNING) << "Failed streaming a tracing event.";
1419 }
1420 }
1421
PreProcessTraceForMethodInfos(uintptr_t * method_trace_entries,size_t current_offset,std::unordered_map<ArtMethod *,std::string> & method_infos)1422 void TraceWriter::PreProcessTraceForMethodInfos(
1423 uintptr_t* method_trace_entries,
1424 size_t current_offset,
1425 std::unordered_map<ArtMethod*, std::string>& method_infos) {
1426 // Compute the method infos before we process the entries. We don't want to assign an encoding
1427 // for the method here. The expectation is that once we assign a method id we write it to the
1428 // file before any other thread can see the method id. So we should assign method encoding while
1429 // holding the trace_writer_lock_ and not release it till we flush the method info to the file. We
1430 // don't want to flush entries to file while holding the mutator lock. We need the mutator lock to
1431 // get method info. So we just precompute method infos without assigning a method encoding here.
1432 // There may be a race and multiple threads computing the method info but only one of them would
1433 // actually put into the method_id_map_.
1434 MutexLock mu(Thread::Current(), trace_writer_lock_);
1435 size_t num_entries = GetNumEntries(clock_source_);
1436 DCHECK_EQ((kPerThreadBufSize - current_offset) % num_entries, 0u);
1437 for (size_t entry_index = kPerThreadBufSize; entry_index != current_offset;) {
1438 entry_index -= num_entries;
1439 uintptr_t method_and_action = method_trace_entries[entry_index];
1440 ArtMethod* method = reinterpret_cast<ArtMethod*>(method_and_action & kMaskTraceAction);
1441 if (!HasMethodEncoding(method) && method_infos.find(method) == method_infos.end()) {
1442 method_infos.emplace(method, GetMethodInfoLine(method));
1443 }
1444 }
1445 }
1446
RecordMethodInfoV1(const std::string & method_info_line,uint64_t method_id)1447 void TraceWriter::RecordMethodInfoV1(const std::string& method_info_line, uint64_t method_id) {
1448 // Write a special block with the name.
1449 std::string method_line;
1450 size_t header_size;
1451 static constexpr size_t kMethodNameHeaderSize = 5;
1452 DCHECK_LT(kMethodNameHeaderSize, kPerThreadBufSize);
1453 uint8_t method_header[kMethodNameHeaderSize];
1454 uint16_t method_line_length = static_cast<uint16_t>(method_line.length());
1455 DCHECK(method_line.length() < (1 << 16));
1456 // Write a special block with the name.
1457 Append2LE(method_header, 0);
1458 method_header[2] = kOpNewMethod;
1459 method_line = GetMethodLine(method_info_line, method_id);
1460 method_line_length = static_cast<uint16_t>(method_line.length());
1461 Append2LE(method_header + 3, method_line_length);
1462 header_size = kMethodNameHeaderSize;
1463
1464 const uint8_t* ptr = reinterpret_cast<const uint8_t*>(method_line.c_str());
1465 if (!trace_file_->WriteFully(method_header, header_size) ||
1466 !trace_file_->WriteFully(ptr, method_line_length)) {
1467 PLOG(WARNING) << "Failed streaming a tracing event.";
1468 }
1469 }
1470
FlushAllThreadBuffers()1471 void TraceWriter::FlushAllThreadBuffers() {
1472 ScopedThreadStateChange stsc(Thread::Current(), ThreadState::kSuspended);
1473 ScopedSuspendAll ssa(__FUNCTION__);
1474 {
1475 MutexLock mu(Thread::Current(), *Locks::thread_list_lock_);
1476 for (Thread* thread : Runtime::Current()->GetThreadList()->GetList()) {
1477 if (thread->GetMethodTraceBuffer() != nullptr) {
1478 FlushBuffer(thread, /* is_sync= */ true, /* free_buffer= */ false);
1479 // We cannot flush anynore data, so just break.
1480 if (overflow_) {
1481 break;
1482 }
1483 }
1484 }
1485 }
1486 Trace::RemoveListeners();
1487 return;
1488 }
1489
PrepareBufferForNewEntries(Thread * thread)1490 uintptr_t* TraceWriter::PrepareBufferForNewEntries(Thread* thread) {
1491 if (trace_output_mode_ == TraceOutputMode::kStreaming) {
1492 // In streaming mode, just flush the per-thread buffer and reuse the
1493 // existing buffer for new entries.
1494 FlushBuffer(thread, /* is_sync= */ false, /* free_buffer= */ false);
1495 DCHECK_EQ(overflow_, false);
1496 } else {
1497 // For non-streaming mode, flush all the threads to check if we have space in the common
1498 // buffer to record any future events.
1499 FlushAllThreadBuffers();
1500 }
1501 if (overflow_) {
1502 return nullptr;
1503 }
1504 return thread->GetMethodTraceBuffer();
1505 }
1506
InitializeTraceBuffers()1507 void TraceWriter::InitializeTraceBuffers() {
1508 for (size_t i = 0; i < owner_tids_.size(); i++) {
1509 owner_tids_[i].store(0);
1510 }
1511
1512 trace_buffer_.reset(new uintptr_t[kPerThreadBufSize * owner_tids_.size()]);
1513 CHECK(trace_buffer_.get() != nullptr);
1514 }
1515
AcquireTraceBuffer(size_t tid)1516 uintptr_t* TraceWriter::AcquireTraceBuffer(size_t tid) {
1517 Thread* self = Thread::Current();
1518
1519 // Fast path, check if there is a free buffer in the pool
1520 for (size_t index = 0; index < owner_tids_.size(); index++) {
1521 size_t owner = 0;
1522 if (owner_tids_[index].compare_exchange_strong(owner, tid)) {
1523 return trace_buffer_.get() + index * kPerThreadBufSize;
1524 }
1525 }
1526
1527 // Increment a counter so we know how many threads are potentially suspended in the tracing code.
1528 // We need this when stopping tracing. We need to wait for all these threads to finish executing
1529 // this code so we can safely delete the trace related data.
1530 num_waiters_for_buffer_.fetch_add(1);
1531
1532 uintptr_t* buffer = nullptr;
1533 // If finish_tracing_ is set to true we shouldn't suspend ourselves. So check for finish_tracing_
1534 // before the thread suspension. As an example, consider the following:
1535 // T2 is looking for a free buffer in the loop above
1536 // T1 calls stop tracing -> Sets finish_tracing_ to true -> Checks that there are no waiters ->
1537 // Waiting to suspend all threads.
1538 // T2 doesn't find a buffer.
1539 // If T2 suspends before checking for finish_tracing_ there is a possibility T1 succeeds entering
1540 // SuspendAllScope while thread T2 is still in the TraceWriter code.
1541 // To avoid this, we increment the num_waiters_for_buffer and then check for finish_tracing
1542 // before suspending the thread. StopTracing sets finish_tracing_ to true first and then checks
1543 // for num_waiters_for_buffer. Both these are atomic variables and we use sequential consistency
1544 // (acquire for load and release for stores), so all threads see the updates for these variables
1545 // in the same order. That ensures we don't suspend in the tracing logic after Trace::StopTracing
1546 // has returned. This is required so that we can safely delete tracing data.
1547 if (self->IsThreadSuspensionAllowable() && !finish_tracing_.load()) {
1548 ScopedThreadSuspension sts(self, ThreadState::kSuspended);
1549 while (1) {
1550 MutexLock mu(self, buffer_pool_lock_);
1551 // Tracing is being stopped, so don't wait for a free buffer. Just return early.
1552 if (finish_tracing_.load()) {
1553 break;
1554 }
1555
1556 // Check if there's a free buffer in the pool
1557 for (size_t index = 0; index < owner_tids_.size(); index++) {
1558 size_t owner = 0;
1559 if (owner_tids_[index].compare_exchange_strong(owner, tid)) {
1560 buffer = trace_buffer_.get() + index * kPerThreadBufSize;
1561 break;
1562 }
1563 }
1564
1565 // Found a buffer
1566 if (buffer != nullptr) {
1567 break;
1568 }
1569
1570 if (thread_pool_ == nullptr ||
1571 (thread_pool_->GetTaskCount(self) < num_waiters_for_buffer_.load())) {
1572 // We have fewer buffers than active threads, just allocate a new one.
1573 break;
1574 }
1575
1576 buffer_available_.WaitHoldingLocks(self);
1577 }
1578 }
1579
1580 // The thread is no longer in the suspend scope, so decrement the counter.
1581 num_waiters_for_buffer_.fetch_sub(1);
1582 if (num_waiters_for_buffer_.load() == 0 && finish_tracing_.load()) {
1583 MutexLock mu(self, buffer_pool_lock_);
1584 num_waiters_zero_cond_.Broadcast(self);
1585 }
1586
1587 if (buffer == nullptr) {
1588 // Allocate a new buffer. We either don't want to wait or have too few buffers.
1589 buffer = new uintptr_t[kPerThreadBufSize];
1590 CHECK(buffer != nullptr);
1591 }
1592 return buffer;
1593 }
1594
StopTracing()1595 void TraceWriter::StopTracing() {
1596 Thread* self = Thread::Current();
1597 MutexLock mu(self, buffer_pool_lock_);
1598 finish_tracing_.store(true);
1599 while (num_waiters_for_buffer_.load() != 0) {
1600 buffer_available_.Broadcast(self);
1601 num_waiters_zero_cond_.WaitHoldingLocks(self);
1602 }
1603 }
1604
ReleaseBuffer(int index)1605 void TraceWriter::ReleaseBuffer(int index) {
1606 // Only the trace_writer_ thread can release the buffer.
1607 MutexLock mu(Thread::Current(), buffer_pool_lock_);
1608 if (index != -1) {
1609 owner_tids_[index].store(0);
1610 }
1611 buffer_available_.Signal(Thread::Current());
1612 }
1613
ReleaseBufferForThread(Thread * self)1614 void TraceWriter::ReleaseBufferForThread(Thread* self) {
1615 uintptr_t* buffer = self->GetMethodTraceBuffer();
1616 int index = GetMethodTraceIndex(buffer);
1617 if (index == -1) {
1618 delete[] buffer;
1619 } else {
1620 ReleaseBuffer(index);
1621 }
1622 }
1623
GetMethodTraceIndex(uintptr_t * current_buffer)1624 int TraceWriter::GetMethodTraceIndex(uintptr_t* current_buffer) {
1625 if (current_buffer < trace_buffer_.get() ||
1626 current_buffer > trace_buffer_.get() + (owner_tids_.size() - 1) * kPerThreadBufSize) {
1627 // This was the temporary buffer we allocated.
1628 return -1;
1629 }
1630 return (current_buffer - trace_buffer_.get()) / kPerThreadBufSize;
1631 }
1632
FlushBuffer(Thread * thread,bool is_sync,bool release)1633 void TraceWriter::FlushBuffer(Thread* thread, bool is_sync, bool release) {
1634 uintptr_t* method_trace_entries = thread->GetMethodTraceBuffer();
1635 uintptr_t** current_entry_ptr = thread->GetTraceBufferCurrEntryPtr();
1636 size_t current_offset = *current_entry_ptr - method_trace_entries;
1637 size_t tid = thread->GetTid();
1638 DCHECK(method_trace_entries != nullptr);
1639
1640 if (is_sync || thread_pool_ == nullptr) {
1641 std::unordered_map<ArtMethod*, std::string> method_infos;
1642 if (trace_format_version_ == Trace::kFormatV1) {
1643 PreProcessTraceForMethodInfos(method_trace_entries, current_offset, method_infos);
1644 }
1645 FlushBuffer(method_trace_entries, current_offset, tid, method_infos);
1646
1647 // This is a synchronous flush, so no need to allocate a new buffer. This is used either
1648 // when the tracing has finished or in non-streaming mode.
1649 // Just reset the buffer pointer to the initial value, so we can reuse the same buffer.
1650 if (release) {
1651 thread->SetMethodTraceBuffer(nullptr, 0);
1652 } else {
1653 thread->SetMethodTraceBufferCurrentEntry(kPerThreadBufSize);
1654 }
1655 } else {
1656 int old_index = GetMethodTraceIndex(method_trace_entries);
1657 // The TraceWriterTask takes the ownership of the buffer and releases the buffer once the
1658 // entries are flushed.
1659 thread_pool_->AddTask(
1660 Thread::Current(),
1661 new TraceEntriesWriterTask(this, old_index, method_trace_entries, current_offset, tid));
1662 if (release) {
1663 thread->SetMethodTraceBuffer(nullptr, 0);
1664 } else {
1665 thread->SetMethodTraceBuffer(AcquireTraceBuffer(tid), kPerThreadBufSize);
1666 }
1667 }
1668
1669 return;
1670 }
1671
ReadValuesFromRecord(uintptr_t * method_trace_entries,size_t record_index,MethodTraceRecord & record,bool has_thread_cpu_clock,bool has_wall_clock)1672 void TraceWriter::ReadValuesFromRecord(uintptr_t* method_trace_entries,
1673 size_t record_index,
1674 MethodTraceRecord& record,
1675 bool has_thread_cpu_clock,
1676 bool has_wall_clock) {
1677 uintptr_t method_and_action = method_trace_entries[record_index++];
1678 record.method = reinterpret_cast<ArtMethod*>(method_and_action & kMaskTraceAction);
1679 CHECK(record.method != nullptr);
1680 record.action = DecodeTraceAction(method_and_action);
1681
1682 record.thread_cpu_time = 0;
1683 record.wall_clock_time = 0;
1684 if (has_thread_cpu_clock) {
1685 record.thread_cpu_time = method_trace_entries[record_index++];
1686 }
1687 if (has_wall_clock) {
1688 uint64_t timestamp = method_trace_entries[record_index++];
1689 if (art::kRuntimePointerSize == PointerSize::k32) {
1690 // On 32-bit architectures timestamp is stored as two 32-bit values.
1691 uint64_t high_timestamp = method_trace_entries[record_index++];
1692 timestamp = (high_timestamp << 32 | timestamp);
1693 }
1694 record.wall_clock_time = GetMicroTime(timestamp) - start_time_;
1695 }
1696 }
1697
FlushEntriesFormatV1(uintptr_t * method_trace_entries,size_t tid,const std::unordered_map<ArtMethod *,std::string> & method_infos,size_t end_offset,size_t * current_index,uint8_t * buffer_ptr)1698 void TraceWriter::FlushEntriesFormatV1(
1699 uintptr_t* method_trace_entries,
1700 size_t tid,
1701 const std::unordered_map<ArtMethod*, std::string>& method_infos,
1702 size_t end_offset,
1703 size_t* current_index,
1704 uint8_t* buffer_ptr) {
1705 uint16_t thread_id = GetThreadEncoding(tid);
1706 bool has_thread_cpu_clock = UseThreadCpuClock(clock_source_);
1707 bool has_wall_clock = UseWallClock(clock_source_);
1708 size_t buffer_index = *current_index;
1709 size_t num_entries = GetNumEntries(clock_source_);
1710 const size_t record_size = GetRecordSize(clock_source_, trace_format_version_);
1711
1712 for (size_t entry_index = kPerThreadBufSize; entry_index != end_offset;) {
1713 entry_index -= num_entries;
1714
1715 MethodTraceRecord record;
1716 ReadValuesFromRecord(
1717 method_trace_entries, entry_index, record, has_thread_cpu_clock, has_wall_clock);
1718
1719 auto [method_id, is_new_method] = GetMethodEncoding(record.method);
1720 if (is_new_method && trace_output_mode_ == TraceOutputMode::kStreaming) {
1721 RecordMethodInfoV1(method_infos.find(record.method)->second, method_id);
1722 }
1723
1724 DCHECK_LT(buffer_index + record_size, buffer_size_);
1725 EncodeEventEntry(buffer_ptr + buffer_index,
1726 thread_id,
1727 method_id,
1728 record.action,
1729 record.thread_cpu_time,
1730 record.wall_clock_time);
1731 buffer_index += record_size;
1732 }
1733 *current_index = buffer_index;
1734 }
1735
FlushEntriesFormatV2(uintptr_t * method_trace_entries,size_t tid,size_t num_records,size_t * current_index,uint8_t * init_buffer_ptr)1736 void TraceWriter::FlushEntriesFormatV2(
1737 uintptr_t* method_trace_entries,
1738 size_t tid,
1739 size_t num_records,
1740 size_t* current_index,
1741 uint8_t* init_buffer_ptr) {
1742 uint8_t* current_buffer_ptr = init_buffer_ptr;
1743
1744 EncodeEventBlockHeader(current_buffer_ptr, tid, num_records);
1745 current_buffer_ptr += kEntryHeaderSizeV2;
1746
1747 bool has_thread_cpu_clock = UseThreadCpuClock(clock_source_);
1748 bool has_wall_clock = UseWallClock(clock_source_);
1749 size_t num_entries = GetNumEntries(clock_source_);
1750 uint32_t prev_wall_timestamp = 0;
1751 uint32_t prev_thread_timestamp = 0;
1752 uint64_t prev_method_action_encoding = 0;
1753 size_t entry_index = kPerThreadBufSize;
1754 for (size_t i = 0; i < num_records; i++) {
1755 entry_index -= num_entries;
1756
1757 MethodTraceRecord record;
1758 ReadValuesFromRecord(
1759 method_trace_entries, entry_index, record, has_thread_cpu_clock, has_wall_clock);
1760
1761 // TODO(mythria): Explore the possibility of using method pointer instead of having an encoding.
1762 // On 64-bit this means method ids would use 8 bytes but that is okay since we only encode the
1763 // full method id in the header and then encode the diff against the method id in the header.
1764 // The diff is usually expected to be small.
1765 uint64_t method_id = reinterpret_cast<uintptr_t>(record.method);
1766 uint64_t method_action_encoding = method_id | record.action;
1767
1768 int64_t method_diff = method_action_encoding - prev_method_action_encoding;
1769 current_buffer_ptr = EncodeSignedLeb128(current_buffer_ptr, method_diff);
1770 prev_method_action_encoding = method_action_encoding;
1771
1772 if (has_wall_clock) {
1773 current_buffer_ptr =
1774 EncodeUnsignedLeb128(current_buffer_ptr, (record.wall_clock_time - prev_wall_timestamp));
1775 prev_wall_timestamp = record.wall_clock_time;
1776 }
1777
1778 if (has_thread_cpu_clock) {
1779 current_buffer_ptr = EncodeUnsignedLeb128(current_buffer_ptr,
1780 (record.thread_cpu_time - prev_thread_timestamp));
1781 prev_thread_timestamp = record.thread_cpu_time;
1782 }
1783 }
1784
1785 // Update the total size of the block excluding header size.
1786 uint8_t* total_size_loc = init_buffer_ptr + kEntryHeaderSizeV2 - 4;
1787 Append4LE(total_size_loc, current_buffer_ptr - (init_buffer_ptr + kEntryHeaderSizeV2));
1788 *current_index += current_buffer_ptr - init_buffer_ptr;
1789 }
1790
FlushBuffer(uintptr_t * method_trace_entries,size_t current_offset,size_t tid,const std::unordered_map<ArtMethod *,std::string> & method_infos)1791 void TraceWriter::FlushBuffer(uintptr_t* method_trace_entries,
1792 size_t current_offset,
1793 size_t tid,
1794 const std::unordered_map<ArtMethod*, std::string>& method_infos) {
1795 // Take a trace_writer_lock_ to serialize writes across threads. We also need to allocate a unique
1796 // method id for each method. We do that by maintaining a map from id to method for each newly
1797 // seen method. trace_writer_lock_ is required to serialize these.
1798 MutexLock mu(Thread::Current(), trace_writer_lock_);
1799 size_t current_index = 0;
1800 uint8_t* buffer_ptr = buf_.get();
1801 size_t buffer_size = buffer_size_;
1802
1803 size_t num_entries = GetNumEntries(clock_source_);
1804 size_t num_records = (kPerThreadBufSize - current_offset) / num_entries;
1805 DCHECK_EQ((kPerThreadBufSize - current_offset) % num_entries, 0u);
1806 const size_t record_size = GetRecordSize(clock_source_, trace_format_version_);
1807 DCHECK_LT(record_size, kPerThreadBufSize);
1808
1809 if (trace_output_mode_ != TraceOutputMode::kStreaming) {
1810 // In non-streaming mode we only flush to file at the end, so retain the earlier data. If the
1811 // buffer is full we don't process any more entries.
1812 current_index = cur_offset_;
1813
1814 // Check if there is sufficient place in the buffer for non-streaming case. If not return early.
1815 if (cur_offset_ + record_size * num_records >= buffer_size) {
1816 overflow_ = true;
1817 return;
1818 }
1819 }
1820 num_records_ += num_records;
1821
1822 DCHECK_GT(buffer_size_, record_size * num_entries);
1823 if (trace_format_version_ == Trace::kFormatV1) {
1824 FlushEntriesFormatV1(
1825 method_trace_entries, tid, method_infos, current_offset, ¤t_index, buffer_ptr);
1826 } else {
1827 FlushEntriesFormatV2(
1828 method_trace_entries, tid, num_records, ¤t_index, buffer_ptr + current_index);
1829 }
1830
1831 if (trace_output_mode_ == TraceOutputMode::kStreaming) {
1832 // Flush the contents of buffer to file.
1833 if (!trace_file_->WriteFully(buffer_ptr, current_index)) {
1834 PLOG(WARNING) << "Failed streaming a tracing event.";
1835 }
1836 } else {
1837 // In non-streaming mode, we keep the data in the buffer and write to the
1838 // file when tracing has stopped. Just updated the offset of the buffer.
1839 cur_offset_ = current_index;
1840 }
1841 return;
1842 }
1843
LogMethodTraceEvent(Thread * thread,ArtMethod * method,TraceAction action,uint32_t thread_clock_diff,uint64_t timestamp_counter)1844 void Trace::LogMethodTraceEvent(Thread* thread,
1845 ArtMethod* method,
1846 TraceAction action,
1847 uint32_t thread_clock_diff,
1848 uint64_t timestamp_counter) {
1849 // This method is called in both tracing modes (method and sampling). In sampling mode, this
1850 // method is only called by the sampling thread. In method tracing mode, it can be called
1851 // concurrently.
1852
1853 uintptr_t* method_trace_buffer = thread->GetMethodTraceBuffer();
1854 uintptr_t** current_entry_ptr = thread->GetTraceBufferCurrEntryPtr();
1855 // Initialize the buffer lazily. It's just simpler to keep the creation at one place.
1856 if (method_trace_buffer == nullptr) {
1857 method_trace_buffer = trace_writer_->AcquireTraceBuffer(thread->GetTid());
1858 DCHECK(method_trace_buffer != nullptr);
1859 thread->SetMethodTraceBuffer(method_trace_buffer, kPerThreadBufSize);
1860 trace_writer_->RecordThreadInfo(thread);
1861 }
1862
1863 if (trace_writer_->HasOverflow()) {
1864 // In non-streaming modes, we stop recoding events once the buffer is full. Just reset the
1865 // index, so we don't go to runtime for each method.
1866 thread->SetMethodTraceBufferCurrentEntry(kPerThreadBufSize);
1867 return;
1868 }
1869
1870 size_t required_entries = GetNumEntries(clock_source_);
1871 if (*current_entry_ptr - required_entries < method_trace_buffer) {
1872 // This returns nullptr in non-streaming mode if there's an overflow and we cannot record any
1873 // more entries. In streaming mode, it returns nullptr if it fails to allocate a new buffer.
1874 method_trace_buffer = trace_writer_->PrepareBufferForNewEntries(thread);
1875 if (method_trace_buffer == nullptr) {
1876 thread->SetMethodTraceBufferCurrentEntry(kPerThreadBufSize);
1877 return;
1878 }
1879 }
1880 *current_entry_ptr = *current_entry_ptr - required_entries;
1881
1882 // Record entry in per-thread trace buffer.
1883 int entry_index = 0;
1884 uintptr_t* current_entry = *current_entry_ptr;
1885 // Ensure we always use the non-obsolete version of the method so that entry/exit events have the
1886 // same pointer value.
1887 method = method->GetNonObsoleteMethod();
1888 current_entry[entry_index++] = reinterpret_cast<uintptr_t>(method) | action;
1889 if (UseThreadCpuClock(clock_source_)) {
1890 current_entry[entry_index++] = thread_clock_diff;
1891 }
1892 if (UseWallClock(clock_source_)) {
1893 if (art::kRuntimePointerSize == PointerSize::k32) {
1894 // On 32-bit architectures store timestamp counter as two 32-bit values.
1895 current_entry[entry_index++] = static_cast<uint32_t>(timestamp_counter);
1896 current_entry[entry_index++] = timestamp_counter >> 32;
1897 } else {
1898 current_entry[entry_index++] = timestamp_counter;
1899 }
1900 }
1901 }
1902
EncodeEventEntry(uint8_t * ptr,uint16_t thread_id,uint32_t method_index,TraceAction action,uint32_t thread_clock_diff,uint32_t wall_clock_diff)1903 void TraceWriter::EncodeEventEntry(uint8_t* ptr,
1904 uint16_t thread_id,
1905 uint32_t method_index,
1906 TraceAction action,
1907 uint32_t thread_clock_diff,
1908 uint32_t wall_clock_diff) {
1909 static constexpr size_t kPacketSize = 14U; // The maximum size of data in a packet.
1910 DCHECK(method_index < (1 << (32 - TraceActionBits)));
1911 uint32_t method_value = (method_index << TraceActionBits) | action;
1912 Append2LE(ptr, thread_id);
1913 Append4LE(ptr + 2, method_value);
1914 ptr += 6;
1915
1916 if (UseThreadCpuClock(clock_source_)) {
1917 Append4LE(ptr, thread_clock_diff);
1918 ptr += 4;
1919 }
1920 if (UseWallClock(clock_source_)) {
1921 Append4LE(ptr, wall_clock_diff);
1922 }
1923 static_assert(kPacketSize == 2 + 4 + 4 + 4, "Packet size incorrect.");
1924 }
1925
EncodeEventBlockHeader(uint8_t * ptr,uint32_t thread_id,uint32_t num_records)1926 void TraceWriter::EncodeEventBlockHeader(uint8_t* ptr, uint32_t thread_id, uint32_t num_records) {
1927 ptr[0] = kEntryHeaderV2;
1928 Append4LE(ptr + 1, thread_id);
1929 // This specifies the total number of records encoded in the block using lebs.
1930 DCHECK_LT(num_records, 1u << 24);
1931 Append3LE(ptr + 5, num_records);
1932 }
1933
EnsureSpace(uint8_t * buffer,size_t * current_index,size_t buffer_size,size_t required_size)1934 void TraceWriter::EnsureSpace(uint8_t* buffer,
1935 size_t* current_index,
1936 size_t buffer_size,
1937 size_t required_size) {
1938 if (*current_index + required_size < buffer_size) {
1939 return;
1940 }
1941
1942 if (!trace_file_->WriteFully(buffer, *current_index)) {
1943 PLOG(WARNING) << "Failed streaming a tracing event.";
1944 }
1945 *current_index = 0;
1946 }
1947
DumpMethodList(std::ostream & os)1948 void TraceWriter::DumpMethodList(std::ostream& os) {
1949 MutexLock mu(Thread::Current(), trace_writer_lock_);
1950 for (auto const& entry : art_method_id_map_) {
1951 os << GetMethodLine(GetMethodInfoLine(entry.first), entry.second);
1952 }
1953 }
1954
DumpThreadList(std::ostream & os)1955 void TraceWriter::DumpThreadList(std::ostream& os) {
1956 MutexLock mu(Thread::Current(), trace_writer_lock_);
1957 for (const auto& it : threads_list_) {
1958 os << it.first << "\t" << it.second << "\n";
1959 }
1960 }
1961
GetOutputMode()1962 TraceOutputMode Trace::GetOutputMode() {
1963 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1964 CHECK(the_trace_ != nullptr) << "Trace output mode requested, but no trace currently running";
1965 return the_trace_->trace_writer_->GetOutputMode();
1966 }
1967
GetMode()1968 Trace::TraceMode Trace::GetMode() {
1969 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1970 CHECK(the_trace_ != nullptr) << "Trace mode requested, but no trace currently running";
1971 return the_trace_->trace_mode_;
1972 }
1973
GetFlags()1974 int Trace::GetFlags() {
1975 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1976 CHECK(the_trace_ != nullptr) << "Trace flags requested, but no trace currently running";
1977 return the_trace_->flags_;
1978 }
1979
GetIntervalInMillis()1980 int Trace::GetIntervalInMillis() {
1981 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1982 CHECK(the_trace_ != nullptr) << "Trace interval requested, but no trace currently running";
1983 return the_trace_->interval_us_;
1984 }
1985
GetBufferSize()1986 size_t Trace::GetBufferSize() {
1987 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1988 CHECK(the_trace_ != nullptr) << "Trace buffer size requested, but no trace currently running";
1989 return the_trace_->trace_writer_->GetBufferSize();
1990 }
1991
IsTracingEnabled()1992 bool Trace::IsTracingEnabled() {
1993 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1994 return the_trace_ != nullptr;
1995 }
1996
IsTracingEnabledLocked()1997 bool Trace::IsTracingEnabledLocked() {
1998 return the_trace_ != nullptr;
1999 }
2000
2001 } // namespace art
2002