1405584 - Add telemetry to track toolbox/tool opening time

Status: RESOLVED FIXED

(DevTools :: General, enhancement, P2)

Description

[Alexandre Poirot [:ochameau]]

We should track the time it takes to open the toolbox/tool.

When users hit any keyshort to open a tool or use "inspect element" context menu, we should record the time it takes between this event, and the tool is fully loaded.

In term of implementation, it won't be necessarely easy. Especially to correctly track the first toolbox opening, which starts from devtools-startup.js.
http://searchfox.org/mozilla-central/rev/e62604a97286f49993eb29c493672c17c7398da9/devtools/shim/devtools-startup.js#361-365
  onKey(window, key) {
    let require = this.initDevTools("KeyShortcut");
    let { gDevToolsBrowser } = require("devtools/client/framework/devtools-browser");
    gDevToolsBrowser.onKeyShortcut(window, key);
  },

Here we have to track the call to initDevTools, which introduce significant computations.

It may be relevant to have distinct probes between first devtools interaction, and the subsequent ones. The first interaction will load many devtools core modules, whereas all the others won't.

Otherwise, as for DAMP, it is challending to know when the tool is really done loading. But as of today, the best is to listen for gDevTools.showToolbox promise completion. This is what DAMP currently tracks. I already know it is flaky for Debugger and I still suspect it from being imperfect for other tools.

May be we can start tracking that and improve this probe later? (that would increase its value)

Comment 1

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1405584 - Add telemetry to track toolbox open time. datareview=francois

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

Comment 2

