Closed Bug 1341531 Opened 7 years ago Closed 7 years ago

Measure input event to event dispatcher (handler)

Categories

(Toolkit :: Performance Monitoring, defect)

Product:
Toolkit
Component:
Performance Monitoring
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla55
Project Flags:
Performance Impact high
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: wcpan, Assigned: wcpan)

References

Details

Attachments

(1 file)

Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RECEIVED_MS)
59 bytes, text/x-review-board-request
smaug
: review+
Details 
In bug 1313465, we want to measure event to dispatch latency, which can be divide to three parts:
1. from user input to event dispatcher (including IPC)
2. from event dispatcher to paint request (mostly in JavaScript engine)
3. from paint request to actual rendering (compositor, gfx ... etc.)

This bug measures the first part.
Assignee: nobody → wpan
Blocks: 1313465
Summary: Measure event to dispatch latency → Measure input event to dispatch latency
Comment on attachment 8839805 [details]
Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RECEIVED_MS)

https://reviewboard.mozilla.org/r/114364/#review115878

::: dom/events/EventDispatcher.cpp:631
(Diff revision 1)
>    }
>  #endif
>  
> +  if (auto wheelEvent = aEvent->AsWheelEvent()) {
> +    if (wheelEvent->mFlags.mHandledByAPZ) {
> +      Telemetry::AccumulateTimeDelta(Telemetry::APZ_SCROLLING_EVENT_RESPONSE_MS, wheelEvent->mTimeStamp);

Have you profiled how much Telemetry::AccumulateTimeDelta slows down event handling?
(we have had recently several cases when telemetry probes slow down execution significantly. I don't want that to start happening during event dispatch.)
Comment on attachment 8839805 [details]
Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RECEIVED_MS)

https://reviewboard.mozilla.org/r/114364/#review115880

Please profile and add also IsTrusted check.

::: dom/events/EventDispatcher.cpp:629
(Diff revision 1)
>                 NS_ConvertUTF16toUTF8(elementTagName).get());
>      }
>    }
>  #endif
>  
> +  if (auto wheelEvent = aEvent->AsWheelEvent()) {

You don't want untrusted events to affect to telemetry numbers, so this code needs some IsTrusted check.

But testing performance is easier without IsTrusted check, since one can just have a loop
which dispatches for example mousemove events.


var e = new MouseEvent("mousemove");
for (var i = 0; i < 10000; ++i) {
  document.dispatchEvent(e);
}
If that is done by a web page, how does the profile look like?

::: dom/events/EventDispatcher.cpp:633
(Diff revision 1)
>  
> +  if (auto wheelEvent = aEvent->AsWheelEvent()) {
> +    if (wheelEvent->mFlags.mHandledByAPZ) {
> +      Telemetry::AccumulateTimeDelta(Telemetry::APZ_SCROLLING_EVENT_RESPONSE_MS, wheelEvent->mTimeStamp);
> +    } else {
> +      Telemetry::AccumulateTimeDelta(Telemetry::MOUSE_EVENT_RESPONSE_MS, wheelEvent->mTimeStamp);

Is AccumulateTimeDelta guaranteed to work as expected when timestamp is coming from different process?
Attachment #8839805 - Flags: review?(bugs) → review-
(In reply to Olli Pettay [:smaug] (pto-ish for couple of days) from comment #4)
> var e = new MouseEvent("mousemove");
> for (var i = 0; i < 10000; ++i) {
>   document.dispatchEvent(e);
> }
> If that is done by a web page, how does the profile look like?

It takes about 10.x% longer to dispatch 100k events.

> ::: dom/events/EventDispatcher.cpp:633
> (Diff revision 1)
> >  
> > +  if (auto wheelEvent = aEvent->AsWheelEvent()) {
> > +    if (wheelEvent->mFlags.mHandledByAPZ) {
> > +      Telemetry::AccumulateTimeDelta(Telemetry::APZ_SCROLLING_EVENT_RESPONSE_MS, wheelEvent->mTimeStamp);
> > +    } else {
> > +      Telemetry::AccumulateTimeDelta(Telemetry::MOUSE_EVENT_RESPONSE_MS, wheelEvent->mTimeStamp);
> 
> Is AccumulateTimeDelta guaranteed to work as expected when timestamp is
> coming from different process?

The timestamp is a copy from parent process, so I think it will work.
This should minimalize possible overhead by
1. removing type casting and temporary variables
2. using switch instead of if-else
3. filter out unnecessary input events just like INPUT_EVENT_RESPONSE_MS did
(In reply to Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] from comment #5)
> (In reply to Olli Pettay [:smaug] (pto-ish for couple of days) from comment
> #4)
> > var e = new MouseEvent("mousemove");
> > for (var i = 0; i < 10000; ++i) {
> >   document.dispatchEvent(e);
> > }
> > If that is done by a web page, how does the profile look like?
> 
> It takes about 10.x% longer to dispatch 100k events.
That is crazy high number.

What is the overhead with the new patch?
Comment on attachment 8839805 [details]
Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RECEIVED_MS)

https://reviewboard.mozilla.org/r/114364/#review118358

::: layout/base/PresShell.cpp:8150
(Diff revision 2)
>      Telemetry::Accumulate(Telemetry::INPUT_EVENT_RESPONSE_MS, millis);
>      if (mDocument && mDocument->GetReadyStateEnum() != nsIDocument::READYSTATE_COMPLETE) {
>        Telemetry::Accumulate(Telemetry::LOAD_INPUT_EVENT_RESPONSE_MS, millis);
>      }
> +
> +    switch (aEvent->mMessage) {

So having telemetry here changes the meaning totally, since this code is after DOM event dispatch.

::: layout/base/PresShell.cpp:8151
(Diff revision 2)
>      if (mDocument && mDocument->GetReadyStateEnum() != nsIDocument::READYSTATE_COMPLETE) {
>        Telemetry::Accumulate(Telemetry::LOAD_INPUT_EVENT_RESPONSE_MS, millis);
>      }
> +
> +    switch (aEvent->mMessage) {
> +    case eMouseMove:

indent case

::: layout/base/PresShell.cpp:8170
(Diff revision 2)
> +    case eKeyPress:
> +    case eKeyUp:
> +    case eKeyDown:
> +      Telemetry::Accumulate(Telemetry::KEYBOARD_EVENT_RESPONSE_MS, millis);
> +      break;
> +    case eVRDisplayPresentChange:

Why do we want to have telemetry for vrdisplaypresentchange? That doesn't seem to have anything to do with these other input events.

kip would need to review this part, since I don't know when vrdisplaypresentchange is dispatched and the current WebVR spec is quite vague.
Attachment #8839805 - Flags: review?(bugs) → review-
You changed the meaning of the patch. not 1 anymore but 1+2, yet initial description talks about 1.
So what are we trying to measure here?
(In reply to Olli Pettay [:smaug] from comment #10)
> You changed the meaning of the patch. not 1 anymore but 1+2, yet initial
> description talks about 1.
> So what are we trying to measure here?

We want to measure time from input to just before it entering JS engine.
So before/after dispatch maybe doesn't make too much difference.

(In reply to Olli Pettay [:smaug] from comment #9)
> Comment on attachment 8839805 [details]
> ::: layout/base/PresShell.cpp:8170
> (Diff revision 2)
> > +    case eKeyPress:
> > +    case eKeyUp:
> > +    case eKeyDown:
> > +      Telemetry::Accumulate(Telemetry::KEYBOARD_EVENT_RESPONSE_MS, millis);
> > +      break;
> > +    case eVRDisplayPresentChange:
> 
> Why do we want to have telemetry for vrdisplaypresentchange? That doesn't
> seem to have anything to do with these other input events.
> 
> kip would need to review this part, since I don't know when
> vrdisplaypresentchange is dispatched and the current WebVR spec is quite
> vague.

bug 1313465 also mentioned about WebVR so I added it here.

(In reply to Olli Pettay [:smaug] from comment #8)
> That is crazy high number.
> 
> What is the overhead with the new patch?

The time to dispatch 10k events is 575~580ms on my machine. (without any event handler attached)
If I add this code to EventDispatcher::Dispatch, it will increase to 590~610ms.

If this is still too high, maybe we can skip some samples, e.g. only measure one for every 16 events.
But why vrdisplaypresentchange? Is that really the right event to use here?
I'm not familiar enough with WebVR.
Flags: needinfo?(kgilbert)
And since you moved the telemetry stuff to presshell, I'm not too worried about overhead.
(In reply to Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] from comment #11)
> (In reply to Olli Pettay [:smaug] from comment #10)
> > You changed the meaning of the patch. not 1 anymore but 1+2, yet initial
> > description talks about 1.
> > So what are we trying to measure here?
> 
> We want to measure time from input to just before it entering JS engine.
> So before/after dispatch maybe doesn't make too much difference.


How so? DOM Event dispatch is during which we start to execute JS (event listeners)
What you mean with " entering JS engine" ?
Comment on attachment 8839805 [details]
Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RECEIVED_MS)

https://reviewboard.mozilla.org/r/114364/#review118858

::: layout/base/PresShell.cpp:8170
(Diff revision 2)
> +    case eKeyPress:
> +    case eKeyUp:
> +    case eKeyDown:
> +      Telemetry::Accumulate(Telemetry::KEYBOARD_EVENT_RESPONSE_MS, millis);
> +      break;
> +    case eVRDisplayPresentChange:

VRDisplayPresentChange is not latency sensitive.  Input from VR controllers is handled in the gamepad API.  Latency in tracking headset movement could be affected by the VRDisplay.requestAnimationFrame callback latency (IPC or otherwise).  Once content receives this RAF callback, it polls frame data including headset orientation with VRDisplay.getFrameData, which could add more latency due to IPC and underlying VR API calls.  Finally more latency could be added within the call to VRDisplay.submitFrame() call due to IPC, GPU stalls, and underlying VR API calls.
(In reply to :kip (Kearwood Gilbert) from comment #15)
> Comment on attachment 8839805 [details]
> Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RESPONSE_MS)
> 
> https://reviewboard.mozilla.org/r/114364/#review118858
> 
> ::: layout/base/PresShell.cpp:8170
> (Diff revision 2)
> > +    case eKeyPress:
> > +    case eKeyUp:
> > +    case eKeyDown:
> > +      Telemetry::Accumulate(Telemetry::KEYBOARD_EVENT_RESPONSE_MS, millis);
> > +      break;
> > +    case eVRDisplayPresentChange:
> 
> VRDisplayPresentChange is not latency sensitive.  Input from VR controllers
> is handled in the gamepad API.  Latency in tracking headset movement could
> be affected by the VRDisplay.requestAnimationFrame callback latency (IPC or
> otherwise).  Once content receives this RAF callback, it polls frame data
> including headset orientation with VRDisplay.getFrameData, which could add
> more latency due to IPC and underlying VR API calls.  Finally more latency
> could be added within the call to VRDisplay.submitFrame() call due to IPC,
> GPU stalls, and underlying VR API calls.

TL;DR - We aren't worried about latency with VRDisplayPresentChange, but the VR quality can be affected by latency with:

- VRDisplay.requestAnimationFrame() callback
- VRDisplay.getFrameData()
- VRDisplay.submitFrame()

Any telemetry for the Gamepad API would cover our VR controllers.

I hope this helps!
Flags: needinfo?(kgilbert)
Summary: Measure input event to dispatch latency → Measure input event to event dispatcher (handler)
Changed:
1. move the telemetry part to the begining of mozilla::PresShell::HandleEventInternal, as we only care about events that actually been handled, but don't want to include handler's execution time.
2. remove VR related histogram, as I think it should belongs to another bug.
3. set the expire version to 60, max value 500ms, 100 buckets.
(In reply to :kip (Kearwood Gilbert) from comment #16)
> TL;DR - We aren't worried about latency with VRDisplayPresentChange, but the
> VR quality can be affected by latency with:
> 
> - VRDisplay.requestAnimationFrame() callback
> - VRDisplay.getFrameData()
> - VRDisplay.submitFrame()
> 
> Any telemetry for the Gamepad API would cover our VR controllers.
> 
> I hope this helps!

This helps a lots!
Then I believe VR should be handled in another bug, I'll remove the VR part from this patch.
So what is the INPUT_EVENT_RESPONSE_MS we currently have?
(In reply to Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] from comment #19)
> Changed:
> 1. move the telemetry part to the begining of
> mozilla::PresShell::HandleEventInternal, as we only care about events that
> actually been handled, but don't want to include handler's execution time.
You mean we care events we aren't handled yet.
Comment on attachment 8839805 [details]
Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RECEIVED_MS)

https://reviewboard.mozilla.org/r/114364/#review121012

::: layout/base/PresShell.cpp:8081
(Diff revision 3)
>            }
>          }
>          break;
>        }
>  
> +      case eScroll:

eScroll doesn't make sense here. Scroll event is dispatched after scrolling and doesn't even get through this code path.

::: layout/base/PresShell.cpp:8084
(Diff revision 3)
>        }
>  
> +      case eScroll:
> +      case eWheel:
> +        if (aEvent->mFlags.mHandledByAPZ) {
> +          Telemetry::AccumulateTimeDelta(Telemetry::APZ_HANDLED_EVENT_RESPONSE_MS, aEvent->mTimeStamp);

Why we put wheel event to the same bucket as mouse events (assuming we're dealing with APZ).


Have you checked in which all cases mHnadledByAPZ is true?

::: toolkit/components/telemetry/Histograms.json:11140
(Diff revision 3)
>      "kind": "categorical",
>      "labels": ["installAmoAccepted", "installAmoRejected", "installLocalAccepted", "installLocalRejected", "installWebAccepted", "installWebRejected", "sideloadAccepted", "sideloadRejected", "updateAccepted", "updateRejected"],
>      "description": "Results of displaying add-on installation notifications.",
>      "releaseChannelCollection": "opt-out"
> +  },
> +  "MOUSE_EVENT_RESPONSE_MS": {

Could we call these something else than _RESPONSE, since we have INPUT_EVENT_RESPONSE_MS measuring time after event handling.

perhaps MOUSE_EVENT_RECEIVED_MS and similar for others events

::: toolkit/components/telemetry/Histograms.json:11147
(Diff revision 3)
> +    "expires_in_version": "60",
> +    "kind": "exponential",
> +    "high": 50000,
> +    "n_buckets": 100,
> +    "bug_numbers": [1341531],
> +    "description": "Time (ms) for the mouse event to dispatch, but before handler executing."

Either "handler execution" or 
"handlers executing"


Same with other probes too
Attachment #8839805 - Flags: review?(bugs) → review-
Comment on attachment 8839805 [details]
Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RECEIVED_MS)

https://reviewboard.mozilla.org/r/114364/#review121018

I think this is close, but some tweaks so that telemetry data would be more useful. Especially that APZ part needs a change. I would expect different events using APZ get separate probes.
Whiteboard: [qf:p1]
Summary:
* seperate APZ handled events to three probes: touchmove, mousemove, and wheel (according to APZCTreeManager::ReceiveInputEvent)
* seperate mouse events (that are not handled by APZ) to two probes: mousemove and mouseclick, since their density and meaning are different
Comment on attachment 8839805 [details]
Bug 1341531 - Measure input event dispatching latency. (*_EVENT_RECEIVED_MS)

https://reviewboard.mozilla.org/r/114364/#review123078

Hmm, did you actually test you get reasonable values for all the events.
I wonder click and doubleclick, since those are dispatched from child process, not forwarded from parent to child.
See http://searchfox.org/mozilla-central/rev/571c1fd0ba0617f83175ccc06ed6f3eb0a1a8b92/widget/WidgetEventImpl.cpp#318
Same with pointer events

What is the RecordInteractionTime stuff? Are we now recording pretty much the same data using several probes?
Could you figure out if we could get rid of RecordInteractionTime

issues fixed, r+, but please figure out the RecordInteractionTime stuff before landing.

::: layout/base/PresShell.cpp:8070
(Diff revision 4)
>        case ePointerUp:
>          isHandlingUserInput = true;
>          mPresContext->RecordInteractionTime(
>            nsPresContext::InteractionType::eClickInteraction,
>            aEvent->mTimeStamp);
> +      case eMouseDoubleClick:

Don't add mousedoubleclick and click

::: layout/base/PresShell.cpp:8072
(Diff revision 4)
>          mPresContext->RecordInteractionTime(
>            nsPresContext::InteractionType::eClickInteraction,
>            aEvent->mTimeStamp);
> +      case eMouseDoubleClick:
> +      case eMouseClick:
> +        Telemetry::AccumulateTimeDelta(Telemetry::MOUSE_CLICK_EVENT_RECEIVED_MS, aEvent->mTimeStamp);

So this shouldn't cover pointerup/down
Attachment #8839805 - Flags: review?(bugs) → review+
> I wonder click and doubleclick, since those are dispatched from child process, not forwarded from parent to child.

Do we need to file a separate bug to measure those or are they included with mouseup?
measuring click/dblclick vs mousedown/up is like measuring apples and oranges in e10s case, so it is unclear to me what we want to measure there.
click is something child process itself dispatches once it knows that the target of mousedown and mouseup are the same.
Flags: needinfo?(hkirschner)
Removed click and dblclick, as they are kind of redundant to mouse up/down.
Also moved telemetry code so that it does not record pointer events.

(In reply to Olli Pettay [:smaug] from comment #27)
> Hmm, did you actually test you get reasonable values for all the events.
> I wonder click and doubleclick, since those are dispatched from child
> process, not forwarded from parent to child.
> See
> http://searchfox.org/mozilla-central/rev/
> 571c1fd0ba0617f83175ccc06ed6f3eb0a1a8b92/widget/WidgetEventImpl.cpp#318
> Same with pointer events

I did get some reasonable values for clicks and dblclicks, but I didn't notice that they are dispatched from different path.
It seems click events can be covered by mouse up/down events, so I think we can just record up/down ones.

> What is the RecordInteractionTime stuff? Are we now recording pretty much
> the same data using several probes?
> Could you figure out if we could get rid of RecordInteractionTime
> 
> issues fixed, r+, but please figure out the RecordInteractionTime stuff
> before landing.

bug 1307675 only measures the first interaction for top presshell, so I think it has a different meaning to this bug.


:digitarald, please correct me if I misread bug 1307675 or anything else, thanks.
bug 1307675 is an engagement probe (expected to become a proxy for improved performance) and unrelated to this bug.
Flags: needinfo?(hkirschner)
Pushed by wpan@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/140374af2570
Measure input event dispatching latency. (*_EVENT_RECEIVED_MS) r=smaug
Pushed by wpan@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e846c455670e
Measure input event dispatching latency. (*_EVENT_RECEIVED_MS) r=smaug
https://hg.mozilla.org/mozilla-central/rev/e846c455670e
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Flags: needinfo?(wpan)
Performance Impact: --- → P1
Whiteboard: [qf:p1]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: