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