New issue
Advanced search Search tips

Issue 860801 link

Starred by 3 users

Issue metadata

Status: Fixed
Owner:
Closed: Jul 24
Cc:
Components:
EstimatedDays: ----
NextAction: 2018-08-15
OS: Windows
Pri: 2
Type: Bug-Regression



Sign in to add a comment

17ms + 20ms startup regression updating histograms in base::MessageLoop

Project Member Reported by wittman@chromium.org, Jul 6

Issue description

We're seeing 17ms extra work during the first 30 seconds of startup updating histograms in base::MessageLoop::DoDelayedWork(), and 0.5% extra non-idle work during continuous profiling.

Startup: https://uma.googleplex.com/p/chrome/callstacks?sid=ba6aa98c41293de915f9b7ff7f637ef2

Continuous profiling: https://uma.googleplex.com/p/chrome/callstacks?sid=0b6ba5aa1f41b21c1d2f0d0d363a2c93

This is on the browser process UI thread on 64-bit Chrome on Windows in 69.0.3478.0 Canary.

The responsible CL appears to be https://chromium.googlesource.com/chromium/src.git/+/f93ca115caf2976f5a799b1782aaddfd6544102e

Suspecting this is WAI, but filing a bug just in case.
 
Labels: ReleaseBlock-Beta M-69
Oh, thanks, and there's actually another 17ms in AddToIncomingQueue which was another diagnosis metric I recently added : https://uma.googleplex.com/p/chrome/callstacks?sid=69963eab439f67d2f39e61c6f0f1d065

I'll mark this ReleaseBlock M69 Beta to remove the diagnosis metrics before branch.

Seems the majority of ^base::Histogram on Main/IO thread is spent in these diagnosis metric (I wonder why they're so bad... high frequency + multi-threading is slowing down the atomics logic in metrics code?).
Summary: 17ms + 20ms startup regression updating histograms in base::MessageLoop (was: 17ms startup regression updating histograms in base::MessageLoop::DoDelayedWork() )
Actually second regression is more 20ms when adding another diagnosis metric in DoIdleWork() : https://uma.googleplex.com/p/chrome/callstacks?sid=12d114d5fb16ad3e89efa18181397d29
M69 branch is coming VERY soon on July 19th, Your bug is marked as ReleaseBlock-Beta for M69. Please try to land the fix ASAP to trunk in order to prevent many merges going after M69 branch. This will also help us to branch M69 from high quality trunk. Thank you.

Friendly ping to get an update as it is marked as RBB.
Thanks..!
Status: Started (was: Assigned)
Working on it.
M69 branch is coming VERY soon on this Thursday, July 19th, Your bug is marked as ReleaseBlock-Beta for M69. Please try to land the fix ASAP to trunk in order to prevent many merges going after M69 branch. This will also help us to branch M69 from high quality trunk. Thank you.
Gentle ping to get an update on this issue as per C#6.
Thanks..!
Project Member

Comment 9 by bugdroid1@chromium.org, Jul 19

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/81626592441ad8517fb6acc8c85e4df4544222e4

commit 81626592441ad8517fb6acc8c85e4df4544222e4
Author: Gabriel Charette <gab@chromium.org>
Date: Thu Jul 19 23:22:46 2018

[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}
[modify] https://crrev.com/81626592441ad8517fb6acc8c85e4df4544222e4/base/message_loop/incoming_task_queue.cc
[modify] https://crrev.com/81626592441ad8517fb6acc8c85e4df4544222e4/base/message_loop/message_loop.cc
[modify] https://crrev.com/81626592441ad8517fb6acc8c85e4df4544222e4/base/message_loop/message_loop.h
[modify] https://crrev.com/81626592441ad8517fb6acc8c85e4df4544222e4/base/message_loop/message_loop_unittest.cc
[modify] https://crrev.com/81626592441ad8517fb6acc8c85e4df4544222e4/tools/metrics/histograms/histograms.xml

Project Member

Comment 10 by bugdroid1@chromium.org, Jul 23

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/c512937e6b6f6ec01384fbb210401aac0c7f1467

commit c512937e6b6f6ec01384fbb210401aac0c7f1467
Author: Wez <wez@chromium.org>
Date: Mon Jul 23 09:56:44 2018

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

This reverts commit 81626592441ad8517fb6acc8c85e4df4544222e4.

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}
[modify] https://crrev.com/c512937e6b6f6ec01384fbb210401aac0c7f1467/base/message_loop/incoming_task_queue.cc
[modify] https://crrev.com/c512937e6b6f6ec01384fbb210401aac0c7f1467/base/message_loop/message_loop.cc
[modify] https://crrev.com/c512937e6b6f6ec01384fbb210401aac0c7f1467/base/message_loop/message_loop.h
[modify] https://crrev.com/c512937e6b6f6ec01384fbb210401aac0c7f1467/base/message_loop/message_loop_unittest.cc
[modify] https://crrev.com/c512937e6b6f6ec01384fbb210401aac0c7f1467/tools/metrics/histograms/histograms.xml

