1503074 - Intermittent browser/components/payments/test/browser/<random_test> | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource:

Status: RESOLVED FIXED

(Firefox :: Tabbed Browser, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=208517493&repo=autoland

https://queue.taskcluster.net/v1/task/RhWn6t8lQBGuw3iZ3JOb8w/runs/0/artifacts/public/logs/live_backing.log

[task 2018-10-30T00:59:36.018Z] 00:59:36     INFO - TEST-START | browser/components/payments/test/browser/browser_payment_completion.js
[task 2018-10-30T00:59:36.056Z] 00:59:36     INFO - TEST-INFO | started process screentopng
[task 2018-10-30T00:59:36.482Z] 00:59:36     INFO - TEST-INFO | screentopng: exit 0
[task 2018-10-30T00:59:36.482Z] 00:59:36     INFO - Buffered messages logged at 00:59:36
[task 2018-10-30T00:59:36.484Z] 00:59:36     INFO - Entering test bound setup_head
[task 2018-10-30T00:59:36.485Z] 00:59:36     INFO - Leaving test bound setup_head
[task 2018-10-30T00:59:36.486Z] 00:59:36     INFO - Entering test bound test_complete_success
[task 2018-10-30T00:59:36.488Z] 00:59:36     INFO - Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 388}]
[task 2018-10-30T00:59:36.489Z] 00:59:36     INFO - timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:388:9
[task 2018-10-30T00:59:36.490Z] 00:59:36     INFO - timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:208:12
[task 2018-10-30T00:59:36.491Z] 00:59:36     INFO - onPaint@resource:///modules/AsyncTabSwitcher.jsm:744:18
[task 2018-10-30T00:59:36.492Z] 00:59:36     INFO - handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1046:9
[task 2018-10-30T00:59:36.494Z] 00:59:36     INFO - EventListener.handleEvent*AsyncTabSwitcher@resource:///modules/AsyncTabSwitcher.jsm:140:5
[task 2018-10-30T00:59:36.495Z] 00:59:36     INFO - _getSwitcher@chrome://browser/content/tabbrowser.js:4139:24
[task 2018-10-30T00:59:36.496Z] 00:59:36     INFO - updateCurrentBrowser@chrome://browser/content/tabbrowser.js:860:9
[task 2018-10-30T00:59:36.497Z] 00:59:36     INFO - _setupEventListeners/<@chrome://browser/content/tabbrowser.js:4507:9
[task 2018-10-30T00:59:36.498Z] 00:59:36     INFO - set selectedIndex@chrome://global/content/elements/tabbox.js:201:7
[task 2018-10-30T00:59:36.499Z] 00:59:36     INFO - set selectedPanel@chrome://global/content/elements/tabbox.js:215:5
[task 2018-10-30T00:59:36.500Z] 00:59:36     INFO - set_selectedIndex@chrome://global/content/bindings/tabbox.xml:172:15
[task 2018-10-30T00:59:36.501Z] 00:59:36     INFO - set_selectedItem@chrome://global/content/bindings/tabbox.xml:197:34
[task 2018-10-30T00:59:36.502Z] 00:59:36     INFO - set selectedTab@chrome://global/content/elements/tabbox.js:80:9
[task 2018-10-30T00:59:36.503Z] 00:59:36     INFO - set selectedTab@chrome://browser/content/tabbrowser.js:274:5
[task 2018-10-30T00:59:36.504Z] 00:59:36     INFO - _blurTab@chrome://browser/content/tabbrowser.js:3188:24
[task 2018-10-30T00:59:36.506Z] 00:59:36     INFO - _beginRemoveTab@chrome://browser/content/tabbrowser.js:2888:5
[task 2018-10-30T00:59:36.507Z] 00:59:36     INFO - removeTab@chrome://browser/content/tabbrowser.js:2796:10
[task 2018-10-30T00:59:36.508Z] 00:59:36     INFO - removeTab@resource://testing-common/BrowserTestUtils.jsm:1208:5
[task 2018-10-30T00:59:36.509Z] 00:59:36     INFO - test_openPreferences/<@chrome://mochitests/content/browser/browser/components/payments/test/browser/browser_openPreferences.js:55:11
[task 2018-10-30T00:59:36.510Z] 00:59:36     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
[task 2018-10-30T00:59:36.511Z] 00:59:36     INFO - async*test_openPreferences@chrome://mochitests/content/browser/browser/components/payments/test/browser/browser_openPreferences.js:13:9
[task 2018-10-30T00:59:36.512Z] 00:59:36     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1093:34
[task 2018-10-30T00:59:36.513Z] 00:59:36     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1084:16
[task 2018-10-30T00:59:36.514Z] 00:59:36     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:986:9
[task 2018-10-30T00:59:36.515Z] 00:59:36     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-10-30T00:59:36.516Z] 00:59:36     INFO - 
[task 2018-10-30T00:59:36.517Z] 00:59:36     INFO - Buffered messages finished
[task 2018-10-30T00:59:36.519Z] 00:59:36     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_payment_completion.js | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 388}]
[task 2018-10-30T00:59:36.520Z] 00:59:36     INFO - timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:388:9
[task 2018-10-30T00:59:36.521Z] 00:59:36     INFO - timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:208:12
[task 2018-10-30T00:59:36.522Z] 00:59:36     INFO - onPaint@resource:///modules/AsyncTabSwitcher.jsm:744:18
[task 2018-10-30T00:59:36.523Z] 00:59:36     INFO - handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1046:9
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - EventListener.handleEvent*AsyncTabSwitcher@resource:///modules/AsyncTabSwitcher.jsm:140:5
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - _getSwitcher@chrome://browser/content/tabbrowser.js:4139:24
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - updateCurrentBrowser@chrome://browser/content/tabbrowser.js:860:9
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - _setupEventListeners/<@chrome://browser/content/tabbrowser.js:4507:9
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - set selectedIndex@chrome://global/content/elements/tabbox.js:201:7
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - set selectedPanel@chrome://global/content/elements/tabbox.js:215:5
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - set_selectedIndex@chrome://global/content/bindings/tabbox.xml:172:15
[task 2018-10-30T00:59:36.528Z] 00:59:36     INFO - set_selectedItem@chrome://global/content/bindings/tabbox.xml:197:34
[task 2018-10-30T00:59:36.529Z] 00:59:36     INFO - set selectedTab@chrome://global/content/elements/tabbox.js:80:9
[task 2018-10-30T00:59:36.530Z] 00:59:36     INFO - set selectedTab@chrome://browser/content/tabbrowser.js:274:5
[task 2018-10-30T00:59:36.533Z] 00:59:36     INFO - _blurTab@chrome://browser/content/tabbrowser.js:3188:24
[task 2018-10-30T00:59:36.534Z] 00:59:36     INFO - _beginRemoveTab@chrome://browser/content/tabbrowser.js:2888:5
[task 2018-10-30T00:59:36.535Z] 00:59:36     INFO - removeTab@chrome://browser/content/tabbrowser.js:2796:10
[task 2018-10-30T00:59:36.536Z] 00:59:36     INFO - removeTab@resource://testing-common/BrowserTestUtils.jsm:1208:5
[task 2018-10-30T00:59:36.537Z] 00:59:36     INFO - test_openPreferences/<@chrome://mochitests/content/browser/browser/components/payments/test/browser/browser_openPreferences.js:55:11
[task 2018-10-30T00:59:36.538Z] 00:59:36     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
[task 2018-10-30T00:59:36.539Z] 00:59:36     INFO - async*test_openPreferences@chrome://mochitests/content/browser/browser/components/payments/test/browser/browser_openPreferences.js:13:9
[task 2018-10-30T00:59:36.540Z] 00:59:36     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1093:34
[task 2018-10-30T00:59:36.542Z] 00:59:36     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1084:16
[task 2018-10-30T00:59:36.542Z] 00:59:36     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:986:9
[task 2018-10-30T00:59:36.544Z] 00:59:36     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-10-30T00:59:36.545Z] 00:59:36     INFO -  - 
[task 2018-10-30T00:59:36.546Z] 00:59:36     INFO - Stack trace:
[task 2018-10-30T00:59:36.547Z] 00:59:36     INFO - chrome://mochitests/content/browser/browser/components/payments/test/browser/head.js:onConsoleMessage:365
[task 2018-10-30T00:59:36.549Z] 00:59:36     INFO - chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:observe/<:388
[task 2018-10-30T00:59:36.550Z] 00:59:36     INFO - waitForMessageFromWidget: paymentDialogReady
[task 2018-10-30T00:59:36.551Z] 00:59:36     INFO - TEST-PASS | browser/components/payments/test/browser/browser_payment_completion.js | requestId should be defined -

