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

RESOLVED FIXED in Firefox 46

Status

()

P2
minor
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: yarik.sheptykin, Assigned: mak)

Tracking

(Blocks: 1 bug)

Trunk
mozilla46
Points:
---

Firefox Tracking Flags

(firefox46 fixed)

Details

(Whiteboard: [unifiedcomplete][fxsearch])

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(2 attachments)

(Reporter)

Description

3 years ago
Created attachment 8699421 [details]
unifiedcomplete-telemetry-stopwatch.log

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

3 years ago
Hi Georg! I failed the bug on PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS.
Flags: needinfo?(gfritzsche)
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)
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

3 years ago
Flags: needinfo?(paolo.mozmail)
Priority: -- → P2
Whiteboard: [unifiedcomplete][fxsearch]
(Reporter)

Comment 4

3 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)
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)
(Assignee)

Updated

3 years ago
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)
Created attachment 8707529 [details]
MozReview Request: Bug 1233369 - UnifiedComplete.js calls TelemetryStopwatch.finish() for PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS multiple times. r=adw

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

3 years ago
Attachment #8707529 - Flags: review?(adw) → review+

Comment 11

3 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/6cb4eea487ad
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox46: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla46
You need to log in before you can comment on or make changes to this bug.