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

Status: RESOLVED FIXED

Description

[Iaroslav Sheptykin]

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

Comment 1

[Iaroslav Sheptykin]

Hi Georg! I failed the bug on PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS.

Comment 2

[Georg Fritzsche [: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?

Comment 3

[Marco Bonardo [::mak] (Away 9-26 Aug)]

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?)

Comment 4

[Iaroslav Sheptykin]

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?

Comment 5

[Marco Bonardo [::mak] (Away 9-26 Aug)]

I think we can fix it to avoid the console spew. I'm happy the error is not propagated but just reported.

Comment 7

[Daniel Holbert [:dholbert]]

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.

Comment 8

[Marco Bonardo [::mak] (Away 9-26 Aug)]

yeah sorry.

Comment 9

[Marco Bonardo [::mak] (Away 9-26 Aug)]

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/

Comment 10

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/6cb4eea487ad

Comment 11

[Wes Kocher (:KWierso)]

https://hg.mozilla.org/mozilla-central/rev/6cb4eea487ad