How to measure performance impact of l10n on UI

[zbran...@mozilla.com]

As part of the work we're doing to replace old l10n API (DTD for HTML/XUL and StringBundle for JS) with new API, we're trying to measure the performance cost of DTD, StringBundle and its replacements.

The challenge we encountered is that there doesn't seem to be a way to measure something that I'd intuitively and naively would call "first paint".

By first paint, I mean the moment when the engine paints the UI for the first time.

I'd expect there to be some way to get it via Performance API, or some Mozilla-specific event, but everything I see does not seem to do this.

MozAfterPaint reports every paint, and it fires before DOMContentLoaded, between DOMContentLoaded and window.onload, and after. It's impossible to say, which one of them marks the event I'm after*.

bz created a POC of an API for us that pauses frame creation (**) and that's awesome as it ensures that we will not cause FOUCs, but now we need to measure when the "first paint" happens with our code vs. with DTD and I don't know how to get the required event.
There seems to be `widget-first-paint` event (***) but if I understand it correctly it'll only mark when chrome window is painted for the first time, now a document.

Can someone help us? If we have to add it, where?

Thanks,
zb.


*) And it's not the first. I can reliably modify visible DOM after first MozAfterPaint and I will not have FOUC.
**) https://bugzilla.mozilla.org/show_bug.cgi?id=1280260
***) https://dxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.cpp#9157

[Mike Conley]

Is the firstPaint timestamp in nsIAppStartup's getStartupInfo[1] not
sufficient? It's apparently recording the time that firstPaint occurred.
I think you're already aware of this, but I'm in the process of
modifying ts_paint to record the delta between the firstPaint timestamp
and the process start timestamp in bug 1287938.

If it's not sufficient, I'd like to understand why.

As for MozAfterPaint firing all over the place - you might find this
useful:
https://groups.google.com/forum/#!searchin/mozilla.dev.platform/MozAfterPaint/mozilla.dev.platform/pCLwWdYc_GY/j9A-vWm3AgAJ

See the second example I wrote in
https://developer.mozilla.org/en-US/docs/Web/Events/MozAfterPaint#Example

Is any of that helpful?

-Mike

[1]:
https://developer.mozilla.org/en-US/docs/Mozilla/Tech/XPCOM/Reference/Interface/nsIAppStartup#getStartupInfo()

> _______________________________________________
> dev-platform mailing list
> dev-pl...@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-platform
>

[zbran...@mozilla.com]

On Friday, July 22, 2016 at 6:53:45 AM UTC-7, Mike Conley wrote:
> Is the firstPaint timestamp in nsIAppStartup's getStartupInfo[1] not
> sufficient? It's apparently recording the time that firstPaint occurred.
> I think you're already aware of this, but I'm in the process of
> modifying ts_paint to record the delta between the firstPaint timestamp
> and the process start timestamp in bug 1287938.
>
> If it's not sufficient, I'd like to understand why.

If I understand correctly, firstPaint from getStartupInfo will tell me when the first paint of the window occured.

But since I'm operating in a document (I'm working on about:support document), I'm looking for the firstPaint of the document, not the whole browser window.

So, what I'm looking for is something like "performance.timing.firstPaint" for each document.

Am I missing something?

>
> As for MozAfterPaint firing all over the place - you might find this
> useful:
> https://groups.google.com/forum/#!searchin/mozilla.dev.platform/MozAfterPaint/mozilla.dev.platform/pCLwWdYc_GY/j9A-vWm3AgAJ
>
> See the second example I wrote in
> https://developer.mozilla.org/en-US/docs/Web/Events/MozAfterPaint#Example
>
> Is any of that helpful?

That seems helpful!

If I understand correctly, I can take the transaction Id at DOMContentLoaded (or DOMInteractive?) and assume that the first paint with the transaction ID higher than that is the paint that flashed the document.

Then, if my code modifies DOM after that paint, I will reflow/flash.

Is that a correct assumption?

zb.

[zbran...@mozilla.com]

On Friday, July 22, 2016 at 6:53:45 AM UTC-7, Mike Conley wrote:

> As for MozAfterPaint firing all over the place - you might find this
> useful:
> https://groups.google.com/forum/#!searchin/mozilla.dev.platform/MozAfterPaint/mozilla.dev.platform/pCLwWdYc_GY/j9A-vWm3AgAJ
>
> See the second example I wrote in
> https://developer.mozilla.org/en-US/docs/Web/Events/MozAfterPaint#Example

Follow-up question.

I started using the transaction ID in my tests and am getting this weird result:

1) 24.00: DOM Loading
1) 65.50: Paint with transaction ID 38
2) 73.00: DOM Interactive (winUtils.lastTransactionId == 39)
3) 74.00: DOMContentLoadedEventStart
4) 94.00: DOMComplete
5) 162.00: loadEventEnd
6) 196.97: Paint with transaction ID 39
7) 271.94: Paint with transaction ID 40

And this order happens relatively often. What's surprising is that the winUtils.lastTransactionId read done at readyState=='interactive' is 39.

From what you said in the linked post, the transaction ID 39 is the one that has been sent to the compositor *before* document.readyState changed to 'interactive'.

That means that this transaction did not contain DOM from HTML and will not result in a layout yet, so I'm hunting for the *next* transaction after it, which has ID 40.

But the next paint happens at 196.97 and it has the transaction ID 39, and then finally the paint with transacation ID 40 happens at 271.94

Should I take the one with ID 39 or 40 as "the first paint of the document"?

zb.

[zbran...@mozilla.com]

One hour of reading DXR later and I *think* I want to get the timestamp of this: https://dxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.cpp#3809

or something around it :)


as this will tell me a couple of things:

1) Things injected into DOM after this timestamp may/will cause reflow.
2) Things injected into DOM before this timestamp are unlikely to cause FOUC
3) If I change any code in ContentSink, HTMLParser, or if I'll inject a MutationObserver that will be catching nodes as the Parser feeds the DOM and modifying them, I should see this timestamp being affected and in result performance being impacted.

Does it sound like what I'm looking for?

zb.

[Mike Conley]

> If I understand correctly, firstPaint from getStartupInfo will tell me when the first paint of the window occured.
>
> But since I'm operating in a document (I'm working on about:support document), I'm looking for the firstPaint of the document, not the whole browser window.
>
> So, what I'm looking for is something like "performance.timing.firstPaint" for each document.
>
> Am I missing something?

Ah, in that case, yes, firstPaint is definitely not what you want.
You're right - it's recording the time that the first top-level window
is painted.

Possibly? It certainly looks like that'll get you the time before we
start a paint.

Can you point me to the test you've written so far? That might help me
to better understand what you're attempting to measure and how you're
going about it.

-Mike