1411887 - Add telemetry to track webconsole update time on page reload

Status: RESOLVED FIXED

(DevTools :: Console, enhancement)

Description

[Alexandre Poirot [:ochameau]]

Bug 1405585 introduced a generic way to track how much time each panel takes to update after a page reload. This bug added support for the inspector.

Now all other panels should emit a "reloaded" event on its Panel object whenever it consider it is fully updated after a page reload.
This is not obvious and will require specific decision for each tool.

Here for the webconsole, we should at least wait for all messages logged before "load" event to be fully rendered.

Comment 1

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1411887 - Add telemetry to track console refresh time when reload a page.

Review commit: https://reviewboard.mozilla.org/r/193270/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/193270/

Comment 2

[Alexandre Poirot [:ochameau]]

Nicolas, I moved the console telemetry in its own bug to proceed with inspector one.
See my responses to your review comments here.

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #23)
> Comment on attachment 8921893 [details]
> Bug 1405585 - Add telemetry to track console refresh time when reload a page.
> 
> https://reviewboard.mozilla.org/r/192932/#review198468
> 
> :::
> devtools/client/webconsole/new-console-output/new-console-output-wrapper.js:
> 306
> (Diff revision 1)
> > +      if (this.throttleCallback) {
> > +        this.throttleCallback();
> > +        delete this.throttleCallback;
> > +      }
> 
> since in the end `this.throttleCallback` existence is tied to
> `newConsoleOutput.throttledDispatchTimeout` , and given we only want to emit
> the "reloaded" event,  couldn't we check directly for
> `newConsoleOutput.throttledDispatchTimeout` instead of adding and removing a
> function ?
> 
> 
> It might be a really small thing, but `delete` is known to be slow, so if we
> could avoid doing this, it would be nice

Yes, we should expose an explicit API if we define this probe that way.
Something like newConsoleOutput.isThrottledDispatchPending().

> 
> ::: devtools/client/webconsole/new-webconsole.js:333
> (Diff revision 1)
> > +
> > +    if (event == "navigate") {
> > +      let timeout = this.newConsoleOutput.throttledDispatchTimeout;
> > +      if (timeout) {
> > +        this.newConsoleOutput.throttleCallback = () => {
> > +          let delay = this.window.performance.now() - this._navigationStart;
> 
> `delay` is never used
> 
> ::: W:335
> (Diff revision 1)
> > +          // TODO - REMOVE DEBUG CODE
> > +          let window = this.window;
> > +          let canvas = window.document.createElementNS("http://www.w3.org/1999/xhtml", "html:canvas");
> > +          let context = canvas.getContext("2d");
> > +          canvas.width = window.innerWidth;
> > +          canvas.height = window.innerHeight;
> > +          context.drawWindow(window, 0, 0, canvas.width, canvas.height, "rgb(255, 255, 255)");
> > +          dump(">> "+canvas.toDataURL()+"\n");
> > +          // TODO - REMOVE DEBUG CODE
> 
> looks like it should be removed. 
> Also, I'm curious, what are you using this for ?

This code does a synchronous screenshot so that you can assert how the console looks like
and so be sure the measurement stops at a point where everything is rendered.

I kept it there for you to may be play with that and find some alternative to this patch
or other meaningful probe to measure.

> ::: devtools/client/webconsole/panel.js:84
> (Diff revision 1)
> > +        // Pipe 'reloaded' event from NewWebConsoleFrame to WebConsolePanel.
> > +        // These events are listened by the Toolbox.
> > +        this.hud.ui.on("reloaded", () => {
> > +          this.emit("reloaded");
> > +        });
> 
> can't we directly emit from the panel object (if we can have the reference
> in the console code), or listen to `hud.ui` in the toolbox ?

Today, the panel object lives on its own. It is not exposed to anyone.
So we would have to pass the panel all over the abstractions from panel down to NewWebConsoleFrame.

But before going into the detail of this patch, could you confirm this kind of measurement make sense?
Do we correctly capture the time it takes to render all the messages logged before "load" event?
(does it work with "persist logs" feature? does it also work for network logs (if filter at set accordingly)?)
Also, is "the time it takes to render all the messages logged before "load" event" meaningful to you as the page reload telemetry?

Comment 3

[Nicolas Chevobbe [:nchevobbe]]

It does look like it's working in every case
Basic, reloading with logged messages, with network requests, with "Persist" checked on or off.
The canvas debugging trick here is really handy :)

Do you want me to review the patch again and we'll address my comments in a follow up ?

Comment 4

[Alexandre Poirot [:ochameau]]

Comment on attachment 8922242 [details]
Bug 1411887 - Add telemetry to track console refresh time when reload a page.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/193270/diff/1-2/

Comment 5

[Alexandre Poirot [:ochameau]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #3)
> It does look like it's working in every case
> Basic, reloading with logged messages, with network requests, with "Persist"
> checked on or off.
> The canvas debugging trick here is really handy :)
> 
> Do you want me to review the patch again and we'll address my comments in a
> follow up ?

Cool! Thanks for testing. And the observed delays made sense to you?

Here is a more reasonable patch, without all the debug code.

Comment 6

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8922242 [details]
Bug 1411887 - Add telemetry to track console refresh time when reload a page.

https://reviewboard.mozilla.org/r/193270/#review199496

::: devtools/client/webconsole/new-webconsole.js:311
(Diff revision 2)
>     * @param object packet
>     *        Notification packet received from the server.
>     */
> -  handleTabNavigated: function (event, packet) {
> +  handleTabNavigated: async function (event, packet) {
>      if (event == "will-navigate") {
> +      this._navigationStart = this.window.performance.now();

when do we use this ? I can't find where we make sense of this variable. Should it be passed to the "reloaded" event ?

Comment 7

[Alexandre Poirot [:ochameau]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #6)
> Comment on attachment 8922242 [details]
> Bug 1411887 - Add telemetry to track console refresh time when reload a page.
> 
> https://reviewboard.mozilla.org/r/193270/#review199496
> 
> ::: devtools/client/webconsole/new-webconsole.js:311
> (Diff revision 2)
> >     * @param object packet
> >     *        Notification packet received from the server.
> >     */
> > -  handleTabNavigated: function (event, packet) {
> > +  handleTabNavigated: async function (event, packet) {
> >      if (event == "will-navigate") {
> > +      this._navigationStart = this.window.performance.now();
> 
> when do we use this ? I can't find where we make sense of this variable.
> Should it be passed to the "reloaded" event ?

Was just a leftover, toolbox's code is having a similar listener on will-navigate event.

Comment 8

[Alexandre Poirot [:ochameau]]

Comment on attachment 8922242 [details]
Bug 1411887 - Add telemetry to track console refresh time when reload a page.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/193270/diff/2-3/

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b2cdaf947908
Add telemetry to track console refresh time when reload a page. r=nchevobbe

Comment 10

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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