1456194 - Investigate 60s+ DEVTOOLS_*_TOOLBOX_OPEN_DELAY_MS for broken measurement

Status: RESOLVED FIXED

(DevTools :: General, enhancement)

Description

[:Harald Kirschner :digitarald]

Console, Debugger, Settings and all core panels both have a 95th percentile of 60s+

Console: https://mzl.la/2HL84CO
Debugger: https://mzl.la/2qSF95X

We need to investigate if the probe might measure some edge cases incorrectly.

Comment 1

[:Harald Kirschner :digitarald]

Alex for

Comment 2

[Alexandre Poirot [:ochameau]]

These probes always looked like that, I assumed it was due to a long tail of slow load.
If you look at the distribution:
  https://mzl.la/2vIXHdN
You can see that there is one.
But looking at it more closely, it would have meant that there is a long tail approximatively over 500seconds for the console which sounds unlikely.

So I looked into the code and yes, I've been tricked by performance.now behavior and by the time origin, specific for each window:
https://developer.mozilla.org/en-US/docs/Web/API/DOMHighResTimeStamp#The_time_origin
The big spike over 60s is related to users opening more than one top level window, the toolbox not opened in the first window were having wrong measurements.

Comment 3

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1456194 - Fix toolbox startup telemetry measurement when using more than one top level window.

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

Comment 4

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8970838 [details]
Bug 1456194 - Fix toolbox startup telemetry measurement when using more than one top level window.

https://reviewboard.mozilla.org/r/239624/#review245460

Yikes, good catch!  This seems like a good incremental improvement.

Would it be better to use something like `TelemetryStopwatch`[1] instead that is designed for this purpose?  From that module, it appears there is a `Cu.now()` API[2], which might be a simpler approach if we still want to track the time ourselves while avoiding time origin issues.

[1]: https://searchfox.org/mozilla-central/source/toolkit/components/telemetry/TelemetryStopwatch.jsm
[2]: https://searchfox.org/mozilla-central/rev/36dec78aecc40539ecc8d78e91612e38810f963c/js/xpconnect/idl/xpccomponents.idl#668

Comment 6

[Alexandre Poirot [:ochameau]]

(In reply to J. Ryan Stinnett [:jryans] (use ni?) (on PTO Apr 30 - May 1) from comment #4)
> Would it be better to use something like `TelemetryStopwatch`[1] instead
> that is designed for this purpose?

I looked into TelemetryStopwatch but it requires knowing the telemetry key and toolId on start,
which isn't the case here.

>  From that module, it appears there is a `Cu.now()` API[2], which might be a simpler approach
> if we still want to track the time ourselves while avoiding time origin issues.

I switched to Cu.now everywhere. May be the telemetry RFC is going to help refactor this code to the new devtools telemetry api...

Comment 7

[Alexandre Poirot [:ochameau]]

Comment on attachment 8970838 [details]
Bug 1456194 - Fix toolbox startup telemetry measurement when using more than one top level window.

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

Comment 8

[Alexandre Poirot [:ochameau]]

Comment on attachment 8970838 [details]
Bug 1456194 - Fix toolbox startup telemetry measurement when using more than one top level window.

Could you take a look at the new patch?

Comment 9

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8970838 [details]
Bug 1456194 - Fix toolbox startup telemetry measurement when using more than one top level window.

https://reviewboard.mozilla.org/r/239624/#review247056

This really makes me wish for some kind of types or tagging in the time, so we could have some way to verify that the same time base was used, rather than just hoping...

Anyway, looks good! :)

Comment 10

[Mozilla Autoland]

hg error in cmd: hg push -r tip ssh://hg.mozilla.org/integration/autoland: pushing to ssh://hg.mozilla.org/integration/autoland
remote: *** failed to import extension vcsreplicator from /var/hg/version-control-tools/pylib/vcsreplicator/vcsreplicator/hgext.py: [Errno 2] No such file or directory: '/var/hg/version-control-tools/pylib/vcsreplicator/vcsreplicator/../bootstrap.py'
searching for changes
remote: adding changesets
remote: adding manifests
remote: adding file changes
remote: added 1 changesets with 6 changes to 6 files
remote: transaction abort!
remote: rollback completed
remote: pretxnchangegroup.d_webidl hook is invalid: import of "mozhghooks.prevent_webidl_changes" failed
remote: (run with --traceback for stack trace)
abort: push failed on remote

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a46dfe2330ff
Fix toolbox startup telemetry measurement when using more than one top level window. r=jryans

Comment 12

[Andrei Ciure[:aciure]]

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