blob: d629ce66a83f72c43757deb48259f91d002b1a6a [file] [log] [blame]
Elliott Hughes2faa5f12012-01-30 14:42:07 -08001/*
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 */
jeffhaoe343b762011-12-05 16:36:44 -080016
17#include "trace.h"
18
jeffhaoa9ef3fd2011-12-13 18:33:43 -080019#include <sys/uio.h>
John Reck0624a272015-03-26 15:47:54 -070020#include <unistd.h>
jeffhaoa9ef3fd2011-12-13 18:33:43 -080021
Ian Rogerscf7f1912014-10-22 22:06:39 -070022#define ATRACE_TAG ATRACE_TAG_DALVIK
23#include "cutils/trace.h"
24
Mathieu Chartiere401d142015-04-22 13:56:20 -070025#include "art_method-inl.h"
Andreas Gampee34a42c2015-04-25 14:44:29 -070026#include "base/casts.h"
Jeff Hao0abc72e2013-08-13 13:45:14 -070027#include "base/stl_util.h"
Vladimir Marko80afd022015-05-19 18:08:00 +010028#include "base/time_utils.h"
Elliott Hughes76160052012-12-12 16:31:20 -080029#include "base/unix_file/fd_file.h"
jeffhaoe343b762011-12-05 16:36:44 -080030#include "class_linker.h"
Ian Rogers62d6c772013-02-27 08:32:07 -080031#include "common_throws.h"
jeffhaoa9ef3fd2011-12-13 18:33:43 -080032#include "debugger.h"
Ian Rogers4f6ad8a2013-03-18 15:27:28 -070033#include "dex_file-inl.h"
jeffhao725a9572012-11-13 18:20:12 -080034#include "instrumentation.h"
Ian Rogers4f6ad8a2013-03-18 15:27:28 -070035#include "mirror/class-inl.h"
Andreas Gampe40da2862015-02-27 12:49:04 -080036#include "mirror/dex_cache-inl.h"
Ian Rogers2dd0e2c2013-01-24 12:42:14 -080037#include "mirror/object_array-inl.h"
Ian Rogers4f6ad8a2013-03-18 15:27:28 -070038#include "mirror/object-inl.h"
jeffhaoa9ef3fd2011-12-13 18:33:43 -080039#include "os.h"
Ian Rogers00f7d0e2012-07-19 15:28:27 -070040#include "scoped_thread_state_change.h"
Jeff Hao0abc72e2013-08-13 13:45:14 -070041#include "ScopedLocalRef.h"
jeffhaoe343b762011-12-05 16:36:44 -080042#include "thread.h"
Ian Rogers57b86d42012-03-27 16:05:41 -070043#include "thread_list.h"
Vladimir Marko80afd022015-05-19 18:08:00 +010044#include "utils.h"
Ian Rogers166db042013-07-26 12:05:57 -070045#include "entrypoints/quick/quick_entrypoints.h"
jeffhao2692b572011-12-16 15:42:28 -080046
47namespace art {
48
Mathieu Chartier4d64cd42015-06-02 16:38:29 -070049static constexpr size_t TraceActionBits = MinimumBitsToStore(
50 static_cast<size_t>(kTraceMethodActionMask));
Andreas Gampe40da2862015-02-27 12:49:04 -080051static constexpr uint8_t kOpNewMethod = 1U;
52static constexpr uint8_t kOpNewThread = 2U;
53
Jeff Hao0abc72e2013-08-13 13:45:14 -070054class BuildStackTraceVisitor : public StackVisitor {
55 public:
Nicolas Geoffray8e5bd182015-05-06 11:34:34 +010056 explicit BuildStackTraceVisitor(Thread* thread)
57 : StackVisitor(thread, nullptr, StackVisitor::StackWalkKind::kIncludeInlinedFrames),
58 method_trace_(Trace::AllocStackTrace()) {}
Jeff Hao0abc72e2013-08-13 13:45:14 -070059
Mathieu Chartier90443472015-07-16 20:32:27 -070060 bool VisitFrame() SHARED_REQUIRES(Locks::mutator_lock_) {
Mathieu Chartiere401d142015-04-22 13:56:20 -070061 ArtMethod* m = GetMethod();
Jeff Hao0abc72e2013-08-13 13:45:14 -070062 // Ignore runtime frames (in particular callee save).
63 if (!m->IsRuntimeMethod()) {
64 method_trace_->push_back(m);
65 }
66 return true;
67 }
68
69 // Returns a stack trace where the topmost frame corresponds with the first element of the vector.
Mathieu Chartiere401d142015-04-22 13:56:20 -070070 std::vector<ArtMethod*>* GetStackTrace() const {
Jeff Hao0abc72e2013-08-13 13:45:14 -070071 return method_trace_;
72 }
73
74 private:
Mathieu Chartiere401d142015-04-22 13:56:20 -070075 std::vector<ArtMethod*>* const method_trace_;
Jeff Hao0abc72e2013-08-13 13:45:14 -070076};
77
jeffhaoa9ef3fd2011-12-13 18:33:43 -080078static const char kTraceTokenChar = '*';
79static const uint16_t kTraceHeaderLength = 32;
80static const uint32_t kTraceMagicValue = 0x574f4c53;
81static const uint16_t kTraceVersionSingleClock = 2;
82static const uint16_t kTraceVersionDualClock = 3;
Mathieu Chartier4d64cd42015-06-02 16:38:29 -070083static const uint16_t kTraceRecordSizeSingleClock = 10; // using v2
84static const uint16_t kTraceRecordSizeDualClock = 14; // using v3 with two timestamps
jeffhaoa9ef3fd2011-12-13 18:33:43 -080085
Ian Rogerse63db272014-07-15 15:36:11 -070086TraceClockSource Trace::default_clock_source_ = kDefaultTraceClockSource;
Elliott Hughese119a362012-05-22 17:37:06 -070087
Andreas Gampe40da2862015-02-27 12:49:04 -080088Trace* volatile Trace::the_trace_ = nullptr;
Jeff Hao0abc72e2013-08-13 13:45:14 -070089pthread_t Trace::sampling_pthread_ = 0U;
Mathieu Chartiere401d142015-04-22 13:56:20 -070090std::unique_ptr<std::vector<ArtMethod*>> Trace::temp_stack_trace_;
Ian Rogers62d6c772013-02-27 08:32:07 -080091
Sebastien Hertz0462c4c2015-04-01 16:34:17 +020092// The key identifying the tracer to update instrumentation.
93static constexpr const char* kTracerInstrumentationKey = "Tracer";
94
Ian Rogers62d6c772013-02-27 08:32:07 -080095static TraceAction DecodeTraceAction(uint32_t tmid) {
96 return static_cast<TraceAction>(tmid & kTraceMethodActionMask);
97}
98
Mathieu Chartier4d64cd42015-06-02 16:38:29 -070099ArtMethod* Trace::DecodeTraceMethod(uint32_t tmid) {
100 MutexLock mu(Thread::Current(), *unique_methods_lock_);
101 return unique_methods_[tmid >> TraceActionBits];
102}
103
104uint32_t Trace::EncodeTraceMethod(ArtMethod* method) {
105 MutexLock mu(Thread::Current(), *unique_methods_lock_);
106 uint32_t idx;
107 auto it = art_method_id_map_.find(method);
108 if (it != art_method_id_map_.end()) {
109 idx = it->second;
110 } else {
111 unique_methods_.push_back(method);
112 idx = unique_methods_.size() - 1;
113 art_method_id_map_.emplace(method, idx);
114 }
115 DCHECK_LT(idx, unique_methods_.size());
116 DCHECK_EQ(unique_methods_[idx], method);
117 return idx;
118}
119
120uint32_t Trace::EncodeTraceMethodAndAction(ArtMethod* method, TraceAction action) {
121 uint32_t tmid = (EncodeTraceMethod(method) << TraceActionBits) | action;
122 DCHECK_EQ(method, DecodeTraceMethod(tmid));
Ian Rogers62d6c772013-02-27 08:32:07 -0800123 return tmid;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800124}
125
Mathieu Chartiere401d142015-04-22 13:56:20 -0700126std::vector<ArtMethod*>* Trace::AllocStackTrace() {
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700127 return (temp_stack_trace_.get() != nullptr) ? temp_stack_trace_.release() :
128 new std::vector<ArtMethod*>();
Jeff Hao5ce4b172013-08-16 16:27:18 -0700129}
130
Mathieu Chartiere401d142015-04-22 13:56:20 -0700131void Trace::FreeStackTrace(std::vector<ArtMethod*>* stack_trace) {
Jeff Hao5ce4b172013-08-16 16:27:18 -0700132 stack_trace->clear();
133 temp_stack_trace_.reset(stack_trace);
134}
135
Ian Rogerse63db272014-07-15 15:36:11 -0700136void Trace::SetDefaultClockSource(TraceClockSource clock_source) {
Elliott Hughes0a18df82015-01-09 15:16:16 -0800137#if defined(__linux__)
Ian Rogers62d6c772013-02-27 08:32:07 -0800138 default_clock_source_ = clock_source;
139#else
Igor Murashkinaaebaa02015-01-26 10:55:53 -0800140 if (clock_source != TraceClockSource::kWall) {
Jeff Hao5ce4b172013-08-16 16:27:18 -0700141 LOG(WARNING) << "Ignoring tracing request to use CPU time.";
Ian Rogers62d6c772013-02-27 08:32:07 -0800142 }
143#endif
144}
145
Ian Rogerse63db272014-07-15 15:36:11 -0700146static uint16_t GetTraceVersion(TraceClockSource clock_source) {
Igor Murashkinaaebaa02015-01-26 10:55:53 -0800147 return (clock_source == TraceClockSource::kDual) ? kTraceVersionDualClock
Ian Rogers62d6c772013-02-27 08:32:07 -0800148 : kTraceVersionSingleClock;
149}
150
Ian Rogerse63db272014-07-15 15:36:11 -0700151static uint16_t GetRecordSize(TraceClockSource clock_source) {
Igor Murashkinaaebaa02015-01-26 10:55:53 -0800152 return (clock_source == TraceClockSource::kDual) ? kTraceRecordSizeDualClock
Ian Rogers62d6c772013-02-27 08:32:07 -0800153 : kTraceRecordSizeSingleClock;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800154}
155
Elliott Hughese119a362012-05-22 17:37:06 -0700156bool Trace::UseThreadCpuClock() {
Igor Murashkinaaebaa02015-01-26 10:55:53 -0800157 return (clock_source_ == TraceClockSource::kThreadCpu) ||
158 (clock_source_ == TraceClockSource::kDual);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800159}
160
Elliott Hughese119a362012-05-22 17:37:06 -0700161bool Trace::UseWallClock() {
Igor Murashkinaaebaa02015-01-26 10:55:53 -0800162 return (clock_source_ == TraceClockSource::kWall) ||
163 (clock_source_ == TraceClockSource::kDual);
Elliott Hughese119a362012-05-22 17:37:06 -0700164}
165
Jeff Haoc5d824a2014-07-28 18:35:38 -0700166void Trace::MeasureClockOverhead() {
167 if (UseThreadCpuClock()) {
Jeff Hao57dac6e2013-08-15 16:36:24 -0700168 Thread::Current()->GetCpuMicroTime();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800169 }
Jeff Haoc5d824a2014-07-28 18:35:38 -0700170 if (UseWallClock()) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800171 MicroTime();
172 }
173}
174
Jeff Hao5ce4b172013-08-16 16:27:18 -0700175// Compute an average time taken to measure clocks.
Jeff Haoc5d824a2014-07-28 18:35:38 -0700176uint32_t Trace::GetClockOverheadNanoSeconds() {
Jeff Hao57dac6e2013-08-15 16:36:24 -0700177 Thread* self = Thread::Current();
178 uint64_t start = self->GetCpuMicroTime();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800179
180 for (int i = 4000; i > 0; i--) {
Jeff Haoc5d824a2014-07-28 18:35:38 -0700181 MeasureClockOverhead();
182 MeasureClockOverhead();
183 MeasureClockOverhead();
184 MeasureClockOverhead();
185 MeasureClockOverhead();
186 MeasureClockOverhead();
187 MeasureClockOverhead();
188 MeasureClockOverhead();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800189 }
190
Jeff Hao5ce4b172013-08-16 16:27:18 -0700191 uint64_t elapsed_us = self->GetCpuMicroTime() - start;
192 return static_cast<uint32_t>(elapsed_us / 32);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800193}
194
Elliott Hughesffb465f2012-03-01 18:46:05 -0800195// TODO: put this somewhere with the big-endian equivalent used by JDWP.
196static void Append2LE(uint8_t* buf, uint16_t val) {
Jeff Hao5ce4b172013-08-16 16:27:18 -0700197 *buf++ = static_cast<uint8_t>(val);
198 *buf++ = static_cast<uint8_t>(val >> 8);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800199}
200
Elliott Hughesffb465f2012-03-01 18:46:05 -0800201// TODO: put this somewhere with the big-endian equivalent used by JDWP.
202static void Append4LE(uint8_t* buf, uint32_t val) {
Jeff Hao5ce4b172013-08-16 16:27:18 -0700203 *buf++ = static_cast<uint8_t>(val);
204 *buf++ = static_cast<uint8_t>(val >> 8);
205 *buf++ = static_cast<uint8_t>(val >> 16);
206 *buf++ = static_cast<uint8_t>(val >> 24);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800207}
208
Elliott Hughesffb465f2012-03-01 18:46:05 -0800209// TODO: put this somewhere with the big-endian equivalent used by JDWP.
210static void Append8LE(uint8_t* buf, uint64_t val) {
Jeff Hao5ce4b172013-08-16 16:27:18 -0700211 *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 *buf++ = static_cast<uint8_t>(val >> 32);
216 *buf++ = static_cast<uint8_t>(val >> 40);
217 *buf++ = static_cast<uint8_t>(val >> 48);
218 *buf++ = static_cast<uint8_t>(val >> 56);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800219}
220
Mathieu Chartier90443472015-07-16 20:32:27 -0700221static void GetSample(Thread* thread, void* arg) SHARED_REQUIRES(Locks::mutator_lock_) {
Jeff Hao0abc72e2013-08-13 13:45:14 -0700222 BuildStackTraceVisitor build_trace_visitor(thread);
223 build_trace_visitor.WalkStack();
Mathieu Chartiere401d142015-04-22 13:56:20 -0700224 std::vector<ArtMethod*>* stack_trace = build_trace_visitor.GetStackTrace();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700225 Trace* the_trace = reinterpret_cast<Trace*>(arg);
226 the_trace->CompareAndUpdateStackTrace(thread, stack_trace);
227}
228
Andreas Gampeca714582015-04-03 19:41:34 -0700229static void ClearThreadStackTraceAndClockBase(Thread* thread, void* arg ATTRIBUTE_UNUSED) {
Jeff Hao5ce4b172013-08-16 16:27:18 -0700230 thread->SetTraceClockBase(0);
Mathieu Chartiere401d142015-04-22 13:56:20 -0700231 std::vector<ArtMethod*>* stack_trace = thread->GetStackTraceSample();
Andreas Gampe40da2862015-02-27 12:49:04 -0800232 thread->SetStackTraceSample(nullptr);
Jeff Hao5ce4b172013-08-16 16:27:18 -0700233 delete stack_trace;
234}
235
Jeff Hao0abc72e2013-08-13 13:45:14 -0700236void Trace::CompareAndUpdateStackTrace(Thread* thread,
Mathieu Chartiere401d142015-04-22 13:56:20 -0700237 std::vector<ArtMethod*>* stack_trace) {
Jeff Hao0abc72e2013-08-13 13:45:14 -0700238 CHECK_EQ(pthread_self(), sampling_pthread_);
Mathieu Chartiere401d142015-04-22 13:56:20 -0700239 std::vector<ArtMethod*>* old_stack_trace = thread->GetStackTraceSample();
Jeff Hao5ce4b172013-08-16 16:27:18 -0700240 // Update the thread's stack trace sample.
241 thread->SetStackTraceSample(stack_trace);
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700242 // Read timer clocks to use for all events in this trace.
243 uint32_t thread_clock_diff = 0;
244 uint32_t wall_clock_diff = 0;
245 ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
Andreas Gampe40da2862015-02-27 12:49:04 -0800246 if (old_stack_trace == nullptr) {
Jeff Hao5ce4b172013-08-16 16:27:18 -0700247 // If there's no previous stack trace sample for this thread, log an entry event for all
Jeff Hao0abc72e2013-08-13 13:45:14 -0700248 // methods in the trace.
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700249 for (auto rit = stack_trace->rbegin(); rit != stack_trace->rend(); ++rit) {
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700250 LogMethodTraceEvent(thread, *rit, instrumentation::Instrumentation::kMethodEntered,
251 thread_clock_diff, wall_clock_diff);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700252 }
253 } else {
254 // If there's a previous stack trace for this thread, diff the traces and emit entry and exit
255 // events accordingly.
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700256 auto old_rit = old_stack_trace->rbegin();
257 auto rit = stack_trace->rbegin();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700258 // Iterate bottom-up over both traces until there's a difference between them.
259 while (old_rit != old_stack_trace->rend() && rit != stack_trace->rend() && *old_rit == *rit) {
260 old_rit++;
261 rit++;
262 }
263 // Iterate top-down over the old trace until the point where they differ, emitting exit events.
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700264 for (auto old_it = old_stack_trace->begin(); old_it != old_rit.base(); ++old_it) {
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700265 LogMethodTraceEvent(thread, *old_it, instrumentation::Instrumentation::kMethodExited,
266 thread_clock_diff, wall_clock_diff);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700267 }
268 // Iterate bottom-up over the new trace from the point where they differ, emitting entry events.
269 for (; rit != stack_trace->rend(); ++rit) {
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700270 LogMethodTraceEvent(thread, *rit, instrumentation::Instrumentation::kMethodEntered,
271 thread_clock_diff, wall_clock_diff);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700272 }
Jeff Hao5ce4b172013-08-16 16:27:18 -0700273 FreeStackTrace(old_stack_trace);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700274 }
275}
276
277void* Trace::RunSamplingThread(void* arg) {
278 Runtime* runtime = Runtime::Current();
Ian Rogersef7d42f2014-01-06 12:55:46 -0800279 intptr_t interval_us = reinterpret_cast<intptr_t>(arg);
Jeff Hao4044bda2014-01-06 15:50:45 -0800280 CHECK_GE(interval_us, 0);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700281 CHECK(runtime->AttachCurrentThread("Sampling Profiler", true, runtime->GetSystemThreadGroup(),
Mathieu Chartiere5f13e52015-02-24 09:37:21 -0800282 !runtime->IsAotCompiler()));
Jeff Hao0abc72e2013-08-13 13:45:14 -0700283
284 while (true) {
Jeff Hao23009dc2013-08-22 15:36:42 -0700285 usleep(interval_us);
Jeff Hao5ce4b172013-08-16 16:27:18 -0700286 ATRACE_BEGIN("Profile sampling");
Jeff Hao0abc72e2013-08-13 13:45:14 -0700287 Thread* self = Thread::Current();
288 Trace* the_trace;
289 {
290 MutexLock mu(self, *Locks::trace_lock_);
291 the_trace = the_trace_;
Andreas Gampe40da2862015-02-27 12:49:04 -0800292 if (the_trace == nullptr) {
Jeff Hao0abc72e2013-08-13 13:45:14 -0700293 break;
294 }
295 }
296
Mathieu Chartierbf9fc582015-03-13 17:21:25 -0700297 runtime->GetThreadList()->SuspendAll(__FUNCTION__);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700298 {
299 MutexLock mu(self, *Locks::thread_list_lock_);
300 runtime->GetThreadList()->ForEach(GetSample, the_trace);
301 }
302 runtime->GetThreadList()->ResumeAll();
Jeff Hao5ce4b172013-08-16 16:27:18 -0700303 ATRACE_END();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700304 }
305
306 runtime->DetachCurrentThread();
Andreas Gampe40da2862015-02-27 12:49:04 -0800307 return nullptr;
Jeff Hao0abc72e2013-08-13 13:45:14 -0700308}
309
Andreas Gampee34a42c2015-04-25 14:44:29 -0700310void Trace::Start(const char* trace_filename, int trace_fd, size_t buffer_size, int flags,
Andreas Gampe7e7e0f42015-03-29 15:26:23 -0700311 TraceOutputMode output_mode, TraceMode trace_mode, int interval_us) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800312 Thread* self = Thread::Current();
313 {
314 MutexLock mu(self, *Locks::trace_lock_);
Andreas Gampe40da2862015-02-27 12:49:04 -0800315 if (the_trace_ != nullptr) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800316 LOG(ERROR) << "Trace already in progress, ignoring this request";
317 return;
318 }
jeffhaoe343b762011-12-05 16:36:44 -0800319 }
Jeff Haod063d912014-09-08 09:38:18 -0700320
321 // Check interval if sampling is enabled
Andreas Gampe7e7e0f42015-03-29 15:26:23 -0700322 if (trace_mode == TraceMode::kSampling && interval_us <= 0) {
Jeff Haod063d912014-09-08 09:38:18 -0700323 LOG(ERROR) << "Invalid sampling interval: " << interval_us;
324 ScopedObjectAccess soa(self);
325 ThrowRuntimeException("Invalid sampling interval: %d", interval_us);
326 return;
327 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800328
jeffhao2692b572011-12-16 15:42:28 -0800329 // Open trace file if not going directly to ddms.
Ian Rogers700a4022014-05-19 16:49:03 -0700330 std::unique_ptr<File> trace_file;
Andreas Gampe7e7e0f42015-03-29 15:26:23 -0700331 if (output_mode != TraceOutputMode::kDDMS) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800332 if (trace_fd < 0) {
Brian Carlstrom7571e8b2013-08-12 17:04:14 -0700333 trace_file.reset(OS::CreateEmptyFile(trace_filename));
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800334 } else {
Ian Rogers62d6c772013-02-27 08:32:07 -0800335 trace_file.reset(new File(trace_fd, "tracefile"));
Elliott Hughes76160052012-12-12 16:31:20 -0800336 trace_file->DisableAutoClose();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800337 }
Andreas Gampe40da2862015-02-27 12:49:04 -0800338 if (trace_file.get() == nullptr) {
jeffhaob5e81852012-03-12 11:15:45 -0700339 PLOG(ERROR) << "Unable to open trace file '" << trace_filename << "'";
Ian Rogers62d6c772013-02-27 08:32:07 -0800340 ScopedObjectAccess soa(self);
341 ThrowRuntimeException("Unable to open trace file '%s'", trace_filename);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800342 return;
343 }
344 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800345
Jeff Haod063d912014-09-08 09:38:18 -0700346 Runtime* runtime = Runtime::Current();
Mathieu Chartier9ef78b52014-09-25 17:03:12 -0700347
348 // Enable count of allocs if specified in the flags.
349 bool enable_stats = false;
350
Mathieu Chartierbf9fc582015-03-13 17:21:25 -0700351 runtime->GetThreadList()->SuspendAll(__FUNCTION__);
Jeff Haod063d912014-09-08 09:38:18 -0700352
jeffhao2692b572011-12-16 15:42:28 -0800353 // Create Trace object.
Ian Rogers62d6c772013-02-27 08:32:07 -0800354 {
355 MutexLock mu(self, *Locks::trace_lock_);
Andreas Gampe40da2862015-02-27 12:49:04 -0800356 if (the_trace_ != nullptr) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800357 LOG(ERROR) << "Trace already in progress, ignoring this request";
358 } else {
Mathieu Chartier9ef78b52014-09-25 17:03:12 -0700359 enable_stats = (flags && kTraceCountAllocs) != 0;
Andreas Gampe40da2862015-02-27 12:49:04 -0800360 the_trace_ = new Trace(trace_file.release(), trace_filename, buffer_size, flags, output_mode,
361 trace_mode);
Andreas Gampe7e7e0f42015-03-29 15:26:23 -0700362 if (trace_mode == TraceMode::kSampling) {
Andreas Gampe40da2862015-02-27 12:49:04 -0800363 CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread,
Jeff Hao23009dc2013-08-22 15:36:42 -0700364 reinterpret_cast<void*>(interval_us)),
365 "Sampling profiler thread");
Andreas Gampe40da2862015-02-27 12:49:04 -0800366 the_trace_->interval_us_ = interval_us;
Jeff Hao0abc72e2013-08-13 13:45:14 -0700367 } else {
368 runtime->GetInstrumentation()->AddListener(the_trace_,
369 instrumentation::Instrumentation::kMethodEntered |
370 instrumentation::Instrumentation::kMethodExited |
371 instrumentation::Instrumentation::kMethodUnwind);
Andreas Gampe40da2862015-02-27 12:49:04 -0800372 // TODO: In full-PIC mode, we don't need to fully deopt.
Sebastien Hertz0462c4c2015-04-01 16:34:17 +0200373 runtime->GetInstrumentation()->EnableMethodTracing(kTracerInstrumentationKey);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700374 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800375 }
jeffhao0791adc2012-04-04 11:14:32 -0700376 }
Jeff Haod063d912014-09-08 09:38:18 -0700377
Ian Rogers62d6c772013-02-27 08:32:07 -0800378 runtime->GetThreadList()->ResumeAll();
Mathieu Chartier9ef78b52014-09-25 17:03:12 -0700379
380 // Can't call this when holding the mutator lock.
381 if (enable_stats) {
382 runtime->SetStatsEnabled(true);
383 }
jeffhao2692b572011-12-16 15:42:28 -0800384}
385
Andreas Gampe40da2862015-02-27 12:49:04 -0800386void Trace::StopTracing(bool finish_tracing, bool flush_file) {
Mathieu Chartier9ef78b52014-09-25 17:03:12 -0700387 bool stop_alloc_counting = false;
Mathieu Chartier02e5f162015-03-11 09:54:22 -0700388 Runtime* const runtime = Runtime::Current();
389 Trace* the_trace = nullptr;
Jeff Hao0abc72e2013-08-13 13:45:14 -0700390 pthread_t sampling_pthread = 0U;
Ian Rogers62d6c772013-02-27 08:32:07 -0800391 {
392 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
Andreas Gampe40da2862015-02-27 12:49:04 -0800393 if (the_trace_ == nullptr) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800394 LOG(ERROR) << "Trace stop requested, but no trace currently running";
395 } else {
396 the_trace = the_trace_;
Andreas Gampe40da2862015-02-27 12:49:04 -0800397 the_trace_ = nullptr;
Jeff Hao0abc72e2013-08-13 13:45:14 -0700398 sampling_pthread = sampling_pthread_;
Ian Rogers62d6c772013-02-27 08:32:07 -0800399 }
jeffhao2692b572011-12-16 15:42:28 -0800400 }
Mathieu Chartier02e5f162015-03-11 09:54:22 -0700401 // Make sure that we join before we delete the trace since we don't want to have
402 // the sampling thread access a stale pointer. This finishes since the sampling thread exits when
403 // the_trace_ is null.
404 if (sampling_pthread != 0U) {
Andreas Gampe40da2862015-02-27 12:49:04 -0800405 CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, nullptr), "sampling thread shutdown");
Mathieu Chartier02e5f162015-03-11 09:54:22 -0700406 sampling_pthread_ = 0U;
407 }
Mathieu Chartierbf9fc582015-03-13 17:21:25 -0700408 runtime->GetThreadList()->SuspendAll(__FUNCTION__);
Andreas Gampe40da2862015-02-27 12:49:04 -0800409
Mathieu Chartier02e5f162015-03-11 09:54:22 -0700410 if (the_trace != nullptr) {
Andreas Gampe40da2862015-02-27 12:49:04 -0800411 stop_alloc_counting = (the_trace->flags_ & Trace::kTraceCountAllocs) != 0;
412 if (finish_tracing) {
413 the_trace->FinishTracing();
414 }
Jeff Hao0abc72e2013-08-13 13:45:14 -0700415
Andreas Gampe7e7e0f42015-03-29 15:26:23 -0700416 if (the_trace->trace_mode_ == TraceMode::kSampling) {
Jeff Hao5ce4b172013-08-16 16:27:18 -0700417 MutexLock mu(Thread::Current(), *Locks::thread_list_lock_);
Mathieu Chartier02e5f162015-03-11 09:54:22 -0700418 runtime->GetThreadList()->ForEach(ClearThreadStackTraceAndClockBase, nullptr);
Jeff Hao5ce4b172013-08-16 16:27:18 -0700419 } else {
Sebastien Hertz0462c4c2015-04-01 16:34:17 +0200420 runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey);
Mathieu Chartier02e5f162015-03-11 09:54:22 -0700421 runtime->GetInstrumentation()->RemoveListener(
422 the_trace, instrumentation::Instrumentation::kMethodEntered |
423 instrumentation::Instrumentation::kMethodExited |
424 instrumentation::Instrumentation::kMethodUnwind);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700425 }
Andreas Gampe4303ba92014-11-06 01:00:46 -0800426 if (the_trace->trace_file_.get() != nullptr) {
427 // Do not try to erase, so flush and close explicitly.
Andreas Gampe40da2862015-02-27 12:49:04 -0800428 if (flush_file) {
429 if (the_trace->trace_file_->Flush() != 0) {
Andreas Gampe7526d782015-06-22 22:53:45 -0700430 PLOG(WARNING) << "Could not flush trace file.";
Andreas Gampe40da2862015-02-27 12:49:04 -0800431 }
432 } else {
433 the_trace->trace_file_->MarkUnchecked(); // Do not trigger guard.
Andreas Gampe4303ba92014-11-06 01:00:46 -0800434 }
435 if (the_trace->trace_file_->Close() != 0) {
436 PLOG(ERROR) << "Could not close trace file.";
437 }
438 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800439 delete the_trace;
440 }
441 runtime->GetThreadList()->ResumeAll();
Mathieu Chartier9ef78b52014-09-25 17:03:12 -0700442 if (stop_alloc_counting) {
443 // Can be racy since SetStatsEnabled is not guarded by any locks.
Mathieu Chartier02e5f162015-03-11 09:54:22 -0700444 runtime->SetStatsEnabled(false);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700445 }
jeffhao2692b572011-12-16 15:42:28 -0800446}
447
Andreas Gampe40da2862015-02-27 12:49:04 -0800448void Trace::Abort() {
449 // Do not write anything anymore.
450 StopTracing(false, false);
451}
452
453void Trace::Stop() {
454 // Finish writing.
455 StopTracing(true, true);
456}
457
jeffhaob5e81852012-03-12 11:15:45 -0700458void Trace::Shutdown() {
Jeff Hao64caa7d2013-08-29 11:18:01 -0700459 if (GetMethodTracingMode() != kTracingInactive) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800460 Stop();
jeffhaob5e81852012-03-12 11:15:45 -0700461 }
jeffhaob5e81852012-03-12 11:15:45 -0700462}
463
Andreas Gampe40da2862015-02-27 12:49:04 -0800464void Trace::Pause() {
465 bool stop_alloc_counting = false;
466 Runtime* runtime = Runtime::Current();
467 Trace* the_trace = nullptr;
468
469 pthread_t sampling_pthread = 0U;
470 {
471 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
472 if (the_trace_ == nullptr) {
473 LOG(ERROR) << "Trace pause requested, but no trace currently running";
474 return;
475 } else {
476 the_trace = the_trace_;
477 sampling_pthread = sampling_pthread_;
478 }
479 }
480
481 if (sampling_pthread != 0U) {
482 {
483 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
484 the_trace_ = nullptr;
485 }
486 CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, nullptr), "sampling thread shutdown");
487 sampling_pthread_ = 0U;
488 {
489 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
490 the_trace_ = the_trace;
491 }
492 }
493
494 if (the_trace != nullptr) {
495 runtime->GetThreadList()->SuspendAll(__FUNCTION__);
496 stop_alloc_counting = (the_trace->flags_ & Trace::kTraceCountAllocs) != 0;
497
498 if (the_trace->trace_mode_ == TraceMode::kSampling) {
499 MutexLock mu(Thread::Current(), *Locks::thread_list_lock_);
500 runtime->GetThreadList()->ForEach(ClearThreadStackTraceAndClockBase, nullptr);
501 } else {
Sebastien Hertz0462c4c2015-04-01 16:34:17 +0200502 runtime->GetInstrumentation()->DisableMethodTracing(kTracerInstrumentationKey);
Andreas Gampe40da2862015-02-27 12:49:04 -0800503 runtime->GetInstrumentation()->RemoveListener(the_trace,
504 instrumentation::Instrumentation::kMethodEntered |
505 instrumentation::Instrumentation::kMethodExited |
506 instrumentation::Instrumentation::kMethodUnwind);
507 }
508 runtime->GetThreadList()->ResumeAll();
509 }
510
511 if (stop_alloc_counting) {
512 // Can be racy since SetStatsEnabled is not guarded by any locks.
513 Runtime::Current()->SetStatsEnabled(false);
514 }
515}
516
517void Trace::Resume() {
518 Thread* self = Thread::Current();
519 Trace* the_trace;
520 {
521 MutexLock mu(self, *Locks::trace_lock_);
522 if (the_trace_ == nullptr) {
523 LOG(ERROR) << "No trace to resume (or sampling mode), ignoring this request";
524 return;
525 }
526 the_trace = the_trace_;
527 }
528
529 Runtime* runtime = Runtime::Current();
530
531 // Enable count of allocs if specified in the flags.
532 bool enable_stats = (the_trace->flags_ && kTraceCountAllocs) != 0;
533
534 runtime->GetThreadList()->SuspendAll(__FUNCTION__);
535
536 // Reenable.
537 if (the_trace->trace_mode_ == TraceMode::kSampling) {
538 CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, nullptr, &RunSamplingThread,
539 reinterpret_cast<void*>(the_trace->interval_us_)), "Sampling profiler thread");
540 } else {
541 runtime->GetInstrumentation()->AddListener(the_trace,
542 instrumentation::Instrumentation::kMethodEntered |
543 instrumentation::Instrumentation::kMethodExited |
544 instrumentation::Instrumentation::kMethodUnwind);
545 // TODO: In full-PIC mode, we don't need to fully deopt.
Sebastien Hertz0462c4c2015-04-01 16:34:17 +0200546 runtime->GetInstrumentation()->EnableMethodTracing(kTracerInstrumentationKey);
Andreas Gampe40da2862015-02-27 12:49:04 -0800547 }
548
549 runtime->GetThreadList()->ResumeAll();
550
551 // Can't call this when holding the mutator lock.
552 if (enable_stats) {
553 runtime->SetStatsEnabled(true);
554 }
555}
556
Jeff Hao64caa7d2013-08-29 11:18:01 -0700557TracingMode Trace::GetMethodTracingMode() {
Ian Rogers62d6c772013-02-27 08:32:07 -0800558 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
Andreas Gampe40da2862015-02-27 12:49:04 -0800559 if (the_trace_ == nullptr) {
Jeff Hao64caa7d2013-08-29 11:18:01 -0700560 return kTracingInactive;
Jeff Hao64caa7d2013-08-29 11:18:01 -0700561 } else {
Andreas Gampe7e7e0f42015-03-29 15:26:23 -0700562 switch (the_trace_->trace_mode_) {
563 case TraceMode::kSampling:
564 return kSampleProfilingActive;
565 case TraceMode::kMethodTracing:
566 return kMethodTracingActive;
567 }
568 LOG(FATAL) << "Unreachable";
569 UNREACHABLE();
Jeff Hao64caa7d2013-08-29 11:18:01 -0700570 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800571}
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800572
Andreas Gampee34a42c2015-04-25 14:44:29 -0700573static constexpr size_t kMinBufSize = 18U; // Trace header is up to 18B.
Andreas Gampe40da2862015-02-27 12:49:04 -0800574
Andreas Gampee34a42c2015-04-25 14:44:29 -0700575Trace::Trace(File* trace_file, const char* trace_name, size_t buffer_size, int flags,
Andreas Gampe40da2862015-02-27 12:49:04 -0800576 TraceOutputMode output_mode, TraceMode trace_mode)
577 : trace_file_(trace_file),
Andreas Gampee34a42c2015-04-25 14:44:29 -0700578 buf_(new uint8_t[std::max(kMinBufSize, buffer_size)]()),
Andreas Gampe40da2862015-02-27 12:49:04 -0800579 flags_(flags), trace_output_mode_(output_mode), trace_mode_(trace_mode),
580 clock_source_(default_clock_source_),
Andreas Gampee34a42c2015-04-25 14:44:29 -0700581 buffer_size_(std::max(kMinBufSize, buffer_size)),
Andreas Gampe40da2862015-02-27 12:49:04 -0800582 start_time_(MicroTime()), clock_overhead_ns_(GetClockOverheadNanoSeconds()), cur_offset_(0),
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700583 overflow_(false), interval_us_(0), streaming_lock_(nullptr),
Andreas Gampe7526d782015-06-22 22:53:45 -0700584 unique_methods_lock_(new Mutex("unique methods lock", kTracingUniqueMethodsLock)) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800585 uint16_t trace_version = GetTraceVersion(clock_source_);
Andreas Gampe40da2862015-02-27 12:49:04 -0800586 if (output_mode == TraceOutputMode::kStreaming) {
587 trace_version |= 0xF0U;
588 }
589 // Set up the beginning of the trace.
jeffhao2692b572011-12-16 15:42:28 -0800590 memset(buf_.get(), 0, kTraceHeaderLength);
591 Append4LE(buf_.get(), kTraceMagicValue);
Ian Rogers62d6c772013-02-27 08:32:07 -0800592 Append2LE(buf_.get() + 4, trace_version);
jeffhao2692b572011-12-16 15:42:28 -0800593 Append2LE(buf_.get() + 6, kTraceHeaderLength);
594 Append8LE(buf_.get() + 8, start_time_);
Ian Rogers62d6c772013-02-27 08:32:07 -0800595 if (trace_version >= kTraceVersionDualClock) {
596 uint16_t record_size = GetRecordSize(clock_source_);
597 Append2LE(buf_.get() + 16, record_size);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800598 }
Andreas Gampee34a42c2015-04-25 14:44:29 -0700599 static_assert(18 <= kMinBufSize, "Minimum buffer size not large enough for trace header");
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800600
jeffhao2692b572011-12-16 15:42:28 -0800601 // Update current offset.
Ian Rogers8ab25ef2014-07-09 18:00:50 -0700602 cur_offset_.StoreRelaxed(kTraceHeaderLength);
Andreas Gampe40da2862015-02-27 12:49:04 -0800603
604 if (output_mode == TraceOutputMode::kStreaming) {
605 streaming_file_name_ = trace_name;
Andreas Gampe7526d782015-06-22 22:53:45 -0700606 streaming_lock_ = new Mutex("tracing lock", LockLevel::kTracingStreamingLock);
Andreas Gampe40da2862015-02-27 12:49:04 -0800607 seen_threads_.reset(new ThreadIDBitSet());
608 }
609}
610
611Trace::~Trace() {
612 delete streaming_lock_;
Andreas Gampe7526d782015-06-22 22:53:45 -0700613 delete unique_methods_lock_;
Ian Rogers62d6c772013-02-27 08:32:07 -0800614}
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800615
Mathieu Chartiere401d142015-04-22 13:56:20 -0700616static uint64_t ReadBytes(uint8_t* buf, size_t bytes) {
617 uint64_t ret = 0;
618 for (size_t i = 0; i < bytes; ++i) {
619 ret |= static_cast<uint64_t>(buf[i]) << (i * 8);
620 }
621 return ret;
622}
623
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700624void Trace::DumpBuf(uint8_t* buf, size_t buf_size, TraceClockSource clock_source) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800625 uint8_t* ptr = buf + kTraceHeaderLength;
626 uint8_t* end = buf + buf_size;
627
628 while (ptr < end) {
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700629 uint32_t tmid = ReadBytes(ptr + 2, sizeof(tmid));
630 ArtMethod* method = DecodeTraceMethod(tmid);
Ian Rogers62d6c772013-02-27 08:32:07 -0800631 TraceAction action = DecodeTraceAction(tmid);
632 LOG(INFO) << PrettyMethod(method) << " " << static_cast<int>(action);
633 ptr += GetRecordSize(clock_source);
634 }
jeffhaoe343b762011-12-05 16:36:44 -0800635}
636
Andreas Gampe40da2862015-02-27 12:49:04 -0800637static void GetVisitedMethodsFromBitSets(
Andreas Gampe7526d782015-06-22 22:53:45 -0700638 const std::map<const DexFile*, DexIndexBitSet*>& seen_methods,
Mathieu Chartier90443472015-07-16 20:32:27 -0700639 std::set<ArtMethod*>* visited_methods) SHARED_REQUIRES(Locks::mutator_lock_) {
Andreas Gampe7526d782015-06-22 22:53:45 -0700640 ClassLinker* class_linker = Runtime::Current()->GetClassLinker();
Mathieu Chartier673ed3d2015-08-28 14:56:43 -0700641 Thread* const self = Thread::Current();
Andreas Gampe40da2862015-02-27 12:49:04 -0800642 for (auto& e : seen_methods) {
643 DexIndexBitSet* bit_set = e.second;
Mathieu Chartier673ed3d2015-08-28 14:56:43 -0700644 // TODO: Visit trace methods as roots.
645 mirror::DexCache* dex_cache = class_linker->FindDexCache(self, *e.first, false);
Andreas Gampe40da2862015-02-27 12:49:04 -0800646 for (uint32_t i = 0; i < bit_set->size(); ++i) {
647 if ((*bit_set)[i]) {
Andreas Gampe7526d782015-06-22 22:53:45 -0700648 visited_methods->insert(dex_cache->GetResolvedMethod(i, sizeof(void*)));
Andreas Gampe40da2862015-02-27 12:49:04 -0800649 }
650 }
651 }
652}
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800653
Andreas Gampe40da2862015-02-27 12:49:04 -0800654void Trace::FinishTracing() {
655 size_t final_offset = 0;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800656
Mathieu Chartiere401d142015-04-22 13:56:20 -0700657 std::set<ArtMethod*> visited_methods;
Andreas Gampe40da2862015-02-27 12:49:04 -0800658 if (trace_output_mode_ == TraceOutputMode::kStreaming) {
659 // Write the secondary file with all the method names.
660 GetVisitedMethodsFromBitSets(seen_methods_, &visited_methods);
661
662 // Clean up.
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700663 STLDeleteValues(&seen_methods_);
Andreas Gampe40da2862015-02-27 12:49:04 -0800664 } else {
665 final_offset = cur_offset_.LoadRelaxed();
666 GetVisitedMethods(final_offset, &visited_methods);
667 }
668
669 // Compute elapsed time.
670 uint64_t elapsed = MicroTime() - start_time_;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800671
672 std::ostringstream os;
673
674 os << StringPrintf("%cversion\n", kTraceTokenChar);
Ian Rogers62d6c772013-02-27 08:32:07 -0800675 os << StringPrintf("%d\n", GetTraceVersion(clock_source_));
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800676 os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false");
677 if (UseThreadCpuClock()) {
678 if (UseWallClock()) {
679 os << StringPrintf("clock=dual\n");
680 } else {
681 os << StringPrintf("clock=thread-cpu\n");
682 }
683 } else {
684 os << StringPrintf("clock=wall\n");
685 }
Ian Rogersef7d42f2014-01-06 12:55:46 -0800686 os << StringPrintf("elapsed-time-usec=%" PRIu64 "\n", elapsed);
Andreas Gampe40da2862015-02-27 12:49:04 -0800687 if (trace_output_mode_ != TraceOutputMode::kStreaming) {
688 size_t num_records = (final_offset - kTraceHeaderLength) / GetRecordSize(clock_source_);
689 os << StringPrintf("num-method-calls=%zd\n", num_records);
690 }
Jeff Haoc5d824a2014-07-28 18:35:38 -0700691 os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead_ns_);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800692 os << StringPrintf("vm=art\n");
John Reck0624a272015-03-26 15:47:54 -0700693 os << StringPrintf("pid=%d\n", getpid());
jeffhao0791adc2012-04-04 11:14:32 -0700694 if ((flags_ & kTraceCountAllocs) != 0) {
695 os << StringPrintf("alloc-count=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_OBJECTS));
696 os << StringPrintf("alloc-size=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_BYTES));
697 os << StringPrintf("gc-count=%d\n", Runtime::Current()->GetStat(KIND_GC_INVOCATIONS));
698 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800699 os << StringPrintf("%cthreads\n", kTraceTokenChar);
700 DumpThreadList(os);
701 os << StringPrintf("%cmethods\n", kTraceTokenChar);
Ian Rogers62d6c772013-02-27 08:32:07 -0800702 DumpMethodList(os, visited_methods);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800703 os << StringPrintf("%cend\n", kTraceTokenChar);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800704 std::string header(os.str());
Andreas Gampe40da2862015-02-27 12:49:04 -0800705
706 if (trace_output_mode_ == TraceOutputMode::kStreaming) {
707 File file;
708 if (!file.Open(streaming_file_name_ + ".sec", O_CREAT | O_WRONLY)) {
709 LOG(WARNING) << "Could not open secondary trace file!";
710 return;
Ian Rogers62d6c772013-02-27 08:32:07 -0800711 }
Andreas Gampe40da2862015-02-27 12:49:04 -0800712 if (!file.WriteFully(header.c_str(), header.length())) {
713 file.Erase();
Elliott Hughes7b9d9962012-04-20 18:48:18 -0700714 std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno)));
715 PLOG(ERROR) << detail;
Ian Rogers62d6c772013-02-27 08:32:07 -0800716 ThrowRuntimeException("%s", detail.c_str());
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800717 }
Andreas Gampe40da2862015-02-27 12:49:04 -0800718 if (file.FlushCloseOrErase() != 0) {
719 PLOG(ERROR) << "Could not write secondary file";
720 }
721 } else {
722 if (trace_file_.get() == nullptr) {
723 iovec iov[2];
724 iov[0].iov_base = reinterpret_cast<void*>(const_cast<char*>(header.c_str()));
725 iov[0].iov_len = header.length();
726 iov[1].iov_base = buf_.get();
727 iov[1].iov_len = final_offset;
728 Dbg::DdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2);
729 const bool kDumpTraceInfo = false;
730 if (kDumpTraceInfo) {
731 LOG(INFO) << "Trace sent:\n" << header;
732 DumpBuf(buf_.get(), final_offset, clock_source_);
733 }
734 } else {
735 if (!trace_file_->WriteFully(header.c_str(), header.length()) ||
736 !trace_file_->WriteFully(buf_.get(), final_offset)) {
737 std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno)));
738 PLOG(ERROR) << detail;
739 ThrowRuntimeException("%s", detail.c_str());
740 }
741 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800742 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800743}
744
Ian Rogers62d6c772013-02-27 08:32:07 -0800745void Trace::DexPcMoved(Thread* thread, mirror::Object* this_object,
Mathieu Chartiere401d142015-04-22 13:56:20 -0700746 ArtMethod* method, uint32_t new_dex_pc) {
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700747 UNUSED(thread, this_object, method, new_dex_pc);
Ian Rogers62d6c772013-02-27 08:32:07 -0800748 // We're not recorded to listen to this kind of event, so complain.
749 LOG(ERROR) << "Unexpected dex PC event in tracing " << PrettyMethod(method) << " " << new_dex_pc;
Andreas Gampec8ccf682014-09-29 20:07:43 -0700750}
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800751
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700752void Trace::FieldRead(Thread* thread, mirror::Object* this_object,
Mathieu Chartiere401d142015-04-22 13:56:20 -0700753 ArtMethod* method, uint32_t dex_pc, ArtField* field)
Mathieu Chartier90443472015-07-16 20:32:27 -0700754 SHARED_REQUIRES(Locks::mutator_lock_) {
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700755 UNUSED(thread, this_object, method, dex_pc, field);
Sebastien Hertz3f52eaf2014-04-04 17:50:18 +0200756 // We're not recorded to listen to this kind of event, so complain.
757 LOG(ERROR) << "Unexpected field read event in tracing " << PrettyMethod(method) << " " << dex_pc;
758}
759
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700760void Trace::FieldWritten(Thread* thread, mirror::Object* this_object,
Mathieu Chartiere401d142015-04-22 13:56:20 -0700761 ArtMethod* method, uint32_t dex_pc, ArtField* field,
Sebastien Hertz3f52eaf2014-04-04 17:50:18 +0200762 const JValue& field_value)
Mathieu Chartier90443472015-07-16 20:32:27 -0700763 SHARED_REQUIRES(Locks::mutator_lock_) {
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700764 UNUSED(thread, this_object, method, dex_pc, field, field_value);
Sebastien Hertz3f52eaf2014-04-04 17:50:18 +0200765 // We're not recorded to listen to this kind of event, so complain.
766 LOG(ERROR) << "Unexpected field write event in tracing " << PrettyMethod(method) << " " << dex_pc;
767}
768
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700769void Trace::MethodEntered(Thread* thread, mirror::Object* this_object ATTRIBUTE_UNUSED,
Mathieu Chartiere401d142015-04-22 13:56:20 -0700770 ArtMethod* method, uint32_t dex_pc ATTRIBUTE_UNUSED) {
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700771 uint32_t thread_clock_diff = 0;
772 uint32_t wall_clock_diff = 0;
773 ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
774 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodEntered,
775 thread_clock_diff, wall_clock_diff);
Ian Rogers62d6c772013-02-27 08:32:07 -0800776}
777
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700778void Trace::MethodExited(Thread* thread, mirror::Object* this_object ATTRIBUTE_UNUSED,
Mathieu Chartiere401d142015-04-22 13:56:20 -0700779 ArtMethod* method, uint32_t dex_pc ATTRIBUTE_UNUSED,
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700780 const JValue& return_value ATTRIBUTE_UNUSED) {
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700781 uint32_t thread_clock_diff = 0;
782 uint32_t wall_clock_diff = 0;
783 ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
784 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodExited,
785 thread_clock_diff, wall_clock_diff);
Ian Rogers62d6c772013-02-27 08:32:07 -0800786}
787
Ian Rogers6a3c1fc2014-10-31 00:33:20 -0700788void Trace::MethodUnwind(Thread* thread, mirror::Object* this_object ATTRIBUTE_UNUSED,
Mathieu Chartiere401d142015-04-22 13:56:20 -0700789 ArtMethod* method, uint32_t dex_pc ATTRIBUTE_UNUSED) {
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700790 uint32_t thread_clock_diff = 0;
791 uint32_t wall_clock_diff = 0;
792 ReadClocks(thread, &thread_clock_diff, &wall_clock_diff);
793 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodUnwind,
794 thread_clock_diff, wall_clock_diff);
Ian Rogers62d6c772013-02-27 08:32:07 -0800795}
796
Nicolas Geoffray14691c52015-03-05 10:40:17 +0000797void Trace::ExceptionCaught(Thread* thread, mirror::Throwable* exception_object)
Mathieu Chartier90443472015-07-16 20:32:27 -0700798 SHARED_REQUIRES(Locks::mutator_lock_) {
Nicolas Geoffray14691c52015-03-05 10:40:17 +0000799 UNUSED(thread, exception_object);
Ian Rogers62d6c772013-02-27 08:32:07 -0800800 LOG(ERROR) << "Unexpected exception caught event in tracing";
801}
802
Mathieu Chartiere401d142015-04-22 13:56:20 -0700803void Trace::BackwardBranch(Thread* /*thread*/, ArtMethod* method,
Mathieu Chartiere5f13e52015-02-24 09:37:21 -0800804 int32_t /*dex_pc_offset*/)
Mathieu Chartier90443472015-07-16 20:32:27 -0700805 SHARED_REQUIRES(Locks::mutator_lock_) {
Mathieu Chartiere5f13e52015-02-24 09:37:21 -0800806 LOG(ERROR) << "Unexpected backward branch event in tracing" << PrettyMethod(method);
807}
808
Nicolas Geoffray5550ca82015-08-21 18:38:30 +0100809void Trace::InvokeVirtualOrInterface(Thread*,
810 mirror::Object*,
811 ArtMethod* method,
812 uint32_t dex_pc,
813 ArtMethod*) {
814 LOG(ERROR) << "Unexpected invoke event in tracing" << PrettyMethod(method)
815 << " " << dex_pc;
816}
817
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700818void Trace::ReadClocks(Thread* thread, uint32_t* thread_clock_diff, uint32_t* wall_clock_diff) {
819 if (UseThreadCpuClock()) {
820 uint64_t clock_base = thread->GetTraceClockBase();
821 if (UNLIKELY(clock_base == 0)) {
822 // First event, record the base time in the map.
823 uint64_t time = thread->GetCpuMicroTime();
824 thread->SetTraceClockBase(time);
825 } else {
826 *thread_clock_diff = thread->GetCpuMicroTime() - clock_base;
827 }
828 }
829 if (UseWallClock()) {
830 *wall_clock_diff = MicroTime() - start_time_;
831 }
832}
833
Mathieu Chartiere401d142015-04-22 13:56:20 -0700834bool Trace::RegisterMethod(ArtMethod* method) {
Andreas Gampe40da2862015-02-27 12:49:04 -0800835 mirror::DexCache* dex_cache = method->GetDexCache();
Andreas Gampe7526d782015-06-22 22:53:45 -0700836 const DexFile* dex_file = dex_cache->GetDexFile();
Mathieu Chartiere401d142015-04-22 13:56:20 -0700837 auto* resolved_method = dex_cache->GetResolvedMethod(method->GetDexMethodIndex(), sizeof(void*));
838 if (resolved_method != method) {
839 DCHECK(resolved_method == nullptr);
840 dex_cache->SetResolvedMethod(method->GetDexMethodIndex(), method, sizeof(void*));
Andreas Gampe40da2862015-02-27 12:49:04 -0800841 }
Andreas Gampe7526d782015-06-22 22:53:45 -0700842 if (seen_methods_.find(dex_file) == seen_methods_.end()) {
843 seen_methods_.insert(std::make_pair(dex_file, new DexIndexBitSet()));
Andreas Gampe40da2862015-02-27 12:49:04 -0800844 }
Andreas Gampe7526d782015-06-22 22:53:45 -0700845 DexIndexBitSet* bit_set = seen_methods_.find(dex_file)->second;
Andreas Gampe40da2862015-02-27 12:49:04 -0800846 if (!(*bit_set)[method->GetDexMethodIndex()]) {
847 bit_set->set(method->GetDexMethodIndex());
848 return true;
849 }
850 return false;
851}
852
853bool Trace::RegisterThread(Thread* thread) {
854 pid_t tid = thread->GetTid();
855 CHECK_LT(0U, static_cast<uint32_t>(tid));
856 CHECK_LT(static_cast<uint32_t>(tid), 65536U);
857
858 if (!(*seen_threads_)[tid]) {
859 seen_threads_->set(tid);
860 return true;
861 }
862 return false;
863}
864
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700865std::string Trace::GetMethodLine(ArtMethod* method) {
Mathieu Chartiere3b034a2015-05-31 14:29:23 -0700866 method = method->GetInterfaceMethodIfProxy(sizeof(void*));
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700867 return StringPrintf("%p\t%s\t%s\t%s\t%s\n",
868 reinterpret_cast<void*>((EncodeTraceMethod(method) << TraceActionBits)),
Andreas Gampe40da2862015-02-27 12:49:04 -0800869 PrettyDescriptor(method->GetDeclaringClassDescriptor()).c_str(), method->GetName(),
870 method->GetSignature().ToString().c_str(), method->GetDeclaringClassSourceFile());
871}
872
873void Trace::WriteToBuf(const uint8_t* src, size_t src_size) {
874 int32_t old_offset = cur_offset_.LoadRelaxed();
875 int32_t new_offset = old_offset + static_cast<int32_t>(src_size);
Andreas Gampee34a42c2015-04-25 14:44:29 -0700876 if (dchecked_integral_cast<size_t>(new_offset) > buffer_size_) {
Andreas Gampe40da2862015-02-27 12:49:04 -0800877 // Flush buffer.
878 if (!trace_file_->WriteFully(buf_.get(), old_offset)) {
879 PLOG(WARNING) << "Failed streaming a tracing event.";
880 }
Andreas Gampee34a42c2015-04-25 14:44:29 -0700881
882 // Check whether the data is too large for the buffer, then write immediately.
883 if (src_size >= buffer_size_) {
884 if (!trace_file_->WriteFully(src, src_size)) {
885 PLOG(WARNING) << "Failed streaming a tracing event.";
886 }
887 cur_offset_.StoreRelease(0); // Buffer is empty now.
888 return;
889 }
890
Andreas Gampe40da2862015-02-27 12:49:04 -0800891 old_offset = 0;
892 new_offset = static_cast<int32_t>(src_size);
893 }
894 cur_offset_.StoreRelease(new_offset);
895 // Fill in data.
896 memcpy(buf_.get() + old_offset, src, src_size);
897}
898
Mathieu Chartiere401d142015-04-22 13:56:20 -0700899void Trace::LogMethodTraceEvent(Thread* thread, ArtMethod* method,
Jeff Haoc1ff4b72013-08-19 11:33:10 -0700900 instrumentation::Instrumentation::InstrumentationEvent event,
901 uint32_t thread_clock_diff, uint32_t wall_clock_diff) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800902 // Advance cur_offset_ atomically.
903 int32_t new_offset;
Andreas Gampe40da2862015-02-27 12:49:04 -0800904 int32_t old_offset = 0;
905
906 // We do a busy loop here trying to acquire the next offset.
907 if (trace_output_mode_ != TraceOutputMode::kStreaming) {
908 do {
909 old_offset = cur_offset_.LoadRelaxed();
910 new_offset = old_offset + GetRecordSize(clock_source_);
Andreas Gampee34a42c2015-04-25 14:44:29 -0700911 if (static_cast<size_t>(new_offset) > buffer_size_) {
Andreas Gampe40da2862015-02-27 12:49:04 -0800912 overflow_ = true;
913 return;
914 }
915 } while (!cur_offset_.CompareExchangeWeakSequentiallyConsistent(old_offset, new_offset));
916 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800917
Ian Rogers62d6c772013-02-27 08:32:07 -0800918 TraceAction action = kTraceMethodEnter;
919 switch (event) {
920 case instrumentation::Instrumentation::kMethodEntered:
921 action = kTraceMethodEnter;
922 break;
923 case instrumentation::Instrumentation::kMethodExited:
924 action = kTraceMethodExit;
925 break;
926 case instrumentation::Instrumentation::kMethodUnwind:
927 action = kTraceUnroll;
928 break;
929 default:
930 UNIMPLEMENTED(FATAL) << "Unexpected event: " << event;
931 }
932
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700933 uint32_t method_value = EncodeTraceMethodAndAction(method, action);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800934
935 // Write data
Andreas Gampe40da2862015-02-27 12:49:04 -0800936 uint8_t* ptr;
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700937 static constexpr size_t kPacketSize = 14U; // The maximum size of data in a packet.
Andreas Gampe40da2862015-02-27 12:49:04 -0800938 uint8_t stack_buf[kPacketSize]; // Space to store a packet when in streaming mode.
939 if (trace_output_mode_ == TraceOutputMode::kStreaming) {
940 ptr = stack_buf;
941 } else {
942 ptr = buf_.get() + old_offset;
943 }
944
Ian Rogers62d6c772013-02-27 08:32:07 -0800945 Append2LE(ptr, thread->GetTid());
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700946 Append4LE(ptr + 2, method_value);
947 ptr += 6;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800948
949 if (UseThreadCpuClock()) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800950 Append4LE(ptr, thread_clock_diff);
951 ptr += 4;
952 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800953 if (UseWallClock()) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800954 Append4LE(ptr, wall_clock_diff);
955 }
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700956 static_assert(kPacketSize == 2 + 4 + 4 + 4, "Packet size incorrect.");
Andreas Gampe40da2862015-02-27 12:49:04 -0800957
958 if (trace_output_mode_ == TraceOutputMode::kStreaming) {
959 MutexLock mu(Thread::Current(), *streaming_lock_); // To serialize writing.
960 if (RegisterMethod(method)) {
961 // Write a special block with the name.
962 std::string method_line(GetMethodLine(method));
963 uint8_t buf2[5];
964 Append2LE(buf2, 0);
965 buf2[2] = kOpNewMethod;
966 Append2LE(buf2 + 3, static_cast<uint16_t>(method_line.length()));
967 WriteToBuf(buf2, sizeof(buf2));
968 WriteToBuf(reinterpret_cast<const uint8_t*>(method_line.c_str()), method_line.length());
969 }
970 if (RegisterThread(thread)) {
971 // It might be better to postpone this. Threads might not have received names...
972 std::string thread_name;
973 thread->GetThreadName(thread_name);
974 uint8_t buf2[7];
975 Append2LE(buf2, 0);
976 buf2[2] = kOpNewThread;
977 Append2LE(buf2 + 3, static_cast<uint16_t>(thread->GetTid()));
978 Append2LE(buf2 + 5, static_cast<uint16_t>(thread_name.length()));
979 WriteToBuf(buf2, sizeof(buf2));
980 WriteToBuf(reinterpret_cast<const uint8_t*>(thread_name.c_str()), thread_name.length());
981 }
982 WriteToBuf(stack_buf, sizeof(stack_buf));
983 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800984}
985
Ian Rogers62d6c772013-02-27 08:32:07 -0800986void Trace::GetVisitedMethods(size_t buf_size,
Mathieu Chartiere401d142015-04-22 13:56:20 -0700987 std::set<ArtMethod*>* visited_methods) {
jeffhao2692b572011-12-16 15:42:28 -0800988 uint8_t* ptr = buf_.get() + kTraceHeaderLength;
Ian Rogers62d6c772013-02-27 08:32:07 -0800989 uint8_t* end = buf_.get() + buf_size;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800990
991 while (ptr < end) {
Mathieu Chartier4d64cd42015-06-02 16:38:29 -0700992 uint32_t tmid = ReadBytes(ptr + 2, sizeof(tmid));
993 ArtMethod* method = DecodeTraceMethod(tmid);
Ian Rogers62d6c772013-02-27 08:32:07 -0800994 visited_methods->insert(method);
995 ptr += GetRecordSize(clock_source_);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800996 }
997}
998
Mathieu Chartiere401d142015-04-22 13:56:20 -0700999void Trace::DumpMethodList(std::ostream& os, const std::set<ArtMethod*>& visited_methods) {
Mathieu Chartier02e25112013-08-14 16:14:24 -07001000 for (const auto& method : visited_methods) {
Andreas Gampe40da2862015-02-27 12:49:04 -08001001 os << GetMethodLine(method);
jeffhaoa9ef3fd2011-12-13 18:33:43 -08001002 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -08001003}
1004
1005static void DumpThread(Thread* t, void* arg) {
Elliott Hughesffb465f2012-03-01 18:46:05 -08001006 std::ostream& os = *reinterpret_cast<std::ostream*>(arg);
1007 std::string name;
1008 t->GetThreadName(name);
1009 os << t->GetTid() << "\t" << name << "\n";
jeffhaoa9ef3fd2011-12-13 18:33:43 -08001010}
1011
1012void Trace::DumpThreadList(std::ostream& os) {
Ian Rogers81d425b2012-09-27 16:03:43 -07001013 Thread* self = Thread::Current();
Jeff Haoe094b872014-10-14 13:12:01 -07001014 for (auto it : exited_threads_) {
1015 os << it.first << "\t" << it.second << "\n";
1016 }
Ian Rogers81d425b2012-09-27 16:03:43 -07001017 Locks::thread_list_lock_->AssertNotHeld(self);
1018 MutexLock mu(self, *Locks::thread_list_lock_);
jeffhaoa9ef3fd2011-12-13 18:33:43 -08001019 Runtime::Current()->GetThreadList()->ForEach(DumpThread, &os);
jeffhaoe343b762011-12-05 16:36:44 -08001020}
1021
Jeff Haoe094b872014-10-14 13:12:01 -07001022void Trace::StoreExitingThreadInfo(Thread* thread) {
1023 MutexLock mu(thread, *Locks::trace_lock_);
1024 if (the_trace_ != nullptr) {
1025 std::string name;
1026 thread->GetThreadName(name);
Andreas Gampea1785c52014-11-25 20:40:08 -08001027 // The same thread/tid may be used multiple times. As SafeMap::Put does not allow to override
1028 // a previous mapping, use SafeMap::Overwrite.
1029 the_trace_->exited_threads_.Overwrite(thread->GetTid(), name);
Jeff Haoe094b872014-10-14 13:12:01 -07001030 }
1031}
1032
Andreas Gampe40da2862015-02-27 12:49:04 -08001033Trace::TraceOutputMode Trace::GetOutputMode() {
1034 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1035 CHECK(the_trace_ != nullptr) << "Trace output mode requested, but no trace currently running";
1036 return the_trace_->trace_output_mode_;
1037}
1038
1039Trace::TraceMode Trace::GetMode() {
1040 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1041 CHECK(the_trace_ != nullptr) << "Trace mode requested, but no trace currently running";
1042 return the_trace_->trace_mode_;
1043}
1044
Andreas Gampee34a42c2015-04-25 14:44:29 -07001045size_t Trace::GetBufferSize() {
1046 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
1047 CHECK(the_trace_ != nullptr) << "Trace mode requested, but no trace currently running";
1048 return the_trace_->buffer_size_;
1049}
1050
jeffhaoe343b762011-12-05 16:36:44 -08001051} // namespace art