[e10s] TelemetryStopwatch: key "FX_PAGE_LOAD_MS" was already initialized

RESOLVED WORKSFORME

Status

()

defect
RESOLVED WORKSFORME
4 years ago
3 years ago

People

(Reporter: cpeterson, Unassigned)

Tracking

unspecified
x86
macOS
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(e10s+, firefox47 verified)

Details

(URL)

(Reporter)

Description

4 years ago
I see this error in the browser console when logging into the Yammer using Okta SSO, but only when e10s is enabled:

https://www.yammer.com/mozilla.com

TelemetryStopwatch: key "FX_PAGE_LOAD_MS" was already initialized
I see the following similar error in Fennec:

E GeckoConsole(28429)         [JavaScript Error: "TelemetryStopwatch: key "READER_MODE_SERIALIZE_DOM_MS" was already initialized" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 52}]
This is not an e10s bug, I see it in single-process desktop Developer Edition 41: "TelemetryStopwatch: key "FX_PAGE_LOAD_MS" was already initialized"

Nick: I think you're seeing a different error. This isn't a bug in TelemetryStopwatch, it's a bug in the code that uses it. TelemetryStopwatch just calls Cu.reportError when it notices it's being used incorrectly.

Tim: How can TelemetryStopwatch.start("FX_PAGE_LOAD_MS", ...) get called twice before TelemetryStopwatch.finish("FX_PAGE_LOAD_MS", ..) ever gets called? Two tabs being loaded simultaneously?
Flags: needinfo?(ttaubert)
Loading https://www.yammer.com/mozilla.com in a tab I indeed see:

start, start, stop, stop

If I assume that the first "stop" belongs to the first "start" then that would also mess with the measurements if we'd always cancel() before start(). And those are supposed to be top-level loads, hm.
Flags: needinfo?(ttaubert)
The first page loaded looks like this:

<html>
<head>
  <title>Submit Form</title>
</head>
<body onload="javascript:document.forms[0].submit()">
  <form method="post" action="https://mozilla.okta.com/app/yammer/k102e4iirRLLYWTGTOPP/sso/saml">
    <input type="hidden" name="SAMLRequest" value="..."/>
    <input type="hidden" name="RelayState" value="..."/>
  </form>
</body>
</html>

So shortly after that has loaded a new POST request is sent, which probably is the second "start". Not sure what to do about that... Should the key passed to start(), finish(), and cancel() maybe be something like:

key = {browser: aBrowser, uri: aRequest.URI.spec}

? There might be edge cases, maybe not.
Yeah a more unique key passed to TelemetryStopwatch would help
Note that the key is not compared for deep equality. It's only checked as a reference to the same object.

Maybe changing the key from aBrowser to aRequest would work, if the aRequest received on finish is the same obj as the one received on start (I imagine it is)
(Reporter)

Comment 7

3 years ago
WFM in Nightly 47.
Status: NEW → RESOLVED
Last Resolved: 3 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.