// Copyright 2014 The Chromium Authors // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. #include "base/task/common/task_annotator.h" #include #include #include #include "base/auto_reset.h" #include "base/check_op.h" #include "base/compiler_specific.h" #include "base/debug/alias.h" #include "base/hash/md5.h" #include "base/logging.h" #include "base/ranges/algorithm.h" #include "base/sys_byteorder.h" #include "base/time/time.h" #include "base/trace_event/base_tracing.h" #include "base/tracing_buildflags.h" #include "build/build_config.h" #include "third_party/abseil-cpp/absl/base/attributes.h" #if BUILDFLAG(ENABLE_BASE_TRACING) #include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_mojo_event_info.pbzero.h" // nogncheck #endif namespace base { namespace { TaskAnnotator::ObserverForTesting* g_task_annotator_observer = nullptr; // The PendingTask currently in progress on each thread. Used to allow creating // a breadcrumb of program counters on the stack to help identify a task's // origin in crashes. ABSL_CONST_INIT thread_local PendingTask* current_pending_task = nullptr; // Scoped IPC-related data (IPC hash and/or IPC interface name). IPC hash or // interface name can be known before the associated task object is created; // thread-local so that this data can be affixed to the associated task. ABSL_CONST_INIT thread_local TaskAnnotator::ScopedSetIpcHash* current_scoped_ipc_hash = nullptr; ABSL_CONST_INIT thread_local TaskAnnotator::LongTaskTracker* current_long_task_tracker = nullptr; // These functions can be removed, and the calls below replaced with direct // variable accesses, once the MSAN workaround is not necessary. TaskAnnotator::ScopedSetIpcHash* GetCurrentScopedIpcHash() { // Workaround false-positive MSAN use-of-uninitialized-value on // thread_local storage for loaded libraries: // https://github.com/google/sanitizers/issues/1265 MSAN_UNPOISON(¤t_scoped_ipc_hash, sizeof(TaskAnnotator::ScopedSetIpcHash*)); return current_scoped_ipc_hash; } TaskAnnotator::LongTaskTracker* GetCurrentLongTaskTracker() { // Workaround false-positive MSAN use-of-uninitialized-value on // thread_local storage for loaded libraries: // https://github.com/google/sanitizers/issues/1265 MSAN_UNPOISON(¤t_long_task_tracker, sizeof(TaskAnnotator::LongTaskTracker*)); return current_long_task_tracker; } } // namespace const PendingTask* TaskAnnotator::CurrentTaskForThread() { // Workaround false-positive MSAN use-of-uninitialized-value on // thread_local storage for loaded libraries: // https://github.com/google/sanitizers/issues/1265 MSAN_UNPOISON(¤t_pending_task, sizeof(PendingTask*)); return current_pending_task; } void TaskAnnotator::OnIPCReceived(const char* interface_name, uint32_t (*method_info)(), bool is_response) { auto* const tracker = GetCurrentLongTaskTracker(); if (!tracker) { return; } tracker->SetIpcDetails(interface_name, method_info, is_response); } void TaskAnnotator::MarkCurrentTaskAsInterestingForTracing() { auto* const tracker = GetCurrentLongTaskTracker(); if (!tracker) { return; } tracker->is_interesting_task = true; } TaskAnnotator::TaskAnnotator() = default; TaskAnnotator::~TaskAnnotator() = default; void TaskAnnotator::WillQueueTask(perfetto::StaticString trace_event_name, PendingTask* pending_task) { DCHECK(pending_task); TRACE_EVENT_INSTANT( "toplevel.flow", trace_event_name, perfetto::Flow::ProcessScoped(GetTaskTraceID(*pending_task))); DCHECK(!pending_task->task_backtrace[0]) << "Task backtrace was already set, task posted twice??"; if (pending_task->task_backtrace[0]) return; DCHECK(!pending_task->ipc_interface_name); DCHECK(!pending_task->ipc_hash); const auto* const hash = GetCurrentScopedIpcHash(); if (hash) { pending_task->ipc_interface_name = hash->GetIpcInterfaceName(); pending_task->ipc_hash = hash->GetIpcHash(); } const auto* parent_task = CurrentTaskForThread(); if (!parent_task) return; pending_task->task_backtrace[0] = parent_task->posted_from.program_counter(); std::copy(parent_task->task_backtrace.begin(), parent_task->task_backtrace.end() - 1, pending_task->task_backtrace.begin() + 1); pending_task->task_backtrace_overflow = parent_task->task_backtrace_overflow || parent_task->task_backtrace.back() != nullptr; } void TaskAnnotator::RunTaskImpl(PendingTask& pending_task) { TRACE_HEAP_PROFILER_API_SCOPED_TASK_EXECUTION( pending_task.posted_from.file_name()); // Before running the task, store the IPC context and the task backtrace with // the chain of PostTasks that resulted in this call and deliberately alias it // to ensure it is on the stack if the task crashes. Be careful not to assume // that the variable itself will have the expected value when displayed by the // optimizer in an optimized build. Look at a memory dump of the stack. static constexpr int kStackTaskTraceSnapshotSize = PendingTask::kTaskBacktraceLength + 4; std::array task_backtrace; // Store a marker to locate |task_backtrace| content easily on a memory // dump. The layout is as follows: // // +------------ +----+---------+-----+-----------+----------+-------------+ // | Head Marker | PC | frame 0 | ... | frame N-1 | IPC hash | Tail Marker | // +------------ +----+---------+-----+-----------+----------+-------------+ // // Markers glossary (compliments of wez): // cool code,do it dude! // 0x c001 c0de d0 17 d00d // o dude,i did it biig // 0x 0 d00d 1 d1d 17 8119 task_backtrace.front() = reinterpret_cast(0xc001c0ded017d00d); task_backtrace.back() = reinterpret_cast(0x0d00d1d1d178119); task_backtrace[1] = pending_task.posted_from.program_counter(); ranges::copy(pending_task.task_backtrace, task_backtrace.begin() + 2); task_backtrace[kStackTaskTraceSnapshotSize - 2] = reinterpret_cast(pending_task.ipc_hash); debug::Alias(&task_backtrace); // Record the task time in convenient units. This can be compared to times // stored in places like ReportThreadHang() and BrowserMain() when analyzing // hangs. const int64_t task_time = pending_task.GetDesiredExecutionTime().since_origin().InSeconds(); base::debug::Alias(&task_time); { const AutoReset resetter(¤t_pending_task, &pending_task); if (g_task_annotator_observer) { g_task_annotator_observer->BeforeRunTask(&pending_task); } std::move(pending_task.task).Run(); #if BUILDFLAG(IS_WIN) && defined(ARCH_CPU_X86_FAMILY) // Some tasks on some machines clobber the non-volatile XMM registers in // violation of the Windows ABI. This empty assembly language block with // clobber directives tells the compiler to assume that these registers // may have lost their values. This ensures that this function will not rely // on the registers retaining their values, and it ensures that it will // restore the values when this function ends. This is needed because the // code-gen for at least one caller of this function in official builds // relies on an XMM register (usually XMM7, cleared to zero) maintaining its // value as multiple tasks are run, which causes crashes if it is corrupted, // since "zeroed" variables end up not being zeroed. The third-party issue // is believed to be fixed but will take a while to propagate to users which // is why this mitigation is needed. For details see // https://crbug.com/1218384. asm("" : : : "%xmm6", "%xmm7", "%xmm8", "%xmm9", "%xmm10", "%xmm11", "%xmm12", "%xmm13", "%xmm14", "%xmm15"); #endif } // Stomp the markers. Otherwise they can stick around on the unused parts of // stack and cause |task_backtrace| to be associated with an unrelated stack // sample on this thread later in the event of a crash. Alias once again after // these writes to make sure the compiler doesn't optimize them out (unused // writes to a local variable). task_backtrace.front() = nullptr; task_backtrace.back() = nullptr; debug::Alias(&task_backtrace); } uint64_t TaskAnnotator::GetTaskTraceID(const PendingTask& task) const { return (static_cast(task.sequence_num) << 32) | ((static_cast(reinterpret_cast(this)) << 32) >> 32); } // static void TaskAnnotator::RegisterObserverForTesting(ObserverForTesting* observer) { DCHECK(!g_task_annotator_observer); g_task_annotator_observer = observer; } // static void TaskAnnotator::ClearObserverForTesting() { g_task_annotator_observer = nullptr; } #if BUILDFLAG(ENABLE_BASE_TRACING) // TRACE_EVENT argument helper, writing the task location data into // EventContext. void TaskAnnotator::EmitTaskLocation(perfetto::EventContext& ctx, const PendingTask& task) { ctx.event()->set_task_execution()->set_posted_from_iid( base::trace_event::InternedSourceLocation::Get(&ctx, task.posted_from)); } // TRACE_EVENT argument helper, writing the incoming task flow information // into EventContext if toplevel.flow category is enabled. void TaskAnnotator::MaybeEmitIncomingTaskFlow(perfetto::EventContext& ctx, const PendingTask& task) const { static const uint8_t* flow_enabled = TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("toplevel.flow"); if (!*flow_enabled) return; perfetto::TerminatingFlow::ProcessScoped(GetTaskTraceID(task))(ctx); } void TaskAnnotator::MaybeEmitIPCHashAndDelay(perfetto::EventContext& ctx, const PendingTask& task) const { static const uint8_t* toplevel_ipc_enabled = TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( TRACE_DISABLED_BY_DEFAULT("toplevel.ipc")); if (!*toplevel_ipc_enabled) return; auto* event = ctx.event(); auto* annotator = event->set_chrome_task_annotator(); annotator->set_ipc_hash(task.ipc_hash); if (!task.delayed_run_time.is_null()) { annotator->set_task_delay_us(static_cast( (task.delayed_run_time - task.queue_time).InMicroseconds())); } } #endif // BUILDFLAG(ENABLE_BASE_TRACING) TaskAnnotator::ScopedSetIpcHash::ScopedSetIpcHash(uint32_t ipc_hash) : ScopedSetIpcHash(ipc_hash, nullptr) {} TaskAnnotator::ScopedSetIpcHash::ScopedSetIpcHash( const char* ipc_interface_name) : ScopedSetIpcHash(0, ipc_interface_name) {} TaskAnnotator::ScopedSetIpcHash::ScopedSetIpcHash( uint32_t ipc_hash, const char* ipc_interface_name) : resetter_(¤t_scoped_ipc_hash, this), ipc_hash_(ipc_hash), ipc_interface_name_(ipc_interface_name) {} // Static uint32_t TaskAnnotator::ScopedSetIpcHash::MD5HashMetricName( base::StringPiece name) { base::MD5Digest digest; base::MD5Sum(name.data(), name.size(), &digest); uint32_t value; DCHECK_GE(sizeof(digest.a), sizeof(value)); memcpy(&value, digest.a, sizeof(value)); return base::NetToHost32(value); } TaskAnnotator::ScopedSetIpcHash::~ScopedSetIpcHash() { DCHECK_EQ(this, GetCurrentScopedIpcHash()); } TaskAnnotator::LongTaskTracker::LongTaskTracker(const TickClock* tick_clock, PendingTask& pending_task, TaskAnnotator* task_annotator) : resetter_(¤t_long_task_tracker, this), tick_clock_(tick_clock), pending_task_(pending_task), task_annotator_(task_annotator) { TRACE_EVENT_CATEGORY_GROUP_ENABLED("scheduler.long_tasks", &is_tracing_); if (is_tracing_) { task_start_time_ = tick_clock_->NowTicks(); } } TaskAnnotator::LongTaskTracker::~LongTaskTracker() { DCHECK_EQ(this, GetCurrentLongTaskTracker()); if (!is_tracing_) return; task_end_time_ = tick_clock_->NowTicks(); MaybeTraceInterestingTaskDetails(); if ((task_end_time_ - task_start_time_) >= kMaxTaskDurationTimeDelta) { TRACE_EVENT_BEGIN("scheduler.long_tasks", "LongTaskTracker", perfetto::Track::ThreadScoped(task_annotator_), task_start_time_, [&](perfetto::EventContext& ctx) { TaskAnnotator::EmitTaskLocation(ctx, *pending_task_); EmitReceivedIPCDetails(ctx); }); TRACE_EVENT_END("scheduler.long_tasks", perfetto::Track::ThreadScoped(task_annotator_), task_end_time_); } } void TaskAnnotator::LongTaskTracker::SetIpcDetails(const char* interface_name, uint32_t (*method_info)(), bool is_response) { ipc_interface_name_ = interface_name; is_response_ = is_response; if (!method_info) return; ipc_hash_ = (*method_info)(); ipc_method_info_ = method_info; } void TaskAnnotator::LongTaskTracker::EmitReceivedIPCDetails( perfetto::EventContext& ctx) { if (!ipc_interface_name_ || !ipc_hash_ || !ipc_method_info_) return; #if BUILDFLAG(ENABLE_BASE_TRACING) && !BUILDFLAG(IS_NACL) // Emit all of the IPC hash information if this task // comes from a mojo interface. auto* info = ctx.event()->set_chrome_mojo_event_info(); info->set_mojo_interface_tag(ipc_interface_name_); info->set_ipc_hash(ipc_hash_); info->set_is_reply(is_response_); // The Native client will not build as the relevant implementation of // base::ModuleCache::CreateModuleForAddress is not implemented for it. // Thus the below code must be included on a conditional basis. const auto ipc_method_address = reinterpret_cast(ipc_method_info_); const absl::optional location_iid = base::trace_event::InternedUnsymbolizedSourceLocation::Get( &ctx, ipc_method_address); if (location_iid) { info->set_mojo_interface_method_iid(*location_iid); } #endif } // This method is used to record the queueing time and task start time for tasks // that may be of interest during a trace, even if they are not considered long // tasks. For example, input - the queue time and flow information is required // to calculate chrome input to browser intervals in perfetto, and further // calculate the chrome tasks blocking input. We need LatencyInfo slices to be // associated with the correct input IPCs, hence record in the LongTaskTracker. void TaskAnnotator::LongTaskTracker::MaybeTraceInterestingTaskDetails() { if (is_interesting_task && ipc_interface_name_) { // Record the equivalent of a delayed instant trace event, acting as the // start of the flow between task queue time and task execution start time. TRACE_EVENT_INSTANT("scheduler.long_tasks", "InterestingTask_QueueingTime", perfetto::Track::ThreadScoped(task_annotator_), pending_task_->queue_time, perfetto::Flow::ProcessScoped( task_annotator_->GetTaskTraceID(*pending_task_))); // Record the equivalent of a top-level event with enough IPC information // to calculate the input to browser interval. This event will be the // termination of the event above, aka the start of task execution. TRACE_EVENT_BEGIN( "scheduler.long_tasks", "InterestingTask_ProcessingTime", perfetto::Track::ThreadScoped(task_annotator_), task_start_time_, [&](perfetto::EventContext& ctx) { perfetto::TerminatingFlow::ProcessScoped( task_annotator_->GetTaskTraceID(*pending_task_))(ctx); auto* info = ctx.event()->set_chrome_mojo_event_info(); info->set_mojo_interface_tag(ipc_interface_name_); }); TRACE_EVENT_END("scheduler.long_tasks", perfetto::Track::ThreadScoped(task_annotator_), task_end_time_); } } } // namespace base