1433735 - TelemetryStopwatch: key "FX_SCHEDULE_PRESSURE_IDLE_SAMPLE_MS" was already initialized

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Wellington Torrejais da Silva]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:59.0) Gecko/20100101 Firefox/59.0
Build ID: 20180118161404

Steps to reproduce:

Watching Netflix nothing special just poor Internet.


Actual results:

Browser console many times JS alert error:

03:12:09.084 TelemetryStopwatch: key "FX_SCHEDULE_PRESSURE_IDLE_SAMPLE_MS" was already initialized 1 TelemetryStopwatch.jsm:356
	start resource://gre/modules/TelemetryStopwatch.jsm:356:9
	start resource://gre/modules/TelemetryStopwatch.jsm:137:12
	_createTimeoutFn/< resource:///modules/SchedulePressure.jsm:42:11



Expected results:

No Telemetry errors...

Thanks!

Comment 1

[Chris H-C :chutten]

Luckily this isn't a telemetry error, just a warning that stopwatch will have reset the count to the second call to `start`.

Specifically, this means that SchedulePressure[1] is trying to start an already-started stopwatch. Throwing some ni? towards those who wrote and reviewed the code.

Looking at the code... it is trying its darnedest to be a good user of stopwatch. I'm thinking from its use of `start` in an if condition that it probably wants to check `!running` in the if instead. That'll avoid the log. But I don't see how it would call it multiple times (the closures in that file are making my head dizzy). If we could avoid calling start more than once, that would probably be the better solution, rather than checking `!running`, as that would save Firefox some execution time.

[1]: https://searchfox.org/mozilla-central/source/browser/modules/SchedulePressure.jsm

Comment 2

[Jared Wein [:jaws] (please needinfo? me)]

The FX_SCHEDULE_PRESSURE_IDLE_SAMPLE_MS histogram is expiring soon so we may just be fine with removing this code altogether.

However, the first note in comment 1 is a little scary since that means that our data that we collecting might not be reliable.

It looks like we may be missing a call to TelemetryStopwatch.cancel() within the stopMonitoring function.

Comment 3

[Mike Conley (:mconley) (:⚙️)]

(In reply to Jared Wein [:jaws] (please needinfo? me) from comment #2)
> 
> It looks like we may be missing a call to TelemetryStopwatch.cancel() within
> the stopMonitoring function.

Ooof, yep, that's missing. I agree that this means we likely have some contamination within the data we've collected.

I wouldn't be opposed to patching this to stop the stopwatch when we stop monitoring, and getting a few more weeks of data. The probe expires in 61, so if we can get this patched for 60, that'll give us one release to determine whether or not the data means we need to extend the probe longer.

Comment 4

[Jared Wein [:jaws] (please needinfo? me)]

Attachment: Bug 1433735 - Cancel the TelemetryStopwatch when we stop monitoring a window for schedule pressure.

Review commit: https://reviewboard.mozilla.org/r/216912/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/216912/

Comment 5

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 8947137 [details]
Bug 1433735 - Cancel the TelemetryStopwatch when we stop monitoring a window for schedule pressure.

https://reviewboard.mozilla.org/r/216912/#review222734

Looks good, thanks jaws.

As an aside, it'd be nice if we could somehow annotate or otherwise add commentary to a dataset. In the case of this probe, I'd probably say, "Ignore everything bug 1433735 landing".

Comment 6

[Jared Wein [:jaws] (please needinfo? me)]

With this patch I'm no longer able to reproduce the warning. I tested by using "Open All in Tabs" from two bookmark folders with 12 and 80 bookmarks in each, then closing all other tabs, and reopening repeatedly.

Prior to the patch I was able to see the warning but I am not able to see the warning after applying the patch.

Comment 7

[Chris H-C :chutten]

Adding commentary to a given probe such that datasets that display it would have access to it... sounds like a use case for the probe info service. :Dexter, is there a place we're collecting use cases for the probe info service?

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5eac5a53b1de
Cancel the TelemetryStopwatch when we stop monitoring a window for schedule pressure. r=mconley

Comment 9

[Alessio Placitelli [:Dexter]]

(In reply to Chris H-C :chutten from comment #7)
> Adding commentary to a given probe such that datasets that display it would
> have access to it... sounds like a use case for the probe info service.
> :Dexter, is there a place we're collecting use cases for the probe info
> service?

Not that I know of. Georg?

Comment 10

[Georg Fritzsche [:gfritzsche]]

We want something like this feature, but we don't have it yet. We can add use-case tracking here:
https://docs.google.com/document/d/1iqjMeHOXzb8zOUuBWPkKiIxp5Lagr2P8B0XJsBkYMcY/edit

For now adding info to the probe description should work.
That actually shows up in e.g. the probe dictionary:
https://georgf.github.io/fx-data-explorer/?search=fx_schedule&optout=false&channel=nightly&view=search-results-view&detailView=histogram%2FFX_SCHEDULE_PRESSURE_IDLE_SAMPLE_MS

Comment 11

[Georg Fritzsche [:gfritzsche]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #10)
> We want something like this feature, but we don't have it yet. We can add
> use-case tracking here:
> https://docs.google.com/document/d/
> 1iqjMeHOXzb8zOUuBWPkKiIxp5Lagr2P8B0XJsBkYMcY/edit

Alternatively filing an issue with the probe-scraper repo would work.
https://github.com/mozilla/probe-scraper

Comment 12

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/5eac5a53b1de