Emit a console warning when blocking event listener is delayed for too long

Emit a console warning when blocking event listener is delayed for too long

BUG=609172
Committed: https://crrev.com/d6fb47a68199ad74ddbc33c5cf88bfdfed5fce86
Cr-Commit-Position: refs/heads/master@{#393432}

[caseq, 2016-05-03 22:55:41]

caseq@chromium.org changed reviewers:
+ dtapuska@chromium.org, pfeldman@chromium.org

[dtapuska, 2016-05-03 23:42:07]

Bug=?

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
File third_party/WebKit/Source/core/events/EventTarget.cpp (right):

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
third_party/WebKit/Source/core/events/EventTarget.cpp:429: bool
shouldReportBlockedEvent =
InspectorInstrumentation::shouldReportBlockedEvent(context, event);
This code codes two wtf monotonically increasing time calls. Can't it just be
called once? Should this also not be reported for uncanceleable events?

[caseq, 2016-05-04 00:04:49]

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
File third_party/WebKit/Source/core/events/EventTarget.cpp (right):

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
third_party/WebKit/Source/core/events/EventTarget.cpp:429: bool
shouldReportBlockedEvent =
InspectorInstrumentation::shouldReportBlockedEvent(context, event);
On 2016/05/03 23:42:06, dtapuska wrote:
> This code codes two wtf monotonically increasing time calls. Can't it just be
> called once? Should this also not be reported for uncanceleable events? 

The check for event types is within InspectorInputAgent, and the second call for
monotonicallyOIncreasingTime() is conditional on shouldReportBlockedEvent()
returning true -- i.e. on the event being of the types that we report, the
front-end being attached and the delay being over threshold. So it's actually
either zero or one monotonicallyIncresaingTime() calls unless we'll be actually
reporting the event.

I could perhaps return the timestamp as an output parameter of
shouldReportBlockedEvent() and thus reduce two potential calls to at most one at
the cost of making the interface a bit strange, but I'm not sure it's worth
doing considering we rarely actually take timestamp twice. WDYT?

[caseq, 2016-05-04 17:25:20]

Description was changed from

==========
Emit a console warning when blocking event listener is delayed for too long
==========

to

==========
Emit a console warning when blocking event listener is delayed for too long

BUG=609172
==========

[dtapuska, 2016-05-04 17:46:10]

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
File third_party/WebKit/Source/core/events/EventTarget.cpp (right):

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
third_party/WebKit/Source/core/events/EventTarget.cpp:429: bool
shouldReportBlockedEvent =
InspectorInstrumentation::shouldReportBlockedEvent(context, event);
On 2016/05/04 00:04:49, caseq wrote:
> On 2016/05/03 23:42:06, dtapuska wrote:
> > This code codes two wtf monotonically increasing time calls. Can't it just
be
> > called once? Should this also not be reported for uncanceleable events? 
> 
> The check for event types is within InspectorInputAgent, and the second call
for
> monotonicallyOIncreasingTime() is conditional on shouldReportBlockedEvent()
> returning true -- i.e. on the event being of the types that we report, the
> front-end being attached and the delay being over threshold. So it's actually
> either zero or one monotonicallyIncresaingTime() calls unless we'll be
actually
> reporting the event.
> 
> I could perhaps return the timestamp as an output parameter of
> shouldReportBlockedEvent() and thus reduce two potential calls to at most one
at
> the cost of making the interface a bit strange, but I'm not sure it's worth
> doing considering we rarely actually take timestamp twice. WDYT?

this is probably ok

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
third_party/WebKit/Source/core/events/EventTarget.cpp:458: if
(shouldReportBlockedEvent && !registeredListener.passive &&
!registeredListener.blockedEventWarningEmitted && !event->defaultPrevented())
So this is when the event listener registers as a passive handler. But the
compositor could force the event to be un=cancelable. Do we want to report this
blocked metric for cases that fall into our intervention?

(Alternate is to do the check in shouldReportBlockedEvent as per my other
comment).

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
File third_party/WebKit/Source/core/inspector/InspectorInputAgent.cpp (right):

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
third_party/WebKit/Source/core/inspector/InspectorInputAgent.cpp:248: if
(eventType != EventTypeNames::touchstart
I think this needs a event->cancelable() &&

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
third_party/WebKit/Source/core/inspector/InspectorInputAgent.cpp:256: bool
report = now - event->platformTimeStamp() > m_blockedEventsWarningThreshold;
There should likely be a test for now - event->platformTimeStamp being positive.

There was some talk about exposing the timestamp to the EventInit.
(https://github.com/whatwg/dom/issues/76) And if that is implemented it is
possible that the now < event->platformTimeStamp

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
File third_party/WebKit/Source/core/inspector/InspectorInputAgent.h (right):

https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
third_party/WebKit/Source/core/inspector/InspectorInputAgent.h:68: void
reportBlockedEvent(ExecutionContext*, Event*, RegisteredEventListener*, double
delayedSeconds);
I think Event can be const.

[caseq, 2016-05-04 18:40:20]

Patchset #2 (id:20001) has been deleted

[caseq, 2016-05-04 19:01:18]

On 2016/05/04 17:46:10, dtapuska wrote:

> So this is when the event listener registers as a passive handler. But the
> compositor could force the event to be un=cancelable. Do we want to report
this
> blocked metric for cases that fall into our intervention?
> (Alternate is to do the check in shouldReportBlockedEvent as per my other
> comment).

I've added a bail-out upon !event->cancelable() in shouldReportBlockedEvent() as
per your other comment, but I'm really not sure what's the best thing to do here
-- if we make an intervention, shouldn't we report it (perhaps, separately)?

>
https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
> third_party/WebKit/Source/core/inspector/InspectorInputAgent.cpp:256: bool
> report = now - event->platformTimeStamp() > m_blockedEventsWarningThreshold;
> There should likely be a test for now - event->platformTimeStamp being
positive.
> 
> There was some talk about exposing the timestamp to the EventInit.
> (https://github.com/whatwg/dom/issues/76) And if that is implemented it is
> possible that the now < event->platformTimeStamp

Thanks for pointing out -- I went through the discussion there and it looks to
me that the use cases for this would be when an event is synthesized based on
some other event, which was presumably in the past. So I hope that when we add
this, we explicitly disallow timestamps from the future, so adding a check with
NOTREACHABLE() for the time being.


>
https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
> File third_party/WebKit/Source/core/inspector/InspectorInputAgent.h (right):
> 
>
https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
> third_party/WebKit/Source/core/inspector/InspectorInputAgent.h:68: void
> reportBlockedEvent(ExecutionContext*, Event*, RegisteredEventListener*, double
> delayedSeconds);
> I think Event can be const.

Thanks, fixed!

[dtapuska, 2016-05-04 19:08:18]

On 2016/05/04 19:01:18, caseq wrote:
> On 2016/05/04 17:46:10, dtapuska wrote:
> 
> > So this is when the event listener registers as a passive handler. But the
> > compositor could force the event to be un=cancelable. Do we want to report
> this
> > blocked metric for cases that fall into our intervention?
> > (Alternate is to do the check in shouldReportBlockedEvent as per my other
> > comment).
> 
> I've added a bail-out upon !event->cancelable() in shouldReportBlockedEvent()
as
> per your other comment, but I'm really not sure what's the best thing to do
here
> -- if we make an intervention, shouldn't we report it (perhaps, separately)?
> 
> >
>
https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
> > third_party/WebKit/Source/core/inspector/InspectorInputAgent.cpp:256: bool
> > report = now - event->platformTimeStamp() > m_blockedEventsWarningThreshold;
> > There should likely be a test for now - event->platformTimeStamp being
> positive.
> > 
> > There was some talk about exposing the timestamp to the EventInit.
> > (https://github.com/whatwg/dom/issues/76) And if that is implemented it is
> > possible that the now < event->platformTimeStamp
> 
> Thanks for pointing out -- I went through the discussion there and it looks to
> me that the use cases for this would be when an event is synthesized based on
> some other event, which was presumably in the past. So I hope that when we add
> this, we explicitly disallow timestamps from the future, so adding a check
with
> NOTREACHABLE() for the time being.
> 
> 
> >
>
https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
> > File third_party/WebKit/Source/core/inspector/InspectorInputAgent.h (right):
> > 
> >
>
https://codereview.chromium.org/1949793002/diff/1/third_party/WebKit/Source/c...
> > third_party/WebKit/Source/core/inspector/InspectorInputAgent.h:68: void
> > reportBlockedEvent(ExecutionContext*, Event*, RegisteredEventListener*,
double
> > delayedSeconds);
> > I think Event can be const.
> 
> Thanks, fixed!

lgtm

[pfeldman, 2016-05-04 22:58:02]

https://codereview.chromium.org/1949793002/diff/40001/third_party/WebKit/Sour...
File third_party/WebKit/Source/core/events/EventTarget.cpp (right):

https://codereview.chromium.org/1949793002/diff/40001/third_party/WebKit/Sour...
third_party/WebKit/Source/core/events/EventTarget.cpp:429: bool
shouldReportBlockedEvent =
InspectorInstrumentation::shouldReportBlockedEvent(context, event);
Lets instead call EventTarget::logBlockedEventsToConsole();

https://codereview.chromium.org/1949793002/diff/40001/third_party/WebKit/Sour...
File third_party/WebKit/Source/core/inspector/InspectorDOMDebuggerAgent.cpp
(right):

https://codereview.chromium.org/1949793002/diff/40001/third_party/WebKit/Sour...
third_party/WebKit/Source/core/inspector/InspectorDOMDebuggerAgent.cpp:124:
v8::Local<v8::Function> function;
Is this change related? Extract?

[caseq, 2016-05-10 01:54:56]

ptal -- the logic is moved to EventTarget.cpp and the threshold value is now in
Settings as per Dmitry's suggestion.

[caseq, 2016-05-10 17:24:14]

Patchset #4 (id:80001) has been deleted

[pfeldman, 2016-05-10 20:01:23]

lgtm % comments

https://codereview.chromium.org/1949793002/diff/100001/third_party/WebKit/Sou...
File third_party/WebKit/Source/core/events/EventTarget.cpp (right):

https://codereview.chromium.org/1949793002/diff/100001/third_party/WebKit/Sou...
third_party/WebKit/Source/core/events/EventTarget.cpp:104: "Handling of %s input
event was delayed for %ld ms. due to main thread being busy. "
'%s'

https://codereview.chromium.org/1949793002/diff/100001/third_party/WebKit/Sou...
third_party/WebKit/Source/core/events/EventTarget.cpp:104: "Handling of %s input
event was delayed for %ld ms. due to main thread being busy. "
No need for . after ms

https://codereview.chromium.org/1949793002/diff/100001/third_party/WebKit/Sou...
third_party/WebKit/Source/core/events/EventTarget.cpp:105: "Consider marking
event handler as passive to make the page appear more responive.",
'passive'

https://codereview.chromium.org/1949793002/diff/100001/third_party/WebKit/Sou...
third_party/WebKit/Source/core/events/EventTarget.cpp:105: "Consider marking
event handler as passive to make the page appear more responive.",
s/appear//

https://codereview.chromium.org/1949793002/diff/100001/third_party/WebKit/Sou...
File third_party/WebKit/Source/core/inspector/InspectorInputAgent.h (right):

https://codereview.chromium.org/1949793002/diff/100001/third_party/WebKit/Sou...
third_party/WebKit/Source/core/inspector/InspectorInputAgent.h:64: void
setBlockedEventsWarningThreshold(ErrorString*, double threshold) override;
Now that it is a setting, we could move it into the page agent.

[caseq, 2016-05-11 20:20:24]

The CQ bit was checked by caseq@chromium.org

[caseq, 2016-05-11 20:20:24]

The patchset sent to the CQ was uploaded after l-g-t-m from
dtapuska@chromium.org, pfeldman@chromium.org
Link to the patchset: https://codereview.chromium.org/1949793002/#ps140001
(title: "rebased")

[commit-bot: I haz the power, 2016-05-11 20:20:56]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1949793002/140001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1949793002/140001

[caseq, 2016-05-11 20:21:20]

The CQ bit was unchecked by caseq@chromium.org

[caseq, 2016-05-11 20:29:13]

The CQ bit was checked by caseq@chromium.org

[caseq, 2016-05-11 20:29:14]

The patchset sent to the CQ was uploaded after l-g-t-m from
dtapuska@chromium.org, pfeldman@chromium.org
Link to the patchset: https://codereview.chromium.org/1949793002/#ps160001
(title: "reverted changes to InspectorInputAgent.h")

[commit-bot: I haz the power, 2016-05-11 20:29:55]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1949793002/160001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1949793002/160001

[caseq, 2016-05-11 20:36:13]

The CQ bit was unchecked by caseq@chromium.org

[caseq, 2016-05-12 01:38:11]

The CQ bit was checked by caseq@chromium.org

[commit-bot: I haz the power, 2016-05-12 01:38:36]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1949793002/160001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1949793002/160001

[commit-bot: I haz the power, 2016-05-12 01:44:00]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-05-12 01:44:02]

Try jobs failed on following builders:
  chromium_presubmit on tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/chromium_presub...)

[caseq, 2016-05-13 00:00:22]

The CQ bit was checked by caseq@chromium.org

[caseq, 2016-05-13 00:00:22]

The patchset sent to the CQ was uploaded after l-g-t-m from
dtapuska@chromium.org, pfeldman@chromium.org
Link to the patchset: https://codereview.chromium.org/1949793002/#ps180001
(title: "rebased")

[commit-bot: I haz the power, 2016-05-13 00:00:43]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1949793002/180001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1949793002/180001

[commit-bot: I haz the power, 2016-05-13 02:20:32]

Description was changed from

==========
Emit a console warning when blocking event listener is delayed for too long

BUG=609172
==========

to

==========
Emit a console warning when blocking event listener is delayed for too long

BUG=609172
==========

[commit-bot: I haz the power, 2016-05-13 02:20:34]

Committed patchset #8 (id:180001)

[commit-bot: I haz the power, 2016-05-13 02:21:49]

Description was changed from

==========
Emit a console warning when blocking event listener is delayed for too long

BUG=609172
==========

to

==========
Emit a console warning when blocking event listener is delayed for too long

BUG=609172

Committed: https://crrev.com/d6fb47a68199ad74ddbc33c5cf88bfdfed5fce86
Cr-Commit-Position: refs/heads/master@{#393432}
==========

[commit-bot: I haz the power, 2016-05-13 02:21:51]

Patchset 8 (id:??) landed as
https://crrev.com/d6fb47a68199ad74ddbc33c5cf88bfdfed5fce86
Cr-Commit-Position: refs/heads/master@{#393432}