Closed
Bug 1233369
Opened 7 years ago
Closed 6 years ago
UnifiedComplete.js calls TelemetryStopwatch.finish() for PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS twice
Categories
(Toolkit :: Places, defect, P2)
Toolkit
Places
Tracking
()
RESOLVED
FIXED
mozilla46
Tracking | Status | |
---|---|---|
firefox46 | --- | fixed |
People
(Reporter: yarik.sheptykin, Assigned: mak)
References
Details
(Whiteboard: [unifiedcomplete][fxsearch])
Attachments
(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: https://dxr.mozilla.org/mozilla-central/source/toolkit/components/places/UnifiedComplete.js#1332 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}] 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: " + 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
Reporter | ||
Comment 1•7 years ago
|
||
Hi Georg! I failed the bug on PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS.
Flags: needinfo?(gfritzsche)
Comment 2•7 years ago
|
||
Paolo, hg history shows you and Marco having worked around there: https://hg.mozilla.org/mozilla-central/annotate/0babaa3edcf908c393b68a3dc2d1c2a2450c31ed/toolkit/components/places/UnifiedComplete.js#l1332 Can you look into this?
Blocks: 1105864
Flags: needinfo?(gfritzsche) → needinfo?(paolo.mozmail)
Assignee | ||
Comment 3•7 years ago
|
||
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?)
Assignee | ||
Updated•7 years ago
|
Flags: needinfo?(paolo.mozmail)
Priority: -- → P2
Whiteboard: [unifiedcomplete][fxsearch]
Reporter | ||
Comment 4•7 years ago
|
||
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)
Assignee | ||
Comment 5•7 years ago
|
||
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)
Comment 7•7 years ago
|
||
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)
Assignee | ||
Comment 9•7 years ago
|
||
Review commit: https://reviewboard.mozilla.org/r/30745/diff/#index_header See other reviews: https://reviewboard.mozilla.org/r/30745/
Attachment #8707529 -
Flags: review?(adw)
Updated•6 years ago
|
Attachment #8707529 -
Flags: review?(adw) → review+
Comment 11•6 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/6cb4eea487ad
Status: NEW → RESOLVED
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.
Description
•