blob: d435129a2eebe3ad450e8b20219c1631c7afebf8 [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>
20
Jeff Hao0abc72e2013-08-13 13:45:14 -070021#include "base/stl_util.h"
Elliott Hughes76160052012-12-12 16:31:20 -080022#include "base/unix_file/fd_file.h"
jeffhaoe343b762011-12-05 16:36:44 -080023#include "class_linker.h"
Ian Rogers62d6c772013-02-27 08:32:07 -080024#include "common_throws.h"
jeffhaoa9ef3fd2011-12-13 18:33:43 -080025#include "debugger.h"
Ian Rogers4f6ad8a2013-03-18 15:27:28 -070026#include "dex_file-inl.h"
jeffhao725a9572012-11-13 18:20:12 -080027#include "instrumentation.h"
Brian Carlstromea46f952013-07-30 01:26:50 -070028#include "mirror/art_method-inl.h"
Ian Rogers4f6ad8a2013-03-18 15:27:28 -070029#include "mirror/class-inl.h"
Ian Rogers2dd0e2c2013-01-24 12:42:14 -080030#include "mirror/dex_cache.h"
31#include "mirror/object_array-inl.h"
Ian Rogers4f6ad8a2013-03-18 15:27:28 -070032#include "mirror/object-inl.h"
jeffhaoa9ef3fd2011-12-13 18:33:43 -080033#include "object_utils.h"
34#include "os.h"
Ian Rogers00f7d0e2012-07-19 15:28:27 -070035#include "scoped_thread_state_change.h"
Jeff Hao0abc72e2013-08-13 13:45:14 -070036#include "ScopedLocalRef.h"
jeffhaoe343b762011-12-05 16:36:44 -080037#include "thread.h"
Ian Rogers57b86d42012-03-27 16:05:41 -070038#include "thread_list.h"
Ian Rogers166db042013-07-26 12:05:57 -070039#if !defined(ART_USE_PORTABLE_COMPILER)
40#include "entrypoints/quick/quick_entrypoints.h"
41#endif
jeffhao2692b572011-12-16 15:42:28 -080042
43namespace art {
44
Elliott Hughese119a362012-05-22 17:37:06 -070045// File format:
46// header
47// record 0
48// record 1
49// ...
50//
51// Header format:
52// u4 magic ('SLOW')
53// u2 version
54// u2 offset to data
55// u8 start date/time in usec
56// u2 record size in bytes (version >= 2 only)
57// ... padding to 32 bytes
58//
59// Record format v1:
60// u1 thread ID
61// u4 method ID | method action
62// u4 time delta since start, in usec
63//
64// Record format v2:
65// u2 thread ID
66// u4 method ID | method action
67// u4 time delta since start, in usec
68//
69// Record format v3:
70// u2 thread ID
71// u4 method ID | method action
72// u4 time delta since start, in usec
73// u4 wall time since start, in usec (when clock == "dual" only)
74//
75// 32 bits of microseconds is 70 minutes.
76//
77// All values are stored in little-endian order.
78
Ian Rogers62d6c772013-02-27 08:32:07 -080079enum TraceAction {
Brian Carlstrom7934ac22013-07-26 10:54:15 -070080 kTraceMethodEnter = 0x00, // method entry
81 kTraceMethodExit = 0x01, // method exit
82 kTraceUnroll = 0x02, // method exited by exception unrolling
Ian Rogers62d6c772013-02-27 08:32:07 -080083 // 0x03 currently unused
Brian Carlstrom7934ac22013-07-26 10:54:15 -070084 kTraceMethodActionMask = 0x03, // two bits
Ian Rogers62d6c772013-02-27 08:32:07 -080085};
86
Jeff Hao0abc72e2013-08-13 13:45:14 -070087class BuildStackTraceVisitor : public StackVisitor {
88 public:
89 explicit BuildStackTraceVisitor(Thread* thread) : StackVisitor(thread, NULL),
Ian Rogerse2f77e72013-08-13 19:19:40 -070090 method_trace_(new std::vector<mirror::ArtMethod*>) {}
Jeff Hao0abc72e2013-08-13 13:45:14 -070091
92 bool VisitFrame() {
Ian Rogerse2f77e72013-08-13 19:19:40 -070093 mirror::ArtMethod* m = GetMethod();
Jeff Hao0abc72e2013-08-13 13:45:14 -070094 // Ignore runtime frames (in particular callee save).
95 if (!m->IsRuntimeMethod()) {
96 method_trace_->push_back(m);
97 }
98 return true;
99 }
100
101 // Returns a stack trace where the topmost frame corresponds with the first element of the vector.
Ian Rogerse2f77e72013-08-13 19:19:40 -0700102 std::vector<mirror::ArtMethod*>* GetStackTrace() const {
Jeff Hao0abc72e2013-08-13 13:45:14 -0700103 return method_trace_;
104 }
105
106 private:
Ian Rogerse2f77e72013-08-13 19:19:40 -0700107 std::vector<mirror::ArtMethod*>* const method_trace_;
Jeff Hao0abc72e2013-08-13 13:45:14 -0700108};
109
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800110static const char kTraceTokenChar = '*';
111static const uint16_t kTraceHeaderLength = 32;
112static const uint32_t kTraceMagicValue = 0x574f4c53;
113static const uint16_t kTraceVersionSingleClock = 2;
114static const uint16_t kTraceVersionDualClock = 3;
Brian Carlstrom7934ac22013-07-26 10:54:15 -0700115static const uint16_t kTraceRecordSizeSingleClock = 10; // using v2
116static const uint16_t kTraceRecordSizeDualClock = 14; // using v3 with two timestamps
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800117
Ian Rogers62d6c772013-02-27 08:32:07 -0800118#if defined(HAVE_POSIX_CLOCKS)
119ProfilerClockSource Trace::default_clock_source_ = kProfilerClockSourceDual;
120#else
121ProfilerClockSource Trace::default_clock_source_ = kProfilerClockSourceWall;
122#endif
Elliott Hughese119a362012-05-22 17:37:06 -0700123
Jeff Hao0abc72e2013-08-13 13:45:14 -0700124Trace* volatile Trace::the_trace_ = NULL;
125// TODO: Add way to enable sampling and set interval through gui.
126bool Trace::sampling_enabled_ = true;
127uint32_t Trace::sampling_interval_us_ = 10000;
128pthread_t Trace::sampling_pthread_ = 0U;
Ian Rogers62d6c772013-02-27 08:32:07 -0800129
Brian Carlstromea46f952013-07-30 01:26:50 -0700130static mirror::ArtMethod* DecodeTraceMethodId(uint32_t tmid) {
131 return reinterpret_cast<mirror::ArtMethod*>(tmid & ~kTraceMethodActionMask);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800132}
Elliott Hughese119a362012-05-22 17:37:06 -0700133
Ian Rogers62d6c772013-02-27 08:32:07 -0800134static TraceAction DecodeTraceAction(uint32_t tmid) {
135 return static_cast<TraceAction>(tmid & kTraceMethodActionMask);
136}
137
Brian Carlstromea46f952013-07-30 01:26:50 -0700138static uint32_t EncodeTraceMethodAndAction(const mirror::ArtMethod* method,
Ian Rogers62d6c772013-02-27 08:32:07 -0800139 TraceAction action) {
140 uint32_t tmid = reinterpret_cast<uint32_t>(method) | action;
141 DCHECK_EQ(method, DecodeTraceMethodId(tmid));
142 return tmid;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800143}
144
Elliott Hughese119a362012-05-22 17:37:06 -0700145void Trace::SetDefaultClockSource(ProfilerClockSource clock_source) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800146#if defined(HAVE_POSIX_CLOCKS)
147 default_clock_source_ = clock_source;
148#else
149 if (clock_source != kProfilerClockSourceWall) {
150 LOG(WARNING) << "Ignoring tracing request to use ";
151 }
152#endif
153}
154
155static uint16_t GetTraceVersion(ProfilerClockSource clock_source) {
156 return (clock_source == kProfilerClockSourceDual) ? kTraceVersionDualClock
157 : kTraceVersionSingleClock;
158}
159
160static uint16_t GetRecordSize(ProfilerClockSource clock_source) {
161 return (clock_source == kProfilerClockSourceDual) ? kTraceRecordSizeDualClock
162 : kTraceRecordSizeSingleClock;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800163}
164
Elliott Hughese119a362012-05-22 17:37:06 -0700165bool Trace::UseThreadCpuClock() {
Ian Rogers62d6c772013-02-27 08:32:07 -0800166 return (clock_source_ == kProfilerClockSourceThreadCpu) ||
167 (clock_source_ == kProfilerClockSourceDual);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800168}
169
Elliott Hughese119a362012-05-22 17:37:06 -0700170bool Trace::UseWallClock() {
Ian Rogers62d6c772013-02-27 08:32:07 -0800171 return (clock_source_ == kProfilerClockSourceWall) ||
172 (clock_source_ == kProfilerClockSourceDual);
Elliott Hughese119a362012-05-22 17:37:06 -0700173}
174
175static void MeasureClockOverhead(Trace* trace) {
176 if (trace->UseThreadCpuClock()) {
Jeff Hao57dac6e2013-08-15 16:36:24 -0700177 Thread::Current()->GetCpuMicroTime();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800178 }
Elliott Hughese119a362012-05-22 17:37:06 -0700179 if (trace->UseWallClock()) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800180 MicroTime();
181 }
182}
183
Elliott Hughese119a362012-05-22 17:37:06 -0700184static uint32_t GetClockOverhead(Trace* trace) {
Jeff Hao57dac6e2013-08-15 16:36:24 -0700185 Thread* self = Thread::Current();
186 uint64_t start = self->GetCpuMicroTime();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800187
188 for (int i = 4000; i > 0; i--) {
Elliott Hughese119a362012-05-22 17:37:06 -0700189 MeasureClockOverhead(trace);
190 MeasureClockOverhead(trace);
191 MeasureClockOverhead(trace);
192 MeasureClockOverhead(trace);
193 MeasureClockOverhead(trace);
194 MeasureClockOverhead(trace);
195 MeasureClockOverhead(trace);
196 MeasureClockOverhead(trace);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800197 }
198
Jeff Hao57dac6e2013-08-15 16:36:24 -0700199 uint64_t elapsed = self->GetCpuMicroTime() - start;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800200 return uint32_t (elapsed / 32);
201}
202
Elliott Hughesffb465f2012-03-01 18:46:05 -0800203// TODO: put this somewhere with the big-endian equivalent used by JDWP.
204static void Append2LE(uint8_t* buf, uint16_t val) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800205 *buf++ = (uint8_t) val;
206 *buf++ = (uint8_t) (val >> 8);
207}
208
Elliott Hughesffb465f2012-03-01 18:46:05 -0800209// TODO: put this somewhere with the big-endian equivalent used by JDWP.
210static void Append4LE(uint8_t* buf, uint32_t val) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800211 *buf++ = (uint8_t) val;
212 *buf++ = (uint8_t) (val >> 8);
213 *buf++ = (uint8_t) (val >> 16);
214 *buf++ = (uint8_t) (val >> 24);
215}
216
Elliott Hughesffb465f2012-03-01 18:46:05 -0800217// TODO: put this somewhere with the big-endian equivalent used by JDWP.
218static void Append8LE(uint8_t* buf, uint64_t val) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800219 *buf++ = (uint8_t) val;
220 *buf++ = (uint8_t) (val >> 8);
221 *buf++ = (uint8_t) (val >> 16);
222 *buf++ = (uint8_t) (val >> 24);
223 *buf++ = (uint8_t) (val >> 32);
224 *buf++ = (uint8_t) (val >> 40);
225 *buf++ = (uint8_t) (val >> 48);
226 *buf++ = (uint8_t) (val >> 56);
227}
228
Jeff Hao0abc72e2013-08-13 13:45:14 -0700229static void GetSample(Thread* thread, void* arg) SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
230 BuildStackTraceVisitor build_trace_visitor(thread);
231 build_trace_visitor.WalkStack();
Ian Rogerse2f77e72013-08-13 19:19:40 -0700232 std::vector<mirror::ArtMethod*>* stack_trace = build_trace_visitor.GetStackTrace();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700233 Trace* the_trace = reinterpret_cast<Trace*>(arg);
234 the_trace->CompareAndUpdateStackTrace(thread, stack_trace);
235}
236
237void Trace::CompareAndUpdateStackTrace(Thread* thread,
Ian Rogerse2f77e72013-08-13 19:19:40 -0700238 std::vector<mirror::ArtMethod*>* stack_trace) {
Jeff Hao0abc72e2013-08-13 13:45:14 -0700239 CHECK_EQ(pthread_self(), sampling_pthread_);
Ian Rogerse2f77e72013-08-13 19:19:40 -0700240 SafeMap<Thread*, std::vector<mirror::ArtMethod*>*>::iterator map_it = thread_stack_trace_map_.find(thread);
Jeff Hao0abc72e2013-08-13 13:45:14 -0700241 if (map_it == thread_stack_trace_map_.end()) {
242 // If there's no existing stack trace in the map for this thread, log an entry event for all
243 // methods in the trace.
244 thread_stack_trace_map_.Put(thread, stack_trace);
Ian Rogerse2f77e72013-08-13 19:19:40 -0700245 for (std::vector<mirror::ArtMethod*>::reverse_iterator rit = stack_trace->rbegin();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700246 rit != stack_trace->rend(); ++rit) {
247 LogMethodTraceEvent(thread, *rit, instrumentation::Instrumentation::kMethodEntered);
248 }
249 } else {
250 // If there's a previous stack trace for this thread, diff the traces and emit entry and exit
251 // events accordingly.
Ian Rogerse2f77e72013-08-13 19:19:40 -0700252 std::vector<mirror::ArtMethod*>* old_stack_trace = map_it->second;
Jeff Hao0abc72e2013-08-13 13:45:14 -0700253 thread_stack_trace_map_.Overwrite(thread, stack_trace);
Ian Rogerse2f77e72013-08-13 19:19:40 -0700254 std::vector<mirror::ArtMethod*>::reverse_iterator old_rit = old_stack_trace->rbegin();
255 std::vector<mirror::ArtMethod*>::reverse_iterator rit = stack_trace->rbegin();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700256
257 // Iterate bottom-up over both traces until there's a difference between them.
258 while (old_rit != old_stack_trace->rend() && rit != stack_trace->rend() && *old_rit == *rit) {
259 old_rit++;
260 rit++;
261 }
262 // Iterate top-down over the old trace until the point where they differ, emitting exit events.
Ian Rogerse2f77e72013-08-13 19:19:40 -0700263 for (std::vector<mirror::ArtMethod*>::iterator old_it = old_stack_trace->begin();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700264 old_it != old_rit.base(); ++old_it) {
265 LogMethodTraceEvent(thread, *old_it, instrumentation::Instrumentation::kMethodExited);
266 }
267 // Iterate bottom-up over the new trace from the point where they differ, emitting entry events.
268 for (; rit != stack_trace->rend(); ++rit) {
269 LogMethodTraceEvent(thread, *rit, instrumentation::Instrumentation::kMethodEntered);
270 }
271 delete old_stack_trace;
272 }
273}
274
275void* Trace::RunSamplingThread(void* arg) {
276 Runtime* runtime = Runtime::Current();
277 CHECK(runtime->AttachCurrentThread("Sampling Profiler", true, runtime->GetSystemThreadGroup(),
278 !runtime->IsCompiler()));
279
280 while (true) {
281 usleep(sampling_interval_us_);
282
283 Thread* self = Thread::Current();
284 Trace* the_trace;
285 {
286 MutexLock mu(self, *Locks::trace_lock_);
287 the_trace = the_trace_;
288 if (the_trace == NULL) {
289 break;
290 }
291 }
292
293 runtime->GetThreadList()->SuspendAll();
294 {
295 MutexLock mu(self, *Locks::thread_list_lock_);
296 runtime->GetThreadList()->ForEach(GetSample, the_trace);
297 }
298 runtime->GetThreadList()->ResumeAll();
299 }
300
301 runtime->DetachCurrentThread();
302 return NULL;
303}
304
Ian Rogers62d6c772013-02-27 08:32:07 -0800305void Trace::Start(const char* trace_filename, int trace_fd, int buffer_size, int flags,
306 bool direct_to_ddms) {
307 Thread* self = Thread::Current();
308 {
309 MutexLock mu(self, *Locks::trace_lock_);
310 if (the_trace_ != NULL) {
311 LOG(ERROR) << "Trace already in progress, ignoring this request";
312 return;
313 }
jeffhaoe343b762011-12-05 16:36:44 -0800314 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800315 Runtime* runtime = Runtime::Current();
316 runtime->GetThreadList()->SuspendAll();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800317
jeffhao2692b572011-12-16 15:42:28 -0800318 // Open trace file if not going directly to ddms.
Ian Rogers62d6c772013-02-27 08:32:07 -0800319 UniquePtr<File> trace_file;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800320 if (!direct_to_ddms) {
321 if (trace_fd < 0) {
Brian Carlstrom7571e8b2013-08-12 17:04:14 -0700322 trace_file.reset(OS::CreateEmptyFile(trace_filename));
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800323 } else {
Ian Rogers62d6c772013-02-27 08:32:07 -0800324 trace_file.reset(new File(trace_fd, "tracefile"));
Elliott Hughes76160052012-12-12 16:31:20 -0800325 trace_file->DisableAutoClose();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800326 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800327 if (trace_file.get() == NULL) {
jeffhaob5e81852012-03-12 11:15:45 -0700328 PLOG(ERROR) << "Unable to open trace file '" << trace_filename << "'";
Ian Rogers62d6c772013-02-27 08:32:07 -0800329 runtime->GetThreadList()->ResumeAll();
330 ScopedObjectAccess soa(self);
331 ThrowRuntimeException("Unable to open trace file '%s'", trace_filename);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800332 return;
333 }
334 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800335
jeffhao2692b572011-12-16 15:42:28 -0800336 // Create Trace object.
Ian Rogers62d6c772013-02-27 08:32:07 -0800337 {
338 MutexLock mu(self, *Locks::trace_lock_);
Brian Carlstromdf629502013-07-17 22:39:56 -0700339 if (the_trace_ != NULL) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800340 LOG(ERROR) << "Trace already in progress, ignoring this request";
341 } else {
342 the_trace_ = new Trace(trace_file.release(), buffer_size, flags);
jeffhao0791adc2012-04-04 11:14:32 -0700343
Ian Rogers62d6c772013-02-27 08:32:07 -0800344 // Enable count of allocs if specified in the flags.
345 if ((flags && kTraceCountAllocs) != 0) {
346 runtime->SetStatsEnabled(true);
347 }
348
Jeff Hao0abc72e2013-08-13 13:45:14 -0700349 if (sampling_enabled_) {
350 CHECK_PTHREAD_CALL(pthread_create, (&sampling_pthread_, NULL, &RunSamplingThread, NULL),
351 "Sampling profiler thread");
352 } else {
353 runtime->GetInstrumentation()->AddListener(the_trace_,
354 instrumentation::Instrumentation::kMethodEntered |
355 instrumentation::Instrumentation::kMethodExited |
356 instrumentation::Instrumentation::kMethodUnwind);
357 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800358 }
jeffhao0791adc2012-04-04 11:14:32 -0700359 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800360 runtime->GetThreadList()->ResumeAll();
jeffhao2692b572011-12-16 15:42:28 -0800361}
362
363void Trace::Stop() {
Ian Rogers62d6c772013-02-27 08:32:07 -0800364 Runtime* runtime = Runtime::Current();
365 runtime->GetThreadList()->SuspendAll();
366 Trace* the_trace = NULL;
Jeff Hao0abc72e2013-08-13 13:45:14 -0700367 pthread_t sampling_pthread = 0U;
Ian Rogers62d6c772013-02-27 08:32:07 -0800368 {
369 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
370 if (the_trace_ == NULL) {
371 LOG(ERROR) << "Trace stop requested, but no trace currently running";
372 } else {
373 the_trace = the_trace_;
374 the_trace_ = NULL;
Jeff Hao0abc72e2013-08-13 13:45:14 -0700375 sampling_pthread = sampling_pthread_;
376 sampling_pthread_ = 0U;
Ian Rogers62d6c772013-02-27 08:32:07 -0800377 }
jeffhao2692b572011-12-16 15:42:28 -0800378 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800379 if (the_trace != NULL) {
380 the_trace->FinishTracing();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700381
382 if (!sampling_enabled_) {
383 runtime->GetInstrumentation()->RemoveListener(the_trace,
384 instrumentation::Instrumentation::kMethodEntered |
385 instrumentation::Instrumentation::kMethodExited |
386 instrumentation::Instrumentation::kMethodUnwind);
387 }
Ian Rogers62d6c772013-02-27 08:32:07 -0800388 delete the_trace;
389 }
390 runtime->GetThreadList()->ResumeAll();
Jeff Hao0abc72e2013-08-13 13:45:14 -0700391
392 if (sampling_enabled_ && sampling_pthread != 0U) {
393 CHECK_PTHREAD_CALL(pthread_join, (sampling_pthread, NULL), "sampling thread shutdown");
394 }
jeffhao2692b572011-12-16 15:42:28 -0800395}
396
jeffhaob5e81852012-03-12 11:15:45 -0700397void Trace::Shutdown() {
Ian Rogers62d6c772013-02-27 08:32:07 -0800398 if (IsMethodTracingActive()) {
399 Stop();
jeffhaob5e81852012-03-12 11:15:45 -0700400 }
jeffhaob5e81852012-03-12 11:15:45 -0700401}
402
Ian Rogers62d6c772013-02-27 08:32:07 -0800403bool Trace::IsMethodTracingActive() {
404 MutexLock mu(Thread::Current(), *Locks::trace_lock_);
405 return the_trace_ != NULL;
406}
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800407
Ian Rogers62d6c772013-02-27 08:32:07 -0800408Trace::Trace(File* trace_file, int buffer_size, int flags)
409 : trace_file_(trace_file), buf_(new uint8_t[buffer_size]()), flags_(flags),
410 clock_source_(default_clock_source_), buffer_size_(buffer_size), start_time_(MicroTime()),
411 cur_offset_(0), overflow_(false) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800412 // Set up the beginning of the trace.
Ian Rogers62d6c772013-02-27 08:32:07 -0800413 uint16_t trace_version = GetTraceVersion(clock_source_);
jeffhao2692b572011-12-16 15:42:28 -0800414 memset(buf_.get(), 0, kTraceHeaderLength);
415 Append4LE(buf_.get(), kTraceMagicValue);
Ian Rogers62d6c772013-02-27 08:32:07 -0800416 Append2LE(buf_.get() + 4, trace_version);
jeffhao2692b572011-12-16 15:42:28 -0800417 Append2LE(buf_.get() + 6, kTraceHeaderLength);
418 Append8LE(buf_.get() + 8, start_time_);
Ian Rogers62d6c772013-02-27 08:32:07 -0800419 if (trace_version >= kTraceVersionDualClock) {
420 uint16_t record_size = GetRecordSize(clock_source_);
421 Append2LE(buf_.get() + 16, record_size);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800422 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800423
jeffhao2692b572011-12-16 15:42:28 -0800424 // Update current offset.
425 cur_offset_ = kTraceHeaderLength;
Ian Rogers62d6c772013-02-27 08:32:07 -0800426}
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800427
Jeff Hao0abc72e2013-08-13 13:45:14 -0700428Trace::~Trace() {
429 CHECK_EQ(sampling_pthread_, static_cast<pthread_t>(0U));
430 STLDeleteValues(&thread_stack_trace_map_);
431}
432
Ian Rogers62d6c772013-02-27 08:32:07 -0800433static void DumpBuf(uint8_t* buf, size_t buf_size, ProfilerClockSource clock_source)
434 SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
435 uint8_t* ptr = buf + kTraceHeaderLength;
436 uint8_t* end = buf + buf_size;
437
438 while (ptr < end) {
439 uint32_t tmid = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16) | (ptr[5] << 24);
Brian Carlstromea46f952013-07-30 01:26:50 -0700440 mirror::ArtMethod* method = DecodeTraceMethodId(tmid);
Ian Rogers62d6c772013-02-27 08:32:07 -0800441 TraceAction action = DecodeTraceAction(tmid);
442 LOG(INFO) << PrettyMethod(method) << " " << static_cast<int>(action);
443 ptr += GetRecordSize(clock_source);
444 }
jeffhaoe343b762011-12-05 16:36:44 -0800445}
446
jeffhao2692b572011-12-16 15:42:28 -0800447void Trace::FinishTracing() {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800448 // Compute elapsed time.
449 uint64_t elapsed = MicroTime() - start_time_;
450
451 size_t final_offset = cur_offset_;
Elliott Hughese119a362012-05-22 17:37:06 -0700452 uint32_t clock_overhead = GetClockOverhead(this);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800453
jeffhao0791adc2012-04-04 11:14:32 -0700454 if ((flags_ & kTraceCountAllocs) != 0) {
455 Runtime::Current()->SetStatsEnabled(false);
456 }
457
Brian Carlstromea46f952013-07-30 01:26:50 -0700458 std::set<mirror::ArtMethod*> visited_methods;
Ian Rogers62d6c772013-02-27 08:32:07 -0800459 GetVisitedMethods(final_offset, &visited_methods);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800460
461 std::ostringstream os;
462
463 os << StringPrintf("%cversion\n", kTraceTokenChar);
Ian Rogers62d6c772013-02-27 08:32:07 -0800464 os << StringPrintf("%d\n", GetTraceVersion(clock_source_));
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800465 os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false");
466 if (UseThreadCpuClock()) {
467 if (UseWallClock()) {
468 os << StringPrintf("clock=dual\n");
469 } else {
470 os << StringPrintf("clock=thread-cpu\n");
471 }
472 } else {
473 os << StringPrintf("clock=wall\n");
474 }
475 os << StringPrintf("elapsed-time-usec=%llu\n", elapsed);
Ian Rogers62d6c772013-02-27 08:32:07 -0800476 size_t num_records = (final_offset - kTraceHeaderLength) / GetRecordSize(clock_source_);
477 os << StringPrintf("num-method-calls=%zd\n", num_records);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800478 os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead);
479 os << StringPrintf("vm=art\n");
jeffhao0791adc2012-04-04 11:14:32 -0700480 if ((flags_ & kTraceCountAllocs) != 0) {
481 os << StringPrintf("alloc-count=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_OBJECTS));
482 os << StringPrintf("alloc-size=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_BYTES));
483 os << StringPrintf("gc-count=%d\n", Runtime::Current()->GetStat(KIND_GC_INVOCATIONS));
484 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800485 os << StringPrintf("%cthreads\n", kTraceTokenChar);
486 DumpThreadList(os);
487 os << StringPrintf("%cmethods\n", kTraceTokenChar);
Ian Rogers62d6c772013-02-27 08:32:07 -0800488 DumpMethodList(os, visited_methods);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800489 os << StringPrintf("%cend\n", kTraceTokenChar);
490
491 std::string header(os.str());
jeffhao2692b572011-12-16 15:42:28 -0800492 if (trace_file_.get() == NULL) {
Elliott Hughes7b9d9962012-04-20 18:48:18 -0700493 iovec iov[2];
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800494 iov[0].iov_base = reinterpret_cast<void*>(const_cast<char*>(header.c_str()));
495 iov[0].iov_len = header.length();
jeffhao2692b572011-12-16 15:42:28 -0800496 iov[1].iov_base = buf_.get();
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800497 iov[1].iov_len = final_offset;
498 Dbg::DdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2);
Ian Rogers62d6c772013-02-27 08:32:07 -0800499 const bool kDumpTraceInfo = false;
500 if (kDumpTraceInfo) {
501 LOG(INFO) << "Trace sent:\n" << header;
502 DumpBuf(buf_.get(), final_offset, clock_source_);
503 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800504 } else {
505 if (!trace_file_->WriteFully(header.c_str(), header.length()) ||
jeffhao2692b572011-12-16 15:42:28 -0800506 !trace_file_->WriteFully(buf_.get(), final_offset)) {
Elliott Hughes7b9d9962012-04-20 18:48:18 -0700507 std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno)));
508 PLOG(ERROR) << detail;
Ian Rogers62d6c772013-02-27 08:32:07 -0800509 ThrowRuntimeException("%s", detail.c_str());
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800510 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800511 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800512}
513
Ian Rogers62d6c772013-02-27 08:32:07 -0800514void Trace::DexPcMoved(Thread* thread, mirror::Object* this_object,
Brian Carlstromea46f952013-07-30 01:26:50 -0700515 const mirror::ArtMethod* method, uint32_t new_dex_pc) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800516 // We're not recorded to listen to this kind of event, so complain.
517 LOG(ERROR) << "Unexpected dex PC event in tracing " << PrettyMethod(method) << " " << new_dex_pc;
518};
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800519
Ian Rogers62d6c772013-02-27 08:32:07 -0800520void Trace::MethodEntered(Thread* thread, mirror::Object* this_object,
Brian Carlstromea46f952013-07-30 01:26:50 -0700521 const mirror::ArtMethod* method, uint32_t dex_pc) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800522 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodEntered);
523}
524
525void Trace::MethodExited(Thread* thread, mirror::Object* this_object,
Brian Carlstromea46f952013-07-30 01:26:50 -0700526 const mirror::ArtMethod* method, uint32_t dex_pc,
Ian Rogers62d6c772013-02-27 08:32:07 -0800527 const JValue& return_value) {
528 UNUSED(return_value);
529 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodExited);
530}
531
Brian Carlstromea46f952013-07-30 01:26:50 -0700532void Trace::MethodUnwind(Thread* thread, const mirror::ArtMethod* method, uint32_t dex_pc) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800533 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodUnwind);
534}
535
536void Trace::ExceptionCaught(Thread* thread, const ThrowLocation& throw_location,
Brian Carlstromea46f952013-07-30 01:26:50 -0700537 mirror::ArtMethod* catch_method, uint32_t catch_dex_pc,
Ian Rogers62d6c772013-02-27 08:32:07 -0800538 mirror::Throwable* exception_object)
539 SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
540 LOG(ERROR) << "Unexpected exception caught event in tracing";
541}
542
Brian Carlstromea46f952013-07-30 01:26:50 -0700543void Trace::LogMethodTraceEvent(Thread* thread, const mirror::ArtMethod* method,
Ian Rogers62d6c772013-02-27 08:32:07 -0800544 instrumentation::Instrumentation::InstrumentationEvent event) {
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800545 // Advance cur_offset_ atomically.
546 int32_t new_offset;
547 int32_t old_offset;
548 do {
549 old_offset = cur_offset_;
Ian Rogers62d6c772013-02-27 08:32:07 -0800550 new_offset = old_offset + GetRecordSize(clock_source_);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800551 if (new_offset > buffer_size_) {
552 overflow_ = true;
553 return;
554 }
555 } while (android_atomic_release_cas(old_offset, new_offset, &cur_offset_) != 0);
556
Ian Rogers62d6c772013-02-27 08:32:07 -0800557 TraceAction action = kTraceMethodEnter;
558 switch (event) {
559 case instrumentation::Instrumentation::kMethodEntered:
560 action = kTraceMethodEnter;
561 break;
562 case instrumentation::Instrumentation::kMethodExited:
563 action = kTraceMethodExit;
564 break;
565 case instrumentation::Instrumentation::kMethodUnwind:
566 action = kTraceUnroll;
567 break;
568 default:
569 UNIMPLEMENTED(FATAL) << "Unexpected event: " << event;
570 }
571
572 uint32_t method_value = EncodeTraceMethodAndAction(method, action);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800573
574 // Write data
jeffhao2692b572011-12-16 15:42:28 -0800575 uint8_t* ptr = buf_.get() + old_offset;
Ian Rogers62d6c772013-02-27 08:32:07 -0800576 Append2LE(ptr, thread->GetTid());
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800577 Append4LE(ptr + 2, method_value);
578 ptr += 6;
579
580 if (UseThreadCpuClock()) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800581 // TODO: this isn't vaguely thread safe.
582 SafeMap<Thread*, uint64_t>::iterator it = thread_clock_base_map_.find(thread);
583 uint32_t thread_clock_diff = 0;
584 if (UNLIKELY(it == thread_clock_base_map_.end())) {
585 // First event, the diff is 0, record the base time in the map.
Jeff Hao57dac6e2013-08-15 16:36:24 -0700586 uint64_t time = thread->GetCpuMicroTime();
Ian Rogers62d6c772013-02-27 08:32:07 -0800587 thread_clock_base_map_.Put(thread, time);
588 } else {
589 uint64_t thread_clock_base = it->second;
Jeff Hao57dac6e2013-08-15 16:36:24 -0700590 thread_clock_diff = thread->GetCpuMicroTime() - thread_clock_base;
Ian Rogers62d6c772013-02-27 08:32:07 -0800591 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800592 Append4LE(ptr, thread_clock_diff);
593 ptr += 4;
594 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800595 if (UseWallClock()) {
596 uint32_t wall_clock_diff = MicroTime() - start_time_;
597 Append4LE(ptr, wall_clock_diff);
598 }
599}
600
Ian Rogers62d6c772013-02-27 08:32:07 -0800601void Trace::GetVisitedMethods(size_t buf_size,
Brian Carlstromea46f952013-07-30 01:26:50 -0700602 std::set<mirror::ArtMethod*>* visited_methods) {
jeffhao2692b572011-12-16 15:42:28 -0800603 uint8_t* ptr = buf_.get() + kTraceHeaderLength;
Ian Rogers62d6c772013-02-27 08:32:07 -0800604 uint8_t* end = buf_.get() + buf_size;
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800605
606 while (ptr < end) {
Ian Rogers62d6c772013-02-27 08:32:07 -0800607 uint32_t tmid = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16) | (ptr[5] << 24);
Brian Carlstromea46f952013-07-30 01:26:50 -0700608 mirror::ArtMethod* method = DecodeTraceMethodId(tmid);
Ian Rogers62d6c772013-02-27 08:32:07 -0800609 visited_methods->insert(method);
610 ptr += GetRecordSize(clock_source_);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800611 }
612}
613
Ian Rogers62d6c772013-02-27 08:32:07 -0800614void Trace::DumpMethodList(std::ostream& os,
Brian Carlstromea46f952013-07-30 01:26:50 -0700615 const std::set<mirror::ArtMethod*>& visited_methods) {
616 typedef std::set<mirror::ArtMethod*>::const_iterator It; // TODO: C++0x auto
Ian Rogers62d6c772013-02-27 08:32:07 -0800617 MethodHelper mh;
618 for (It it = visited_methods.begin(); it != visited_methods.end(); ++it) {
Brian Carlstromea46f952013-07-30 01:26:50 -0700619 mirror::ArtMethod* method = *it;
Ian Rogers62d6c772013-02-27 08:32:07 -0800620 mh.ChangeMethod(method);
Ian Rogers0399dde2012-06-06 17:09:28 -0700621 os << StringPrintf("%p\t%s\t%s\t%s\t%s\n", method,
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800622 PrettyDescriptor(mh.GetDeclaringClassDescriptor()).c_str(), mh.GetName(),
Ian Rogers0399dde2012-06-06 17:09:28 -0700623 mh.GetSignature().c_str(), mh.GetDeclaringClassSourceFile());
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800624 }
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800625}
626
627static void DumpThread(Thread* t, void* arg) {
Elliott Hughesffb465f2012-03-01 18:46:05 -0800628 std::ostream& os = *reinterpret_cast<std::ostream*>(arg);
629 std::string name;
630 t->GetThreadName(name);
631 os << t->GetTid() << "\t" << name << "\n";
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800632}
633
634void Trace::DumpThreadList(std::ostream& os) {
Ian Rogers81d425b2012-09-27 16:03:43 -0700635 Thread* self = Thread::Current();
636 Locks::thread_list_lock_->AssertNotHeld(self);
637 MutexLock mu(self, *Locks::thread_list_lock_);
jeffhaoa9ef3fd2011-12-13 18:33:43 -0800638 Runtime::Current()->GetThreadList()->ForEach(DumpThread, &os);
jeffhaoe343b762011-12-05 16:36:44 -0800639}
640
jeffhaoe343b762011-12-05 16:36:44 -0800641} // namespace art