Closed Bug 1233369 Opened 7 years ago Closed 6 years ago

UnifiedComplete.js calls TelemetryStopwatch.finish() for PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS twice


(Toolkit :: Places, defect, P2)




Tracking Status
firefox46 --- fixed


(Reporter: yarik.sheptykin, Assigned: mak)



(Whiteboard: [unifiedcomplete][fxsearch])


(2 files)

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

According to callstacks, here is the place where it happens:

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: "PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 303}]

0. if bug 1205898 is still open modify
to include some debug output as for example:
dump("*** ERROR ***: TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: " + aHistogram + "\n");

1. ./mach test toolkit/components/places/tests/unifiedcomplete/test_searchSuggestions.js | grep "TelemetryStopwatch"
2. Observe the error reports.

See the attached file for a sample output obtained by running:
./mach test toolkit/components/places/tests/unifiedcomplete/test_searchSuggestions.js > /tmp/unifiedcomplete-telemetry-stopwatch.log
Flags: needinfo?(gfritzsche)
Paolo, hg history shows you and Marco having worked around there:

Can you look into this?
Blocks: 1105864
Flags: needinfo?(gfritzsche) → needinfo?(paolo.mozmail)
so we are changing the TelemetryStopWatch API?
The bug here is actually something we did ON PURPOSE since the API was designed to allow calling finish multiple times as a no-op. In some cases avoiding a double call complicates the code and the benefit looks low (what is exactly? just linting?)
Flags: needinfo?(paolo.mozmail)
Priority: -- → P2
Whiteboard: [unifiedcomplete][fxsearch]
Hi Marco!

We are extending TelemetryStopwatch API to handle keyed histograms. Existing API will keep working as it used to. Finishing a non-existing timer will still be no-op, but this event is now logged with Cu.reportError(). We believe that this could be helpful for catching unintentional mistakes. This will not affect your code more than an error showing up in console and logs. If you are ok with this, feel free to close this bug. We filed it to make sure nothing is (or was) broken.

Also, the code in Bug 1205898 has not landed yet, so we can still add/change something without much headache. But lets discuss possible changes there. 

How does this sound?
Flags: needinfo?(mak77)
I think we can fix it to avoid the console spew. I'm happy the error is not propagated but just reported.
Flags: needinfo?(mak77)
Duplicate of this bug: 1235553
mak: any chance you could take this, or know someone that you could assign it to?

Bug 1205898 has landed now (which turns this bug into consolespew per comment 4), and the resulting consolespew is pretty bad. In my case, it seems like the warning from comment 0 gets spammed to Browser Console once per character I type in my URLbar, approximately.
Flags: needinfo?(mak77)
yeah sorry.
Assignee: nobody → mak77
Flags: needinfo?(mak77)
Attachment #8707529 - Flags: review?(adw) → review+
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla46
You need to log in before you can comment on or make changes to this bug.