[Alexandre Poirot [:ochameau]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

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

Comment 3

[Alexandre Poirot [:ochameau]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

I don't see the new telemetry on artifact build, but I imagine that's because telemetry still doesn't support artifacts.
But when I build Firefox locally, about:telemetry doesn't have the "Keyed Histogram" panel anymore, so I can't confirm telemetry works.

Anyway, let's first confirm how to retrieve toolbox open time.
Julian, I have to pass around "startTime" over a bunch of method in order to correctly compute the full open time in devtools.js:showToolbox.
It is especially important in devtools-startup.js:onKey, where we want to capture initDevTools call.

Does that look ok to you? If yes, I'll remove debug code and add doc comments about startTime.

Comment 4

[Julian Descottes [:jdescottes]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

https://reviewboard.mozilla.org/r/188316/#review193920

::: devtools/client/framework/devtools.js:483
(Diff revision 2)
> +  logToolboxOpenTime(toolId, startTime) {
> +    let { performance } = Services.appShell.hiddenDOMWindow;
> +    let delay = performance.now() - startTime;
> +    dump("Showing "+toolId+" in "+delay+"ms first:"+this._firstShowToolbox+"\n");
> +    let telemetryKey = this._firstShowToolbox ? "DEVTOOLS_COLD_TOOLBOX_OPEN_DELAY_MS" : "DEVTOOLS_WARM_TOOLBOX_OPEN_DELAY_MS";
> +    this._firstShowToolbox = false;

The _firstShowToolbox flag should be flipped in showToolbox, after the if (startTime) {} block.

If showToolbox is called without a startTime, the next call should not be considered as a cold start.

::: devtools/shim/devtools-startup.js:362
(Diff revision 2)
>      let mainKeyset = doc.getElementById("mainKeyset");
>      mainKeyset.parentNode.insertBefore(keyset, mainKeyset);
>    },
>  
>    onKey(window, key) {
> +    let startTime = window.performance.now();

Not an issue but something to be aware of. 

Users using key shortcuts to open the toolbox will report slower opening times because this time will include the initDevTools() call. 
Users going through the menu already initialized devtools when opening the submenu.

Both still match the time between the user action and the toolbox opening, but it means we are aggregating timings that are technically different. Consequently, improvements and regressions on the initDevTools performances will not be completely visible with this probe. But that's probably not its role.

Comment 5

[Julian Descottes [:jdescottes]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

I think the startTime approach is fine. The only alternative I can think about is to open an API on gDevTools to set the "startTime" that we could call in the user entry points and that we would read at the end of showToolbox. But that feels more complex than what you currently have.

We should probably have a follow up to update the signature of showToolbox to have all the optional paramters as an object argument (and have showToolbox(target, {startTime}) rather than showToolbox(target, null, null, null, startTime))

Comment 6

[Alexandre Poirot [:ochameau]]

(In reply to Julian Descottes [:jdescottes] from comment #4)
> If showToolbox is called without a startTime, the next call should not be
> considered as a cold start.

Oh. Thanks for catching that!

Comment 7

[Alexandre Poirot [:ochameau]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

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

Comment 8

[Alexandre Poirot [:ochameau]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

Harald, Does that look good to you? See second part of comment 4 from Julian.

Comment 9

[Julian Descottes [:jdescottes]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

https://reviewboard.mozilla.org/r/188316/#review194148

Looks good but I want to do a final review with the inspectNode codepath covered.

::: devtools/client/framework/devtools.js:426
(Diff revision 3)
>      }
>    },
>  
>    /**
> +   * Boolean, true, if we never opened a toolbox.
> +   * Used to implement to telemetry tracking toolbox opening.

s/Used to implement to telemetry/Used to implement the telemetry

::: devtools/client/framework/devtools.js:488
(Diff revision 3)
>      return toolbox;
>    }),
>  
> +  /**
> +   * Log telemetry related to toolbox opening.
> +   * Two distinct probes are logged. One for cold startup, when we opening the very first

s/when we opening/when we open

::: devtools/client/framework/devtools.js:493
(Diff revision 3)
> +   * Two distinct probes are logged. One for cold startup, when we opening the very first
> +   * toolbox. This one includes devtools framework loading. And a second one for all
> +   * subsequent toolbox opening, which should all be faster.
> +   * These two probes are indexed by Tool ID.
> +   *
> +   * @param {Number} startTime

even if obvious, misses the jsdoc for the toolid parameter.

::: devtools/client/framework/devtools.js:618
(Diff revision 3)
>     *         markup view.
>     */
>    async inspectNode(tab, nodeSelectors) {
>      let target = TargetFactory.forTab(tab);
>  
>      let toolbox = await gDevTools.showToolbox(target, "inspector");

We should probably cover the inspectNode code path? (our second most used entry point)

Comment 10

[Alexandre Poirot [:ochameau]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

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

Comment 11

[Alexandre Poirot [:ochameau]]

(In reply to Julian Descottes [:jdescottes] from comment #9)
> We should probably cover the inspectNode code path? (our second most used
> entry point)

Thanks for catching that as well!
I thought it was the first entry point (and was able to forgot it...).
Is inspector key shortcut the first one?

Comment 12

[Julian Descottes [:jdescottes]]

(In reply to Alexandre Poirot [:ochameau] from comment #11)
> (In reply to Julian Descottes [:jdescottes] from comment #9)
> > We should probably cover the inspectNode code path? (our second most used
> > entry point)
> 
> Thanks for catching that as well!
> I thought it was the first entry point (and was able to forgot it...).
> Is inspector key shortcut the first one?

Yes, key-shortcut is in the lead: https://mzl.la/2i79LyY

The telemetry results on Release are interesting: system menu is around 20% whereas it is below 10% on Nightly/Beta.

Comment 13

[Julian Descottes [:jdescottes]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

https://reviewboard.mozilla.org/r/188316/#review194168

Looks good to me code-wise. It will be very nice to have some real user timings about toolbox opening. Thanks for working on that!

Comment 14

[François Marier [:francois]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

https://reviewboard.mozilla.org/r/188316/#review194192

This is Category 1 data. datareview+.

Comment 15

[:Harald Kirschner :digitarald]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

If we validated with a profiling or manually that the time reported in telemetry capturing a meaningful loaded state, then I am fine with this.

We should have a follow up metric in the same fashion measure tool switching time, which is very similar experience to opening the toolbox. Users might just use their standard shortcut that gets them into Inspector and then switch to Debugger as their actual target.

Comment 16

[Alexandre Poirot [:ochameau]]

Attachment: Inspector state

Here is screenshot at the precise time we resolve the telemetry.
I looked at the profiler against the profiler and the timing looks correct.
There is asynchronous things happening *after* we resolve the telemetry timing,
but that doesn't update the UI (it is mostly end of toolbox initialization with performance actor setup)

Comment 17

[Alexandre Poirot [:ochameau]]

I don't know how to make bugzilla handle data: uri correctly.
So please copy paste it...

Comment 18

[Alexandre Poirot [:ochameau]]

Attachment: Debugger state

It looks good also for the debugger.

Comment 19

[Alexandre Poirot [:ochameau]]

Attachment: Console state

It is slightly less good for the console.
But we should followup on that, it means DAMP timing is also wrong.
We may just miss one event loop spin as the content is here but we miss some update in filter bar and well as scroll to bottom call.

Comment 20

[Alexandre Poirot [:ochameau]]

Attachment: Netmonitor state

It is also imperfect for Netmonitor.
But it may be hard to make it so that we wait for all requests to be loaded.
It also mean DAMP is as incorrect as the telemetry probe.

Comment 21

[Mozilla Autoland]

We're sorry, Autoland could not rebase your commits for you automatically. Please manually rebase your commits and try again.

hg error in cmd: hg rebase -s 5e5e10fbb0c3 -d 906745acb1ad: rebasing 426467:5e5e10fbb0c3 "Bug 1405584 - Add telemetry to track toolbox open time. r=francois,jdescottes datareview=francois" (tip)
merging devtools/shim/DevToolsShim.jsm
merging devtools/shim/devtools-startup.js
merging toolkit/components/telemetry/Histograms.json
warning: conflicts while merging devtools/shim/DevToolsShim.jsm! (edit, then use 'hg resolve --mark')
warning: conflicts while merging devtools/shim/devtools-startup.js! (edit, then use 'hg resolve --mark')
unresolved conflicts (see hg resolve, then hg rebase --continue)

Comment 22

[Alexandre Poirot [:ochameau]]

Comment on attachment 8917302 [details]
Bug 1405584 - Add telemetry to track toolbox open time.  datareview=francois

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/188316/diff/4-5/

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d6394715adb7
Add telemetry to track toolbox open time. r=francois,jdescottes datareview=francois

Comment 24

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

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

Comment 25

[Alexandre Poirot [:ochameau]]

Here is very approximative medians. (Just by looking at histograms and picking what looks like average result)

COLD:
https://mzl.la/2wYNTsw
  inspector: 1300ms
  console: 800ms
  netmonitor: 800ms
  debugger: 1400ms
WARM:
https://mzl.la/2wYZ4kG
  inspector: 900ms
  console: 700ms
  netmonitor: 600ms
  debugger: 1000ms

It looks like there is for most probes a long tail for opening time >60s!!
But I'm not sure it is worth expanding the probe higher limit (which is 60s).

Harald, do you know how to turn that into trend graphs?

Comment 26

[Alexandre Poirot [:ochameau]]

(In reply to Alexandre Poirot [:ochameau] from comment #25)
> Harald, do you know how to turn that into trend graphs?


Nevermind, I found out. This is yet another telemetry tool:

https://mzl.la/2gPyvZb
This just started, so very short history so far.

Also, telemetry data is polluted by custom panel, containing unique ids.
We should either ignore them or somehow normalize them.