1264798 - Include the composite end time in the MozAfterPaint event

Status: RESOLVED FIXED

(Core :: Layout, defect)

Description

[Mike Conley (:mconley) (:⚙️)]

We have a number of Talos tests that use the MozAfterPaint event in order to determine when something has been presented to the user. It's common practice to handle the MozAfterPaint and then take a delta between the thing that caused a paint and the current time.

One problem with this is that it doesn't account for the things that may have occurred between the time where the MozAfterPaint was enqueued for creation and dispatch in nsPresContext::NotifyDidPaintForSubtree, and the time where the event was actually handled by the test. Any number of things could have occurred in between those times, and it taints the information that is important: at what point was something presented to the user so that they can see it?

What I suggest is that we take the timestamp that nsPresContext::NotifyDidPaintForSubtree knows about, and make it available on the MozAfterPaint event. That means that handlers for that event can get an accurate read on when something was shown to the user, even if it took a while for the MozAfterPaint event to be consumed.

Comment 1

[Mike Conley (:mconley) (:⚙️)]

tnikkel has graciously offered to do this!

Comment 2

[Timothy Nikkel (:tnikkel)]

Attachment: patch

When we call EnsureEventualDidPaintEvent in NotifyDidPaintForSubtree I _think_ we should be ignoring the TimeStamp value there and just using Now() when we actually fire the event. Is that correct?

Comment 3

[Matt Woodrow (:mattwoodrow)]

Comment on attachment 8827678 [details] [diff] [review]
patch

Review of attachment 8827678 [details] [diff] [review]:
-----------------------------------------------------------------

Yeah, I think that's the right thing to do.

I'm not even sure if we really need the eventual did paint timer, it seems like a hack to fix the cases where we forget to fire DidPaint properly.

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8827678 [details] [diff] [review]
patch

> NotifyPaintEvent::Serialize(IPC::Message* aMsg,
>                             bool aSerializeInterfaceType)
> {
>+  //xxx serialize the timestamp?
I don't think there is need. AFAIK, we don't use DOM event serialization.

>+++ b/dom/interfaces/events/nsIDOMNotifyPaintEvent.idl
>@@ -32,10 +32,12 @@ interface nsIDOMNotifyPaintEvent : nsISu
>    * caused by the current document is reported; in particular, painting in subdocuments
>    * is not reported.
>    */
>   readonly attribute nsIDOMClientRect boundingClientRect;
> 
>   readonly attribute nsISupports /* PaintRequestList */ paintRequests;
> 
>   readonly attribute unsigned long long transactionId;
>+
>+  readonly attribute DOMTimeStamp paintTimeStamp;
no need to update .idl files. C++ should just use the class, and .js uses .webidl.
.idl for DOM stuff are slowly going away.

This means also that
+NS_IMETHODIMP
+NotifyPaintEvent::GetPaintTimeStamp(
isn't needed.
>@@ -2198,24 +2201,34 @@ nsPresContext::FireDOMPaintEvent(nsInval
>     // something happened in a subdocument. Tell only the chrome event handler.
>     // (Events sent to the window get propagated to the chrome event handler
>     // automatically.)
>     dispatchTarget = do_QueryInterface(ourWindow->GetParentTarget());
>     if (!dispatchTarget) {
>       return;
>     }
>   }
>+
>+  if (aTimeStamp.IsNull()) {
>+    aTimeStamp = mozilla::TimeStamp::Now();
>+  }
>+  // Convert TimeStamp to js time
>+  const mozilla::TimeStamp tsNow = mozilla::TimeStamp::Now();
>+  int64_t jsNow = JS_Now()/PR_USEC_PER_MSEC;
>+  DOMTimeStamp timeStamp = (aTimeStamp - tsNow).ToMilliseconds() + jsNow;
This looks weird.
What kind of timestamp is this supposed to be.
I would expect something closer to
https://bugzilla.mozilla.org/show_bug.cgi?id=1026804

Note, all the events will have soon performance.now() based timestamp
windows->GetPerformance()->GetDOMTiming()->TimeStampToDOMHighRes(mEvent->mTimeStamp);
Perhaps timestamp of MozAfterPaint could be the composite time?
But adding paint timestamp is ok to me too, but just make it be relative to performance.now()

Comment 5

[Timothy Nikkel (:tnikkel)]

Attachment: patch v2

Updated based on review comments.

I'll get smaug to review again, but he is not currently accepting requests.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/f0f9f8d08df2
Include the composite end time in the MozAfterPaint event. r=smaug r=mattwoodrow

Comment 7

[Timothy Nikkel (:tnikkel)]

Note for using this time in talos tests: the time stamp is relative to the page load time, not a single fixed point in time like "new Date()". So in order to compare the time in the parent process you'd need to pass the page load time stamp or make the time stamp relative to some fixed point in time. (I know this because I first tried the highres timestamp approach (and relative to page load time) and then used the low res time stamp (and relative to a fixed point in time) so I could test my patch).

Comment 8

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/f0f9f8d08df2

Comment 9

[Boris Zbarsky [:bzbarsky]]

Does the talos use case need this exposed to non-chrome callers?

Note that clientRects, boundingClientRect, and paintRequests are not thus exposed.  Would it be a problem if I marked paintTimeStamp as [ChromeOnly]?

Comment 10

[Timothy Nikkel (:tnikkel)]

(In reply to Boris Zbarsky [:bz] (still a bit busy) from comment #9)
> Does the talos use case need this exposed to non-chrome callers?

Good question. mconley knows more about how tps (and other talos tests) are implemented. Forwarding to him.

> Note that clientRects, boundingClientRect, and paintRequests are not thus
> exposed.  Would it be a problem if I marked paintTimeStamp as [ChromeOnly]?

Hmm, how does that work? They seem to all have the same annotations in the webidl file.

Comment 11

[Boris Zbarsky [:bzbarsky]]

> They seem to all have the same annotations in the webidl file.

Yes, but the actual implementations of clientRects, boundingClientRect, and paintRequests call IsCallerChrome() and return useless data (empty list, zero-sized rect, empty list) if not.  I'm aiming to make them actually be annotated as [ChromeOnly] in bug 1334957, fwiw.

Comment 12

[Mike Conley (:mconley) (:⚙️)]

(In reply to Timothy Nikkel (:tnikkel) from comment #10)
> (In reply to Boris Zbarsky [:bz] (still a bit busy) from comment #9)
> > Does the talos use case need this exposed to non-chrome callers?
> 

Yeah, I think so:

http://searchfox.org/mozilla-central/rev/d20e4431d0cf40311afa797868bc5c58c54790a2/testing/talos/talos/config.py#92

There are a number of talos tests that add MozAfterPaint event handlers in content, and ideally, those tests should be able to get at paintTimeStamp (otherwise, I'm afraid this patch will not be useful for a few of the talos tests that measure time to paint content, like tabswitch, tabpaint and tpaint, at least).