Skip to content

GitLab

T
tangled
Commit 5c7b464c authored by Gabriel Charette's avatar Gabriel Charette Committed by Commit Bot
Browse files
Options

Reland "[MessageLoop] Remove heavy diagnosis metrics and leave others only on UI thread" 

This reverts commit c512937e.

Reason for revert: change is correct, fixed test flakiness

Original change's description:
> Revert "[MessageLoop] Remove heavy diagnosis metrics and leave others only on UI thread"
> 
> This reverts commit 81626592.
> 
> Reason for revert: MetricsOnlyFromUILoops test appears to be flaky (see https://crbug.com/866299).
> 
> Original change's description:
> > [MessageLoop] Remove heavy diagnosis metrics and leave others only on UI thread
> >
> > Addresses crbug.com/860801 in time for the M69 branch while keeping the
> > diagnosis signals which will be used to assess future improvements
> > (MessageLoop.DelayedTaskQueueForUI.PendingTasksCountOnIdle that is).
> >
> > Removed MessageLoop.DelayedTaskQueue.PostedDelay as we've
> > learnt everything we needed from this one, that is :
> > We now know that while 99% of tasks are posted with a delay under 30s,
> > 95% of users post at least one task in every portion of the 0ms-3hours
> > range at least once per day:
> > https://uma.googleplex.com/histograms?endDate=20180717&dayCount=1&histograms=MessageLoop.DelayedTaskQueue.PostedDelay&fixupData=true&uniqueUsers=true&showMax=true&filters=platform%2Ceq%2CW%2Cchannel%2Ceq%2C1%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial
> >
> > Removed MessageLoop.ScheduledSleep.* metrics as we've also
> > learnt what we wanted from it, that is :
> > The maximum sleep a MessageLoop ever completes is 1 hour (and
> > even then 99% of completed sleeps are under 1 second), all
> > longer delays are reliably always interrupted.
> > Win : https://uma.googleplex.com/histograms?endDate=20180717&dayCount=1&histograms=MessageLoop.ScheduledSleep.Completed%2CMessageLoop.ScheduledSleep.Interrupted&fixupData=true&showMax=true&filters=platform%2Ceq%2CM%2Cchannel%2Ceq%2C1%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial
> > Mac : https://uma.googleplex.com/histograms?endDate=20180717&dayCount=1&histograms=MessageLoop.ScheduledSleep.Completed%2CMessageLoop.ScheduledSleep.Interrupted&fixupData=true&showMax=true&filters=platform%2Ceq%2CM%2Cchannel%2Ceq%2C1%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial
> > Android : https://uma.googleplex.com/histograms?endDate=20180717&dayCount=1&histograms=MessageLoop.ScheduledSleep.Completed%2CMessageLoop.ScheduledSleep.Interrupted&fixupData=true&showMax=true&filters=platform%2Ceq%2CA%2Cchannel%2Ceq%2C1%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial
> >
> > Added a test for MessageLoop.DelayedTaskQueueForUI.PendingTasksCountOnIdle
> > but it appears to be broken on MacOSX (prior to this CL). Added a note
> > to investigate on the metric but it shouldn't block this CL which
> > doesn't make it worse.
> >
> > R=​kylechar@chromium.org, rkaplow@chromium.org
> >
> > Bug: 860801, 850450, 786597
> > Change-Id: I7a693886ab4e1b9c8e9fbe8a64d906a95019a609
> > Reviewed-on: https://chromium-review.googlesource.com/1142589
> > Commit-Queue: Gabriel Charette <gab@chromium.org>
> > Reviewed-by: kylechar <kylechar@chromium.org>
> > Reviewed-by: Robert Kaplow (OOO until 0730) <rkaplow@chromium.org>
> > Cr-Commit-Position: refs/heads/master@{#576686}
> 
> TBR=gab@chromium.org,rkaplow@chromium.org,erikchen@chromium.org,kylechar@chromium.org
> 
> Bug: 860801, 850450, 786597, 866299
> Change-Id: I848621acf9ddbec69d72649d16a459910ffa937e
> Reviewed-on: https://chromium-review.googlesource.com/1146300
> Commit-Queue: Wez <wez@chromium.org>
> Reviewed-by: Wez <wez@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#577133}

TBR=wez@chromium.org,gab@chromium.org,rkaplow@chromium.org,erikchen@chromium.org,kylechar@chromium.org

Change-Id: Idb53da9b8b40b407ece6cf6c81b95bcb7072d76c
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug: 860801, 850450, 786597, 866299
Reviewed-on: https://chromium-review.googlesource.com/1147360Reviewed-by: default avatarGabriel Charette <gab@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#577228}
parent 14f718b7
Hide whitespace changes
Inline Side-by-side
Showing with 63 additions and 139 deletions
base/message_loop/incoming_task_queue.cc
View file @ 5c7b464c
......@@ -72,9 +72,6 @@ bool IncomingTaskQueue::AddToIncomingQueue(const Location& from_here,
}
#endif
if (!delay.is_zero())
UMA_HISTOGRAM_LONG_TIMES("MessageLoop.DelayedTaskQueue.PostedDelay", delay);
return PostPendingTask(&pending_task);
}
......@@ -85,7 +82,7 @@ void IncomingTaskQueue::Shutdown() {
void IncomingTaskQueue::ReportMetricsOnIdle() const {
UMA_HISTOGRAM_COUNTS_1M(
"MessageLoop.DelayedTaskQueue.PendingTasksCountOnIdle",
"MessageLoop.DelayedTaskQueueForUI.PendingTasksCountOnIdle",
delayed_tasks_.Size());
}
......
base/message_loop/message_loop.cc
View file @ 5c7b464c
......@@ -15,7 +15,6 @@
#include "base/message_loop/message_pump_default.h"
#include "base/message_loop/message_pump_for_io.h"
#include "base/message_loop/message_pump_for_ui.h"
#include "base/metrics/histogram_macros.h"
#include "base/run_loop.h"
#include "base/third_party/dynamic_annotations/dynamic_annotations.h"
#include "base/threading/thread_id_name_manager.h"
......@@ -36,37 +35,6 @@ std::unique_ptr<MessagePump> ReturnPump(std::unique_ptr<MessagePump> pump) {
return pump;
}
enum class ScheduledWakeupResult {
// The MessageLoop went to sleep with a timeout and woke up because of that
// timeout.
kCompleted,
// The MessageLoop went to sleep with a timeout but was woken up before it
// fired.
kInterrupted,
};
// Reports a ScheduledWakeup's result when waking up from a non-infinite sleep.
// Reports are using a 14 day spread (maximum examined delay for
// https://crbug.com/850450#c3), with 50 buckets that still yields 7 buckets
// under 16ms and hence plenty of resolution.
void ReportScheduledWakeupResult(ScheduledWakeupResult result,
TimeDelta intended_sleep) {
switch (result) {
case ScheduledWakeupResult::kCompleted:
UMA_HISTOGRAM_CUSTOM_TIMES("MessageLoop.ScheduledSleep.Completed",
intended_sleep,
base::TimeDelta::FromMilliseconds(1),
base::TimeDelta::FromDays(14), 50);
break;
case ScheduledWakeupResult::kInterrupted:
UMA_HISTOGRAM_CUSTOM_TIMES("MessageLoop.ScheduledSleep.Interrupted",
intended_sleep,
base::TimeDelta::FromMilliseconds(1),
base::TimeDelta::FromDays(14), 50);
break;
}
}
} // namespace
class MessageLoop::Controller : public internal::IncomingTaskQueue::Observer {
......@@ -496,20 +464,6 @@ bool MessageLoop::DoWork() {
// Execute oldest task.
while (incoming_task_queue_->triage_tasks().HasTasks()) {
if (!scheduled_wakeup_.next_run_time.is_null()) {
// While the frontmost task may racily be ripe. The MessageLoop was awaken
// without needing the timeout anyways. Since this metric is about
// determining whether sleeping for long periods ever succeeds: it's
// easier to just consider any untriaged task as an interrupt (this also
// makes the logic simpler for untriaged delayed tasks which may alter the
// top of the task queue prior to DoDelayedWork() but did cause a wakeup
// regardless -- per currently requiring this immediate triage step even
// for long delays).
ReportScheduledWakeupResult(ScheduledWakeupResult::kInterrupted,
scheduled_wakeup_.intended_sleep);
scheduled_wakeup_ = ScheduledWakeup();
}
PendingTask pending_task = incoming_task_queue_->triage_tasks().Pop();
if (pending_task.task.IsCancelled())
continue;
......@@ -533,27 +487,9 @@ bool MessageLoop::DoWork() {
}
bool MessageLoop::DoDelayedWork(TimeTicks* next_delayed_work_time) {
if (!task_execution_allowed_) {
*next_delayed_work_time = TimeTicks();
// |scheduled_wakeup_| isn't used in nested loops that don't process
// application tasks.
DCHECK(scheduled_wakeup_.next_run_time.is_null());
return false;
}
if (!incoming_task_queue_->delayed_tasks().HasTasks()) {
if (!task_execution_allowed_ ||
!incoming_task_queue_->delayed_tasks().HasTasks()) {
*next_delayed_work_time = TimeTicks();
// It's possible to be woken up by a system event and have it cancel the
// upcoming delayed task from under us before DoDelayedWork() -- see comment
// under |next_run_time > recent_time_|. This condition covers the special
// case where such a system event cancelled *all* pending delayed tasks.
if (!scheduled_wakeup_.next_run_time.is_null()) {
ReportScheduledWakeupResult(ScheduledWakeupResult::kInterrupted,
scheduled_wakeup_.intended_sleep);
scheduled_wakeup_ = ScheduledWakeup();
}
return false;
}
......@@ -571,36 +507,10 @@ bool MessageLoop::DoDelayedWork(TimeTicks* next_delayed_work_time) {
recent_time_ = TimeTicks::Now(); // Get a better view of Now();
if (next_run_time > recent_time_) {
*next_delayed_work_time = CapAtOneDay(next_run_time);
// If the loop was woken up early by an untriaged task:
// |scheduled_wakeup_| will have been handled already in DoWork(). If it
// wasn't, it means the early wake up was caused by a system event (e.g.
// MessageLoopForUI or IO).
if (!scheduled_wakeup_.next_run_time.is_null()) {
// Handling the system event may have resulted in cancelling the
// upcoming delayed task (and then it being pruned by
// DelayedTaskQueue::HasTasks()); hence, we cannot check for strict
// equality here. We can however check that the pending task is either
// still there or that a later delay replaced it in front of the queue.
// There shouldn't have been new tasks added in |delayed_tasks()| per
// DoWork() not having triaged new tasks since the last DoIdleWork().
DCHECK_GE(next_run_time, scheduled_wakeup_.next_run_time);
ReportScheduledWakeupResult(ScheduledWakeupResult::kInterrupted,
scheduled_wakeup_.intended_sleep);
scheduled_wakeup_ = ScheduledWakeup();
}
return false;
}
}
if (next_run_time == scheduled_wakeup_.next_run_time) {
ReportScheduledWakeupResult(ScheduledWakeupResult::kCompleted,
scheduled_wakeup_.intended_sleep);
scheduled_wakeup_ = ScheduledWakeup();
}
PendingTask pending_task = incoming_task_queue_->delayed_tasks().Pop();
if (incoming_task_queue_->delayed_tasks().HasTasks()) {
......@@ -619,43 +529,19 @@ bool MessageLoop::DoIdleWork() {
bool need_high_res_timers = false;
#endif
// Do not report idle metrics nor do any logic related to delayed tasks if
// about to quit the loop and/or in a nested loop where
// |!task_execution_allowed_|. In the former case, the loop isn't going to
// sleep and in the latter case DoDelayedWork() will not actually do the work
// this is prepping for.
// Do not report idle metrics if about to quit the loop and/or in a nested
// loop where |!task_execution_allowed_|. In the former case, the loop isn't
// going to sleep and in the latter case DoDelayedWork() will not actually do
// the work this is prepping for.
if (ShouldQuitWhenIdle()) {
pump_->Quit();
} else if (task_execution_allowed_) {
incoming_task_queue_->ReportMetricsOnIdle();
if (incoming_task_queue_->delayed_tasks().HasTasks()) {
TimeTicks scheduled_wakeup_time =
incoming_task_queue_->delayed_tasks().Peek().delayed_run_time;
if (!scheduled_wakeup_.next_run_time.is_null()) {
// It's possible for DoIdleWork() to be invoked twice in a row (e.g. if
// the MessagePump processed system work and became idle twice in a row
// without application tasks in between -- some pumps with a native
// message loop do not invoke DoWork() / DoDelayedWork() when awaken for
// system work only). As in DoDelayedWork(), we cannot check for strict
// equality below as the system work may have cancelled the frontmost
// task.
DCHECK_GE(scheduled_wakeup_time, scheduled_wakeup_.next_run_time);
ReportScheduledWakeupResult(ScheduledWakeupResult::kInterrupted,
scheduled_wakeup_.intended_sleep);
scheduled_wakeup_ = ScheduledWakeup();
}
// Store the remaining delay as well as the programmed wakeup time in
// order to know next time this MessageLoop wakes up whether it woke up
// because of this pending task (is it still the frontmost task in the
// queue?) and be able to report the slept delta (which is lost if not
// saved here).
scheduled_wakeup_ = ScheduledWakeup{
scheduled_wakeup_time, scheduled_wakeup_time - TimeTicks::Now()};
}
// Only track idle metrics in MessageLoopForUI to avoid too much contention
// logging the histogram (https://crbug.com/860801) -- there's typically
// only one UI thread per process and, for practical purposes, restricting
// the MessageLoop diagnostic metrics to it yields similar information.
if (type_ == TYPE_UI)
incoming_task_queue_->ReportMetricsOnIdle();
#if defined(OS_WIN)
// On Windows we activate the high resolution timer so that the wait
......
base/message_loop/message_loop.h
View file @ 5c7b464c
......@@ -287,15 +287,6 @@ class BASE_EXPORT MessageLoop : public MessagePump::Delegate,
// A recent snapshot of Time::Now(), used to check delayed_work_queue_.
TimeTicks recent_time_;
// Non-null when the last thing this MessageLoop did is become idle with
// pending delayed tasks. Used to report metrics on the following wake up.
struct ScheduledWakeup {
// The scheduled time of the next delayed task when this loop became idle.
TimeTicks next_run_time;
// The delta until |next_run_time| when this loop became idle.
TimeDelta intended_sleep;
} scheduled_wakeup_;
ObserverList<DestructionObserver> destruction_observers_;
// A boolean which prevents unintentional reentrant task execution (e.g. from
......
base/message_loop/message_loop_unittest.cc
View file @ 5c7b464c
......@@ -24,6 +24,7 @@
#include "base/synchronization/waitable_event.h"
#include "base/task_scheduler/task_scheduler.h"
#include "base/test/gtest_util.h"
#include "base/test/metrics/histogram_tester.h"
#include "base/test/test_simple_task_runner.h"
#include "base/test/test_timeouts.h"
#include "base/threading/platform_thread.h"
......@@ -1758,6 +1759,33 @@ TEST_P(MessageLoopTypedTest, NestableTasksAllowedManually) {
run_loop.Run();
}
#if defined(OS_MACOSX)
// This metric is a bit broken on Mac OS because CFRunLoop doesn't
// deterministically invoke MessageLoop::DoIdleWork(). This being a temporary
// diagnosis metric, we let this fly and simply not test it on Mac.
#define MAYBE_MetricsOnlyFromUILoops DISABLED_MetricsOnlyFromUILoops
#else
#define MAYBE_MetricsOnlyFromUILoops MetricsOnlyFromUILoops
#endif
TEST_P(MessageLoopTypedTest, MAYBE_MetricsOnlyFromUILoops) {
MessageLoop loop(GetMessageLoopType());
const bool histograms_expected = GetMessageLoopType() == MessageLoop::TYPE_UI;
HistogramTester histogram_tester;
// Loop that goes idle with one pending task.
RunLoop run_loop;
loop.task_runner()->PostDelayedTask(FROM_HERE, run_loop.QuitClosure(),
TimeDelta::FromMilliseconds(1));
run_loop.Run();
histogram_tester.ExpectTotalCount(
"MessageLoop.DelayedTaskQueueForUI.PendingTasksCountOnIdle",
histograms_expected ? 1 : 0);
}
INSTANTIATE_TEST_CASE_P(
,
MessageLoopTypedTest,
......
tools/metrics/histograms/histograms.xml
View file @ 5c7b464c
......@@ -45139,6 +45139,9 @@ uploading your change for review.
</histogram>
<histogram name="MessageLoop.DelayedTaskQueue.PendingTasksCountOnIdle">
<obsolete>
Deprecated as of 07/2018.
</obsolete>
<owner>gab@chromium.org</owner>
<summary>
The size of the delayed task queue when the loop becomes idle. Diagnosis
......@@ -45147,6 +45150,9 @@ uploading your change for review.
</histogram>
<histogram name="MessageLoop.DelayedTaskQueue.PostedDelay" units="ms">
<obsolete>
Deprecated as of 07/2018.
</obsolete>
<owner>gab@chromium.org</owner>
<summary>
Reports the delay of a delayed task posted to a MessageLoop. Reported once
......@@ -45154,7 +45160,20 @@ uploading your change for review.
</summary>
</histogram>
<histogram name="MessageLoop.DelayedTaskQueueForUI.PendingTasksCountOnIdle">
<owner>gab@chromium.org</owner>
<summary>
The size of the delayed task queue when the loop becomes idle on a UI
thread. Diagnosis metric for https://crbug.com/850450#c4. Note: this metric
is a bit broken on Mac OSX as CFRunLoop doesn't deterministically invoke
MessageLoop::DoIdleWork().
</summary>
</histogram>
<histogram name="MessageLoop.ScheduledSleep.Completed" units="ms">
<obsolete>
Deprecated as of 07/2018.
</obsolete>
<owner>gab@chromium.org</owner>
<summary>
Reports the delay for which the MessageLoop successfully slept until an
......@@ -45164,6 +45183,9 @@ uploading your change for review.
</histogram>
<histogram name="MessageLoop.ScheduledSleep.Interrupted" units="ms">
<obsolete>
Deprecated as of 07/2018.
</obsolete>
<owner>gab@chromium.org</owner>
<summary>
Reports the delay for which the MessageLoop had planned to sleep (next
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment