trace.cc revision b2ec9f5c128673c43f776cbe12c8eeb0a6884ebb 
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      ScopedSuspendAll ssa(__FUNCTION__);
307      MutexLock mu(self, *Locks::thread_list_lock_);
308      runtime->GetThreadList()->ForEach(GetSample, the_trace);
309    }
310  }
311
312  runtime->DetachCurrentThread();
313  return nullptr;
314}
315
316void Trace::Start(const char* trace_filename, int trace_fd, size_t buffer_size, int flags,
317                  TraceOutputMode output_mode, TraceMode trace_mode, int interval_us) {
318  Thread* self = Thread::Current();
319  {
320    MutexLock mu(self, *Locks::trace_lock_);
321    if (the_trace_ != nullptr) {
322      LOG(ERROR) << "Trace already in progress, ignoring this request";
323      return;
324    }
325  }
326
327  // Check interval if sampling is enabled
328  if (trace_mode == TraceMode::kSampling && interval_us <= 0) {
329    LOG(ERROR) << "Invalid sampling interval: " << interval_us;
330    ScopedObjectAccess soa(self);
331    ThrowRuntimeException("Invalid sampling interval: %d", interval_us);
332    return;
333  }
334
335  // Open trace file if not going directly to ddms.
336  std::unique_ptr<File> trace_file;
337  if (output_mode != TraceOutputMode::kDDMS) {
338    if (trace_fd < 0) {
339      trace_file.reset(OS::CreateEmptyFileWriteOnly(trace_filename));
340    } else {
341      trace_file.reset(new File(trace_fd, "tracefile"));
342      trace_file->DisableAutoClose();
343    }
344    if (trace_file.get() == nullptr) {
345      PLOG(ERROR) << "Unable to open trace file '" << trace_filename << "'";
346      ScopedObjectAccess soa(self);
347      ThrowRuntimeException("Unable to open trace file '%s'", trace_filename);
348      return;
349    }
350  }
351
352  Runtime* runtime = Runtime::Current();
353
354  // Enable count of allocs if specified in the flags.
355  bool enable_stats = false;
356
357  // Create Trace object.
358  {
359    // Required since EnableMethodTracing calls ConfigureStubs which visits class linker classes.
360    gc::ScopedGCCriticalSection gcs(self,
361                                    gc::kGcCauseInstrumentation,
362                                    gc::kCollectorTypeInstrumentation);
363    ScopedSuspendAll ssa(__FUNCTION__);
364    MutexLock mu(self, *Locks::trace_lock_);
365    if (the_trace_ != nullptr) {
366      LOG(ERROR) << "Trace already in progress, ignoring this request";
367    } else {
368      enable_stats = (flags && kTraceCountAllocs) != 0;
369      the_trace_ = new Trace(trace_file.release(), trace_filename, buffer_size, flags, output_mode,
370                             trace_mode);
371      if (trace_mode == TraceMode::kSampling) {
372        CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread,
373                                            reinterpret_cast<void*>(interval_us)),
374                                            "Sampling profiler thread");
375        the_trace_->interval_us_ = interval_us;
376      } else {
377        runtime->GetInstrumentation()->AddListener(the_trace_,
378                                                   instrumentation::Instrumentation::kMethodEntered |
379                                                   instrumentation::Instrumentation::kMethodExited |
380                                                   instrumentation::Instrumentation::kMethodUnwind);
381        // TODO: In full-PIC mode, we don't need to fully deopt.
382        runtime->GetInstrumentation()->EnableMethodTracing(kTracerInstrumentationKey);
383      }
384    }
385  }
386
387  // Can't call this when holding the mutator lock.
388  if (enable_stats) {
389    runtime->SetStatsEnabled(true);
390  }
391}
392
393void Trace::StopTracing(bool finish_tracing, bool flush_file) {
394  bool stop_alloc_counting = false;
395  Runtime* const runtime = Runtime::Current();
396  Trace* the_trace = nullptr;
397  Thread* const self = Thread::Current();
398  pthread_t sampling_pthread = 0U;
399  {
400    MutexLock mu(self, *Locks::trace_lock_);
401    if (the_trace_ == nullptr) {
402      LOG(ERROR) << "Trace stop requested, but no trace currently running";
403    } else {
404      the_trace = the_trace_;
405      the_trace_ = nullptr;
406      sampling_pthread = sampling_pthread_;
407    }
408  }
409  // Make sure that we join before we delete the trace since we don't want to have
410  // the sampling thread access a stale pointer. This finishes since the sampling thread exits when
411  // the_trace_ is null.
412  if (sampling_pthread != 0U) {
413    CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, nullptr), "sampling thread shutdown");
414    sampling_pthread_ = 0U;
415  }
416
417  if (the_trace != nullptr) {
418    stop_alloc_counting = (the_trace->flags_ & Trace::kTraceCountAllocs) != 0;
419    if (finish_tracing) {
420      the_trace->FinishTracing();
421    }
422    gc::ScopedGCCriticalSection gcs(self,
423                                    gc::kGcCauseInstrumentation,
424                                    gc::kCollectorTypeInstrumentation);
425    ScopedSuspendAll ssa(__FUNCTION__);
426
427    if (the_trace->trace_mode_ == TraceMode::kSampling) {
428      MutexLock mu(self, *Locks::thread_list_lock_);
429      runtime->GetThreadList()->ForEach(ClearThreadStackTraceAndClockBase, nullptr);
430    } else {
431      runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey);
432      runtime->GetInstrumentation()->RemoveListener(
433          the_trace, instrumentation::Instrumentation::kMethodEntered |
434          instrumentation::Instrumentation::kMethodExited |
435          instrumentation::Instrumentation::kMethodUnwind);
436    }
437    if (the_trace->trace_file_.get() != nullptr) {
438      // Do not try to erase, so flush and close explicitly.
439      if (flush_file) {
440        if (the_trace->trace_file_->Flush() != 0) {
441          PLOG(WARNING) << "Could not flush trace file.";
442        }
443      } else {
444        the_trace->trace_file_->MarkUnchecked();  // Do not trigger guard.
445      }
446      if (the_trace->trace_file_->Close() != 0) {
447        PLOG(ERROR) << "Could not close trace file.";
448      }
449    }
450    delete the_trace;
451  }
452  if (stop_alloc_counting) {
453    // Can be racy since SetStatsEnabled is not guarded by any locks.
454    runtime->SetStatsEnabled(false);
455  }
456}
457
458void Trace::Abort() {
459  // Do not write anything anymore.
460  StopTracing(false, false);
461}
462
463void Trace::Stop() {
464  // Finish writing.
465  StopTracing(true, true);
466}
467
468void Trace::Shutdown() {
469  if (GetMethodTracingMode() != kTracingInactive) {
470    Stop();
471  }
472}
473
474void Trace::Pause() {
475  bool stop_alloc_counting = false;
476  Runtime* runtime = Runtime::Current();
477  Trace* the_trace = nullptr;
478
479  Thread* const self = Thread::Current();
480  pthread_t sampling_pthread = 0U;
481  {
482    MutexLock mu(self, *Locks::trace_lock_);
483    if (the_trace_ == nullptr) {
484      LOG(ERROR) << "Trace pause requested, but no trace currently running";
485      return;
486    } else {
487      the_trace = the_trace_;
488      sampling_pthread = sampling_pthread_;
489    }
490  }
491
492  if (sampling_pthread != 0U) {
493    {
494      MutexLock mu(self, *Locks::trace_lock_);
495      the_trace_ = nullptr;
496    }
497    CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, nullptr), "sampling thread shutdown");
498    sampling_pthread_ = 0U;
499    {
500      MutexLock mu(self, *Locks::trace_lock_);
501      the_trace_ = the_trace;
502    }
503  }
504
505  if (the_trace != nullptr) {
506    gc::ScopedGCCriticalSection gcs(self,
507                                    gc::kGcCauseInstrumentation,
508                                    gc::kCollectorTypeInstrumentation);
509    ScopedSuspendAll ssa(__FUNCTION__);
510    stop_alloc_counting = (the_trace->flags_ & Trace::kTraceCountAllocs) != 0;
511
512    if (the_trace->trace_mode_ == TraceMode::kSampling) {
513      MutexLock mu(self, *Locks::thread_list_lock_);
514      runtime->GetThreadList()->ForEach(ClearThreadStackTraceAndClockBase, nullptr);
515    } else {
516      runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey);
517      runtime->GetInstrumentation()->RemoveListener(
518          the_trace,
519          instrumentation::Instrumentation::kMethodEntered |
520          instrumentation::Instrumentation::kMethodExited |
521          instrumentation::Instrumentation::kMethodUnwind);
522    }
523  }
524
525  if (stop_alloc_counting) {
526    // Can be racy since SetStatsEnabled is not guarded by any locks.
527    Runtime::Current()->SetStatsEnabled(false);
528  }
529}
530
531void Trace::Resume() {
532  Thread* self = Thread::Current();
533  Trace* the_trace;
534  {
535    MutexLock mu(self, *Locks::trace_lock_);
536    if (the_trace_ == nullptr) {
537      LOG(ERROR) << "No trace to resume (or sampling mode), ignoring this request";
538      return;
539    }
540    the_trace = the_trace_;
541  }
542
543  Runtime* runtime = Runtime::Current();
544
545  // Enable count of allocs if specified in the flags.
546  bool enable_stats = (the_trace->flags_ && kTraceCountAllocs) != 0;
547
548  {
549    gc::ScopedGCCriticalSection gcs(self,
550                                    gc::kGcCauseInstrumentation,
551                                    gc::kCollectorTypeInstrumentation);
552    ScopedSuspendAll ssa(__FUNCTION__);
553
554    // Reenable.
555    if (the_trace->trace_mode_ == TraceMode::kSampling) {
556      CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread,
557          reinterpret_cast<void*>(the_trace->interval_us_)), "Sampling profiler thread");
558    } else {
559      runtime->GetInstrumentation()->AddListener(the_trace,
560                                                 instrumentation::Instrumentation::kMethodEntered |
561                                                 instrumentation::Instrumentation::kMethodExited |
562                                                 instrumentation::Instrumentation::kMethodUnwind);
563      // TODO: In full-PIC mode, we don't need to fully deopt.
564      runtime->GetInstrumentation()->EnableMethodTracing(kTracerInstrumentationKey);
565    }
566  }
567
568  // Can't call this when holding the mutator lock.
569  if (enable_stats) {
570    runtime->SetStatsEnabled(true);
571  }
572}
573
574TracingMode Trace::GetMethodTracingMode() {
575  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
576  if (the_trace_ == nullptr) {
577    return kTracingInactive;
578  } else {
579    switch (the_trace_->trace_mode_) {
580      case TraceMode::kSampling:
581        return kSampleProfilingActive;
582      case TraceMode::kMethodTracing:
583        return kMethodTracingActive;
584    }
585    LOG(FATAL) << "Unreachable";
586    UNREACHABLE();
587  }
588}
589
590static constexpr size_t kMinBufSize = 18U;  // Trace header is up to 18B.
591
592Trace::Trace(File* trace_file, const char* trace_name, size_t buffer_size, int flags,
593             TraceOutputMode output_mode, TraceMode trace_mode)
594    : trace_file_(trace_file),
595      buf_(new uint8_t[std::max(kMinBufSize, buffer_size)]()),
596      flags_(flags), trace_output_mode_(output_mode), trace_mode_(trace_mode),
597      clock_source_(default_clock_source_),
598      buffer_size_(std::max(kMinBufSize, buffer_size)),
599      start_time_(MicroTime()), clock_overhead_ns_(GetClockOverheadNanoSeconds()), cur_offset_(0),
600      overflow_(false), interval_us_(0), streaming_lock_(nullptr),
601      unique_methods_lock_(new Mutex("unique methods lock", kTracingUniqueMethodsLock)) {
602  uint16_t trace_version = GetTraceVersion(clock_source_);
603  if (output_mode == TraceOutputMode::kStreaming) {
604    trace_version |= 0xF0U;
605  }
606  // Set up the beginning of the trace.
607  memset(buf_.get(), 0, kTraceHeaderLength);
608  Append4LE(buf_.get(), kTraceMagicValue);
609  Append2LE(buf_.get() + 4, trace_version);
610  Append2LE(buf_.get() + 6, kTraceHeaderLength);
611  Append8LE(buf_.get() + 8, start_time_);
612  if (trace_version >= kTraceVersionDualClock) {
613    uint16_t record_size = GetRecordSize(clock_source_);
614    Append2LE(buf_.get() + 16, record_size);
615  }
616  static_assert(18 <= kMinBufSize, "Minimum buffer size not large enough for trace header");
617
618  // Update current offset.
619  cur_offset_.StoreRelaxed(kTraceHeaderLength);
620
621  if (output_mode == TraceOutputMode::kStreaming) {
622    streaming_file_name_ = trace_name;
623    streaming_lock_ = new Mutex("tracing lock", LockLevel::kTracingStreamingLock);
624    seen_threads_.reset(new ThreadIDBitSet());
625  }
626}
627
628Trace::~Trace() {
629  delete streaming_lock_;
630  delete unique_methods_lock_;
631}
632
633static uint64_t ReadBytes(uint8_t* buf, size_t bytes) {
634  uint64_t ret = 0;
635  for (size_t i = 0; i < bytes; ++i) {
636    ret |= static_cast<uint64_t>(buf[i]) << (i * 8);
637  }
638  return ret;
639}
640
641void Trace::DumpBuf(uint8_t* buf, size_t buf_size, TraceClockSource clock_source) {
642  uint8_t* ptr = buf + kTraceHeaderLength;
643  uint8_t* end = buf + buf_size;
644
645  while (ptr < end) {
646    uint32_t tmid = ReadBytes(ptr + 2, sizeof(tmid));
647    ArtMethod* method = DecodeTraceMethod(tmid);
648    TraceAction action = DecodeTraceAction(tmid);
649    LOG(INFO) << ArtMethod::PrettyMethod(method) << " " << static_cast<int>(action);
650    ptr += GetRecordSize(clock_source);
651  }
652}
653
654void Trace::FinishTracing() {
655  size_t final_offset = 0;
656
657  std::set<ArtMethod*> visited_methods;
658  if (trace_output_mode_ == TraceOutputMode::kStreaming) {
659    // Clean up.
660    STLDeleteValues(&seen_methods_);
661  } else {
662    final_offset = cur_offset_.LoadRelaxed();
663    GetVisitedMethods(final_offset, &visited_methods);
664  }
665
666  // Compute elapsed time.
667  uint64_t elapsed = MicroTime() - start_time_;
668
669  std::ostringstream os;
670
671  os << StringPrintf("%cversion\n", kTraceTokenChar);
672  os << StringPrintf("%d\n", GetTraceVersion(clock_source_));
673  os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false");
674  if (UseThreadCpuClock()) {
675    if (UseWallClock()) {
676      os << StringPrintf("clock=dual\n");
677    } else {
678      os << StringPrintf("clock=thread-cpu\n");
679    }
680  } else {
681    os << StringPrintf("clock=wall\n");
682  }
683  os << StringPrintf("elapsed-time-usec=%" PRIu64 "\n", elapsed);
684  if (trace_output_mode_ != TraceOutputMode::kStreaming) {
685    size_t num_records = (final_offset - kTraceHeaderLength) / GetRecordSize(clock_source_);
686    os << StringPrintf("num-method-calls=%zd\n", num_records);
687  }
688  os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead_ns_);
689  os << StringPrintf("vm=art\n");
690  os << StringPrintf("pid=%d\n", getpid());
691  if ((flags_ & kTraceCountAllocs) != 0) {
692    os << StringPrintf("alloc-count=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_OBJECTS));
693    os << StringPrintf("alloc-size=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_BYTES));
694    os << StringPrintf("gc-count=%d\n", Runtime::Current()->GetStat(KIND_GC_INVOCATIONS));
695  }
696  os << StringPrintf("%cthreads\n", kTraceTokenChar);
697  DumpThreadList(os);
698  os << StringPrintf("%cmethods\n", kTraceTokenChar);
699  DumpMethodList(os, visited_methods);
700  os << StringPrintf("%cend\n", kTraceTokenChar);
701  std::string header(os.str());
702
703  if (trace_output_mode_ == TraceOutputMode::kStreaming) {
704    MutexLock mu(Thread::Current(), *streaming_lock_);  // To serialize writing.
705    // Write a special token to mark the end of trace records and the start of
706    // trace summary.
707    uint8_t buf[7];
708    Append2LE(buf, 0);
709    buf[2] = kOpTraceSummary;
710    Append4LE(buf + 3, static_cast<uint32_t>(header.length()));
711    WriteToBuf(buf, sizeof(buf));
712    // Write the trace summary. The summary is identical to the file header when
713    // the output mode is not streaming (except for methods).
714    WriteToBuf(reinterpret_cast<const uint8_t*>(header.c_str()), header.length());
715    // Flush the buffer, which may include some trace records before the summary.
716    FlushBuf();
717  } else {
718    if (trace_file_.get() == nullptr) {
719      std::vector<uint8_t> data;
720      data.resize(header.length() + final_offset);
721      memcpy(data.data(), header.c_str(), header.length());
722      memcpy(data.data() + header.length(), buf_.get(), final_offset);
723      Runtime::Current()->GetRuntimeCallbacks()->DdmPublishChunk(CHUNK_TYPE("MPSE"),
724                                                                 ArrayRef<const uint8_t>(data));
725      const bool kDumpTraceInfo = false;
726      if (kDumpTraceInfo) {
727        LOG(INFO) << "Trace sent:\n" << header;
728        DumpBuf(buf_.get(), final_offset, clock_source_);
729      }
730    } else {
731      if (!trace_file_->WriteFully(header.c_str(), header.length()) ||
732          !trace_file_->WriteFully(buf_.get(), final_offset)) {
733        std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno)));
734        PLOG(ERROR) << detail;
735        ThrowRuntimeException("%s", detail.c_str());
736      }
737    }
738  }
739}
740
741void Trace::DexPcMoved(Thread* thread ATTRIBUTE_UNUSED,
742                       Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
743                       ArtMethod* method,
744                       uint32_t new_dex_pc) {
745  // We're not recorded to listen to this kind of event, so complain.
746  LOG(ERROR) << "Unexpected dex PC event in tracing " << ArtMethod::PrettyMethod(method)
747             << " " << new_dex_pc;
748}
749
750void Trace::FieldRead(Thread* thread ATTRIBUTE_UNUSED,
751                      Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
752                      ArtMethod* method,
753                      uint32_t dex_pc,
754                      ArtField* field ATTRIBUTE_UNUSED)
755    REQUIRES_SHARED(Locks::mutator_lock_) {
756  // We're not recorded to listen to this kind of event, so complain.
757  LOG(ERROR) << "Unexpected field read event in tracing " << ArtMethod::PrettyMethod(method)
758             << " " << dex_pc;
759}
760
761void Trace::FieldWritten(Thread* thread ATTRIBUTE_UNUSED,
762                         Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
763                         ArtMethod* method,
764                         uint32_t dex_pc,
765                         ArtField* field ATTRIBUTE_UNUSED,
766                         const JValue& field_value ATTRIBUTE_UNUSED)
767    REQUIRES_SHARED(Locks::mutator_lock_) {
768  // We're not recorded to listen to this kind of event, so complain.
769  LOG(ERROR) << "Unexpected field write event in tracing " << ArtMethod::PrettyMethod(method)
770             << " " << dex_pc;
771}
772
773void Trace::MethodEntered(Thread* thread,
774                          Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
775                          ArtMethod* method,
776                          uint32_t dex_pc ATTRIBUTE_UNUSED) {
777  uint32_t thread_clock_diff = 0;
778  uint32_t wall_clock_diff = 0;
779  ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
780  LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodEntered,
781                      thread_clock_diff, wall_clock_diff);
782}
783
784void Trace::MethodExited(Thread* thread,
785                         Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
786                         ArtMethod* method,
787                         uint32_t dex_pc ATTRIBUTE_UNUSED,
788                         const JValue& return_value ATTRIBUTE_UNUSED) {
789  uint32_t thread_clock_diff = 0;
790  uint32_t wall_clock_diff = 0;
791  ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
792  LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodExited,
793                      thread_clock_diff, wall_clock_diff);
794}
795
796void Trace::MethodUnwind(Thread* thread,
797                         Handle<mirror::Object> this_object ATTRIBUTE_UNUSED,
798                         ArtMethod* method,
799                         uint32_t dex_pc ATTRIBUTE_UNUSED) {
800  uint32_t thread_clock_diff = 0;
801  uint32_t wall_clock_diff = 0;
802  ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
803  LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodUnwind,
804                      thread_clock_diff, wall_clock_diff);
805}
806
807void Trace::ExceptionThrown(Thread* thread ATTRIBUTE_UNUSED,
808                            Handle<mirror::Throwable> exception_object ATTRIBUTE_UNUSED)
809    REQUIRES_SHARED(Locks::mutator_lock_) {
810  LOG(ERROR) << "Unexpected exception thrown event in tracing";
811}
812
813void Trace::ExceptionHandled(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::Branch(Thread* /*thread*/, ArtMethod* method,
820                   uint32_t /*dex_pc*/, int32_t /*dex_pc_offset*/)
821      REQUIRES_SHARED(Locks::mutator_lock_) {
822  LOG(ERROR) << "Unexpected branch event in tracing" << ArtMethod::PrettyMethod(method);
823}
824
825void Trace::InvokeVirtualOrInterface(Thread*,
826                                     Handle<mirror::Object>,
827                                     ArtMethod* method,
828                                     uint32_t dex_pc,
829                                     ArtMethod*) {
830  LOG(ERROR) << "Unexpected invoke event in tracing" << ArtMethod::PrettyMethod(method)
831             << " " << dex_pc;
832}
833
834void Trace::WatchedFramePop(Thread* self ATTRIBUTE_UNUSED,
835                            const ShadowFrame& frame ATTRIBUTE_UNUSED) {
836  LOG(ERROR) << "Unexpected WatchedFramePop event in tracing";
837}
838
839void Trace::ReadClocks(Thread* thread, uint32_t* thread_clock_diff, uint32_t* wall_clock_diff) {
840  if (UseThreadCpuClock()) {
841    uint64_t clock_base = thread->GetTraceClockBase();
842    if (UNLIKELY(clock_base == 0)) {
843      // First event, record the base time in the map.
844      uint64_t time = thread->GetCpuMicroTime();
845      thread->SetTraceClockBase(time);
846    } else {
847      *thread_clock_diff = thread->GetCpuMicroTime() - clock_base;
848    }
849  }
850  if (UseWallClock()) {
851    *wall_clock_diff = MicroTime() - start_time_;
852  }
853}
854
855bool Trace::RegisterMethod(ArtMethod* method) {
856  mirror::DexCache* dex_cache = method->GetDexCache();
857  const DexFile* dex_file = dex_cache->GetDexFile();
858  if (seen_methods_.find(dex_file) == seen_methods_.end()) {
859    seen_methods_.insert(std::make_pair(dex_file, new DexIndexBitSet()));
860  }
861  DexIndexBitSet* bit_set = seen_methods_.find(dex_file)->second;
862  if (!(*bit_set)[method->GetDexMethodIndex()]) {
863    bit_set->set(method->GetDexMethodIndex());
864    return true;
865  }
866  return false;
867}
868
869bool Trace::RegisterThread(Thread* thread) {
870  pid_t tid = thread->GetTid();
871  CHECK_LT(0U, static_cast<uint32_t>(tid));
872  CHECK_LT(static_cast<uint32_t>(tid), kMaxThreadIdNumber);
873
874  if (!(*seen_threads_)[tid]) {
875    seen_threads_->set(tid);
876    return true;
877  }
878  return false;
879}
880
881std::string Trace::GetMethodLine(ArtMethod* method) {
882  method = method->GetInterfaceMethodIfProxy(kRuntimePointerSize);
883  return StringPrintf("%#x\t%s\t%s\t%s\t%s\n", (EncodeTraceMethod(method) << TraceActionBits),
884      PrettyDescriptor(method->GetDeclaringClassDescriptor()).c_str(), method->GetName(),
885      method->GetSignature().ToString().c_str(), method->GetDeclaringClassSourceFile());
886}
887
888void Trace::WriteToBuf(const uint8_t* src, size_t src_size) {
889  int32_t old_offset = cur_offset_.LoadRelaxed();
890  int32_t new_offset = old_offset + static_cast<int32_t>(src_size);
891  if (dchecked_integral_cast<size_t>(new_offset) > buffer_size_) {
892    // Flush buffer.
893    if (!trace_file_->WriteFully(buf_.get(), old_offset)) {
894      PLOG(WARNING) << "Failed streaming a tracing event.";
895    }
896
897    // Check whether the data is too large for the buffer, then write immediately.
898    if (src_size >= buffer_size_) {
899      if (!trace_file_->WriteFully(src, src_size)) {
900        PLOG(WARNING) << "Failed streaming a tracing event.";
901      }
902      cur_offset_.StoreRelease(0);  // Buffer is empty now.
903      return;
904    }
905
906    old_offset = 0;
907    new_offset = static_cast<int32_t>(src_size);
908  }
909  cur_offset_.StoreRelease(new_offset);
910  // Fill in data.
911  memcpy(buf_.get() + old_offset, src, src_size);
912}
913
914void Trace::FlushBuf() {
915  int32_t offset = cur_offset_.LoadRelaxed();
916  if (!trace_file_->WriteFully(buf_.get(), offset)) {
917    PLOG(WARNING) << "Failed flush the remaining data in streaming.";
918  }
919  cur_offset_.StoreRelease(0);
920}
921
922void Trace::LogMethodTraceEvent(Thread* thread, ArtMethod* method,
923                                instrumentation::Instrumentation::InstrumentationEvent event,
924                                uint32_t thread_clock_diff, uint32_t wall_clock_diff) {
925  // Ensure we always use the non-obsolete version of the method so that entry/exit events have the
926  // same pointer value.
927  method = method->GetNonObsoleteMethod();
928  // Advance cur_offset_ atomically.
929  int32_t new_offset;
930  int32_t old_offset = 0;
931
932  // We do a busy loop here trying to acquire the next offset.
933  if (trace_output_mode_ != TraceOutputMode::kStreaming) {
934    do {
935      old_offset = cur_offset_.LoadRelaxed();
936      new_offset = old_offset + GetRecordSize(clock_source_);
937      if (static_cast<size_t>(new_offset) > buffer_size_) {
938        overflow_ = true;
939        return;
940      }
941    } while (!cur_offset_.CompareAndSetWeakSequentiallyConsistent(old_offset, new_offset));
942  }
943
944  TraceAction action = kTraceMethodEnter;
945  switch (event) {
946    case instrumentation::Instrumentation::kMethodEntered:
947      action = kTraceMethodEnter;
948      break;
949    case instrumentation::Instrumentation::kMethodExited:
950      action = kTraceMethodExit;
951      break;
952    case instrumentation::Instrumentation::kMethodUnwind:
953      action = kTraceUnroll;
954      break;
955    default:
956      UNIMPLEMENTED(FATAL) << "Unexpected event: " << event;
957  }
958
959  uint32_t method_value = EncodeTraceMethodAndAction(method, action);
960
961  // Write data
962  uint8_t* ptr;
963  static constexpr size_t kPacketSize = 14U;  // The maximum size of data in a packet.
964  uint8_t stack_buf[kPacketSize];             // Space to store a packet when in streaming mode.
965  if (trace_output_mode_ == TraceOutputMode::kStreaming) {
966    ptr = stack_buf;
967  } else {
968    ptr = buf_.get() + old_offset;
969  }
970
971  Append2LE(ptr, thread->GetTid());
972  Append4LE(ptr + 2, method_value);
973  ptr += 6;
974
975  if (UseThreadCpuClock()) {
976    Append4LE(ptr, thread_clock_diff);
977    ptr += 4;
978  }
979  if (UseWallClock()) {
980    Append4LE(ptr, wall_clock_diff);
981  }
982  static_assert(kPacketSize == 2 + 4 + 4 + 4, "Packet size incorrect.");
983
984  if (trace_output_mode_ == TraceOutputMode::kStreaming) {
985    MutexLock mu(Thread::Current(), *streaming_lock_);  // To serialize writing.
986    if (RegisterMethod(method)) {
987      // Write a special block with the name.
988      std::string method_line(GetMethodLine(method));
989      uint8_t buf2[5];
990      Append2LE(buf2, 0);
991      buf2[2] = kOpNewMethod;
992      Append2LE(buf2 + 3, static_cast<uint16_t>(method_line.length()));
993      WriteToBuf(buf2, sizeof(buf2));
994      WriteToBuf(reinterpret_cast<const uint8_t*>(method_line.c_str()), method_line.length());
995    }
996    if (RegisterThread(thread)) {
997      // It might be better to postpone this. Threads might not have received names...
998      std::string thread_name;
999      thread->GetThreadName(thread_name);
1000      uint8_t buf2[7];
1001      Append2LE(buf2, 0);
1002      buf2[2] = kOpNewThread;
1003      Append2LE(buf2 + 3, static_cast<uint16_t>(thread->GetTid()));
1004      Append2LE(buf2 + 5, static_cast<uint16_t>(thread_name.length()));
1005      WriteToBuf(buf2, sizeof(buf2));
1006      WriteToBuf(reinterpret_cast<const uint8_t*>(thread_name.c_str()), thread_name.length());
1007    }
1008    WriteToBuf(stack_buf, sizeof(stack_buf));
1009  }
1010}
1011
1012void Trace::GetVisitedMethods(size_t buf_size,
1013                              std::set<ArtMethod*>* visited_methods) {
1014  uint8_t* ptr = buf_.get() + kTraceHeaderLength;
1015  uint8_t* end = buf_.get() + buf_size;
1016
1017  while (ptr < end) {
1018    uint32_t tmid = ReadBytes(ptr + 2, sizeof(tmid));
1019    ArtMethod* method = DecodeTraceMethod(tmid);
1020    visited_methods->insert(method);
1021    ptr += GetRecordSize(clock_source_);
1022  }
1023}
1024
1025void Trace::DumpMethodList(std::ostream& os, const std::set<ArtMethod*>& visited_methods) {
1026  for (const auto& method : visited_methods) {
1027    os << GetMethodLine(method);
1028  }
1029}
1030
1031static void DumpThread(Thread* t, void* arg) {
1032  std::ostream& os = *reinterpret_cast<std::ostream*>(arg);
1033  std::string name;
1034  t->GetThreadName(name);
1035  os << t->GetTid() << "\t" << name << "\n";
1036}
1037
1038void Trace::DumpThreadList(std::ostream& os) {
1039  Thread* self = Thread::Current();
1040  for (auto it : exited_threads_) {
1041    os << it.first << "\t" << it.second << "\n";
1042  }
1043  Locks::thread_list_lock_->AssertNotHeld(self);
1044  MutexLock mu(self, *Locks::thread_list_lock_);
1045  Runtime::Current()->GetThreadList()->ForEach(DumpThread, &os);
1046}
1047
1048void Trace::StoreExitingThreadInfo(Thread* thread) {
1049  MutexLock mu(thread, *Locks::trace_lock_);
1050  if (the_trace_ != nullptr) {
1051    std::string name;
1052    thread->GetThreadName(name);
1053    // The same thread/tid may be used multiple times. As SafeMap::Put does not allow to override
1054    // a previous mapping, use SafeMap::Overwrite.
1055    the_trace_->exited_threads_.Overwrite(thread->GetTid(), name);
1056  }
1057}
1058
1059Trace::TraceOutputMode Trace::GetOutputMode() {
1060  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1061  CHECK(the_trace_ != nullptr) << "Trace output mode requested, but no trace currently running";
1062  return the_trace_->trace_output_mode_;
1063}
1064
1065Trace::TraceMode Trace::GetMode() {
1066  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1067  CHECK(the_trace_ != nullptr) << "Trace mode requested, but no trace currently running";
1068  return the_trace_->trace_mode_;
1069}
1070
1071size_t Trace::GetBufferSize() {
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_->buffer_size_;
1075}
1076
1077bool Trace::IsTracingEnabled() {
1078  MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1079  return the_trace_ != nullptr;
1080}
1081
1082}  // namespace art
1083