Closed Bug 1233004 Opened 5 years ago Closed 3 years ago

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

Categories

(Firefox :: General, defect)

defect
Not set
minor

Tracking

()

RESOLVED FIXED
Firefox 48
Tracking Status
firefox46 --- affected

People

(Reporter: yarik.sheptykin, Unassigned)

References

Details

Attachments

(1 file)

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
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.
Flags: needinfo?(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?
Flags: needinfo?(gfritzsche) → needinfo?(ttaubert)
(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...
Flags: needinfo?(ttaubert)
Duplicate of this bug: 1250093
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
Can we dupe this over to bug 1261738 now?
Flags: needinfo?(gfritzsche)
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.
Flags: needinfo?(gfritzsche)
Hey Michael! I think your comment 5 is addressed in bug 1261738.
Flags: needinfo?(mratcliffe)
(In reply to Iaroslav Sheptykin from comment #8)
> Hey Michael! I think your comment 5 is addressed in bug 1261738.

So it is, thanks.
Flags: needinfo?(mratcliffe)
Duplicate of this bug: 1279638
This was fixed by the second patch in bug 1250784.
Status: NEW → RESOLVED
Closed: 3 years ago
Depends on: 1250784
Resolution: --- → FIXED
Target Milestone: --- → Firefox 48
You need to log in before you can comment on or make changes to this bug.