1233004 - browser.js calls TelemetryStopwatch.finish() for FX_PAGE_LOAD_MS twice

Status: RESOLVED FIXED

(Firefox :: General, defect)

Description

[Iaroslav Sheptykin]

Attachment: browser-js-telemetry-stopwatch.log

While working on bug 1205898 we noticed that some code in browser.js is calling TelemetryStopwatch.finish twice for the Histogram FX_PAGE_LOAD_MS, where as TelemetryStopwatch.start("FX_PAGE_LOAD_MS") is only called once. 

According to callstacks, here is the place where it happens: https://dxr.mozilla.org/mozilla-central/source/browser/base/content/browser.js#4761

After the patch for bug 1205898 lands this will cause a similar message to appear in testing logs and possibly in browser console:

13:24:23     INFO -  3 INFO TEST-INFO | (browser-test.js) | Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 303}]

STR:
0. if bug 1205898 is still open modify 
https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/TelemetryStopwatch.jsm#153
to include some debug output as for example:
dump("*** ERROR ***: TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS");

1. ./mach test browser/base/content/test/ | grep "TelemetryStopwatch"
2. Observe the error reports.

See the attached file for a sample output obtained by running:
./mach test browser/base/content/test/general/browser_aboutHome.js > browser-js-telemetry-stopwatch.log

Comment 1

[Iaroslav Sheptykin]

Hey georg! I submitted a bug report as you suggested. I hope I could describe clearly what the problem is. Could you categorize the bug properly? because I put it into Firefox->general.

Comment 2

[Georg Fritzsche [:gfritzsche]]

Tim, i see you in the annotations here:
https://hg.mozilla.org/mozilla-central/annotate/0babaa3edcf908c393b68a3dc2d1c2a2450c31ed/browser/base/content/browser.js#l4761

Can you provide context? Or do you know who would be good to flag on this now?

Comment 3

[Tim Taubert [:ttaubert] (inactive)]

(In reply to Georg Fritzsche [:gfritzsche] [away Dec 19 - Jan 3] from comment #2)
> Tim, i see you in the annotations here:
> https://hg.mozilla.org/mozilla-central/annotate/
> 0babaa3edcf908c393b68a3dc2d1c2a2450c31ed/browser/base/content/browser.
> js#l4761
> 
> Can you provide context? Or do you know who would be good to flag on this
> now?

I can't provide a lot of context I'm afraid, that was almost 3 years ago. I think someone needs to spend some time and investigate why and under which conditions this happens. nsIWebProgressListener notifications are special sometimes...

Comment 5

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

We get these errors when running all DevTools Mochitests:

128 INFO TEST-OK | devtools/client/storage/test/browser_storage_basic.js | took 5456ms
129 INFO checking window state
130 INFO Console message: [JavaScript Error: "TelemetryStopwatch: key "FX_TAB_SWITCH_TOTAL_MS" was already initialized" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 282}]
this.TelemetryStopwatchImpl.start@resource://gre/modules/TelemetryStopwatch.jsm:282:7
this.TelemetryStopwatch.start@resource://gre/modules/TelemetryStopwatch.jsm:136:12
updateCurrentBrowser@chrome://browser/content/tabbrowser.xml:1036:17
onselect@chrome://browser/content/browser.xul:1:44
set_selectedIndex@chrome://global/content/bindings/tabbox.xml:656:13
set_selectedPanel@chrome://global/content/bindings/tabbox.xml:675:13
set_selectedIndex@chrome://global/content/bindings/tabbox.xml:403:15
set_selectedItem@chrome://global/content/bindings/tabbox.xml:435:34
set_selectedTab@chrome://global/content/bindings/tabbox.xml:114:15
set_selectedTab@chrome://browser/content/tabbrowser.xml:2828:11
_blurTab@chrome://browser/content/tabbrowser.xml:2479:13
_endRemoveTab@chrome://browser/content/tabbrowser.xml:2353:13
removeTab@chrome://browser/content/tabbrowser.xml:2195:15
Tester_waitForWindowsState@chrome://mochikit/content/browser-test.js:305:7
Tester.prototype.nextTest<@chrome://mochikit/content/browser-test.js:594:5
TaskImpl_run@resource://gre/modules/Task.jsm:319:40
promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:395:7
TaskImpl_run@resource://gre/modules/Task.jsm:327:13
TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:400:7
TaskImpl_run@resource://gre/modules/Task.jsm:327:13
TaskImpl@resource://gre/modules/Task.jsm:280:3
createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1060:11
testScope/test_executeSoon/<.run@chrome://mochikit/content/browser-test.js:991:9