Project Member

Comment 11 by bugdroid1@chromium.org, Jul 23

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/5c7b464ca5393510823ad2c2a0262a4eb1460c05

commit 5c7b464ca5393510823ad2c2a0262a4eb1460c05
Author: Gabriel Charette <gab@chromium.org>
Date: Mon Jul 23 20:05:18 2018

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

This reverts commit c512937e6b6f6ec01384fbb210401aac0c7f1467.

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 81626592441ad8517fb6acc8c85e4df4544222e4.
> 
> 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/1147360
Reviewed-by: Gabriel Charette <gab@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#577228}
[modify] https://crrev.com/5c7b464ca5393510823ad2c2a0262a4eb1460c05/base/message_loop/incoming_task_queue.cc
[modify] https://crrev.com/5c7b464ca5393510823ad2c2a0262a4eb1460c05/base/message_loop/message_loop.cc
[modify] https://crrev.com/5c7b464ca5393510823ad2c2a0262a4eb1460c05/base/message_loop/message_loop.h
[modify] https://crrev.com/5c7b464ca5393510823ad2c2a0262a4eb1460c05/base/message_loop/message_loop_unittest.cc
[modify] https://crrev.com/5c7b464ca5393510823ad2c2a0262a4eb1460c05/tools/metrics/histograms/histograms.xml

Project Member

Comment 12 by bugdroid1@chromium.org, Jul 23

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/771b50f56cd66df43f6fa26bc113147432748255

commit 771b50f56cd66df43f6fa26bc113147432748255
Author: Gabriel Charette <gab@chromium.org>
Date: Mon Jul 23 20:15:56 2018

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

This reverts commit 5c7b464ca5393510823ad2c2a0262a4eb1460c05.

Reason for revert: oops, didn't mean to auto-CQ PS1.

Original change's description:
> Reland "[MessageLoop] Remove heavy diagnosis metrics and leave others only on UI thread"
> 
> This reverts commit c512937e6b6f6ec01384fbb210401aac0c7f1467.
> 
> 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 81626592441ad8517fb6acc8c85e4df4544222e4.
> > 
> > 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/1147360
> Reviewed-by: Gabriel Charette <gab@chromium.org>
> Commit-Queue: Gabriel Charette <gab@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#577228}

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

Change-Id: I29dec465bd2a29c3aa16940664ba5e1d3d005c0e
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug:  860801 ,  850450 , 786597,  866299 
Reviewed-on: https://chromium-review.googlesource.com/1147380
Reviewed-by: Gabriel Charette <gab@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#577234}
[modify] https://crrev.com/771b50f56cd66df43f6fa26bc113147432748255/base/message_loop/incoming_task_queue.cc
[modify] https://crrev.com/771b50f56cd66df43f6fa26bc113147432748255/base/message_loop/message_loop.cc
[modify] https://crrev.com/771b50f56cd66df43f6fa26bc113147432748255/base/message_loop/message_loop.h
[modify] https://crrev.com/771b50f56cd66df43f6fa26bc113147432748255/base/message_loop/message_loop_unittest.cc
[modify] https://crrev.com/771b50f56cd66df43f6fa26bc113147432748255/tools/metrics/histograms/histograms.xml

Project Member

