• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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, &timestamp_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, &timestamp_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, &timestamp_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, &timestamp_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