0

[base] Watch for hangs from wake-up to idle.

As opposed to only during a work item. This means watching the message
pump's overhead as a "work item".

And also now watch the end of a task which caused a nested loop.

Furthermore, move the conditional HangWatcher::IsEnabled() logic to
hang_watcher.cc (initially with the intent of allowing
ThreadControllerWithMessagePumpImpl to DCHECK(hang_watch_scope_) in a
few places but turns out none can, added comments to that affect). Kept
this nonetheless and moved the default timeout so that a simple
emplace() can be used to reset the scope.

Also removes the superfluous BeginWorkItem() in DoIdleWork() This was
not a task and that call would make it look like one under
https://chromium-review.googlesource.com/c/chromium/src/+/3687380 Its
presence was the only thing that made the DCHECK(!hang_watch_scope_) at
the end of ThreadControllerWithMessagePumpImpl::Run() pass (as its
OnEndWorkItem() cleared the scope). It didn't however mean that the
scopes were well matched since OnBeginWorkItem overrides prior scopes.

OnSystemIdle() is now being watched as part of the last HangWatchScope
before the end of DoIdleWork().

Bug: 1329717, 1034046
Change-Id: Ic4550a8e5ac2ace9da8c9e1f7f4a22cf2e38f941
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3686243
Commit-Queue: Gabriel Charette <gab@chromium.org>
Reviewed-by: Olivier Li <olivierli@chromium.org>
Reviewed-by: Etienne Bergeron <etienneb@chromium.org>
Reviewed-by: Francois Pierre Doray <fdoray@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1013676}
This commit is contained in:
Gabriel Charette
2022-06-13 22:00:54 +00:00
committed by Chromium LUCI CQ
parent 2f0642124e
commit 468e46f825
5 changed files with 47 additions and 45 deletions

