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