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