trace.cc revision e45b3b18c97ba00ec2c0b79c9cda9f05799189f3 
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/stringprintf.h"
23
24#include "art_method-inl.h"
25#include "base/casts.h"
26#include "base/enums.h"
27#include "base/stl_util.h"
28#include "base/systrace.h"
29#include "base/time_utils.h"
30#include "base/unix_file/fd_file.h"
31#include "class_linker.h"
32#include "common_throws.h"
33#include "debugger.h"
34#include "dex/descriptors_names.h"
35#include "dex/dex_file-inl.h"
36#include "entrypoints/quick/quick_entrypoints.h"
37#include "gc/scoped_gc_critical_section.h"
38#include "instrumentation.h"
39#include "mirror/class-inl.h"
40#include "mirror/dex_cache-inl.h"
41#include "mirror/object-inl.h"
42#include "mirror/object_array-inl.h"
43#include "nativehelper/scoped_local_ref.h"
44#include "os.h"
45#include "scoped_thread_state_change-inl.h"
46#include "stack.h"
47#include "thread.h"
48#include "thread_list.h"
49#include "utils.h"
50
51namespace art {
52
53using android::base::StringPrintf;
54
55static constexpr size_t TraceActionBits = MinimumBitsToStore(
56    static_cast<size_t>(kTraceMethodActionMask));
57static constexpr uint8_t kOpNewMethod = 1U;
58static constexpr uint8_t kOpNewThread = 2U;
59static constexpr uint8_t kOpTraceSummary = 3U;
60
61class BuildStackTraceVisitor : public StackVisitor {
62 public:
63  explicit BuildStackTraceVisitor(Thread* thread)
64      : StackVisitor(thread, nullptr, StackVisitor::StackWalkKind::kIncludeInlinedFrames),
65        method_trace_(Trace::AllocStackTrace()) {}
66
67  bool VisitFrame() REQUIRES_SHARED(Locks::mutator_lock_) {
68    ArtMethod* m = GetMethod();
69    // Ignore runtime frames (in particular callee save).
70    if (!m->IsRuntimeMethod()) {
71      method_trace_->push_back(m);
72    }
73    return true;
74  }
75
76  // Returns a stack trace where the topmost frame corresponds with the first element of the vector.
77  std::vector<ArtMethod*>* GetStackTrace() const {
78    return method_trace_;
79  }
80
81 private:
82  std::vector<ArtMethod*>* const method_trace_;
83
84  DISALLOW_COPY_AND_ASSIGN(BuildStackTraceVisitor);
85};
86
87static const char     kTraceTokenChar             = '*';
88static const uint16_t kTraceHeaderLength          = 32;
89static const uint32_t kTraceMagicValue            = 0x574f4c53;
90static const uint16_t kTraceVersionSingleClock    = 2;
91static const uint16_t kTraceVersionDualClock      = 3;
92static const uint16_t kTraceRecordSizeSingleClock = 10;  // using v2
93static const uint16_t kTraceRecordSizeDualClock   = 14;  // using v3 with two timestamps
94
95TraceClockSource Trace::default_clock_source_ = kDefaultTraceClockSource;
96
97Trace* volatile Trace::the_trace_ = nullptr;
98pthread_t Trace::sampling_pthread_ = 0U;
99std::unique_ptr<std::vector<ArtMethod*>> Trace::temp_stack_trace_;
100
101// The key identifying the tracer to update instrumentation.
102static constexpr const char* kTracerInstrumentationKey = "Tracer";
103
104static TraceAction DecodeTraceAction(uint32_t tmid) {
105  return static_cast<TraceAction>(tmid & kTraceMethodActionMask);
106}
107
108ArtMethod* Trace::DecodeTraceMethod(uint32_t tmid) {
109  MutexLock mu(Thread::Current(), *unique_methods_lock_);
110  return unique_methods_[tmid >> TraceActionBits];
111}
112
113uint32_t Trace::EncodeTraceMethod(ArtMethod* method) {
114  MutexLock mu(Thread::Current(), *unique_methods_lock_);
115  uint32_t idx;
116  auto it = art_method_id_map_.find(method);
117  if (it != art_method_id_map_.end()) {
118    idx = it->second;
119  } else {
120    unique_methods_.push_back(method);
121    idx = unique_methods_.size() - 1;
122    art_method_id_map_.emplace(method, idx);
123  }
124  DCHECK_LT(idx, unique_methods_.size());
125  DCHECK_EQ(unique_methods_[idx], method);
126  return idx;
127}
128
129uint32_t Trace::EncodeTraceMethodAndAction(ArtMethod* method, TraceAction action) {
130  uint32_t tmid = (EncodeTraceMethod(method) << TraceActionBits) | action;
131  DCHECK_EQ(method, DecodeTraceMethod(tmid));
132  return tmid;
133}
134
135std::vector<ArtMethod*>* Trace::AllocStackTrace() {
136  return (temp_stack_trace_.get() != nullptr)  ? temp_stack_trace_.release() :
137      new std::vector<ArtMethod*>();
138}
139
140void Trace::FreeStackTrace(std::vector<ArtMethod*>* stack_trace) {
141  stack_trace->clear();
142  temp_stack_trace_.reset(stack_trace);
143}
144
145void Trace::SetDefaultClockSource(TraceClockSource clock_source) {
146#if defined(__linux__)
147  default_clock_source_ = clock_source;
148#else
149  if (clock_source != TraceClockSource::kWall) {
150    LOG(WARNING) << "Ignoring tracing request to use CPU time.";
151  }
152#endif
153}
154
155static uint16_t GetTraceVersion(TraceClockSource clock_source) {
156  return (clock_source == TraceClockSource::kDual) ? kTraceVersionDualClock
157                                                    : kTraceVersionSingleClock;
158}
159
160static uint16_t GetRecordSize(TraceClockSource clock_source) {
161  return (clock_source == TraceClockSource::kDual) ? kTraceRecordSizeDualClock
162                                                    : kTraceRecordSizeSingleClock;
163}
164
165bool Trace::UseThreadCpuClock() {
166  return (clock_source_ == TraceClockSource::kThreadCpu) ||
167      (clock_source_ == TraceClockSource::kDual);
168}
169
170bool Trace::UseWallClock() {
171  return (clock_source_ == TraceClockSource::kWall) ||
172      (clock_source_ == TraceClockSource::kDual);
173}
174
175void Trace::MeasureClockOverhead() {
176  if (UseThreadCpuClock()) {
177    Thread::Current()->GetCpuMicroTime();
178  }
179  if (UseWallClock()) {
180    MicroTime();
181  }
182}
183
184// Compute an average time taken to measure clocks.
185uint32_t Trace::GetClockOverheadNanoSeconds() {
186  Thread* self = Thread::Current();
187  uint64_t start = self->GetCpuMicroTime();
188
189  for (int i = 4000; i > 0; i--) {
190    MeasureClockOverhead();
191    MeasureClockOverhead();
192    MeasureClockOverhead();
193    MeasureClockOverhead();
194    MeasureClockOverhead();
195    MeasureClockOverhead();
196    MeasureClockOverhead();
197    MeasureClockOverhead();
198  }
199
200  uint64_t elapsed_us = self->GetCpuMicroTime() - start;
201  return static_cast<uint32_t>(elapsed_us / 32);
202}
203
204// TODO: put this somewhere with the big-endian equivalent used by JDWP.
205static void Append2LE(uint8_t* buf, uint16_t val) {
206  *buf++ = static_cast<uint8_t>(val);
207  *buf++ = static_cast<uint8_t>(val >> 8);
208}
209
210// TODO: put this somewhere with the big-endian equivalent used by JDWP.
211static void Append4LE(uint8_t* buf, uint32_t val) {
212  *buf++ = static_cast<uint8_t>(val);
213  *buf++ = static_cast<uint8_t>(val >> 8);
214  *buf++ = static_cast<uint8_t>(val >> 16);
215  *buf++ = static_cast<uint8_t>(val >> 24);
216}
217
218// TODO: put this somewhere with the big-endian equivalent used by JDWP.
219static void Append8LE(uint8_t* buf, uint64_t val) {
220  *buf++ = static_cast<uint8_t>(val);
221  *buf++ = static_cast<uint8_t>(val >> 8);
222  *buf++ = static_cast<uint8_t>(val >> 16);
223  *buf++ = static_cast<uint8_t>(val >> 24);
224  *buf++ = static_cast<uint8_t>(val >> 32);
225  *buf++ = static_cast<uint8_t>(val >> 40);
226  *buf++ = static_cast<uint8_t>(val >> 48);
227  *buf++ = static_cast<uint8_t>(val >> 56);
228}
229
230static void GetSample(Thread* thread, void* arg) REQUIRES_SHARED(Locks::mutator_lock_) {
231  BuildStackTraceVisitor build_trace_visitor(thread);
232  build_trace_visitor.WalkStack();
233  std::vector<ArtMethod*>* stack_trace = build_trace_visitor.GetStackTrace();
234  Trace* the_trace = reinterpret_cast<Trace*>(arg);
235  the_trace->CompareAndUpdateStackTrace(thread, stack_trace);
236}
237
238static void ClearThreadStackTraceAndClockBase(Thread* thread, void* arg ATTRIBUTE_UNUSED) {
239  thread->SetTraceClockBase(0);
240  std::vector<ArtMethod*>* stack_trace = thread->GetStackTraceSample();
241  thread->SetStackTraceSample(nullptr);
242  delete stack_trace;
243}
244
245void Trace::CompareAndUpdateStackTrace(Thread* thread,
246                                       std::vector<ArtMethod*>* stack_trace) {
247  CHECK_EQ(pthread_self(), sampling_pthread_);
248  std::vector<ArtMethod*>* old_stack_trace = thread->GetStackTraceSample();
249  // Update the thread's stack trace sample.
250  thread->SetStackTraceSample(stack_trace);
251  // Read timer clocks to use for all events in this trace.
252  uint32_t thread_clock_diff = 0;
253  uint32_t wall_clock_diff = 0;
254  ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
255  if (old_stack_trace == nullptr) {
256    // If there's no previous stack trace sample for this thread, log an entry event for all
257    // methods in the trace.
258    for (auto rit = stack_trace->rbegin(); rit != stack_trace->rend(); ++rit) {
259      LogMethodTraceEvent(thread, *rit, instrumentation::Instrumentation::kMethodEntered,
260                          thread_clock_diff, wall_clock_diff);
261    }
262  } else {
263    // If there's a previous stack trace for this thread, diff the traces and emit entry and exit
264    // events accordingly.
265    auto old_rit = old_stack_trace->rbegin();
266    auto rit = stack_trace->rbegin();
267    // Iterate bottom-up over both traces until there's a difference between them.
268    while (old_rit != old_stack_trace->rend() && rit != stack_trace->rend() && *old_rit == *rit) {
269      old_rit++;
270      rit++;
271    }
272    // Iterate top-down over the old trace until the point where they differ, emitting exit events.
273    for (auto old_it = old_stack_trace->begin(); old_it != old_rit.base(); ++old_it) {
274      LogMethodTraceEvent(thread, *old_it, instrumentation::Instrumentation::kMethodExited,
275                          thread_clock_diff, wall_clock_diff);
276    }
277    // Iterate bottom-up over the new trace from the point where they differ, emitting entry events.
278    for (; rit != stack_trace->rend(); ++rit) {
279      LogMethodTraceEvent(thread, *rit, instrumentation::Instrumentation::kMethodEntered,
280                          thread_clock_diff, wall_clock_diff);
281    }
282    FreeStackTrace(old_stack_trace);
283  }
284}
285
286void* Trace::RunSamplingThread(void* arg) {
287  Runtime* runtime = Runtime::Current();
288  intptr_t interval_us = reinterpret_cast<intptr_t>(arg);
289  CHECK_GE(interval_us, 0);
290  CHECK(runtime->AttachCurrentThread("Sampling Profiler", true, runtime->GetSystemThreadGroup(),
291                                     !runtime->IsAotCompiler()));
292
293  while (true) {
294    usleep(interval_us);
295    ScopedTrace trace("Profile sampling");
296    Thread* self = Thread::Current();
297    Trace* the_trace;
298    {
299      MutexLock mu(self, *Locks::trace_lock_);
300      the_trace = the_trace_;
301      if (the_trace == nullptr) {
302        break;
303      }
304    }
305    {
306      // Avoid a deadlock between a thread doing garbage collection
307      // and the profile sampling thread, by blocking GC when sampling
308      // thread stacks (see b/73624630).
309      gc::ScopedGCCriticalSection gcs(self,
310                                      art::gc::kGcCauseInstrumentation,
311                                      art::gc::kCollectorTypeInstrumentation);
312      ScopedSuspendAll ssa(__FUNCTION__);
313      MutexLock mu(self, *Locks::thread_list_lock_);
314      runtime->GetThreadList()->ForEach(GetSample, the_trace);
315    }
316  }
317
318  runtime->DetachCurrentThread();
319  return nullptr;
320}
321
322void Trace::Start(const char* trace_filename, int trace_fd, size_t buffer_size, int flags,
323                  TraceOutputMode output_mode, TraceMode trace_mode, int interval_us) {
324  Thread* self = Thread::Current();
325  {
326    MutexLock mu(self, *Locks::trace_lock_);
327    if (the_trace_ != nullptr) {
328      LOG(ERROR) << "Trace already in progress, ignoring this request";
329      return;
330    }
331  }
332
333  // Check interval if sampling is enabled
334  if (trace_mode == TraceMode::kSampling && interval_us <= 0) {
335    LOG(ERROR) << "Invalid sampling interval: " << interval_us;
336    ScopedObjectAccess soa(self);
337    ThrowRuntimeException("Invalid sampling interval: %d", interval_us);
338    return;
339  }
340
341  // Open trace file if not going directly to ddms.
342  std::unique_ptr<File> trace_file;
343  if (output_mode != TraceOutputMode::kDDMS) {
344    if (trace_fd < 0) {
345      trace_file.reset(OS::CreateEmptyFileWriteOnly(trace_filename));
346    } else {
347      trace_file.reset(new File(trace_fd, "tracefile"));
348      trace_file->DisableAutoClose();
349    }
350    if (trace_file.get() == nullptr) {
351      PLOG(ERROR) << "Unable to open trace file '" << trace_filename << "'";
352      ScopedObjectAccess soa(self);
353      ThrowRuntimeException("Unable to open trace file '%s'", trace_filename);
354      return;
355    }
356  }
357
358  Runtime* runtime = Runtime::Current();
359
360  // Enable count of allocs if specified in the flags.
361  bool enable_stats = false;
362
363  // Create Trace object.
364  {
365    // Required since EnableMethodTracing calls ConfigureStubs which visits class linker classes.
366    gc::ScopedGCCriticalSection gcs(self,
367                                    gc::kGcCauseInstrumentation,
368                                    gc::kCollectorTypeInstrumentation);
369    ScopedSuspendAll ssa(__FUNCTION__);
370    MutexLock mu(self, *Locks::trace_lock_);
371    if (the_trace_ != nullptr) {
372      LOG(ERROR) << "Trace already in progress, ignoring this request";
373    } else {
374      enable_stats = (flags && kTraceCountAllocs) != 0;
375      the_trace_ = new Trace(trace_file.release(), trace_filename, buffer_size, flags, output_mode,
376                             trace_mode);
377      if (trace_mode == TraceMode::kSampling) {
378        CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread,
379                                            reinterpret_cast<void*>(interval_us)),
380                                            "Sampling profiler thread");
381        the_trace_->interval_us_ = interval_us;
382      } else {
383        runtime->GetInstrumentation()->AddListener(the_trace_,
384                                                   instrumentation::Instrumentation::kMethodEntered |
385                                                   instrumentation::Instrumentation::kMethodExited |
386                                                   instrumentation::Instrumentation::kMethodUnwind);
387        // TODO: In full-PIC mode, we don't need to fully deopt.
388        runtime->GetInstrumentation()->EnableMethodTracing(kTracerInstrumentationKey);
389      }
390    }
391  }
392
393  // Can't call this when holding the mutator lock.
394  if (enable_stats) {
395    runtime->SetStatsEnabled(true);
396  }
397}
398
399void Trace::StopTracing(bool finish_tracing, bool flush_file) {
400  bool stop_alloc_counting = false;
401  Runtime* const runtime = Runtime::Current();
402  Trace* the_trace = nullptr;
403  Thread* const self = Thread::Current();
404  pthread_t sampling_pthread = 0U;
405  {
406    MutexLock mu(self, *Locks::trace_lock_);
407    if (the_trace_ == nullptr) {
408      LOG(ERROR) << "Trace stop requested, but no trace currently running";
409    } else {
410      the_trace = the_trace_;
411      the_trace_ = nullptr;
412      sampling_pthread = sampling_pthread_;
413    }
414  }
415  // Make sure that we join before we delete the trace since we don't want to have
416  // the sampling thread access a stale pointer. This finishes since the sampling thread exits when
417  // the_trace_ is null.
418  if (sampling_pthread != 0U) {
419    CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, nullptr), "sampling thread shutdown");
420    sampling_pthread_ = 0U;
421  }
422
423  if (the_trace != nullptr) {
424    stop_alloc_counting = (the_trace->flags_ & Trace::kTraceCountAllocs) != 0;
425    if (finish_tracing) {
426      the_trace->FinishTracing();
427    }
428    gc::ScopedGCCriticalSection gcs(self,
429                                    gc::kGcCauseInstrumentation,
430                                    gc::kCollectorTypeInstrumentation);
431    ScopedSuspendAll ssa(__FUNCTION__);
432
433    if (the_trace->trace_mode_ == TraceMode::kSampling) {
434      MutexLock mu(self, *Locks::thread_list_lock_);
435      runtime->GetThreadList()->ForEach(ClearThreadStackTraceAndClockBase, nullptr);
436    } else {
437      runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey);
438      runtime->GetInstrumentation()->RemoveListener(
439          the_trace, instrumentation::Instrumentation::kMethodEntered |
440          instrumentation::Instrumentation::kMethodExited |
441          instrumentation::Instrumentation::kMethodUnwind);
442    }
443    if (the_trace->trace_file_.get() != nullptr) {
444      // Do not try to erase, so flush and close explicitly.
445      if (flush_file) {
446        if (the_trace->trace_file_->Flush() != 0) {
447          PLOG(WARNING) << "Could not flush trace file.";
448        }
449      } else {
450        the_trace->trace_file_->MarkUnchecked();  // Do not trigger guard.
451      }
452      if (the_trace->trace_file_->Close() != 0) {
453        PLOG(ERROR) << "Could not close trace file.";
454      }
455    }
456    delete the_trace;
457  }
458  if (stop_alloc_counting) {
459    // Can be racy since SetStatsEnabled is not guarded by any locks.
460    runtime->SetStatsEnabled(false);
461  }
462}
463
464void Trace::Abort() {
465  // Do not write anything anymore.
466  StopTracing(false, false);
467}
468
469void Trace::Stop() {
470  // Finish writing.
471  StopTracing(true, true);
472}
473
474void Trace::Shutdown() {
475  if (GetMethodTracingMode() != kTracingInactive) {
476    Stop();
477  }
478}
479
480void Trace::Pause() {
481  bool stop_alloc_counting = false;
482  Runtime* runtime = Runtime::Current();
483  Trace* the_trace = nullptr;
484
485  Thread* const self = Thread::Current();
486  pthread_t sampling_pthread = 0U;
487  {
488    MutexLock mu(self, *Locks::trace_lock_);
489    if (the_trace_ == nullptr) {
490      LOG(ERROR) << "Trace pause requested, but no trace currently running";
491      return;
492    } else {
493      the_trace = the_trace_;
494      sampling_pthread = sampling_pthread_;
495    }
496  }
497
498  if (sampling_pthread != 0U) {
499    {
500      MutexLock mu(self, *Locks::trace_lock_);
501      the_trace_ = nullptr;
502    }
503    CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, nullptr), "sampling thread shutdown");
504    sampling_pthread_ = 0U;
505    {
506      MutexLock mu(self, *Locks::trace_lock_);
507      the_trace_ = the_trace;
508    }
509  }
510
511  if (the_trace != nullptr) {
512    gc::ScopedGCCriticalSection gcs(self,
513                                    gc::kGcCauseInstrumentation,
514                                    gc::kCollectorTypeInstrumentation);
515    ScopedSuspendAll ssa(__FUNCTION__);
516    stop_alloc_counting = (the_trace->flags_ & Trace::kTraceCountAllocs) != 0;
517
518    if (the_trace->trace_mode_ == TraceMode::kSampling) {
519      MutexLock mu(self, *Locks::thread_list_lock_);
520      runtime->GetThreadList()->ForEach(ClearThreadStackTraceAndClockBase, nullptr);
521    } else {
522      runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey);
523      runtime->GetInstrumentation()->RemoveListener(
524          the_trace,
525          instrumentation::Instrumentation::kMethodEntered |
526          instrumentation::Instrumentation::kMethodExited |
527          instrumentation::Instrumentation::kMethodUnwind);
528    }
529  }
530
531  if (stop_alloc_counting) {
532    // Can be racy since SetStatsEnabled is not guarded by any locks.
533    Runtime::Current()->SetStatsEnabled(false);
534  }
535}
536
537void Trace::Resume() {
538  Thread* self = Thread::Current();
539  Trace* the_trace;
540  {
541    MutexLock mu(self, *Locks::trace_lock_);
542    if (the_trace_ == nullptr) {
543      LOG(ERROR) << "No trace to resume (or sampling mode), ignoring this request";
544      return;
545    }
546    the_trace = the_trace_;
547  }
548
549  Runtime* runtime = Runtime::Current();
550
551  // Enable count of allocs if specified in the flags.
552  bool enable_stats = (the_trace->flags_ && kTraceCountAllocs) != 0;
553
554  {
555    gc::ScopedGCCriticalSection gcs(self,
556                                    gc::kGcCauseInstrumentation,
557                                    gc::kCollectorTypeInstrumentation);
558    ScopedSuspendAll ssa(__FUNCTION__);
559
560    // Reenable.
561    if (the_trace->trace_mode_ == TraceMode::kSampling) {
562      CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread,
563          reinterpret_cast<void*>(the_trace->interval_us_)), "Sampling profiler thread");
564    } else {
565      runtime->GetInstrumentation()->AddListener(the_trace,
566                                                 instrumentation::Instrumentation::kMethodEntered |
567                                                 instrumentation::Instrumentation::kMethodExited |
568                                                 instrumentation::Instrumentation::kMethodUnwind);
569      // TODO: In full-PIC mode, we don't need to fully deopt.
570      runtime->GetInstrumentation()->EnableMethodTracing(kTracerInstrumentationKey);
571    }
572  }
573
574  // Can't call this when holding the mutator lock.
575  if (enable_stats) {
576    runtime->SetStatsEnabled(true);
577  }
578}
579
580TracingMode Trace::GetMethodTracingMode() {
581  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
582  if (the_trace_ == nullptr) {
583    return kTracingInactive;
584  } else {
585    switch (the_trace_->trace_mode_) {
586      case TraceMode::kSampling:
587        return kSampleProfilingActive;
588      case TraceMode::kMethodTracing:
589        return kMethodTracingActive;
590    }
591    LOG(FATAL) << "Unreachable";
592    UNREACHABLE();
593  }
594}
595
596static constexpr size_t kMinBufSize = 18U;  // Trace header is up to 18B.
597
598Trace::Trace(File* trace_file, const char* trace_name, size_t buffer_size, int flags,
599             TraceOutputMode output_mode, TraceMode trace_mode)
600    : trace_file_(trace_file),
601      buf_(new uint8_t[std::max(kMinBufSize, buffer_size)]()),
602      flags_(flags), trace_output_mode_(output_mode), trace_mode_(trace_mode),
603      clock_source_(default_clock_source_),
604      buffer_size_(std::max(kMinBufSize, buffer_size)),
605      start_time_(MicroTime()), clock_overhead_ns_(GetClockOverheadNanoSeconds()), cur_offset_(0),
606      overflow_(false), interval_us_(0), streaming_lock_(nullptr),
607      unique_methods_lock_(new Mutex("unique methods lock", kTracingUniqueMethodsLock)) {
608  uint16_t trace_version = GetTraceVersion(clock_source_);
609  if (output_mode == TraceOutputMode::kStreaming) {
610    trace_version |= 0xF0U;
611  }
612  // Set up the beginning of the trace.
613  memset(buf_.get(), 0, kTraceHeaderLength);
614  Append4LE(buf_.get(), kTraceMagicValue);
615  Append2LE(buf_.get() + 4, trace_version);
616  Append2LE(buf_.get() + 6, kTraceHeaderLength);
617  Append8LE(buf_.get() + 8, start_time_);
618  if (trace_version >= kTraceVersionDualClock) {
619    uint16_t record_size = GetRecordSize(clock_source_);
620    Append2LE(buf_.get() + 16, record_size);
621  }
622  static_assert(18 <= kMinBufSize, "Minimum buffer size not large enough for trace header");
623
624  // Update current offset.
625  cur_offset_.StoreRelaxed(kTraceHeaderLength);
626
627  if (output_mode == TraceOutputMode::kStreaming) {
628    streaming_file_name_ = trace_name;
629    streaming_lock_ = new Mutex("tracing lock", LockLevel::kTracingStreamingLock);
630    seen_threads_.reset(new ThreadIDBitSet());
631  }
632}
633
634Trace::~Trace() {
635  delete streaming_lock_;
636  delete unique_methods_lock_;
637}
638
639static uint64_t ReadBytes(uint8_t* buf, size_t bytes) {
640  uint64_t ret = 0;
641  for (size_t i = 0; i < bytes; ++i) {
642    ret |= static_cast<uint64_t>(buf[i]) << (i * 8);
643  }
644  return ret;
645}
646
647void Trace::DumpBuf(uint8_t* buf, size_t buf_size, TraceClockSource clock_source) {
648  uint8_t* ptr = buf + kTraceHeaderLength;
649  uint8_t* end = buf + buf_size;
650
651  while (ptr < end) {
652    uint32_t tmid = ReadBytes(ptr + 2, sizeof(tmid));
653    ArtMethod* method = DecodeTraceMethod(tmid);
654    TraceAction action = DecodeTraceAction(tmid);
655    LOG(INFO) << ArtMethod::PrettyMethod(method) << " " << static_cast<int>(action);
656    ptr += GetRecordSize(clock_source);
657  }
658}
659
660void Trace::FinishTracing() {
661  size_t final_offset = 0;
662
663  std::set<ArtMethod*> visited_methods;
664  if (trace_output_mode_ == TraceOutputMode::kStreaming) {
665    // Clean up.
666    STLDeleteValues(&seen_methods_);
667  } else {
668    final_offset = cur_offset_.LoadRelaxed();
669    GetVisitedMethods(final_offset, &visited_methods);
670  }
671
672  // Compute elapsed time.
673  uint64_t elapsed = MicroTime() - start_time_;
674
675  std::ostringstream os;
676
677  os << StringPrintf("%cversion\n", kTraceTokenChar);
678  os << StringPrintf("%d\n", GetTraceVersion(clock_source_));
679  os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false");
680  if (UseThreadCpuClock()) {
681    if (UseWallClock()) {
682      os << StringPrintf("clock=dual\n");
683    } else {
684      os << StringPrintf("clock=thread-cpu\n");
685    }
686  } else {
687    os << StringPrintf("clock=wall\n");
688  }
689  os << StringPrintf("elapsed-time-usec=%" PRIu64 "\n", elapsed);
690  if (trace_output_mode_ != TraceOutputMode::kStreaming) {
691    size_t num_records = (final_offset - kTraceHeaderLength) / GetRecordSize(clock_source_);
692    os << StringPrintf("num-method-calls=%zd\n", num_records);
693  }
694  os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead_ns_);
695  os << StringPrintf("vm=art\n");
696  os << StringPrintf("pid=%d\n", getpid());
697  if ((flags_ & kTraceCountAllocs) != 0) {
698    os << StringPrintf("alloc-count=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_OBJECTS));
699    os << StringPrintf("alloc-size=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_BYTES));
700    os << StringPrintf("gc-count=%d\n", Runtime::Current()->GetStat(KIND_GC_INVOCATIONS));
701  }
702  os << StringPrintf("%cthreads\n", kTraceTokenChar);
703  DumpThreadList(os);
704  os << StringPrintf("%cmethods\n", kTraceTokenChar);
705  DumpMethodList(os, visited_methods);
706  os << StringPrintf("%cend\n", kTraceTokenChar);
707  std::string header(os.str());
708
709  if (trace_output_mode_ == TraceOutputMode::kStreaming) {
710    MutexLock mu(Thread::Current(), *streaming_lock_);  // To serialize writing.
711    // Write a special token to mark the end of trace records and the start of
712    // trace summary.
713    uint8_t buf[7];
714    Append2LE(buf, 0);
715    buf[2] = kOpTraceSummary;
716    Append4LE(buf + 3, static_cast<uint32_t>(header.length()));
717    WriteToBuf(buf, sizeof(buf));
718    // Write the trace summary. The summary is identical to the file header when
719    // the output mode is not streaming (except for methods).
720    WriteToBuf(reinterpret_cast<const uint8_t*>(header.c_str()), header.length());
721    // Flush the buffer, which may include some trace records before the summary.
722    FlushBuf();
723  } else {
724    if (trace_file_.get() == nullptr) {
725      std::vector<uint8_t> data;
726      data.resize(header.length() + final_offset);
727      memcpy(data.data(), header.c_str(), header.length());
728      memcpy(data.data() + header.length(), buf_.get(), final_offset);
729      Runtime::Current()->GetRuntimeCallbacks()->DdmPublishChunk(CHUNK_TYPE("MPSE"),
730                                                                 ArrayRef<const uint8_t>(data));
731      const bool kDumpTraceInfo = false;
732      if (kDumpTraceInfo) {
733        LOG(INFO) << "Trace sent:\n" << header;
734        DumpBuf(buf_.get(), final_offset, clock_source_);
735      }
736    } else {
737      if (!trace_file_->WriteFully(header.c_str(), header.length()) ||
738          !trace_file_->WriteFully(buf_.get(), final_offset)) {
739        std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno)));
740        PLOG(ERROR) << detail;
741        ThrowRuntimeException("%s", detail.c_str());
742      }
743    }
744  }
745}
746
747void Trace::DexPcMoved(Thread* thread ATTRIBUTE_UNUSED,
748                       Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
749                       ArtMethod* method,
750                       uint32_t new_dex_pc) {
751  // We're not recorded to listen to this kind of event, so complain.
752  LOG(ERROR) << "Unexpected dex PC event in tracing " << ArtMethod::PrettyMethod(method)
753             << " " << new_dex_pc;
754}
755
756void Trace::FieldRead(Thread* thread ATTRIBUTE_UNUSED,
757                      Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
758                      ArtMethod* method,
759                      uint32_t dex_pc,
760                      ArtField* field ATTRIBUTE_UNUSED)
761    REQUIRES_SHARED(Locks::mutator_lock_) {
762  // We're not recorded to listen to this kind of event, so complain.
763  LOG(ERROR) << "Unexpected field read event in tracing " << ArtMethod::PrettyMethod(method)
764             << " " << dex_pc;
765}
766
767void Trace::FieldWritten(Thread* thread ATTRIBUTE_UNUSED,
768                         Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
769                         ArtMethod* method,
770                         uint32_t dex_pc,
771                         ArtField* field ATTRIBUTE_UNUSED,
772                         const JValue& field_value ATTRIBUTE_UNUSED)
773    REQUIRES_SHARED(Locks::mutator_lock_) {
774  // We're not recorded to listen to this kind of event, so complain.
775  LOG(ERROR) << "Unexpected field write event in tracing " << ArtMethod::PrettyMethod(method)
776             << " " << dex_pc;
777}
778
779void Trace::MethodEntered(Thread* thread,
780                          Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
781                          ArtMethod* method,
782                          uint32_t dex_pc ATTRIBUTE_UNUSED) {
783  uint32_t thread_clock_diff = 0;
784  uint32_t wall_clock_diff = 0;
785  ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
786  LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodEntered,
787                      thread_clock_diff, wall_clock_diff);
788}
789
790void Trace::MethodExited(Thread* thread,
791                         Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
792                         ArtMethod* method,
793                         uint32_t dex_pc ATTRIBUTE_UNUSED,
794                         const JValue& return_value ATTRIBUTE_UNUSED) {
795  uint32_t thread_clock_diff = 0;
796  uint32_t wall_clock_diff = 0;
797  ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
798  LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodExited,
799                      thread_clock_diff, wall_clock_diff);
800}
801
802void Trace::MethodUnwind(Thread* thread,
803                         Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
804                         ArtMethod* method,
805                         uint32_t dex_pc ATTRIBUTE_UNUSED) {
806  uint32_t thread_clock_diff = 0;
807  uint32_t wall_clock_diff = 0;
808  ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
809  LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodUnwind,
810                      thread_clock_diff, wall_clock_diff);
811}
812
813void Trace::ExceptionThrown(Thread* thread ATTRIBUTE_UNUSED,
814                            Handle<mirror::Throwable> exception_object ATTRIBUTE_UNUSED)
815    REQUIRES_SHARED(Locks::mutator_lock_) {
816  LOG(ERROR) << "Unexpected exception thrown event in tracing";
817}
818
819void Trace::ExceptionHandled(Thread* thread ATTRIBUTE_UNUSED,
820                             Handle<mirror::Throwable> exception_object ATTRIBUTE_UNUSED)
821    REQUIRES_SHARED(Locks::mutator_lock_) {
822  LOG(ERROR) << "Unexpected exception thrown event in tracing";
823}
824
825void Trace::Branch(Thread* /*thread*/, ArtMethod* method,
826                   uint32_t /*dex_pc*/, int32_t /*dex_pc_offset*/)
827      REQUIRES_SHARED(Locks::mutator_lock_) {
828  LOG(ERROR) << "Unexpected branch event in tracing" << ArtMethod::PrettyMethod(method);
829}
830
831void Trace::InvokeVirtualOrInterface(Thread*,
832                                     Handle<mirror::Object>,
833                                     ArtMethod* method,
834                                     uint32_t dex_pc,
835                                     ArtMethod*) {
836  LOG(ERROR) << "Unexpected invoke event in tracing" << ArtMethod::PrettyMethod(method)
837             << " " << dex_pc;
838}
839
840void Trace::WatchedFramePop(Thread* self ATTRIBUTE_UNUSED,
841                            const ShadowFrame& frame ATTRIBUTE_UNUSED) {
842  LOG(ERROR) << "Unexpected WatchedFramePop event in tracing";
843}
844
845void Trace::ReadClocks(Thread* thread, uint32_t* thread_clock_diff, uint32_t* wall_clock_diff) {
846  if (UseThreadCpuClock()) {
847    uint64_t clock_base = thread->GetTraceClockBase();
848    if (UNLIKELY(clock_base == 0)) {
849      // First event, record the base time in the map.
850      uint64_t time = thread->GetCpuMicroTime();
851      thread->SetTraceClockBase(time);
852    } else {
853      *thread_clock_diff = thread->GetCpuMicroTime() - clock_base;
854    }
855  }
856  if (UseWallClock()) {
857    *wall_clock_diff = MicroTime() - start_time_;
858  }
859}
860
861bool Trace::RegisterMethod(ArtMethod* method) {
862  mirror::DexCache* dex_cache = method->GetDexCache();
863  const DexFile* dex_file = dex_cache->GetDexFile();
864  if (seen_methods_.find(dex_file) == seen_methods_.end()) {
865    seen_methods_.insert(std::make_pair(dex_file, new DexIndexBitSet()));
866  }
867  DexIndexBitSet* bit_set = seen_methods_.find(dex_file)->second;
868  if (!(*bit_set)[method->GetDexMethodIndex()]) {
869    bit_set->set(method->GetDexMethodIndex());
870    return true;
871  }
872  return false;
873}
874
875bool Trace::RegisterThread(Thread* thread) {
876  pid_t tid = thread->GetTid();
877  CHECK_LT(0U, static_cast<uint32_t>(tid));
878  CHECK_LT(static_cast<uint32_t>(tid), kMaxThreadIdNumber);
879
880  if (!(*seen_threads_)[tid]) {
881    seen_threads_->set(tid);
882    return true;
883  }
884  return false;
885}
886
887std::string Trace::GetMethodLine(ArtMethod* method) {
888  method = method->GetInterfaceMethodIfProxy(kRuntimePointerSize);
889  return StringPrintf("%#x\t%s\t%s\t%s\t%s\n", (EncodeTraceMethod(method) << TraceActionBits),
890      PrettyDescriptor(method->GetDeclaringClassDescriptor()).c_str(), method->GetName(),
891      method->GetSignature().ToString().c_str(), method->GetDeclaringClassSourceFile());
892}
893
894void Trace::WriteToBuf(const uint8_t* src, size_t src_size) {
895  int32_t old_offset = cur_offset_.LoadRelaxed();
896  int32_t new_offset = old_offset + static_cast<int32_t>(src_size);
897  if (dchecked_integral_cast<size_t>(new_offset) > buffer_size_) {
898    // Flush buffer.
899    if (!trace_file_->WriteFully(buf_.get(), old_offset)) {
900      PLOG(WARNING) << "Failed streaming a tracing event.";
901    }
902
903    // Check whether the data is too large for the buffer, then write immediately.
904    if (src_size >= buffer_size_) {
905      if (!trace_file_->WriteFully(src, src_size)) {
906        PLOG(WARNING) << "Failed streaming a tracing event.";
907      }
908      cur_offset_.StoreRelease(0);  // Buffer is empty now.
909      return;
910    }
911
912    old_offset = 0;
913    new_offset = static_cast<int32_t>(src_size);
914  }
915  cur_offset_.StoreRelease(new_offset);
916  // Fill in data.
917  memcpy(buf_.get() + old_offset, src, src_size);
918}
919
920void Trace::FlushBuf() {
921  int32_t offset = cur_offset_.LoadRelaxed();
922  if (!trace_file_->WriteFully(buf_.get(), offset)) {
923    PLOG(WARNING) << "Failed flush the remaining data in streaming.";
924  }
925  cur_offset_.StoreRelease(0);
926}
927
928void Trace::LogMethodTraceEvent(Thread* thread, ArtMethod* method,
929                                instrumentation::Instrumentation::InstrumentationEvent event,
930                                uint32_t thread_clock_diff, uint32_t wall_clock_diff) {
931  // Ensure we always use the non-obsolete version of the method so that entry/exit events have the
932  // same pointer value.
933  method = method->GetNonObsoleteMethod();
934  // Advance cur_offset_ atomically.
935  int32_t new_offset;
936  int32_t old_offset = 0;
937
938  // We do a busy loop here trying to acquire the next offset.
939  if (trace_output_mode_ != TraceOutputMode::kStreaming) {
940    do {
941      old_offset = cur_offset_.LoadRelaxed();
942      new_offset = old_offset + GetRecordSize(clock_source_);
943      if (static_cast<size_t>(new_offset) > buffer_size_) {
944        overflow_ = true;
945        return;
946      }
947    } while (!cur_offset_.CompareAndSetWeakSequentiallyConsistent(old_offset, new_offset));
948  }
949
950  TraceAction action = kTraceMethodEnter;
951  switch (event) {
952    case instrumentation::Instrumentation::kMethodEntered:
953      action = kTraceMethodEnter;
954      break;
955    case instrumentation::Instrumentation::kMethodExited:
956      action = kTraceMethodExit;
957      break;
958    case instrumentation::Instrumentation::kMethodUnwind:
959      action = kTraceUnroll;
960      break;
961    default:
962      UNIMPLEMENTED(FATAL) << "Unexpected event: " << event;
963  }
964
965  uint32_t method_value = EncodeTraceMethodAndAction(method, action);
966
967  // Write data
968  uint8_t* ptr;
969  static constexpr size_t kPacketSize = 14U;  // The maximum size of data in a packet.
970  uint8_t stack_buf[kPacketSize];             // Space to store a packet when in streaming mode.
971  if (trace_output_mode_ == TraceOutputMode::kStreaming) {
972    ptr = stack_buf;
973  } else {
974    ptr = buf_.get() + old_offset;
975  }
976
977  Append2LE(ptr, thread->GetTid());
978  Append4LE(ptr + 2, method_value);
979  ptr += 6;
980
981  if (UseThreadCpuClock()) {
982    Append4LE(ptr, thread_clock_diff);
983    ptr += 4;
984  }
985  if (UseWallClock()) {
986    Append4LE(ptr, wall_clock_diff);
987  }
988  static_assert(kPacketSize == 2 + 4 + 4 + 4, "Packet size incorrect.");
989
990  if (trace_output_mode_ == TraceOutputMode::kStreaming) {
991    MutexLock mu(Thread::Current(), *streaming_lock_);  // To serialize writing.
992    if (RegisterMethod(method)) {
993      // Write a special block with the name.
994      std::string method_line(GetMethodLine(method));
995      uint8_t buf2[5];
996      Append2LE(buf2, 0);
997      buf2[2] = kOpNewMethod;
998      Append2LE(buf2 + 3, static_cast<uint16_t>(method_line.length()));
999      WriteToBuf(buf2, sizeof(buf2));
1000      WriteToBuf(reinterpret_cast<const uint8_t*>(method_line.c_str()), method_line.length());
1001    }
1002    if (RegisterThread(thread)) {
1003      // It might be better to postpone this. Threads might not have received names...
1004      std::string thread_name;
1005      thread->GetThreadName(thread_name);
1006      uint8_t buf2[7];
1007      Append2LE(buf2, 0);
1008      buf2[2] = kOpNewThread;
1009      Append2LE(buf2 + 3, static_cast<uint16_t>(thread->GetTid()));
1010      Append2LE(buf2 + 5, static_cast<uint16_t>(thread_name.length()));
1011      WriteToBuf(buf2, sizeof(buf2));
1012      WriteToBuf(reinterpret_cast<const uint8_t*>(thread_name.c_str()), thread_name.length());
1013    }
1014    WriteToBuf(stack_buf, sizeof(stack_buf));
1015  }
1016}
1017
1018void Trace::GetVisitedMethods(size_t buf_size,
1019                              std::set<ArtMethod*>* visited_methods) {
1020  uint8_t* ptr = buf_.get() + kTraceHeaderLength;
1021  uint8_t* end = buf_.get() + buf_size;
1022
1023  while (ptr < end) {
1024    uint32_t tmid = ReadBytes(ptr + 2, sizeof(tmid));
1025    ArtMethod* method = DecodeTraceMethod(tmid);
1026    visited_methods->insert(method);
1027    ptr += GetRecordSize(clock_source_);
1028  }
1029}
1030
1031void Trace::DumpMethodList(std::ostream& os, const std::set<ArtMethod*>& visited_methods) {
1032  for (const auto& method : visited_methods) {
1033    os << GetMethodLine(method);
1034  }
1035}
1036
1037static void DumpThread(Thread* t, void* arg) {
1038  std::ostream& os = *reinterpret_cast<std::ostream*>(arg);
1039  std::string name;
1040  t->GetThreadName(name);
1041  os << t->GetTid() << "\t" << name << "\n";
1042}
1043
1044void Trace::DumpThreadList(std::ostream& os) {
1045  Thread* self = Thread::Current();
1046  for (auto it : exited_threads_) {
1047    os << it.first << "\t" << it.second << "\n";
1048  }
1049  Locks::thread_list_lock_->AssertNotHeld(self);
1050  MutexLock mu(self, *Locks::thread_list_lock_);
1051  Runtime::Current()->GetThreadList()->ForEach(DumpThread, &os);
1052}
1053
1054void Trace::StoreExitingThreadInfo(Thread* thread) {
1055  MutexLock mu(thread, *Locks::trace_lock_);
1056  if (the_trace_ != nullptr) {
1057    std::string name;
1058    thread->GetThreadName(name);
1059    // The same thread/tid may be used multiple times. As SafeMap::Put does not allow to override
1060    // a previous mapping, use SafeMap::Overwrite.
1061    the_trace_->exited_threads_.Overwrite(thread->GetTid(), name);
1062  }
1063}
1064
1065Trace::TraceOutputMode Trace::GetOutputMode() {
1066  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1067  CHECK(the_trace_ != nullptr) << "Trace output mode requested, but no trace currently running";
1068  return the_trace_->trace_output_mode_;
1069}
1070
1071Trace::TraceMode Trace::GetMode() {
1072  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1073  CHECK(the_trace_ != nullptr) << "Trace mode requested, but no trace currently running";
1074  return the_trace_->trace_mode_;
1075}
1076
1077size_t Trace::GetBufferSize() {
1078  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1079  CHECK(the_trace_ != nullptr) << "Trace mode requested, but no trace currently running";
1080  return the_trace_->buffer_size_;
1081}
1082
1083bool Trace::IsTracingEnabled() {
1084  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1085  return the_trace_ != nullptr;
1086}
1087
1088}  // namespace art
1089