@ -226,19 +226,6 @@ void ThreadControllerWithMessagePumpImpl::InitializeThreadTaskRunnerHandle() {
power_monitor_.BindToCurrentThread();
}
void ThreadControllerWithMessagePumpImpl::MaybeStartWatchHangsInScope() {
if (base::HangWatcher::IsEnabled()) {
// If run_level_tracker.num_run_level() == 1 this starts the first scope. If
// it's greater than 1 then this cancels the existing scope and starts a new
// one. This behavior is desired since #task-in-task-implies-nested (see
// RunLevelTracker class comments). In a nested loop it's desirable to
// cancel the hang watching that applies to the outer loop since the
// expectations that were setup with regards to its expected runtime do not
// apply anymore.
hang_watch_scope_.emplace(base::WatchHangsInScope::kDefaultHangWatchTime);
}
}
scoped_refptr<SingleThreadTaskRunner>
ThreadControllerWithMessagePumpImpl::GetDefaultTaskRunner() {
base::internal::CheckedAutoLock lock(task_runner_lock_);
@ -265,22 +252,28 @@ void ThreadControllerWithMessagePumpImpl::RemoveNestingObserver(
}
void ThreadControllerWithMessagePumpImpl::OnBeginWorkItem() {
MaybeStartWatchHangsInScope();
hang_watch_scope_.emplace();
work_id_provider_->IncrementWorkId();
run_level_tracker_.OnTaskStarted();
}
void ThreadControllerWithMessagePumpImpl::OnEndWorkItem() {
// Work completed, stop hang watching this specific work item.
hang_watch_scope_.reset();
// Work completed, begin a new hang watch until the next task (watching the
// pump's overhead).
hang_watch_scope_.emplace();
work_id_provider_->IncrementWorkId();
run_level_tracker_.OnTaskEnded();
}
void ThreadControllerWithMessagePumpImpl::BeforeWait() {
work_id_provider_->IncrementWorkId();
// The loop is going to sleep, stop watching for hangs.
// In most cases, DoIdleWork() will already have cleared the
// `hang_watch_scope_` but in some cases where the native side of the
// MessagePump impl is instrumented, it's possible to get a BeforeWait()
// outside of a DoWork cycle (e.g. message_pump_win.cc :
// MessagePumpForUI::HandleWorkMessage).
hang_watch_scope_.reset();
work_id_provider_->IncrementWorkId();
run_level_tracker_.OnIdle();
}
@ -457,6 +450,12 @@ absl::optional<WakeUp> ThreadControllerWithMessagePumpImpl::DoWorkImpl(
bool ThreadControllerWithMessagePumpImpl::DoIdleWork() {
TRACE_EVENT0("sequence_manager", "SequenceManager::DoIdleWork");
// A hang watch scope should already be in place in most cases but some
// MessagePump impls (e.g. Mac) can call DoIdleWork straight out of idle
// without first calling DoWork.
hang_watch_scope_.emplace();
#if BUILDFLAG(IS_WIN)
if (!power_monitor_.IsProcessInPowerSuspendState()) {
// Avoid calling Time::ActivateHighResolutionTimer() between
@ -479,18 +478,19 @@ bool ThreadControllerWithMessagePumpImpl::DoIdleWork() {
}
#endif // BUILDFLAG(IS_WIN)
{
auto work_item_scope = BeginWorkItem();
if (main_thread_only().task_source->OnSystemIdle()) {
// The OnSystemIdle() callback resulted in more immediate work, so
// schedule a DoWork callback. For some message pumps returning true from
// here is sufficient to do that but not on mac.
pump_->ScheduleWork();
return false;
}
if (main_thread_only().task_source->OnSystemIdle()) {
// The OnSystemIdle() callback resulted in more immediate work, so schedule
// a DoWork callback. For some message pumps returning true from here is
// sufficient to do that but not on mac.
pump_->ScheduleWork();
return false;
}
run_level_tracker_.OnIdle();
// This is mostly redundant with the identical call in BeforeWait (upcoming)
// but some uninstrumented MessagePump impls don't call BeforeWait so it must
// also be done here.
hang_watch_scope_.reset();
// Check if any runloop timeout has expired.
if (main_thread_only().quit_runloop_after != TimeTicks::Max() &&
@ -524,6 +524,7 @@ void ThreadControllerWithMessagePumpImpl::Run(bool application_tasks_allowed,
// true here. We can't use InTopLevelDoWork() in Quit() as this call may be
// outside top-level DoWork but still in Run().
main_thread_only().quit_pending = false;
hang_watch_scope_.emplace();
if (application_tasks_allowed && !main_thread_only().task_execution_allowed) {
// Allow nested task execution as explicitly requested.
DCHECK(RunLoop::IsNestedOnCurrentThread());
@ -537,9 +538,14 @@ void ThreadControllerWithMessagePumpImpl::Run(bool application_tasks_allowed,
run_level_tracker_.OnRunLoopEnded();
main_thread_only().quit_pending = false;
// All work items should be over when exiting the loop so hang watching should
// not be live.
DCHECK(!hang_watch_scope_);
// If this was a nested loop, hang watch the remainder of the task which
// caused it. Otherwise, stop watching as we're no longer running.
if (RunLoop::IsNestedOnCurrentThread()) {
hang_watch_scope_.emplace();
} else {
hang_watch_scope_.reset();
}
work_id_provider_->IncrementWorkId();
}
void ThreadControllerWithMessagePumpImpl::OnBeginNestedRunLoop() {

@ -166,10 +166,6 @@ class BASE_EXPORT ThreadControllerWithMessagePumpImpl
return main_thread_only_;
}
// Instantiate a WatchHangsInScope to cover the current work if hang
// watching is activated via finch.
void MaybeStartWatchHangsInScope();
MainThreadOnly main_thread_only_;
mutable base::internal::CheckedLock task_runner_lock_;
@ -202,8 +198,10 @@ class BASE_EXPORT ThreadControllerWithMessagePumpImpl
base::internal::ScopedSetSequenceLocalStorageMapForCurrentThread>
scoped_set_sequence_local_storage_map_for_current_thread_;
// Reset at the start of each unit of work to cover the work itself and then
// transition to the next one.
// Reset at the start & end of each unit of work to cover the work itself and
// the overhead between each work item (no-op if HangWatcher is not enabled
// on this thread). Cleared when going to sleep and at the end of a Run()
// (i.e. when Quit()). Nested runs override their parent.
absl::optional<WatchHangsInScope> hang_watch_scope_;
};

@ -422,7 +422,7 @@ void WorkerThread::RunWorker() {
#endif
absl::optional<WatchHangsInScope> hang_watch_scope;
if (watch_for_hangs)
hang_watch_scope.emplace(base::WatchHangsInScope::kDefaultHangWatchTime);
hang_watch_scope.emplace();
UpdateThreadPriority(GetDesiredThreadPriority());

@ -205,10 +205,6 @@ constexpr base::FeatureParam<int> kUtilityProcessThreadPoolLogLevel{
&kEnableHangWatcher, "utility_process_threadpool_log_level",
static_cast<int>(LoggingLevel::kUmaOnly)};
// static
const base::TimeDelta WatchHangsInScope::kDefaultHangWatchTime =
base::Seconds(10);
constexpr const char* kThreadName = "HangWatcher";
// The time that the HangWatcher thread will sleep for between calls to
@ -223,7 +219,9 @@ constexpr auto kMonitoringPeriod = base::Seconds(10);
WatchHangsInScope::WatchHangsInScope(TimeDelta timeout) {
internal::HangWatchState* current_hang_watch_state =
internal::HangWatchState::GetHangWatchStateForCurrentThread()->Get();
HangWatcher::IsEnabled()
? internal::HangWatchState::GetHangWatchStateForCurrentThread()->Get()
: nullptr;
DCHECK(timeout >= base::TimeDelta()) << "Negative timeouts are invalid.";

@ -68,12 +68,12 @@ class BASE_EXPORT WatchHangsInScope {
// A good default value needs to be large enough to represent a significant
// hang and avoid noise while being small enough to not exclude too many
// hangs. The nature of the work that gets executed on the thread is also
// important. We can be much stricter when monitoring a UI thread compared tp
// important. We can be much stricter when monitoring a UI thread compared to
// a ThreadPool thread for example.
static const base::TimeDelta kDefaultHangWatchTime;
static constexpr base::TimeDelta kDefaultHangWatchTime = base::Seconds(10);
// Constructing/destructing thread must be the same thread.
explicit WatchHangsInScope(TimeDelta timeout);
explicit WatchHangsInScope(TimeDelta timeout = kDefaultHangWatchTime);
~WatchHangsInScope();
WatchHangsInScope(const WatchHangsInScope&) = delete;