1205898 - Make TelemetryStopwatch.jsm handle keyed histograms

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Nick Alexander :nalexander [he/him]]

We have a very nice module for measuring durations (https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/TelemetryStopwatch.jsm) but it does not appear to handle keyed histograms.  This ticket tracks making it do so.

Motivation: over in Bug 1205705, I'd like to add some keyed duration Telemetry histograms.  That is, I want to collect connection times keyed by various endpoints: that is, each entry is a path and a duration, like (/settings, 1000).  TelemetryStopwatch is good at measuring but I can't see how to associate a key.

Comment 1

[Georg Fritzsche [:gfritzsche]]

Are you planning to work on this?
It shouldn't be too hard to make TelemetryStopwatch support both plain and keyed histograms.

Comment 2

[Nick Alexander :nalexander [he/him]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #1)
> Are you planning to work on this?

No.  I worked around it in Bug 1205705.  (Other places do similar things.)

> It shouldn't be too hard to make TelemetryStopwatch support both plain and
> keyed histograms.

I don't think so either, but I don't know anything about this code.  Seems like a good mentor ticket, if you can mentor it.

Comment 3

[Georg Fritzsche [:gfritzsche]]

I think the most straight-forward approach would be adding additional methods for keyed measurements to TelemetryStopwatch:
startKeyed(aHistogram, aKey, aObj)
cancelKeyed(aHistogram, aKey, aObj)
timeElapsed(aHistogram, aKey, aObj)
finish(aHistogram, aKey, aObj)

Vladan, how does that sound to you?

Comment 4

[Georg Fritzsche [:gfritzsche]]

Iaroslav, would this bug be interesting for you?
When we have an API consensus here we can think about how to share code best internally.

Comment 5

[Iaroslav Sheptykin]

Yeah, this sounds interesting. And the matters sound familiar - I did similar work for Translation.jsm.

Comment 6

[Vladan Djeric (:vladan)]

(In reply to Georg Fritzsche [:gfritzsche] from comment #3)
> I think the most straight-forward approach would be adding additional
> methods for keyed measurements to TelemetryStopwatch:
> startKeyed(aHistogram, aKey, aObj)
> cancelKeyed(aHistogram, aKey, aObj)
> timeElapsed(aHistogram, aKey, aObj)
> finish(aHistogram, aKey, aObj)
> 
> Vladan, how does that sound to you?

That's one option, another option is to keep the same interfaces but specify keys in the histogram name argument, e.g. TelemetryStopwatch.start("FX_HISTOGRAM_NAME_MS#my_key_name") like we do internally in Telemetry.cpp. What do you think?

Comment 7

[Nick Alexander :nalexander [he/him]]

(In reply to Vladan Djeric (:vladan) -- please needinfo! from comment #6)
> (In reply to Georg Fritzsche [:gfritzsche] from comment #3)
> > I think the most straight-forward approach would be adding additional
> > methods for keyed measurements to TelemetryStopwatch:
> > startKeyed(aHistogram, aKey, aObj)
> > cancelKeyed(aHistogram, aKey, aObj)
> > timeElapsed(aHistogram, aKey, aObj)
> > finish(aHistogram, aKey, aObj)
> > 
> > Vladan, how does that sound to you?
> 
> That's one option, another option is to keep the same interfaces but specify
> keys in the histogram name argument, e.g.
> TelemetryStopwatch.start("FX_HISTOGRAM_NAME_MS#my_key_name") like we do
> internally in Telemetry.cpp. What do you think?

Do this internally, if you must; but please don't expose this string-munging as the API.  It's hard to search for (it's already hard to find uses of histograms because people break the prefix out of the suffix) and if the format ever changes, or grows additional options, life will be hard.

I.e., I strongly prefer

function startKeyed(histogram, key, obj) {
  this.start(histogram + "#" + key, obj);
}

Comment 8

[Georg Fritzsche [:gfritzsche]]

(In reply to Nick Alexander :nalexander from comment #7)
> (In reply to Vladan Djeric (:vladan) -- please needinfo! from comment #6)
> > (In reply to Georg Fritzsche [:gfritzsche] from comment #3)
> > > I think the most straight-forward approach would be adding additional
> > > methods for keyed measurements to TelemetryStopwatch:
> > > startKeyed(aHistogram, aKey, aObj)
> > > cancelKeyed(aHistogram, aKey, aObj)
> > > timeElapsed(aHistogram, aKey, aObj)
> > > finish(aHistogram, aKey, aObj)
> > > 
> > > Vladan, how does that sound to you?
> > 
> > That's one option, another option is to keep the same interfaces but specify
> > keys in the histogram name argument, e.g.
> > TelemetryStopwatch.start("FX_HISTOGRAM_NAME_MS#my_key_name") like we do
> > internally in Telemetry.cpp. What do you think?
> 
> Do this internally, if you must; but please don't expose this string-munging
> as the API.  It's hard to search for (it's already hard to find uses of
> histograms because people break the prefix out of the suffix) and if the
> format ever changes, or grows additional options, life will be hard.
> 
> I.e., I strongly prefer
> 
> function startKeyed(histogram, key, obj) {
>   this.start(histogram + "#" + key, obj);
> }

Yeah, i agree with this.
We shouldn't use the internal name details here though and instead go through the proper nsITelemetry API to access the keyed histograms (the histogram name is really an implementation detail that i don't want to leak out of the C++ parts).

Comment 9

[Georg Fritzsche [:gfritzsche]]

So, i'd propose to simplify the implementation to use one common map to hold the timers, of the form (histogramKey -> (object -> timerInfo))
... where `object` may be `null` for those timers not bound to an object and `timerInfo` is of the form:
{
  startTime: <Number>, // start time in ms
  key: <String>, // histogram key or null
}

How does that sound Iaroslav?
That should let us keep the implementation relatively simple and code properly shared.

Comment 10

[Iaroslav Sheptykin]

(In reply to Georg Fritzsche [:gfritzsche] from comment #9)

> How does that sound Iaroslav?

Yeah, that sounds reasonable. I am drafting an implementation of this.

Comment 11

[Iaroslav Sheptykin]

Attachment: MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzche

Comment 12

[Iaroslav Sheptykin]

Hi Guys! Please take a look on my WIP patch. I took me a little longer than I thought. What you see is actually a v3. Previous 2 diverged too much from the initial implementation and I decided to abandon them.

I had to change the structure of timers hash proposed by Georg a little bit:

> So, i'd propose to simplify the implementation to use one common map to hold
> the timers, of the form (histogramKey -> (object -> timerInfo))
> ... where `object` may be `null` for those timers not bound to an object and
> `timerInfo` is of the form:
> {
>   startTime: <Number>, // start time in ms
>   key: <String>, // histogram key or null
> }

It turned into {histogramKey: WeakMap {object: keyedTimerInfo {key: timerInfo }}}.
I introduced keyedTimerInfo in order to distinguish between timers of the same histogram, related to the same object, but referring to different keys. I one of the alternative implementations I had this accomplished by creating a new histogramKey in a form aHistogram + "#" + aKey. This is easier to implement and comprehend. However, as far as I understand comments 7 and 8 this is not the best way to go. On the other hand, as you might see from my implementation, having a 3-level-hash makes the code less readable.

In order to stay DRY I extracted some of the earlier code into an Implementation object. I also moved the functions related to the manipulation of the hash structure into the hash itself.

If you think this is developing in a wrong direction please let me know :)

Comment 13

[Iaroslav Sheptykin]

(In reply to Georg Fritzsche [:gfritzsche] from comment #9)

One more thing: WeakMap only allows non-null objects as keys. Thus,

> ... where `object` may be `null` for those timers not bound to an object and

did not work.

Comment 14

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8666877 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

https://reviewboard.mozilla.org/r/20613/#review18853

I think we can make this a bit simpler and make the Timers object hide the difference between keyed and plain timers.

I imagine that we can have one common implementation like this:
```javascript
TelemetryStopWatch = {
  ...
  start: function(histogram, object) {
    return TelemetryStopWatchImpl.start(histogram, object, null);
  },
  
  startKeyed: function(histogram, key, object) {
    return TelemetryStopwatchImpl.start(histogram, object, key);
  },
  ...
},

TelemetryStopwatchImpl = {
  ...
  start: function(histogram, object, key) {
    ...
    let timerInfo = Timers.getTimerInfo(histogram, object || NULL_OBJECT, key || NULL_KEY);
    ...
```

The rest of the implementations should be equivalent.
Then we can the buildKey/validKey juggling because key objects are internal to the `Timers` implementation.
We also wouldn't need to store any functions to retrieve a histogram, we could just dynamically return it based on key being `NULL_KEY` or not.

What do you think?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:20
(Diff revision 1)
> +let TIMERS = {

Nit: `let Timers = { ...`

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:172
(Diff revision 1)
> +  startKeyed(aHistogram, aKey, aObj) {

High-level i think we should have both the keyed and non-keyed functions follow the same pattern.

So, TelemetryStopWatchImpl.startKeyed() should just directly call TelemetryStopWatchImpl.startKeyed().

Comment 15

[Iaroslav Sheptykin]

Comment on attachment 8666877 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Comment 16

[Georg Fritzsche [:gfritzsche]]

Thanks, i'm travelling right now and will catch up here on friday or monday.

Comment 17

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8666877 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

https://reviewboard.mozilla.org/r/20613/#review19523

This looks pretty close in structure, so i am doing a more thorough review here.
While this may look like a lot of comments below, there only two real issues here:
* how this uses the `NULL_KEY` has some identity issues
* how TelemetryStopwatchImpl.finish treats keyed histograms seems off

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:17
(Diff revisions 1 - 2)
> +const NULL_KEY = "DEFAULT";

I think this approach runs into identity issues - consider someone using a key of "DEFAULT" (which is totally valid).

E.g. you could try out something like this in the web console:
null_key = "DEFAULT";
m = new Map();
m.set(null_key, 1);
m.has("DEFAULT"); // ... true

A simple solution would be to use a unique object here as well, i.e. `NULL_KEY = {}`.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:59
(Diff revisions 1 - 2)
>      if (!this.validKey(aKey)) {

I think the one (only?) place where actually need the `validKey` check is in `putTimerInfo`.
All the other places are protected by lookups.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:82
(Diff revisions 1 - 2)
>      try {

What do we need the try-catch here for?
Where can this fail?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:83
(Diff revisions 1 - 2)
>        let objectMap = aKey.histogram in this ? this[aKey.histogram] : new WeakMap();
>        let keyedInfo = objectMap.has(aKey.obj) ? objectMap.get(aKey.obj) : {};

Could be a little more succinct here:
```javascript
let .. = this[...] || new WeakMap();
let .. = objectMap.has(...) || {};
```

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:84
(Diff revisions 1 - 2)
>        let keyedInfo = objectMap.has(aKey.obj) ? objectMap.get(aKey.obj) : {};
>        keyedInfo[aKey.key] = timerInfo;

Why don't we use a Map() here?
Then we could use proper .get/.set/.has and .size here on this.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:130
(Diff revisions 1 - 2)
> -    return TelemetryStopwatchImpl.start(TIMERS.buildKey(aHistogram, aObj));
> +    return TelemetryStopwatchImpl.start(aHistogram, aObj);

Lets make the function usage more explicit by using `TelemetryStopwatchImpl.start(aHistogram, aObj, null)`.
Ditto for the other non-keyed calls below.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:197
(Diff revisions 1 - 2)
>    timeElapesedKeyed: function(aHistogram, aKey, aObj) {

Typo: should be `timeElapsedKeyed:`

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:210
(Diff revisions 1 - 2)
>        Cu.reportError("TelemetryStopwatch: key \"" +
> -                     key.histogram + "\" was already initialized");
> +                     histogram + "\" was already initialized");

Nit: This would be nicer with template strings: `\`... key "${histogram}" was already ...\``

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:225
(Diff revisions 1 - 2)
>      try {
> -      let timerInfo = TIMERS.get(key);
> +      let timerInfo = Timers.getTimerInfo(histogram, object, key);
>        let delta = Components.utils.now() - timerInfo.startTime;
>        return Math.round(delta);
>      } catch (e) {
>        return -1;
>      }

Lets be more explicit here:
```javascript
let timerInfo = ...
if (!timerInfo) {
  ... log error
  return -1;
}

try {
  let delta ...
  return ...
} catch (e) {
  ... log error
  return -1;
}
```

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:241
(Diff revisions 1 - 2)
> -    timerInfo.histogram().add(delta);
> +                           ? Telemetry.getKeyedHistogramById(histogram, key)

getKeyedHistogramById() only takes one argument, the histogram name.
Instead, `histogramObject.add()` takes a second parameter for the key here.
Do we have test-coverage for `.finishKeyed()`?
If yes, why did it not fail for this?

::: toolkit/components/telemetry/tests/unit/test_TelemetryStopwatch.js:124
(Diff revisions 1 - 2)
>  

Can we add some coverage of invalid types and data being passed for key, object, histogram names?

Comment 18

[Iaroslav Sheptykin]

Comment on attachment 8666877 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Comment 19

[Iaroslav Sheptykin]

Attachment: MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Comment 20

[Georg Fritzsche [:gfritzsche]]

Hey Iaroslav, i see two review requests here now - one with prior review history, one without.
I assume the one with the prior review history is the one i should look into?

Comment 21

[Iaroslav Sheptykin]

Hey Georg! ReviewBoard does not want to become friends with me. I was trying to avoid histedit and pushed the whole bookmark to the review. This resulted in two review requests. The one without the review history has my latest code. I am not sure what to do best now. I could remove the new request, histedit my tree and push it to review again hoping that the board plays along. Does this sound good?

As you see I don't understand completely the workflow with ReviewBoard. There is just too much magic going on.

Comment 22

[Georg Fritzsche [:gfritzsche]]

Yeah, to be honest i still find it a bit confusing too.

If its easier for you i can just continue on the current/new request.
If there are bigger issues with getting review board to work, gps might want to hear about it (on IRC or by filing a bug about specific problems).

Comment 23

[Iaroslav Sheptykin]

Comment on attachment 8674216 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Comment 24

[Iaroslav Sheptykin]

Attachment: MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Comment 25

[Iaroslav Sheptykin]

Hi Georg! Wow, I did quite a mess here. Really sorry. I was trying to discard that new review I created by accident and everything ended up broken. So I discarded all reviews and created a new review request. I will talk to gps to make sure things like these don't happen again. I obviously have a wrong expectations for the ReviewBoard.

Comment 26

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

https://reviewboard.mozilla.org/r/22199/#review20605

Sorry for not getting here earlier.
This looks pretty reasonable now, but i think we should simplify the `Timer` implementation - it seems to have some abstractions that are not needed and could be easier to read.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:20
(Diff revision 1)
> + * Timers is a variation of a hash used for storing information about running
> + * Stopwatches. Times has the following data structure:

s/hash/Map/, s/Times/Timers/?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:26
(Diff revision 1)
> + *        "KEY" || NULL_KEY: TimerInfo

I think we can simplify the `Timers` implementation a lot.
All we really store in it is `startTime`, everything else is already known to the caller.

So internally it only needs to have the format:
```
"HISTOGRAM_NAME": WeakMap {
  Object || NULL_OBJECT: Map {
    "KEY" || NULL_KEY: startTime
...
```

... and usage can look like this:
```javascript
Timers.put(histogram, obj, key, startTime);
...
let startTime = Timers.get(histogram, obj, key);
```

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:34
(Diff revision 1)
> + * Where TimerInfo can be anything but is normally of a form:

*"Where TimerInfo is of the form:"* - we don't really want or expect anything else, right?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:40
(Diff revision 1)
> + * It is expected that you use get{put|has|delete}TimerInfo functions for
> + * working with Timers.

If we expect those to be used by callers, lets prefix the other function names with `_` to make it clear that they are internal.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:54
(Diff revision 1)
> +  buildKey: function(histogram, obj, key) {

I think we don't need to build key objects here, this is just used for argument passing.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:83
(Diff revision 1)
> +    let timerKey = this.buildKey(histogram, object, key);

I don't think we win anything from using `buildKey` and the key objects.

We can just call `has(histogram, object, key)`, `put(histogram, object, key, startTime)`, etc.

At that stage i wonder if we need both `has` and `hasTimerInfo`, `put` and `putTimerInfo` etc.
I think this adds indirection without much gain.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:116
(Diff revision 1)
> +    this[aKey.histogram] = objectMap;

Why are we not storing them in a map, say `this._timers`?
As it is now, we could into problems e.g. if there was a histogram called "put".

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:228
(Diff revision 1)
> +this.TelemetryStopwatchImpl = {

Nit: empty line before this.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:233
(Diff revision 1)
> +      Cu.reportError(singleSpace(`TelemetryStopwatch: key "${histogram}"

Nit: "key" is confusing in this context, "timer for histogram ... was already ..."?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:233
(Diff revision 1)
> +      Cu.reportError(singleSpace(`TelemetryStopwatch: key "${histogram}"
> +                                  was already initialized`));

Lets just use separate strings instead of processing this with `singleSpace`:
```javascript
Cu.reportError("foo" +
               "bar");
```
Ditto for the other uses of `singleSpace` below.

Comment 27

[Iaroslav Sheptykin]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Comment 28

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

https://reviewboard.mozilla.org/r/22199/#review20999

Thanks Iaroslav, this looks much clearer now!
This time i focused more on the details, so there are some style nits below and minor change request - it looks like we should have this done after 1-2 more passes :)

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:44
(Diff revision 2)
> -    if (!validTypes(aHistogram, aObj))
> +  _timers: {},

Lets make it a `Map` so we get proper `.has(x)` & `.size` checks etc.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:47
(Diff revision 2)
> -    if (aObj) {
> -      timers = objectTimers.get(aObj) || {};
> +    let reasonableString = anything => {
> +      return typeof anything === "string" && anything !== "";

Nits:
* `value` instead of `anything`?
* `nonEmptyString` instead of `reasonableString`?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:103
(Diff revision 2)
> +    this._timers[histogram].delete(obj);

This way we will never delete entries for histogram names.
Should we check for that too?

I.e. (assuming using a `Map` for `this._timers`):
```javascript
let objectMap = this._timers.get(histogram);
...

if (objectMap.size > 1) {
  objectMap.delete(obj);
  return true;
}

this._timers.delete(histogram);
...
```

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:115
(Diff revision 2)
> +   *                              from TelemetryHistograms.h

Nit: 
* "... valid histogram name from Histograms.json" or just
* "... valid histogram name."

TelemetryHistograms.h is generated as an implementation detail, the main definition file for histograms is Histograms.json.

All the following function comments have the same issue, either mentioning `TelemetryHistograms.h` or `TelemetryHistograms`.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:119
(Diff revision 2)
> +   *                        timers for a same histogram may be run concurrently,

Nit: "for the same histogram", ditto the comments below.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:150
(Diff revision 2)
>    cancel: function ts_cancel(aHistogram, aObj) {

Minor request: can we drop the function name (`ts_cancel`) here?
This is not needed anymore (this style addressed a short-coming in the debugger which has since been fixed) and makes the style inconsistent.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:214
(Diff revision 2)
> +  startKeyed(aHistogram, aKey, aObj) {

`startKeyed: function(...`

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:280
(Diff revision 2)
> +

Nit: Redundant empty line.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:282
(Diff revision 2)
> +      Timers.delete(histogram, object, key)

Missing semicolon.

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:297
(Diff revision 2)
> -      delta = Math.round(delta);
> +    if (!startTime) {

`if (startTime === null) { ...`

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:303
(Diff revision 2)
> +    try {

Nit: empty line before this.

::: toolkit/components/telemetry/tests/unit/test_TelemetryStopwatch.js:120
(Diff revision 2)
> +  // Finishing a stopwatch of a non existing histogram should throw an exception.
> +  try {
> +    TelemetryStopwatch.finishKeyed("HISTOGRAM", "KEY2");
> +    do_throw("Non-existent histogram name should throw an error.");
> +  } catch (e) {}
> +  try {
> +    TelemetryStopwatch.finishKeyed("HISTOGRAM", "KEY2", refObj);
> +    do_throw("Non-existent histogram name should throw an error.");
> +  } catch (e) {}

I don't think this should throw, the API says it should return false.

I think we should actually change the behavior of `finishKeyed` here if you don't mind: it should report an error and return `false`.
With throwing exceptions the risk is pretty high of breaking other features that just do some timing measurement wrong.

::: toolkit/components/telemetry/tests/unit/test_TelemetryStopwatch.js:142
(Diff revision 2)
> +  // Verify that keyed histograms can only be canceled through "keyed" API.
> +  do_check_true(TelemetryStopwatch.startKeyed(KEYED_HIST.id, KEYED_HIST.key));
> +  do_check_false(TelemetryStopwatch.cancel(KEYED_HIST.id, KEYED_HIST.key));
> +  do_check_true(TelemetryStopwatch.cancelKeyed(KEYED_HIST.id, KEYED_HIST.key));

Lets also verify that we `finishKeyed` returns `false` after that, i.e. cancelling worked properly.

Comment 29

[Iaroslav Sheptykin]

https://reviewboard.mozilla.org/r/22199/#review20999

> This way we will never delete entries for histogram names.
> Should we check for that too?
> 
> I.e. (assuming using a `Map` for `this._timers`):
> ```javascript
> let objectMap = this._timers.get(histogram);
> ...
> 
> if (objectMap.size > 1) {
>   objectMap.delete(obj);
>   return true;
> }
> 
> this._timers.delete(histogram);
> ...
> ```

objectMap is an instance of WeakMap. [WeakMap][1] does not have a size property. Instead it has a property called length. However it seems to always be 0 regardless how many objects the map stores. If we want to delete empty objectMaps, we might need to count their objects ourselves or use another kind of map here. Which way would be more appropriate, Georg?

[1]: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/WeakMap

Comment 30

[Iaroslav Sheptykin]

Hi Georg! Not sure if you are notified when I comment on issues in ReviewBoard. So manually adding a needinfo request for comment 29.

Comment 31

[Georg Fritzsche [:gfritzsche]]

https://reviewboard.mozilla.org/r/22199/#review20999

> objectMap is an instance of WeakMap. [WeakMap][1] does not have a size property. Instead it has a property called length. However it seems to always be 0 regardless how many objects the map stores. If we want to delete empty objectMaps, we might need to count their objects ourselves or use another kind of map here. Which way would be more appropriate, Georg?
> 
> [1]: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/WeakMap

Ok, i think we can neglect that for now. I don't see a trivial & nice solution off-hand.

Comment 32

[Georg Fritzsche [:gfritzsche]]

Sorry for the long turn-around here, i was off sick last week.

Comment 33

[Iaroslav Sheptykin]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/22199/diff/2-3/

Comment 34

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

https://reviewboard.mozilla.org/r/22199/#review23897

This looks good, thanks - i think we are nearly finished here.

I see that TelemetryStopwatch is used a bit across browser/ code.
We should run the mochitest-browser tests in browser/ to see whether the changes here break.

Also, lets run the browser with & without those changes and compare a few example TelemetryStopwatch measurements before & after, e.g.:
FX_TAB_SWITCH_UPDATE_MS
FX_NEW_WINDOW_MS
FX_PAGE_LOAD_MS
We should make sure we trigger the ones with object parameters with a few different objects.

If that goes well we can do a try push and prepare for landing :)

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:14
(Diff revision 3)
> -// simpleTimers are directly associated with a histogram
> -// name. objectTimers are associated with an object _and_
> +// Weak map does not allow using null objects as keys. This object is used
> +// when the associated object is not given.

"... These objects are used as 'null' placeholders instead."?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:48
(Diff revision 3)
> -      timers = objectTimers.get(aObj) || {};
> +      return typeof value === "string" && value !== "";

... && value.length > 0;

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:105
(Diff revision 3)
> +    // this._timers.delete(histogram);

Thats a left-over from the previous discussion?

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:302
(Diff revision 3)
> +                     `for Histogram: "${histogram}", key: "${key}"`);

Add the exception here:
, exception: ${Log.exceptionStr(e)}`);

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:321
(Diff revision 3)
> +                     `"${histogram}", using key: "${key}"`);

Ditto on adding the exceptionStr()

::: toolkit/components/telemetry/tests/unit/test_TelemetryStopwatch.js:118
(Diff revision 3)
> +  do_check_true(TelemetryStopwatch.startKeyed(KEYED_HIST.id, KEYED_HIST.key));

Add: 
```
// Starting & finishing a keyed stopwatch for an existing histogram should work.
```

Comment 35

[Iaroslav Sheptykin]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/22199/diff/3-4/

Comment 36

[Iaroslav Sheptykin]

(In reply to Georg Fritzsche [:gfritzsche] from comment #34)

Hi Georg!

Thanks for the detailed review!

> I see that TelemetryStopwatch is used a bit across browser/ code.
> We should run the mochitest-browser tests in browser/ to see whether the
> changes here break.
> 
> Also, lets run the browser with & without those changes and compare a few
> example TelemetryStopwatch measurements before & after, e.g.:
> FX_TAB_SWITCH_UPDATE_MS
> FX_NEW_WINDOW_MS
> FX_PAGE_LOAD_MS
> We should make sure we trigger the ones with object parameters with a few
> different objects.

I built the browser with and without the patch applied and inspected the histograms you pointed to. The actual values look different but in both cases the histograms appear in about:telemetry. I added logging around the invocation of TelemetryStopwatch.start / stop and the new code seems to work fine with browser.js. Running mochitests for /browser didn't show any issues, but lets see what the try server reports. I you don't mind I would push the patch to try.

Comment 37

[Georg Fritzsche [:gfritzsche]]

Thanks for checking - the values are not expected to match, but as long as they look "sane" and we get the right amount values we should be good.
Lets push to try then! :)

Comment 38

[Iaroslav Sheptykin]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1dac73977463

Comment 39

[Iaroslav Sheptykin]

Lots of failed tests but I don't see any relation to our patch.

Comment 40

[Georg Fritzsche [:gfritzsche]]

Those looks unrelated on a quick look - did you have a chance to scan the raw logs for "exception"/"error"/"telemetry" and see if anything stands out?

Comment 41

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

https://reviewboard.mozilla.org/r/22199/#review24447

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:15
(Diff revisions 3 - 4)
> -// Weak map does not allow using null objects as keys. This object is used
> +// Weak map does not allow using null objects as keys. Thse objects are used

"These"

::: toolkit/components/telemetry/TelemetryStopwatch.jsm:109
(Diff revisions 3 - 4)
> +    // More information on this subject:
> +    // objectMap is a WeakMap. WeakMap does not have a size property. Instead,
> +    // it has a property called length, whic seems to always be 0 regardless,
> +    // how many objects the map stores. So, If we want to delete empty,
> +    // objectMaps, we might need to count their objects ourselves or use another
> +    // kind of map here.
> +    // Inability to detect empty objectMaps here will result in this._timers
> +    // never deleting its keys. Once a histogram name is used as key here,
> +    // it will be kept in memory.

Lets change this to:
"WeakMap is not enumerable, so we can't deterministically say when it's empty.
We accept that trade-off here, given that entries for short-lived objects will go away when they are no longer referenced."

Comment 42

[Iaroslav Sheptykin]

Hi Georg!

Thanks for the hint! I digged into the logs of failed tests and found something suspicious:

13:24:23     INFO -  3 INFO TEST-INFO | (browser-test.js) | Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 303}]

in 
http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-1700ef0248f5e8e0aa05d661d481e5f564f14457/try-win64-debug/try_win8_64-debug_test-mochitest-devtools-chrome-4-bm110-tests1-windows-build1734.txt.gz

This comes from https://treeherder.mozilla.org/#/jobs?repo=try&revision=1dac73977463&selectedJob=14341701

As well as:
08:20:24     INFO -  6 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_TOTAL_E10S_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 303}]

from 
https://treeherder.mozilla.org/#/jobs?repo=try&revision=1dac73977463&selectedJob=14341544

I am investigating on this.

Comment 43

[Iaroslav Sheptykin]

Attachment: stopwatch.log

Hi Georg!

I have taken a look on those Error reports. First, I was able to reproduce these issues locally. They all seem to be related to browser.js handling of Tab Progress. I am not if there is something wrong with browser.js, Tab Progress reporting, or xpcshell-testing, but the StopWatch.jsm seems to report the error correctly. Moreover, without applying our patch the error persists. It just does not show up in logs because the current implementation of StopWatch.jsm simply returns false here:

https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/TelemetryStopwatch.jsm#146

After inserting some debug output I could reproduce this problem without applying the patch.

I attached a logfile (with patch applied), which I captured bu running tests locally. I added some debug information and callstacks. As you see this pattern appears: start -> finish, finish:

...

*** DEBUG ***: TelemetryStopwatch.start(FX_PAGE_LOAD_MS, [object XULElement], null)
console.trace:
_emetryStopwatch.jsm 289 this.TelemetryStopwatchImpl.start
_emetryStopwatch.jsm 144 this.TelemetryStopwatch.start
_/content/browser.js 4758 TabsProgressListener.onStateChange
_tent/tabbrowser.xml 501 callListeners
_tent/tabbrowser.xml 522 _callProgressListeners
_tent/tabbrowser.xml 571 mTabProgressListener/<._callProgressListeners
_tent/tabbrowser.xml 727 mTabProgressListener/<.onStateChange
_/content/browser.js 870 _loadURIWithFlags
_tent/tabbrowser.xml 6533 loadURIWithFlags
_indings/browser.xml 119 loadURI
_tent/tabbrowser.xml 3732 loadURI
_tent/tabbrowser.xml 1462 loadTabs
_/content/browser.js 1140 gBrowserInit._delayedStartup

...

*** DEBUG ***: TelemetryStopwatch.finish(FX_PAGE_LOAD_MS, [object XULElement], null)
console.trace:
_emetryStopwatch.jsm 327 this.TelemetryStopwatchImpl.finish
_emetryStopwatch.jsm 200 this.TelemetryStopwatch.finish
_/content/browser.js 4761 TabsProgressListener.onStateChange
_tent/tabbrowser.xml 501 callListeners
_tent/tabbrowser.xml 522 _callProgressListeners
_tent/tabbrowser.xml 571 mTabProgressListener/<._callProgressListeners
_tent/tabbrowser.xml 727 mTabProgressListener/<.onStateChange

...

*** DEBUG ***: TelemetryStopwatch.finish(FX_TAB_SWITCH_UPDATE_MS, undefined, null)
console.trace:
_emetryStopwatch.jsm 327 this.TelemetryStopwatchImpl.finish
_emetryStopwatch.jsm 200 this.TelemetryStopwatch.finish
_tent/tabbrowser.xml 1224 updateCurrentBrowser
_content/browser.xul 1 onselect
_bindings/tabbox.xml 664 set_selectedIndex
_bindings/tabbox.xml 683 set_selectedPanel
_bindings/tabbox.xml 399 set_selectedIndex
_bindings/tabbox.xml 431 set_selectedItem
_bindings/tabbox.xml 110 set_selectedTab
_tent/tabbrowser.xml 2811 set_selectedTab
_tent/tabbrowser.xml 2435 _blurTab
_tent/tabbrowser.xml 2302 _endRemoveTab
_tent/tabbrowser.xml 2144 removeTab
_ent/browser-test.js 291 Tester_waitForWindowsState
_ent/browser-test.js 563 Tester.prototype.nextTest<
_re/modules/Task.jsm 315 TaskImpl_run
_re/modules/Task.jsm 276 TaskImpl
_re/modules/Task.jsm 250 createAsyncFunction/asyncFunction
_ent/browser-test.js 266 Tester_start
_browser-harness.xul 255 createTester/</<

You can explore the log attached yourself. Maybe you can come up with an explanation for that. I did not dig deeper into this matter because it seems irrelevant for our patch. Seems to me that Stopwatch behaves appropriately.

Comment 44

[Iaroslav Sheptykin]

Just noticed that I copied a wrong chunk in comment 43. The last part of the logfile sample should be:

*** DEBUG ***: TelemetryStopwatch.finish(FX_PAGE_LOAD_MS, [object XULElement], null)
console.trace:
_emetryStopwatch.jsm 327 this.TelemetryStopwatchImpl.finish
_emetryStopwatch.jsm 200 this.TelemetryStopwatch.finish
_/content/browser.js 4761 TabsProgressListener.onStateChange
_tent/tabbrowser.xml 501 callListeners
_tent/tabbrowser.xml 522 _callProgressListeners
_tent/tabbrowser.xml 571 mTabProgressListener/<._callProgressListeners
_tent/tabbrowser.xml 727 mTabProgressListener/<.onStateChange
_indings/browser.xml 105 stop
_tent/tabbrowser.xml 3720 stop
_ent/browser-test.js 292 Tester_waitForWindowsState
_ent/browser-test.js 563 Tester.prototype.nextTest<
_re/modules/Task.jsm 315 TaskImpl_run
_re/modules/Task.jsm 276 TaskImpl
_re/modules/Task.jsm 250 createAsyncFunction/asyncFunction
_ent/browser-test.js 266 Tester_start
_browser-harness.xul 255 createTester/</<

Sorry about the confusion.

Comment 45

[Georg Fritzsche [:gfritzsche]]

This sounds like a bug in browser code then, thanks for checking :)
Can you file a bug about this with the details you found and needinfo me there for bringing it up somewhere?

Unless there are other errors standing out it sounds like we are basically good to go here.

Comment 46

[Iaroslav Sheptykin]

Filed Bug 1233004 for the issue with browser.js. Back to checking the logs for other problems.

Comment 47

[Iaroslav Sheptykin]

With e10s enabled we have lots of instances of error reports for FX_TAB_SWITCH_TOTAL_E10S_MS

INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_TOTAL_E10S_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 303}]

These originate in:
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/tabbrowser.xml#3535

And the same issue with "PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS" from:
https://dxr.mozilla.org/mozilla-central/source/toolkit/components/places/UnifiedComplete.js#1332

I checked PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS without our patch and found that the error remains. This is not something we introduce here. I haven't checked FX_TAB_SWITCH... but I believe I will find the same pattern there.

Based on this research I am quite confident that we can ignore the error reports in the logs and carry on with the landing process. I would suggest we resend it to try.

Meanwhile, do you want me to file same bugs for these keys too?

Comment 48

[Georg Fritzsche [:gfritzsche]]

(In reply to Iaroslav Sheptykin from comment #47)
> I checked PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS without our patch and found
> that the error remains. This is not something we introduce here. I haven't
> checked FX_TAB_SWITCH... but I believe I will find the same pattern there.

Could you please confirm this and file bugs for these two (and needinfo me there as well)?
Thanks!

If FX_TAB_SWITCH... looks good too lets get this landed.
It's great that we have wrong stopwatch usage show up as errors now, that should be helpful in catching more bugs.

Comment 49

[Iaroslav Sheptykin]

Just checked FX_TAB_SWITCH_TOTAL_E10S_MS without patch applied. Same thing here:

....
*** ERRROR ***: TelemetryStopwatch.timeElapsed was called for non existing timer: histogram: FX_TAB_SWITCH_TOTAL_E10S_MS
....

This is triggered by:
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/tabbrowser.xml#3535

I could not find any other TelemetryStopwatch related errors.

Comment 50

[Iaroslav Sheptykin]

Failed 2 more bugs:
Bug 1233369 -  UnifiedComplete.js calls TelemetryStopwatch.finish() for PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS twice
Bug 1233368 - tabbroswer.xml calls TelemetryStopwatch.finish() for FX_TAB_SWITCH_TOTAL_E10S_MS twice

Comment 51

[Iaroslav Sheptykin]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/22199/diff/4-5/

Comment 52

[Iaroslav Sheptykin]

Triggered a try job with the updated patch.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=6f451f2b77e5

Comment 53

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8674253 [details]
MozReview Request: Bug 1205898: Making TelemetryStopwatch.jsm handle keyed histograms. r?gfritzsche

https://reviewboard.mozilla.org/r/22199/#review25307

Looks good to me, thanks for the persistence here!

Comment 54

[Iaroslav Sheptykin]

Some tests failed but they look unrelated. I retriggered tests which failed and they turned green. I believe it is safe to check this in.

Comment 55

[Pulsebot]

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

Comment 56

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b7e9324f4c42

Comment 57

[Iaroslav Sheptykin]

New Implementation of TelemetryStopwatch caused performance regression. Bug 1235197 is addressing this issue,