Comment 13 by bugdroid1@chromium.org, Jul 24

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/5a4495a48fb32b1faa38b4a0a21b47eddce44ef5

commit 5a4495a48fb32b1faa38b4a0a21b47eddce44ef5
Author: Gabriel Charette <gab@chromium.org>
Date: Tue Jul 24 15:34:01 2018

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

Original CL: https://chromium-review.googlesource.com/c/chromium/src/+/1142589
Reverted for test flakiness on Fuchsia.
Implementation is fine (this is a diagnostic metric -- this change
definitely doesn't make it worse). The test was only added to ensure
proper logging on UI thread only. Made the test more robust in this
reland (see diff vs PS1). If it flakes again, please disable it on flaky
platforms instead of reverting.


Original change's description:

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.

TBR=wez@chromium.org

Bug:  860801 ,  850450 , 786597,  866299 
Change-Id: Ic0fb2b58780cd595e47b36f97a9ae440bb988225
Reviewed-on: https://chromium-review.googlesource.com/1147400
Commit-Queue: Gabriel Charette <gab@chromium.org>
Reviewed-by: Wez <wez@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#577553}
[modify] https://crrev.com/5a4495a48fb32b1faa38b4a0a21b47eddce44ef5/base/message_loop/incoming_task_queue.cc
[modify] https://crrev.com/5a4495a48fb32b1faa38b4a0a21b47eddce44ef5/base/message_loop/message_loop.cc
[modify] https://crrev.com/5a4495a48fb32b1faa38b4a0a21b47eddce44ef5/base/message_loop/message_loop.h
[modify] https://crrev.com/5a4495a48fb32b1faa38b4a0a21b47eddce44ef5/base/message_loop/message_loop_unittest.cc
[modify] https://crrev.com/5a4495a48fb32b1faa38b4a0a21b47eddce44ef5/tools/metrics/histograms/histograms.xml

Status: Fixed (was: Started)
r576686 resulted in :
 * -32ms on UI thread (startup)
 * -1.5% non-idle time on UI thread (periodic)
 * -42ms on IO thread (startup)
 * -1.5% non-idle time on IO thread (periodic)

https://uma.googleplex.com/p/chrome/callstacks?sid=5f537b3d7771241e53b4915e57506d8d
https://uma.googleplex.com/p/chrome/callstacks?sid=88d1b199c7f2c473096628c10c04ed8f
https://uma.googleplex.com/p/chrome/callstacks?sid=c8818e59082effa714ebaa9e2d0e268b
https://uma.googleplex.com/p/chrome/callstacks?sid=717d42200eb875b69f878c966453a5ac

Interestingly the remaining Histogram::AddCount() call in DoIdleWork() is still the one caught the most often by sampling profiler (for a "4ms average"): https://uma.googleplex.com/p/chrome/callstacks?sid=69f9e7927036def7c80df9004968f5c6
but it's not slow (1 microsecond per call, on par with other calls to Histogram::AddCount()), it's just made more often.

I'll leave it like this for M70 and remove the diagnosis metric completely when done.
Also, as far as M69 is concerned, we got lucky. r576686 barely made the branch cut and then the revert in r577133 was in M70 (the reland merely tweaked the test so no need for the reverts/reland on branch)
Labels: Merge-TBD
[Auto-generated comment by a script] We noticed that this issue is targeted for M-69; it appears the fix may have landed after branch point, meaning a merge might be required. Please confirm if a merge is required here - if so add Merge-Request-69 label, otherwise remove Merge-TBD label. Thanks.
Labels: -Merge-TBD
Per #15
Oops I've regressed this again in r578809 : 
https://uma.googleplex.com/p/chrome/callstacks?sid=c67b4e6156f9da34ef44ecd9b8e63041

Bad rebase of https://chromium-review.googlesource.com/c/chromium/src/+/1088762 on top of https://chromium-review.googlesource.com/c/chromium/src/+/1147400 ...

Surprised that there isn't a tool catching the addition/presence of logging macros for an obsolete histogram though...
Cc: gayane@chromium.org
@gayane: should/could there be a tool to catch the addition/presence of logging macros for an obsolete histogram? Seems very similar to the new notifications for expired histograms?

(ref. #18 above)
Project Member

Comment 20 by bugdroid1@chromium.org, Aug 14

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/906fbc1875a1ff483cfc07cf9c6a442892fee62c

commit 906fbc1875a1ff483cfc07cf9c6a442892fee62c
Author: Gabriel Charette <gab@chromium.org>
Date: Tue Aug 14 21:59:49 2018

[MessageLoop] Remove logging of obsolete histogram unintentionally re-added

This was removed in r577553 but I unintentionally reintroduced it
in r578809 (incorrect rebase).

This regressed  https://crbug.com/860801#c18 

R=kylechar@chromium.org

Bug:  860801 
Change-Id: Ia42d24f915d271832b59c481ebe77ee1bc6fd11d
Reviewed-on: https://chromium-review.googlesource.com/1175060
Reviewed-by: kylechar <kylechar@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#583048}
[modify] https://crrev.com/906fbc1875a1ff483cfc07cf9c6a442892fee62c/base/message_loop/message_loop_task_runner.cc

Labels: Merge-Request-69
Hi, I'd like to merge r583048 to M69. It's a very simple code removal which results in recovering from this 19ms startup regression : https://uma.googleplex.com/p/chrome/callstacks?sid=c67b4e6156f9da34ef44ecd9b8e63041
NextAction: 2018-08-15
Pls update bug with canary result tomorrow.
It's impossible for this to cause any problems on Canary and it's extremely safe.
Labels: -Merge-Request-69 Merge-Approved-69
Approving merge to M69 branch 3497 based on comment #21, #23 and per offline chat with gab@. Pls merge tomorrow morning after checking on canary. Thank you.
The NextAction date has arrived: 2018-08-15
Labels: -Merge-Approved-69
Actually my bad, I only regressed this in r578809 which is in M70 (realized when trying to merge and getting a conflict)... so nothing to merge after all :)
Project Member

Comment 27 by bugdroid1@chromium.org, Nov 14

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/adafd27118988b9be3854dd372b73a56a01642c9

commit adafd27118988b9be3854dd372b73a56a01642c9
Author: Alexander Timin <altimin@chromium.org>
Date: Wed Nov 14 08:25:48 2018

[message_loop] Remove MessageLoop.DelayedTaskQueueForUI.PendingTasksCountOnIdle metric

MessageLoop is going away and this diagnosis metric will need to be re-evaluated.

For the record, this metric's latest values were:

                   Median     99th'ile   Note
Windows Stable :     37          448      >50% of users hit 500+ >=1 times a day
Windows Canary:      37          258      >50% of users hit 250+ >=1 times a day
Android Stable:      28          113      >50% of users hit 65+ >= 1 times a day
Android Dev:         28          149      >50% of users hit 86+ >=1 times a day

R=gab@chromium.org
BUG= 860801 ,891670

Change-Id: Ib45c47286a2a9153827bc4f6e71c7d056e90a5f0
Reviewed-on: https://chromium-review.googlesource.com/c/1333752
Reviewed-by: Gabriel Charette <gab@chromium.org>
Reviewed-by: Robert Kaplow <rkaplow@chromium.org>
Commit-Queue: Alexander Timin <altimin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#607936}
[modify] https://crrev.com/adafd27118988b9be3854dd372b73a56a01642c9/base/message_loop/message_loop.cc
[modify] https://crrev.com/adafd27118988b9be3854dd372b73a56a01642c9/base/message_loop/message_loop_impl.cc
[modify] https://crrev.com/adafd27118988b9be3854dd372b73a56a01642c9/base/message_loop/message_loop_impl.h
[modify] https://crrev.com/adafd27118988b9be3854dd372b73a56a01642c9/base/message_loop/message_loop_unittest.cc
[modify] https://crrev.com/adafd27118988b9be3854dd372b73a56a01642c9/base/message_loop/pending_task_queue.cc
[modify] https://crrev.com/adafd27118988b9be3854dd372b73a56a01642c9/base/message_loop/pending_task_queue.h
[modify] https://crrev.com/adafd27118988b9be3854dd372b73a56a01642c9/tools/metrics/histograms/histograms.xml

Sign in to add a comment