New issue
Advanced search Search tips

Issue 613230 link

Starred by 5 users

Issue metadata

Status: Fixed
Owner:
Closed: May 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: All
Pri: 1
Type: Bug

Blocking:
issue 574343



Sign in to add a comment

Long-running timer task warning triggers a LOT

Project Member Reported by rbyers@chromium.org, May 19 2016

Issue description

Chrome Version       : 52.0.2739.0

In practice when debugging even simple pages I tend to see this message a lot:
Deferred long-running timer task(s) to improve scrolling smoothness. See  crbug.com/574343 .

Eg. I've seen it a couple times playing with touch events on http://output.jsbin.com/kibaxu with a ToT Release build at #394613 (i.e. includes the fix from 615e70af88d0c4fc1293effa4e797509820e45f1).  I can't reproduce reliably though so can't grab a trace.  I really don't believe there's any "long running timer" on this page.

Perhaps we should start by adding an UMA?


I'm not convinced it's d
 

Comment 1 by rbyers@chromium.org, May 19 2016

(sorry, ignore the last line - meant to delete it).

Comment 2 by rbyers@chromium.org, May 19 2016

Blocking: 574343
When you say debug, does that involve setting breakpoints?

Comment 4 by rbyers@chromium.org, May 19 2016

No I just had the console open, no breakpoints.  I guess we should disable the behavior  when we hit a breakpoint though, eh?

Looking at the jsbin page, there are two setTimeout calls - one to animate away the "edit in jsbin" button (which triggers a layout but really shouldn't be very expensive) and one for google analytics that I don't quite understand yet.  I suppose it's possible the latter one is doing something expensive but I'm skeptical.

The other side of this is that even if the warning is accurate, it's really very hard to get something actionable out of it.  So if we're warning all the time without pointing developers at something concrete they can do, we're just going to create perf warning blindness.

Is the warning supposed to point to the specific line of JavaScript where the timer is defined?  In my tests (eg. on cnn.com) I always see just "(index):1" as the source context for the warning.
Unfortunately we don't have a way to point to a specific line of JS yet. There are too many layers between the scheduler and v8 :P

I'll do some tracing on this page, but I'm starting to suspect that the warning as currently implemented is doing more harm than good. In some sense it is the ground truth because *something* ran for too long, but pointing to the specific culprit automatically is extremely difficult. (For example, the cause might not have been a JS timer but an internal blink task which used a timer.)

Comment 6 by rbyers@chromium.org, May 19 2016

Yeah, I'm getting the same feeling.  For example I just saw this warning on this page: http://rbyers.github.io/eventTest.html which doesn't use a timer at all.
Status: Started (was: Assigned)
Thanks Rick, those are useful test pages. Turns out the message was logged because we blocked all timer tasks from running while waiting for a touchstart to be processed (which we've done for a long time now).

I've got a patch that fixes this and makes the alerting threshold a little more useful in general too: https://codereview.chromium.org/2016943003/
Project Member

Comment 8 by bugdroid1@chromium.org, May 27 2016

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

commit c66723959e9a37f1a5bbd821366a2ee24a9537c2
Author: skyostil <skyostil@chromium.org>
Date: Fri May 27 14:50:44 2016

scheduler: Avoid false alerts about expensive task blocking

This patch adjusts the logic for logging a console message when an
expensive task is blocked:

1. Don't log messages when all timer tasks are blocked (e.g., while
   waiting for a touchstart response). There's nothing the developer can
   do to avoid this type of blocking.

2. Only report blocking for tasks which exceed the 50ms RAIL threshold.
   These types of tasks are most likely to cause user visible jank.
   Lower blocking thresholds are also used for shorter periods of time,
   so shorter tasks are not likely to be deferred for a long time
   in any case.

3. Also mention network tasks in the log message.

BUG= 613230 

Review-Url: https://codereview.chromium.org/2016943003
Cr-Commit-Position: refs/heads/master@{#396467}

[modify] https://crrev.com/c66723959e9a37f1a5bbd821366a2ee24a9537c2/components/scheduler/renderer/renderer_scheduler_impl.cc
[modify] https://crrev.com/c66723959e9a37f1a5bbd821366a2ee24a9537c2/components/scheduler/renderer/renderer_scheduler_impl_unittest.cc

Labels: Merge-Request-52 M-52
Status: Fixed (was: Started)
Requesting a merge to M52.
Requesting to bake the Cl in canary.

If all goes well, please merge to 2743 branch before 05/31,Monday 5.00 pm PST.

Comment 11 by tin...@google.com, May 28 2016

Labels: -Merge-Request-52 Merge-Approved-52 Hotlist-Merge-Approved
Your change meets the bar and is auto-approved for M52 (branch: 2743)
Project Member

Comment 12 by bugdroid1@chromium.org, May 31 2016

Labels: -merge-approved-52 merge-merged-2743
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/72912f97a2fd244ce81b7720694fa34a159d8b22

commit 72912f97a2fd244ce81b7720694fa34a159d8b22
Author: Sami Kyostila <skyostil@chromium.org>
Date: Tue May 31 09:24:53 2016

scheduler: Avoid false alerts about expensive task blocking

This patch adjusts the logic for logging a console message when an
expensive task is blocked:

1. Don't log messages when all timer tasks are blocked (e.g., while
   waiting for a touchstart response). There's nothing the developer can
   do to avoid this type of blocking.

2. Only report blocking for tasks which exceed the 50ms RAIL threshold.
   These types of tasks are most likely to cause user visible jank.
   Lower blocking thresholds are also used for shorter periods of time,
   so shorter tasks are not likely to be deferred for a long time
   in any case.

3. Also mention network tasks in the log message.

BUG= 613230 

Review-Url: https://codereview.chromium.org/2016943003
Cr-Commit-Position: refs/heads/master@{#396467}
(cherry picked from commit c66723959e9a37f1a5bbd821366a2ee24a9537c2)

Review URL: https://codereview.chromium.org/2024823002 .

Cr-Commit-Position: refs/branch-heads/2743@{#136}
Cr-Branched-From: 2b3ae3b8090361f8af5a611712fc1a5ab2de53cb-refs/heads/master@{#394939}

[modify] https://crrev.com/72912f97a2fd244ce81b7720694fa34a159d8b22/components/scheduler/renderer/renderer_scheduler_impl.cc
[modify] https://crrev.com/72912f97a2fd244ce81b7720694fa34a159d8b22/components/scheduler/renderer/renderer_scheduler_impl_unittest.cc

Sign in to add a comment