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