trace.cc revision 834b394ee759ed31c5371d8093d7cd8cd90014a8
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 21#include "base/unix_file/fd_file.h" 22#include "class_linker.h" 23#include "common_throws.h" 24#include "debugger.h" 25#include "dex_file-inl.h" 26#include "instrumentation.h" 27#include "mirror/abstract_method-inl.h" 28#include "mirror/class-inl.h" 29#include "mirror/dex_cache.h" 30#include "mirror/object_array-inl.h" 31#include "mirror/object-inl.h" 32#include "object_utils.h" 33#include "os.h" 34#include "scoped_thread_state_change.h" 35#include "thread.h" 36#include "thread_list.h" 37#if !defined(ART_USE_PORTABLE_COMPILER) 38#include "entrypoints/quick/quick_entrypoints.h" 39#endif 40 41namespace art { 42 43// File format: 44// header 45// record 0 46// record 1 47// ... 48// 49// Header format: 50// u4 magic ('SLOW') 51// u2 version 52// u2 offset to data 53// u8 start date/time in usec 54// u2 record size in bytes (version >= 2 only) 55// ... padding to 32 bytes 56// 57// Record format v1: 58// u1 thread ID 59// u4 method ID | method action 60// u4 time delta since start, in usec 61// 62// Record format v2: 63// u2 thread ID 64// u4 method ID | method action 65// u4 time delta since start, in usec 66// 67// Record format v3: 68// u2 thread ID 69// u4 method ID | method action 70// u4 time delta since start, in usec 71// u4 wall time since start, in usec (when clock == "dual" only) 72// 73// 32 bits of microseconds is 70 minutes. 74// 75// All values are stored in little-endian order. 76 77enum TraceAction { 78 kTraceMethodEnter = 0x00, // method entry 79 kTraceMethodExit = 0x01, // method exit 80 kTraceUnroll = 0x02, // method exited by exception unrolling 81 // 0x03 currently unused 82 kTraceMethodActionMask = 0x03, // two bits 83}; 84 85static const char kTraceTokenChar = '*'; 86static const uint16_t kTraceHeaderLength = 32; 87static const uint32_t kTraceMagicValue = 0x574f4c53; 88static const uint16_t kTraceVersionSingleClock = 2; 89static const uint16_t kTraceVersionDualClock = 3; 90static const uint16_t kTraceRecordSizeSingleClock = 10; // using v2 91static const uint16_t kTraceRecordSizeDualClock = 14; // using v3 with two timestamps 92 93#if defined(HAVE_POSIX_CLOCKS) 94ProfilerClockSource Trace::default_clock_source_ = kProfilerClockSourceDual; 95#else 96ProfilerClockSource Trace::default_clock_source_ = kProfilerClockSourceWall; 97#endif 98 99Trace* Trace::the_trace_ = NULL; 100 101static mirror::AbstractMethod* DecodeTraceMethodId(uint32_t tmid) { 102 return reinterpret_cast<mirror::AbstractMethod*>(tmid & ~kTraceMethodActionMask); 103} 104 105static TraceAction DecodeTraceAction(uint32_t tmid) { 106 return static_cast<TraceAction>(tmid & kTraceMethodActionMask); 107} 108 109static uint32_t EncodeTraceMethodAndAction(const mirror::AbstractMethod* method, 110 TraceAction action) { 111 uint32_t tmid = reinterpret_cast<uint32_t>(method) | action; 112 DCHECK_EQ(method, DecodeTraceMethodId(tmid)); 113 return tmid; 114} 115 116void Trace::SetDefaultClockSource(ProfilerClockSource clock_source) { 117#if defined(HAVE_POSIX_CLOCKS) 118 default_clock_source_ = clock_source; 119#else 120 if (clock_source != kProfilerClockSourceWall) { 121 LOG(WARNING) << "Ignoring tracing request to use "; 122 } 123#endif 124} 125 126static uint16_t GetTraceVersion(ProfilerClockSource clock_source) { 127 return (clock_source == kProfilerClockSourceDual) ? kTraceVersionDualClock 128 : kTraceVersionSingleClock; 129} 130 131static uint16_t GetRecordSize(ProfilerClockSource clock_source) { 132 return (clock_source == kProfilerClockSourceDual) ? kTraceRecordSizeDualClock 133 : kTraceRecordSizeSingleClock; 134} 135 136bool Trace::UseThreadCpuClock() { 137 return (clock_source_ == kProfilerClockSourceThreadCpu) || 138 (clock_source_ == kProfilerClockSourceDual); 139} 140 141bool Trace::UseWallClock() { 142 return (clock_source_ == kProfilerClockSourceWall) || 143 (clock_source_ == kProfilerClockSourceDual); 144} 145 146static void MeasureClockOverhead(Trace* trace) { 147 if (trace->UseThreadCpuClock()) { 148 ThreadCpuMicroTime(); 149 } 150 if (trace->UseWallClock()) { 151 MicroTime(); 152 } 153} 154 155static uint32_t GetClockOverhead(Trace* trace) { 156 uint64_t start = ThreadCpuMicroTime(); 157 158 for (int i = 4000; i > 0; i--) { 159 MeasureClockOverhead(trace); 160 MeasureClockOverhead(trace); 161 MeasureClockOverhead(trace); 162 MeasureClockOverhead(trace); 163 MeasureClockOverhead(trace); 164 MeasureClockOverhead(trace); 165 MeasureClockOverhead(trace); 166 MeasureClockOverhead(trace); 167 } 168 169 uint64_t elapsed = ThreadCpuMicroTime() - start; 170 return uint32_t (elapsed / 32); 171} 172 173// TODO: put this somewhere with the big-endian equivalent used by JDWP. 174static void Append2LE(uint8_t* buf, uint16_t val) { 175 *buf++ = (uint8_t) val; 176 *buf++ = (uint8_t) (val >> 8); 177} 178 179// TODO: put this somewhere with the big-endian equivalent used by JDWP. 180static void Append4LE(uint8_t* buf, uint32_t val) { 181 *buf++ = (uint8_t) val; 182 *buf++ = (uint8_t) (val >> 8); 183 *buf++ = (uint8_t) (val >> 16); 184 *buf++ = (uint8_t) (val >> 24); 185} 186 187// TODO: put this somewhere with the big-endian equivalent used by JDWP. 188static void Append8LE(uint8_t* buf, uint64_t val) { 189 *buf++ = (uint8_t) val; 190 *buf++ = (uint8_t) (val >> 8); 191 *buf++ = (uint8_t) (val >> 16); 192 *buf++ = (uint8_t) (val >> 24); 193 *buf++ = (uint8_t) (val >> 32); 194 *buf++ = (uint8_t) (val >> 40); 195 *buf++ = (uint8_t) (val >> 48); 196 *buf++ = (uint8_t) (val >> 56); 197} 198 199void Trace::Start(const char* trace_filename, int trace_fd, int buffer_size, int flags, 200 bool direct_to_ddms) { 201 Thread* self = Thread::Current(); 202 { 203 MutexLock mu(self, *Locks::trace_lock_); 204 if (the_trace_ != NULL) { 205 LOG(ERROR) << "Trace already in progress, ignoring this request"; 206 return; 207 } 208 } 209 Runtime* runtime = Runtime::Current(); 210 runtime->GetThreadList()->SuspendAll(); 211 212 // Open trace file if not going directly to ddms. 213 UniquePtr<File> trace_file; 214 if (!direct_to_ddms) { 215 if (trace_fd < 0) { 216 trace_file.reset(OS::OpenFile(trace_filename, true)); 217 } else { 218 trace_file.reset(new File(trace_fd, "tracefile")); 219 trace_file->DisableAutoClose(); 220 } 221 if (trace_file.get() == NULL) { 222 PLOG(ERROR) << "Unable to open trace file '" << trace_filename << "'"; 223 runtime->GetThreadList()->ResumeAll(); 224 ScopedObjectAccess soa(self); 225 ThrowRuntimeException("Unable to open trace file '%s'", trace_filename); 226 return; 227 } 228 } 229 230 // Create Trace object. 231 { 232 MutexLock mu(self, *Locks::trace_lock_); 233 if (the_trace_ != NULL) { 234 LOG(ERROR) << "Trace already in progress, ignoring this request"; 235 } else { 236 the_trace_ = new Trace(trace_file.release(), buffer_size, flags); 237 238 // Enable count of allocs if specified in the flags. 239 if ((flags && kTraceCountAllocs) != 0) { 240 runtime->SetStatsEnabled(true); 241 } 242 243 runtime->GetInstrumentation()->AddListener(the_trace_, 244 instrumentation::Instrumentation::kMethodEntered | 245 instrumentation::Instrumentation::kMethodExited | 246 instrumentation::Instrumentation::kMethodUnwind); 247 } 248 } 249 runtime->GetThreadList()->ResumeAll(); 250} 251 252void Trace::Stop() { 253 Runtime* runtime = Runtime::Current(); 254 runtime->GetThreadList()->SuspendAll(); 255 Trace* the_trace = NULL; 256 { 257 MutexLock mu(Thread::Current(), *Locks::trace_lock_); 258 if (the_trace_ == NULL) { 259 LOG(ERROR) << "Trace stop requested, but no trace currently running"; 260 } else { 261 the_trace = the_trace_; 262 the_trace_ = NULL; 263 } 264 } 265 if (the_trace != NULL) { 266 the_trace->FinishTracing(); 267 runtime->GetInstrumentation()->RemoveListener(the_trace, 268 instrumentation::Instrumentation::kMethodEntered | 269 instrumentation::Instrumentation::kMethodExited | 270 instrumentation::Instrumentation::kMethodUnwind); 271 delete the_trace; 272 } 273 runtime->GetThreadList()->ResumeAll(); 274} 275 276void Trace::Shutdown() { 277 if (IsMethodTracingActive()) { 278 Stop(); 279 } 280} 281 282bool Trace::IsMethodTracingActive() { 283 MutexLock mu(Thread::Current(), *Locks::trace_lock_); 284 return the_trace_ != NULL; 285} 286 287Trace::Trace(File* trace_file, int buffer_size, int flags) 288 : trace_file_(trace_file), buf_(new uint8_t[buffer_size]()), flags_(flags), 289 clock_source_(default_clock_source_), buffer_size_(buffer_size), start_time_(MicroTime()), 290 cur_offset_(0), overflow_(false) { 291 // Set up the beginning of the trace. 292 uint16_t trace_version = GetTraceVersion(clock_source_); 293 memset(buf_.get(), 0, kTraceHeaderLength); 294 Append4LE(buf_.get(), kTraceMagicValue); 295 Append2LE(buf_.get() + 4, trace_version); 296 Append2LE(buf_.get() + 6, kTraceHeaderLength); 297 Append8LE(buf_.get() + 8, start_time_); 298 if (trace_version >= kTraceVersionDualClock) { 299 uint16_t record_size = GetRecordSize(clock_source_); 300 Append2LE(buf_.get() + 16, record_size); 301 } 302 303 // Update current offset. 304 cur_offset_ = kTraceHeaderLength; 305} 306 307static void DumpBuf(uint8_t* buf, size_t buf_size, ProfilerClockSource clock_source) 308 SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) { 309 uint8_t* ptr = buf + kTraceHeaderLength; 310 uint8_t* end = buf + buf_size; 311 312 while (ptr < end) { 313 uint32_t tmid = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16) | (ptr[5] << 24); 314 mirror::AbstractMethod* method = DecodeTraceMethodId(tmid); 315 TraceAction action = DecodeTraceAction(tmid); 316 LOG(INFO) << PrettyMethod(method) << " " << static_cast<int>(action); 317 ptr += GetRecordSize(clock_source); 318 } 319} 320 321void Trace::FinishTracing() { 322 // Compute elapsed time. 323 uint64_t elapsed = MicroTime() - start_time_; 324 325 size_t final_offset = cur_offset_; 326 uint32_t clock_overhead = GetClockOverhead(this); 327 328 if ((flags_ & kTraceCountAllocs) != 0) { 329 Runtime::Current()->SetStatsEnabled(false); 330 } 331 332 std::set<mirror::AbstractMethod*> visited_methods; 333 GetVisitedMethods(final_offset, &visited_methods); 334 335 std::ostringstream os; 336 337 os << StringPrintf("%cversion\n", kTraceTokenChar); 338 os << StringPrintf("%d\n", GetTraceVersion(clock_source_)); 339 os << StringPrintf("data-file-overflow=%s\n", overflow_ ? "true" : "false"); 340 if (UseThreadCpuClock()) { 341 if (UseWallClock()) { 342 os << StringPrintf("clock=dual\n"); 343 } else { 344 os << StringPrintf("clock=thread-cpu\n"); 345 } 346 } else { 347 os << StringPrintf("clock=wall\n"); 348 } 349 os << StringPrintf("elapsed-time-usec=%llu\n", elapsed); 350 size_t num_records = (final_offset - kTraceHeaderLength) / GetRecordSize(clock_source_); 351 os << StringPrintf("num-method-calls=%zd\n", num_records); 352 os << StringPrintf("clock-call-overhead-nsec=%d\n", clock_overhead); 353 os << StringPrintf("vm=art\n"); 354 if ((flags_ & kTraceCountAllocs) != 0) { 355 os << StringPrintf("alloc-count=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_OBJECTS)); 356 os << StringPrintf("alloc-size=%d\n", Runtime::Current()->GetStat(KIND_ALLOCATED_BYTES)); 357 os << StringPrintf("gc-count=%d\n", Runtime::Current()->GetStat(KIND_GC_INVOCATIONS)); 358 } 359 os << StringPrintf("%cthreads\n", kTraceTokenChar); 360 DumpThreadList(os); 361 os << StringPrintf("%cmethods\n", kTraceTokenChar); 362 DumpMethodList(os, visited_methods); 363 os << StringPrintf("%cend\n", kTraceTokenChar); 364 365 std::string header(os.str()); 366 if (trace_file_.get() == NULL) { 367 iovec iov[2]; 368 iov[0].iov_base = reinterpret_cast<void*>(const_cast<char*>(header.c_str())); 369 iov[0].iov_len = header.length(); 370 iov[1].iov_base = buf_.get(); 371 iov[1].iov_len = final_offset; 372 Dbg::DdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2); 373 const bool kDumpTraceInfo = false; 374 if (kDumpTraceInfo) { 375 LOG(INFO) << "Trace sent:\n" << header; 376 DumpBuf(buf_.get(), final_offset, clock_source_); 377 } 378 } else { 379 if (!trace_file_->WriteFully(header.c_str(), header.length()) || 380 !trace_file_->WriteFully(buf_.get(), final_offset)) { 381 std::string detail(StringPrintf("Trace data write failed: %s", strerror(errno))); 382 PLOG(ERROR) << detail; 383 ThrowRuntimeException("%s", detail.c_str()); 384 } 385 } 386} 387 388void Trace::DexPcMoved(Thread* thread, mirror::Object* this_object, 389 const mirror::AbstractMethod* method, uint32_t new_dex_pc) { 390 // We're not recorded to listen to this kind of event, so complain. 391 LOG(ERROR) << "Unexpected dex PC event in tracing " << PrettyMethod(method) << " " << new_dex_pc; 392}; 393 394void Trace::MethodEntered(Thread* thread, mirror::Object* this_object, 395 const mirror::AbstractMethod* method, uint32_t dex_pc) { 396 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodEntered); 397} 398 399void Trace::MethodExited(Thread* thread, mirror::Object* this_object, 400 const mirror::AbstractMethod* method, uint32_t dex_pc, 401 const JValue& return_value) { 402 UNUSED(return_value); 403 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodExited); 404} 405 406void Trace::MethodUnwind(Thread* thread, const mirror::AbstractMethod* method, uint32_t dex_pc) { 407 LogMethodTraceEvent(thread, method, instrumentation::Instrumentation::kMethodUnwind); 408} 409 410void Trace::ExceptionCaught(Thread* thread, const ThrowLocation& throw_location, 411 mirror::AbstractMethod* catch_method, uint32_t catch_dex_pc, 412 mirror::Throwable* exception_object) 413 SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) { 414 LOG(ERROR) << "Unexpected exception caught event in tracing"; 415} 416 417void Trace::LogMethodTraceEvent(Thread* thread, const mirror::AbstractMethod* method, 418 instrumentation::Instrumentation::InstrumentationEvent event) { 419 // Advance cur_offset_ atomically. 420 int32_t new_offset; 421 int32_t old_offset; 422 do { 423 old_offset = cur_offset_; 424 new_offset = old_offset + GetRecordSize(clock_source_); 425 if (new_offset > buffer_size_) { 426 overflow_ = true; 427 return; 428 } 429 } while (android_atomic_release_cas(old_offset, new_offset, &cur_offset_) != 0); 430 431 TraceAction action = kTraceMethodEnter; 432 switch (event) { 433 case instrumentation::Instrumentation::kMethodEntered: 434 action = kTraceMethodEnter; 435 break; 436 case instrumentation::Instrumentation::kMethodExited: 437 action = kTraceMethodExit; 438 break; 439 case instrumentation::Instrumentation::kMethodUnwind: 440 action = kTraceUnroll; 441 break; 442 default: 443 UNIMPLEMENTED(FATAL) << "Unexpected event: " << event; 444 } 445 446 uint32_t method_value = EncodeTraceMethodAndAction(method, action); 447 448 // Write data 449 uint8_t* ptr = buf_.get() + old_offset; 450 Append2LE(ptr, thread->GetTid()); 451 Append4LE(ptr + 2, method_value); 452 ptr += 6; 453 454 if (UseThreadCpuClock()) { 455 // TODO: this isn't vaguely thread safe. 456 SafeMap<Thread*, uint64_t>::iterator it = thread_clock_base_map_.find(thread); 457 uint32_t thread_clock_diff = 0; 458 if (UNLIKELY(it == thread_clock_base_map_.end())) { 459 // First event, the diff is 0, record the base time in the map. 460 uint64_t time = ThreadCpuMicroTime(); 461 thread_clock_base_map_.Put(thread, time); 462 } else { 463 uint64_t thread_clock_base = it->second; 464 thread_clock_diff = ThreadCpuMicroTime() - thread_clock_base; 465 } 466 Append4LE(ptr, thread_clock_diff); 467 ptr += 4; 468 } 469 if (UseWallClock()) { 470 uint32_t wall_clock_diff = MicroTime() - start_time_; 471 Append4LE(ptr, wall_clock_diff); 472 } 473} 474 475void Trace::GetVisitedMethods(size_t buf_size, 476 std::set<mirror::AbstractMethod*>* visited_methods) { 477 uint8_t* ptr = buf_.get() + kTraceHeaderLength; 478 uint8_t* end = buf_.get() + buf_size; 479 480 while (ptr < end) { 481 uint32_t tmid = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16) | (ptr[5] << 24); 482 mirror::AbstractMethod* method = DecodeTraceMethodId(tmid); 483 visited_methods->insert(method); 484 ptr += GetRecordSize(clock_source_); 485 } 486} 487 488void Trace::DumpMethodList(std::ostream& os, 489 const std::set<mirror::AbstractMethod*>& visited_methods) { 490 typedef std::set<mirror::AbstractMethod*>::const_iterator It; // TODO: C++0x auto 491 MethodHelper mh; 492 for (It it = visited_methods.begin(); it != visited_methods.end(); ++it) { 493 mirror::AbstractMethod* method = *it; 494 mh.ChangeMethod(method); 495 os << StringPrintf("%p\t%s\t%s\t%s\t%s\n", method, 496 PrettyDescriptor(mh.GetDeclaringClassDescriptor()).c_str(), mh.GetName(), 497 mh.GetSignature().c_str(), mh.GetDeclaringClassSourceFile()); 498 } 499} 500 501static void DumpThread(Thread* t, void* arg) { 502 std::ostream& os = *reinterpret_cast<std::ostream*>(arg); 503 std::string name; 504 t->GetThreadName(name); 505 os << t->GetTid() << "\t" << name << "\n"; 506} 507 508void Trace::DumpThreadList(std::ostream& os) { 509 Thread* self = Thread::Current(); 510 Locks::thread_list_lock_->AssertNotHeld(self); 511 MutexLock mu(self, *Locks::thread_list_lock_); 512 Runtime::Current()->GetThreadList()->ForEach(DumpThread, &os); 513} 514 515} // namespace art 516