Long-running timer task warning triggers a LOT |
||||||
Issue descriptionChrome 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
,
May 19 2016
,
May 19 2016
When you say debug, does that involve setting breakpoints?
,
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.
,
May 19 2016
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.)
,
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.
,
May 27 2016
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/
,
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
,
May 27 2016
Requesting a merge to M52.
,
May 27 2016
Requesting to bake the Cl in canary. If all goes well, please merge to 2743 branch before 05/31,Monday 5.00 pm PST.
,
May 28 2016
Your change meets the bar and is auto-approved for M52 (branch: 2743)
,
May 31 2016
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 |
||||||
Comment 1 by rbyers@chromium.org
, May 19 2016