#include "base/task/sequence_manager/thread_controller.h"
#include <atomic>
#include <string_view>
#include "base/check.h"
#include "base/metrics/histogram.h"
#include "base/metrics/histogram_base.h"
#include "base/metrics/histogram_functions.h"
#include "base/metrics/histogram_macros.h"
#include "base/no_destructor.h"
#include "base/notreached.h"
#include "base/strings/strcat.h"
#include "base/strings/string_util.h"
#include "base/time/tick_clock.h"
#include "base/time/time.h"
#include "base/trace_event/trace_event.h"
namespace base::sequence_manager::internal {
namespace {
std::atomic<bool> g_fortuitous_memory_barrier_on_sleep{
#if defined(THREAD_SANITIZER)
true};
#else
false};
#endif
void PerformFortuitousMemoryBarrierIfNecessary() {
if (g_fortuitous_memory_barrier_on_sleep.load(std::memory_order_relaxed)) {
static constinit std::atomic_uint shared_int{0};
shared_int.fetch_add(1, std::memory_order_acq_rel);
}
}
constexpr TimeDelta kNonTrivialActiveIntervalLength = Milliseconds(1);
constexpr TimeDelta kMediumActiveIntervalLength = Milliseconds(100);
std::string MakeSuffix(std::string_view time_suffix,
std::string_view thread_name) {
return base::StrCat({".", time_suffix, ".", thread_name});
}
}
ThreadController::ThreadController(const TickClock* time_source)
: associated_thread_(AssociatedThreadId::CreateUnbound()),
time_source_(time_source) {}
ThreadController::~ThreadController() = default;
void ThreadController::SetTickClock(const TickClock* clock) {
DCHECK_CALLED_ON_VALID_THREAD(associated_thread_->thread_checker);
time_source_ = clock;
}
ThreadController::RunLevelTracker::RunLevelTracker(
const ThreadController& outer)
: outer_(outer) {}
ThreadController::RunLevelTracker::~RunLevelTracker() {
DCHECK_CALLED_ON_VALID_THREAD(outer_->associated_thread_->thread_checker);
DCHECK_EQ(run_levels_.size(), 0u);
}
void ThreadController::InitializeFeatures() {
g_fortuitous_memory_barrier_on_sleep.store(false, std::memory_order_relaxed);
}
std::string_view ThreadController::RunLevelTracker::RunLevel::GetThreadName() {
std::string_view thread_name = "Other";
if (!time_keeper_->thread_name().empty()) {
thread_name = time_keeper_->thread_name();
}
return thread_name;
}
std::string
ThreadController::RunLevelTracker::RunLevel::GetSuffixForCatchAllHistogram() {
return MakeSuffix("Any", GetThreadName());
}
std::string ThreadController::RunLevelTracker::RunLevel::GetSuffixForHistogram(
TimeDelta duration) {
std::string_view time_suffix;
if (duration < kNonTrivialActiveIntervalLength) {
time_suffix = "Short";
} else if (duration < kMediumActiveIntervalLength) {
time_suffix = "Medium";
}
return MakeSuffix(time_suffix, GetThreadName());
}
void ThreadController::EnableMessagePumpTimeKeeperMetrics(
const char* thread_name,
bool wall_time_based_metrics_enabled_for_testing) {
if (!base::TimeTicks::IsHighResolution()) {
return;
}
run_level_tracker_.EnableTimeKeeperMetrics(
thread_name, wall_time_based_metrics_enabled_for_testing);
}
void ThreadController::RunLevelTracker::EnableTimeKeeperMetrics(
const char* thread_name,
bool wall_time_based_metrics_enabled_for_testing) {
time_keeper_.EnableRecording(thread_name,
wall_time_based_metrics_enabled_for_testing);
}
void ThreadController::RunLevelTracker::TimeKeeper::EnableRecording(
const char* thread_name,
bool wall_time_based_metrics_enabled_for_testing) {
DCHECK(!histogram_);
thread_name_ = thread_name;
wall_time_based_metrics_enabled_for_testing_ =
wall_time_based_metrics_enabled_for_testing;
histogram_ = LinearHistogram::FactoryGet(
JoinString({"Scheduling.MessagePumpTimeKeeper", thread_name}, "."), 1,
Phase::kLastPhase, Phase::kLastPhase + 1,
base::HistogramBase::kUmaTargetedHistogramFlag);
perfetto_track_.emplace("MessagePumpPhases", 0,
perfetto::ThreadTrack::Current());
}
void ThreadController::RunLevelTracker::OnRunLoopStarted(State initial_state,
LazyNow& lazy_now) {
DCHECK_CALLED_ON_VALID_THREAD(outer_->associated_thread_->thread_checker);
const bool is_nested = !run_levels_.empty();
run_levels_.emplace(initial_state, is_nested, time_keeper_, lazy_now);
if (!is_nested && initial_state != kIdle) {
time_keeper_.RecordWakeUp(lazy_now);
}
}
void ThreadController::RunLevelTracker::OnRunLoopEnded() {
DCHECK_CALLED_ON_VALID_THREAD(outer_->associated_thread_->thread_checker);
DCHECK(!run_levels_.empty());
LazyNow exit_lazy_now(outer_->time_source_);
run_levels_.top().set_exit_lazy_now(&exit_lazy_now);
run_levels_.pop();
}
void ThreadController::RunLevelTracker::OnWorkStarted(LazyNow& lazy_now) {
DCHECK_CALLED_ON_VALID_THREAD(outer_->associated_thread_->thread_checker);
if (run_levels_.empty()) {
return;
}
if (run_levels_.top().state() == kRunningWorkItem) {
run_levels_.emplace(kRunningWorkItem, true, time_keeper_,
lazy_now);
} else {
if (run_levels_.top().state() == kIdle) {
time_keeper_.RecordWakeUp(lazy_now);
} else {
time_keeper_.RecordEndOfPhase(kPumpOverhead, lazy_now);
}
run_levels_.top().UpdateState(kRunningWorkItem, lazy_now);
}
}
void ThreadController::RunLevelTracker::OnApplicationTaskSelected(
TimeTicks queue_time,
LazyNow& lazy_now) {
DCHECK_CALLED_ON_VALID_THREAD(outer_->associated_thread_->thread_checker);
if (run_levels_.empty()) {
return;
}
DCHECK_EQ(run_levels_.top().state(), kRunningWorkItem);
time_keeper_.OnApplicationTaskSelected(queue_time, lazy_now);
}
void ThreadController::RunLevelTracker::OnWorkEnded(LazyNow& lazy_now,
int run_level_depth) {
DCHECK_CALLED_ON_VALID_THREAD(outer_->associated_thread_->thread_checker);
if (run_levels_.empty()) {
return;
}
if (run_level_depth != static_cast<int>(num_run_levels())) {
DCHECK_EQ(run_level_depth + 1, static_cast<int>(num_run_levels()));
run_levels_.top().set_exit_lazy_now(&lazy_now);
run_levels_.pop();
} else {
time_keeper_.RecordEndOfPhase(kWorkItem, lazy_now);
}
DCHECK_EQ(run_levels_.top().state(), kRunningWorkItem);
run_levels_.top().UpdateState(kInBetweenWorkItems, lazy_now);
}
void ThreadController::RunLevelTracker::OnIdle(LazyNow& lazy_now) {
DCHECK_CALLED_ON_VALID_THREAD(outer_->associated_thread_->thread_checker);
if (run_levels_.empty()) {
return;
}
DCHECK_NE(run_levels_.top().state(), kRunningWorkItem);
time_keeper_.RecordEndOfPhase(kIdleWork, lazy_now);
run_levels_.top().UpdateState(kIdle, lazy_now);
}
void ThreadController::RunLevelTracker::RecordScheduleWork() {
if (outer_->associated_thread_->IsBoundToCurrentThread()) {
TRACE_EVENT_INSTANT("wakeup.flow", "ScheduleWorkToSelf");
} else {
TRACE_EVENT_INSTANT("wakeup.flow", "ScheduleWork",
perfetto::Flow::FromPointer(this));
}
}
void ThreadController::RunLevelTracker::SetTraceObserverForTesting(
TraceObserverForTesting* trace_observer_for_testing) {
DCHECK_NE(!!trace_observer_for_testing_, !!trace_observer_for_testing);
trace_observer_for_testing_ = trace_observer_for_testing;
}
ThreadController::RunLevelTracker::TraceObserverForTesting*
ThreadController::RunLevelTracker::trace_observer_for_testing_ = nullptr;
ThreadController::RunLevelTracker::RunLevel::RunLevel(State initial_state,
bool is_nested,
TimeKeeper& time_keeper,
LazyNow& lazy_now)
: is_nested_(is_nested), time_keeper_(time_keeper) {
if (is_nested_) {
time_keeper_->RecordEndOfPhase(kWorkItemSuspendedOnNested, lazy_now);
}
UpdateState(initial_state, lazy_now);
}
ThreadController::RunLevelTracker::RunLevel::~RunLevel() {
if (!was_moved_) {
DCHECK(exit_lazy_now_);
UpdateState(kIdle, *exit_lazy_now_);
if (is_nested_) {
time_keeper_->RecordEndOfPhase(kNested, *exit_lazy_now_);
PerformFortuitousMemoryBarrierIfNecessary();
}
}
}
ThreadController::RunLevelTracker::RunLevel::RunLevel(RunLevel&& other) =
default;
void ThreadController::RunLevelTracker::RunLevel::LogPercentageMetric(
const char* name,
int percentage) {
UmaHistogramPercentage(base::StrCat({name, ".", GetThreadName()}),
percentage);
}
void ThreadController::RunLevelTracker::RunLevel::LogPercentageMetric(
const char* name,
int percentage,
base::TimeDelta interval_duration) {
UmaHistogramPercentage(base::StrCat({name, GetSuffixForCatchAllHistogram()}),
percentage);
UmaHistogramPercentage(
base::StrCat({name, GetSuffixForHistogram(interval_duration)}),
percentage);
}
void ThreadController::RunLevelTracker::RunLevel::LogIntervalMetric(
const char* name,
base::TimeDelta value,
base::TimeDelta interval_duration) {
UmaHistogramTimes(base::StrCat({name, GetSuffixForCatchAllHistogram()}),
value);
if (interval_duration < kNonTrivialActiveIntervalLength) {
UmaHistogramCustomMicrosecondsTimes(
base::StrCat({name, GetSuffixForHistogram(interval_duration)}), value,
base::Microseconds(1), kNonTrivialActiveIntervalLength, 100);
} else if (interval_duration < kMediumActiveIntervalLength) {
UmaHistogramCustomTimes(
base::StrCat({name, GetSuffixForHistogram(interval_duration)}), value,
kNonTrivialActiveIntervalLength, kMediumActiveIntervalLength, 100);
}
}
void ThreadController::RunLevelTracker::RunLevel::LogOnActiveMetrics(
LazyNow& lazy_now) {
CHECK(last_active_start_.is_null());
CHECK(last_active_threadtick_start_.is_null());
if (!last_active_end_.is_null()) {
const base::TimeDelta idle_time = lazy_now.Now() - last_active_end_;
LogIntervalMetric("Scheduling.ThreadController.IdleDuration", idle_time,
idle_time);
last_active_end_ = base::TimeTicks();
accumulated_idle_time_ += idle_time;
}
static const bool thread_ticks_supported = ThreadTicks::IsSupported();
const double probability =
time_keeper_->wall_time_based_metrics_enabled_for_testing() ? 1.0 : 0.001;
if (thread_ticks_supported &&
metrics_sub_sampler_.ShouldSample(probability)) {
last_active_start_ = lazy_now.Now();
last_active_threadtick_start_ = ThreadTicks::Now();
}
}
void ThreadController::RunLevelTracker::RunLevel::LogOnIdleMetrics(
LazyNow& lazy_now) {
if (!last_active_start_.is_null()) {
const base::TimeDelta elapsed_ticks = lazy_now.Now() - last_active_start_;
base::TimeDelta elapsed_thread_ticks =
ThreadTicks::Now() - last_active_threadtick_start_;
elapsed_thread_ticks = std::min(elapsed_thread_ticks, elapsed_ticks);
LogIntervalMetric("Scheduling.ThreadController.ActiveIntervalDuration",
elapsed_ticks, elapsed_ticks);
LogIntervalMetric(
"Scheduling.ThreadController.ActiveIntervalOffCpuDuration",
elapsed_ticks - elapsed_thread_ticks, elapsed_ticks);
LogIntervalMetric("Scheduling.ThreadController.ActiveIntervalOnCpuDuration",
elapsed_thread_ticks, elapsed_ticks);
int active_interval_cpu_percentage =
elapsed_ticks.is_zero()
? 100
: static_cast<int>(
(elapsed_thread_ticks * 100).IntDiv(elapsed_ticks));
LogPercentageMetric(
"Scheduling.ThreadController.ActiveIntervalOnCpuPercentage",
active_interval_cpu_percentage, elapsed_ticks);
if (time_keeper_->wall_time_based_metrics_enabled_for_testing()) {
accumulated_active_time_ += elapsed_ticks;
accumulated_active_on_cpu_time_ += elapsed_thread_ticks;
accumulated_active_off_cpu_time_ +=
(elapsed_ticks - elapsed_thread_ticks);
const base::TimeDelta accumulated_wall_time =
accumulated_active_time_ + accumulated_idle_time_;
if (accumulated_wall_time > Seconds(1)) {
const int active_vs_wall_time_percentage = checked_cast<int>(
(accumulated_active_time_ * 100).IntDiv(accumulated_wall_time));
LogPercentageMetric(
"Scheduling.ThreadController.ActiveVsWallTimePercentage",
active_vs_wall_time_percentage);
const int active_on_cpu_vs_wall_time_percentage =
checked_cast<int>((accumulated_active_on_cpu_time_ * 100)
.IntDiv(accumulated_wall_time));
LogPercentageMetric(
"Scheduling.ThreadController.ActiveOnCpuVsWallTimePercentage",
active_on_cpu_vs_wall_time_percentage);
const int active_off_cpu_vs_wall_time_percentage =
checked_cast<int>((accumulated_active_off_cpu_time_ * 100)
.IntDiv(accumulated_wall_time));
LogPercentageMetric(
"Scheduling.ThreadController.ActiveOffCpuVsWallTimePercentage",
active_off_cpu_vs_wall_time_percentage);
accumulated_idle_time_ = base::TimeDelta();
accumulated_active_time_ = base::TimeDelta();
accumulated_active_on_cpu_time_ = base::TimeDelta();
accumulated_active_off_cpu_time_ = base::TimeDelta();
}
}
last_active_start_ = base::TimeTicks();
last_active_threadtick_start_ = base::ThreadTicks();
last_active_end_ = lazy_now.Now();
}
}
void ThreadController::RunLevelTracker::RunLevel::UpdateState(
State new_state,
LazyNow& lazy_now) {
DCHECK(state_ != new_state || new_state == kIdle)
<< state_ << "," << new_state;
const bool was_active = state_ != kIdle;
const bool is_active = new_state != kIdle;
state_ = new_state;
if (was_active == is_active) {
return;
}
if (is_active) {
LogOnActiveMetrics(lazy_now);
TRACE_EVENT_BEGIN("base", "ThreadController active", lazy_now.Now(),
[&](perfetto::EventContext& ctx) {
time_keeper_->MaybeEmitIncomingWakeupFlow(ctx);
});
PerformFortuitousMemoryBarrierIfNecessary();
} else {
PerformFortuitousMemoryBarrierIfNecessary();
LogOnIdleMetrics(lazy_now);
TRACE_EVENT_END("base", lazy_now.Now());
}
if (trace_observer_for_testing_) {
if (is_active) {
trace_observer_for_testing_->OnThreadControllerActiveBegin();
} else {
trace_observer_for_testing_->OnThreadControllerActiveEnd();
}
}
}
ThreadController::RunLevelTracker::TimeKeeper::TimeKeeper(
const RunLevelTracker& outer)
: outer_(outer) {}
void ThreadController::RunLevelTracker::TimeKeeper::RecordWakeUp(
LazyNow& lazy_now) {
if (!ShouldRecordNow(ShouldRecordReqs::kOnWakeUp)) {
return;
}
last_wakeup_ = lazy_now.Now();
last_phase_end_ = last_wakeup_;
TRACE_EVENT_END(TRACE_DISABLED_BY_DEFAULT("base"), *perfetto_track_,
last_wakeup_);
}
void ThreadController::RunLevelTracker::TimeKeeper::OnApplicationTaskSelected(
TimeTicks queue_time,
LazyNow& lazy_now) {
if (!ShouldRecordNow()) {
return;
}
if (!last_wakeup_.is_null()) {
if (!queue_time.is_null() && queue_time < last_wakeup_) {
if (!last_sleep_.is_null() && queue_time < last_sleep_) {
queue_time = last_sleep_;
}
RecordTimeInPhase(kScheduled, queue_time, last_wakeup_);
TRACE_EVENT_BEGIN(TRACE_DISABLED_BY_DEFAULT("base"),
perfetto::StaticString(PhaseToEventName(kScheduled)),
*perfetto_track_, queue_time);
}
last_wakeup_ = TimeTicks();
}
RecordEndOfPhase(kSelectingApplicationTask, lazy_now);
current_work_item_is_native_ = false;
}
void ThreadController::RunLevelTracker::TimeKeeper::RecordEndOfPhase(
Phase phase,
LazyNow& lazy_now) {
if (!ShouldRecordNow(phase == kNested ? ShouldRecordReqs::kOnEndNested
: ShouldRecordReqs::kRegular)) {
return;
}
if (phase == kWorkItem && !current_work_item_is_native_) {
phase = kApplicationTask;
current_work_item_is_native_ = true;
} else if (phase == kWorkItemSuspendedOnNested) {
phase = current_work_item_is_native_ ? kNativeWork : kApplicationTask;
}
const TimeTicks phase_end = lazy_now.Now();
RecordTimeInPhase(phase, last_phase_end_, phase_end);
const char* event_name = PhaseToEventName(phase);
TRACE_EVENT_BEGIN(TRACE_DISABLED_BY_DEFAULT("base"),
perfetto::StaticString(event_name), *perfetto_track_,
last_phase_end_);
TRACE_EVENT_END(TRACE_DISABLED_BY_DEFAULT("base"), *perfetto_track_,
phase_end);
last_phase_end_ = phase_end;
}
void ThreadController::RunLevelTracker::TimeKeeper::MaybeEmitIncomingWakeupFlow(
perfetto::EventContext& ctx) {
static const uint8_t* flow_enabled =
TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("wakeup.flow");
if (!*flow_enabled) {
return;
}
perfetto::TerminatingFlow::ProcessScoped(
reinterpret_cast<uint64_t>(&(outer_.get())))(ctx);
}
bool ThreadController::RunLevelTracker::TimeKeeper::ShouldRecordNow(
ShouldRecordReqs reqs) {
DCHECK_CALLED_ON_VALID_THREAD(
outer_->outer_->associated_thread_->thread_checker);
switch (reqs) {
case ShouldRecordReqs::kRegular:
return histogram_ && !last_phase_end_.is_null() &&
outer_->run_levels_.size() == 1;
case ShouldRecordReqs::kOnWakeUp:
return histogram_ && outer_->run_levels_.size() == 1;
case ShouldRecordReqs::kOnEndNested:
return histogram_ && !last_phase_end_.is_null() &&
outer_->run_levels_.size() <= 2;
}
}
void ThreadController::RunLevelTracker::TimeKeeper::RecordTimeInPhase(
Phase phase,
TimeTicks phase_begin,
TimeTicks phase_end) {
DCHECK(ShouldRecordNow(phase == kNested ? ShouldRecordReqs::kOnEndNested
: ShouldRecordReqs::kRegular));
static constexpr auto kReportInterval = Milliseconds(100);
static constexpr auto kSkippedDelta = Seconds(30);
const auto delta = phase_end - phase_begin;
DCHECK(!delta.is_negative()) << delta;
if (delta >= kSkippedDelta) {
return;
}
deltas_[phase] += delta;
if (deltas_[phase] >= kReportInterval) {
const int count = deltas_[phase] / Milliseconds(1);
histogram_->AddCount(phase, count);
deltas_[phase] -= Milliseconds(count);
}
if (phase == kIdleWork) {
last_sleep_ = phase_end;
}
if (outer_->trace_observer_for_testing_) {
outer_->trace_observer_for_testing_->OnPhaseRecorded(phase);
}
}
const char* ThreadController::RunLevelTracker::TimeKeeper::PhaseToEventName(
Phase phase) {
switch (phase) {
case kScheduled:
return "Scheduled";
case kPumpOverhead:
return "PumpOverhead";
case kNativeWork:
return "NativeTask";
case kSelectingApplicationTask:
return "SelectingApplicationTask";
case kApplicationTask:
return "ApplicationTask";
case kIdleWork:
return "IdleWork";
case kNested:
return "Nested";
case kWorkItemSuspendedOnNested:
NOTREACHED();
}
}
}