131 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_TOTAL_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}]
this.TelemetryStopwatchImpl.timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:297:7
this.TelemetryStopwatchImpl.finish@resource://gre/modules/TelemetryStopwatch.jsm:315:17
this.TelemetryStopwatch.finish@resource://gre/modules/TelemetryStopwatch.jsm:192:12
onMozAfterPaint@chrome://browser/content/tabbrowser.xml:1038:19
EventListener.handleEvent*updateCurrentBrowser@chrome://browser/content/tabbrowser.xml:1037:17
onselect@chrome://browser/content/browser.xul:1:44
set_selectedIndex@chrome://global/content/bindings/tabbox.xml:656:13
set_selectedPanel@chrome://global/content/bindings/tabbox.xml:675:13
set_selectedIndex@chrome://global/content/bindings/tabbox.xml:403:15
set_selectedItem@chrome://global/content/bindings/tabbox.xml:435:34
set_selectedTab@chrome://global/content/bindings/tabbox.xml:114:15
set_selectedTab@chrome://browser/content/tabbrowser.xml:2828:11
_blurTab@chrome://browser/content/tabbrowser.xml:2479:13
_endRemoveTab@chrome://browser/content/tabbrowser.xml:2353:13
removeTab@chrome://browser/content/tabbrowser.xml:2195:15
removeCurrentTab@chrome://browser/content/tabbrowser.xml:2149:13
@chrome://mochitests/content/browser/devtools/client/storage/test/head.js:45:5
Tester.prototype.nextTest<@chrome://mochikit/content/browser-test.js:464:17
TaskImpl_run@resource://gre/modules/Task.jsm:319:40
TaskImpl@resource://gre/modules/Task.jsm:280:3
createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1060:11
testScope/test_executeSoon/<.run@chrome://mochikit/content/browser-test.js:991:9

132 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_TOTAL_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}]
this.TelemetryStopwatchImpl.timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:297:7
this.TelemetryStopwatchImpl.finish@resource://gre/modules/TelemetryStopwatch.jsm:315:17
this.TelemetryStopwatch.finish@resource://gre/modules/TelemetryStopwatch.jsm:192:12
onMozAfterPaint@chrome://browser/content/tabbrowser.xml:1038:19
EventListener.handleEvent*updateCurrentBrowser@chrome://browser/content/tabbrowser.xml:1037:17
onselect@chrome://browser/content/browser.xul:1:44
set_selectedIndex@chrome://global/content/bindings/tabbox.xml:656:13
set_selectedPanel@chrome://global/content/bindings/tabbox.xml:675:13
set_selectedIndex@chrome://global/content/bindings/tabbox.xml:403:15
set_selectedItem@chrome://global/content/bindings/tabbox.xml:435:34
set_selectedTab@chrome://global/content/bindings/tabbox.xml:114:15
set_selectedTab@chrome://browser/content/tabbrowser.xml:2828:11
_blurTab@chrome://browser/content/tabbrowser.xml:2479:13
_endRemoveTab@chrome://browser/content/tabbrowser.xml:2353:13
removeTab@chrome://browser/content/tabbrowser.xml:2195:15
Tester_waitForWindowsState@chrome://mochikit/content/browser-test.js:305:7
Tester.prototype.nextTest<@chrome://mochikit/content/browser-test.js:594:5
TaskImpl_run@resource://gre/modules/Task.jsm:319:40
promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:395:7
TaskImpl_run@resource://gre/modules/Task.jsm:327:13
TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:400:7
TaskImpl_run@resource://gre/modules/Task.jsm:327:13
TaskImpl@resource://gre/modules/Task.jsm:280:3
createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1060:11
testScope/test_executeSoon/<.run@chrome://mochikit/content/browser-test.js:991:9

Comment 6

[Ryan VanderMeulen [:RyanVM]]

Can we dupe this over to bug 1261738 now?

Comment 7

[Iaroslav Sheptykin]

It looks like the Bug 1261738 is dealing with a similar problem occurring for "FX_TAB_SWITCH_TOTAL_MS" measurement. Here, however, the problem is "FX_PAGE_LOAD_MS". If I read the current patch in Bug 1261738 right, it will not fix the issue that we reported here, because they patch tabbrowser.xml and our problem originates in browser.js.

Comment 8

[Iaroslav Sheptykin]

Hey Michael! I think your comment 5 is addressed in bug 1261738.

Comment 9

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

(In reply to Iaroslav Sheptykin from comment #8)
> Hey Michael! I think your comment 5 is addressed in bug 1261738.

So it is, thanks.

Comment 11

[Dão Gottwald [:dao]]

This was fixed by the second patch in bug 1250784.