Comment 4

[Intermittent Failures Robot]

14 failures in 2978 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 4
* autoland: 8
* mozilla-central: 1
* try: 1

Platform breakdown:
* linux64-nightly: 1
* linux64: 8
* linux32: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1503074&startday=2018-10-29&endday=2018-11-04&tree=all

Comment 8

[Intermittent Failures Robot]

27 failures in 3007 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 8
* mozilla-inbound: 9
* autoland: 10

Platform breakdown:
* linux64: 21
* linux32: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1503074&startday=2018-11-05&endday=2018-11-11&tree=all

Comment 9

[Intermittent Failures Robot]

9 failures in 2917 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 2
* autoland: 5
* mozilla-inbound: 2

Platform breakdown:
* linux32: 4
* linux64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1503074&startday=2018-11-12&endday=2018-11-18&tree=all

Comment 11

[Intermittent Failures Robot]

1 failures in 2387 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* try: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1503074&startday=2018-11-19&endday=2018-11-25&tree=all

Comment 12

[(no longer active)]

For unknown reasons, my patch in bug 1509047 seems to turn this into a perma-failure on Linux64 debug mochitest-bc7, so I had to fix this...

The bug is actually trivial to fix.  We can cancel the stopwatch but this code isn't checking to see whether it has been canceled before.

Comment 13

[(no longer active)]

Attachment: Bug 1503074 - Only touch the FX_TAB_SWITCH_COMPOSITE_E10S_MS stopwatch when we have actually started it in the past

Comment 14

[(no longer active)]

Before: https://treeherder.mozilla.org/#/jobs?repo=try&revision=047fd8ffa3d14f0a94e549256b6a8ff30b5b437e
After: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8a523c8bfc107b2bb452d4e4a2e93110f2bd47df

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/63cbd79e897d
Only touch the FX_TAB_SWITCH_COMPOSITE_E10S_MS stopwatch when we have actually started it in the past

Comment 16

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/63cbd79e897d

Comment 17

[Mike Conley (:mconley) (:⚙️)]

ni?ing ehsan just to make sure my review comment for this appears on his radar, since this has already landed.

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5f2c6354443e
follow-up: Address review comments

Comment 19

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/5f2c6354443e