Last Comment Bug 723561 - Create telemetry stopwatch helper to easily store/retrieve timestamp data
: Create telemetry stopwatch helper to easily store/retrieve timestamp data
Status: RESOLVED FIXED
:
Product: Firefox
Classification: Client Software
Component: General (show other bugs)
: unspecified
: All All
: -- normal (vote)
: Firefox 13
Assigned To: :Felipe Gomes (needinfo me!)
:
Mentors:
Depends on:
Blocks: 671038
  Show dependency treegraph
 
Reported: 2012-02-02 09:02 PST by :Felipe Gomes (needinfo me!)
Modified: 2012-03-04 20:10 PST (History)
6 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
Patch v1 (2.09 KB, patch)
2012-02-02 09:09 PST, :Felipe Gomes (needinfo me!)
gavin.sharp: feedback+
dao+bmo: feedback+
Details | Diff | Splinter Review
Patch v2 (10.30 KB, patch)
2012-02-07 10:02 PST, :Felipe Gomes (needinfo me!)
gavin.sharp: review+
Details | Diff | Splinter Review
Patch v3 (9.14 KB, patch)
2012-02-08 14:09 PST, :Felipe Gomes (needinfo me!)
felipc: review+
Details | Diff | Splinter Review
Follow-up: display key name on error (863 bytes, patch)
2012-02-29 22:27 PST, :Felipe Gomes (needinfo me!)
gavin.sharp: review+
Details | Diff | Splinter Review

Description :Felipe Gomes (needinfo me!) 2012-02-02 09:02:52 PST
For various telemetry probes that we want to add at the front end, we have to store timestamp data in order to calculate duration of events that we want to measure (e.g. "how long did it take to do X..")

To do that, we will end up sticking these values in private variables all over the place. Also, in many situations, the beginning and ending of these measurements are at disjoint places, for example the start could be inside a function call and the end inside an event listener fired at a different element. So it becomes tricky and cumbersome to retrieve the start data again.

I suggest that we create a lightweight .jsm that can be easily reached and that will store everything in a single location
Comment 1 :Felipe Gomes (needinfo me!) 2012-02-02 09:09:40 PST
Created attachment 593871 [details] [diff] [review]
Patch v1

Gavin, Dão, what do you think about this? I described the use case in comment 0.
I thought about adding this to "TelemetryTimestamps" since the name matches it perfectly, but Gavin said that module has a more specific purpose, so I decided to create another one.

This current patch uses strings as the keys. Maybe in the future for some cases it'd make more sense to also support a WeakMap mode.

The purpose of the lap function is to generate a stamp without removing the starting point, for cases where two measurements might have the same start point. E.g.:
- start: click on new tab button
- measurement 1: how long does it take for the tab animation to finish
- measurement 2: how long does it take to paint the about:newtab page
Comment 2 Dão Gottwald [:dao] 2012-02-02 09:18:32 PST
Comment on attachment 593871 [details] [diff] [review]
Patch v1

>+  _timestamps: {},

This could be a variable rather than a property of the exported object.

>+  lap: function(aKey, aHistogram) {

It took me some time to understand how to read "lap" here. I expected it to be an abbreviation...

>+  has: function(aKey) {
>+    return aKey in this._timestamps;
>+  },
>+
>+  get: function(aKey) {
>+    return this._timestamps[aKey];
>+  }

Are these methods needed?
Comment 3 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-02-02 09:24:18 PST
Comment on attachment 593871 [details] [diff] [review]
Patch v1

This is a good idea.

_timeStamps can be a local variable within the module to avoid exposing it (I did that for telemetryTimestamps in bug 723181).

The error in start() should probably just say "foo is already started" rather than "Race condition", and I'm not sure it makes sense to delete the existing value.

"lap" seems like a misleading term to use, but maybe it makes sense in a stopWatch context. Or maybe "checkpoint"?

dietrich would tell you that you can just use (new Date()) instead of Date.now() :)

"has" should probably use hasOwnProperty rather than "in".

get() for TelemetryTimestamps returns a copy of the object, you might consider doing that here too.

I'm not sure I understand why has/get are useful, what are the use cases?
Comment 4 Marco Bonardo [::mak] 2012-02-02 09:28:40 PST
Comment on attachment 593871 [details] [diff] [review]
Patch v1

Review of attachment 593871 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/modules/TelemetryStopwatch.jsm
@@ +2,5 @@
> + * License, v. 2.0. If a copy of the MPL was not distributed with this file,
> + * You can obtain one at http://mozilla.org/MPL/2.0/. */
> +
> +const Cc = Components.classes;
> +const Ci = Components.itnerfaces;

this is likely not working
Comment 5 Dão Gottwald [:dao] 2012-02-02 10:23:58 PST
Comment on attachment 593871 [details] [diff] [review]
Patch v1

(In reply to Gavin Sharp (use gavin@gavinsharp.com for email) from comment #3)
> dietrich would tell you that you can just use (new Date()) instead of
> Date.now() :)

This isn't really simpler and there's no point in carrying the Date object around...
Comment 6 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-02-02 11:34:27 PST
Yes, I agree - the claim that was made was that it's somehow faster. That doesn't make much sense to me, but either way it probably doesn't matter in practice. I think we should continue to use Date.now() to get timestamps.
Comment 7 :Felipe Gomes (needinfo me!) 2012-02-07 10:02:47 PST
Created attachment 595073 [details] [diff] [review]
Patch v2

I significantly modified the module after using it in practice while writing some telemetry probes. It should be more useful now. It has two functions only, start and finish.

A timer can be directly associated with a telemetry histogram, or with a pair of a histogram and an object. This makes it possible to measure more than 1 timer for the same histogram. An example would be SS restore time, which then you associated it with the pair histogram+tab, and is way less error prone (helps avoid measuring unpaired finish/start times)

I removed the "lap" function from the previous iteration since it's not useful in practice. Given that the order that two events might happen can be unknown, you'd never be able to know when to |lap| and when to |finish| the timer.

The rationale about removing a timer if it's started twice is to also fail the finish function in that case. Starting it twice should never happen, but if it does, the chance of measuring an unpaired finish/start is high, so it's better to submit no data rather than wrong data.

Should be ready for review. Comments and tests are included.

One thing I was discussing with Marco is that there's nothing browser-specific in this module, so we were wondering if we should perhaps add it to toolkit to make it more useful? On the other hand, do you think we might want to add browser-speficic features for it in the future?
Comment 8 Dietrich Ayala (:dietrich) 2012-02-07 11:35:05 PST
(In reply to Gavin Sharp (use gavin@gavinsharp.com for email) from comment #3)
> dietrich would tell you that you can just use (new Date()) instead of
> Date.now() :)

Heh, I was told that in a review by Taras, who said he was told that by Brendan. Telephone!

Marco measured it, and found that new Date() is faster for instance creation, but that diffing two of those is slower than diffing two of Date.now().
Comment 9 Dietrich Ayala (:dietrich) 2012-02-07 11:37:39 PST
(In reply to Dietrich Ayala (:dietrich) from comment #8)
> Heh, I was told that in a review by Taras, who said he was told that by
> Brendan. Telephone!

Was told that new Date() was faster, that is.
Comment 10 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-02-07 18:14:21 PST
Comment on attachment 595073 [details] [diff] [review]
Patch v2

>diff --git a/browser/modules/TelemetryStopwatch.jsm b/browser/modules/TelemetryStopwatch.jsm

>+    let timers = aObj
>+                 ? stampsMap.get(aObj, {})

Looks like you forgot to update "stampsMap" after renaming it (or forgot to qref!)

>diff --git a/browser/modules/test/test_TelemetryStopwatch.js b/browser/modules/test/test_TelemetryStopwatch.js

>+function run_test() {

>+  try {
>+    do_check_true(TelemetryStopwatch.start("NON-EXISTENT_HISTOGRAM"));

>+  try {
>+    do_check_true(TelemetryStopwatch.start("NON-EXISTENT_HISTOGRAM", refObj));

Can't these checks be outside the try?

>+function finishTest() {

>+  histogram = Telemetry.getHistogramById(HIST_NAME);

Looks like this should be HIST_NAME2?

Which consumers do you have lined up for this module?
Comment 11 Marco Bonardo [::mak] 2012-02-08 00:35:50 PST
This is likely useful for toolkit components, I would use in Places for example, and I'm pretty sure other modules may make good use of it. So should really move to toolkit/components/telemetry otherwise they won't be able to use it.
Comment 12 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-02-08 11:37:35 PST
Putting it in toolkit/content sounds good to me.
Comment 13 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-02-08 11:50:10 PST
toolkit/components/telemetry - even better!
Comment 14 :Felipe Gomes (needinfo me!) 2012-02-08 14:09:55 PST
Created attachment 595529 [details] [diff] [review]
Patch v3

You're right, I had forgotten to qref! There's one other small change after the qref. I had update the validTypes check from:

   (!aObj || typeof aObj == "object");
to
   (aObj === undefined || typeof aObj == "object");

so that validTypes("", "") is false


I now moved it from browser to toolkit/components/telemetry. Do I need to get a new review due to that? Maybe from mak?
Comment 15 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-02-08 14:10:52 PST
No, you don't need another review.
Comment 16 :Felipe Gomes (needinfo me!) 2012-02-08 14:37:59 PST
https://hg.mozilla.org/integration/mozilla-inbound/rev/2ca8d6ac63bc
Comment 17 Ed Morley [:emorley] 2012-02-09 10:25:42 PST
https://hg.mozilla.org/mozilla-central/rev/2ca8d6ac63bc
Comment 18 Mark Côté [:mcote] 2012-02-27 07:54:10 PST
In peptest logs, I am seeing this error at least a couple times per test:

PEP WARNING    | MOZMILL fail {"message":"[JavaScript Error: \"TelemetryStopwatch: key was already initialized\" {file: \"resource:///modules/TelemetryStopwatch.jsm\" line: 52}]"}

Peptest is not doing anything specifically with telemetry.  I'm not sure what's going on here.
Comment 19 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-02-29 18:35:20 PST
Mark: I'm not familiar with what the peptest workload is. The only TelemetryStopwatch user at the moment is sessionstore. Does peptest interact with sessionstore in any way? Can I run peptest myself to debug?
Comment 20 :Felipe Gomes (needinfo me!) 2012-02-29 19:28:03 PST
So hmm I guess we should add the key name in the error message to make it easier to debug future occurrences of key re-use.
Comment 21 Mark Côté [:mcote] 2012-02-29 21:59:37 PST
To my knowledge peptest is not doing anything with sessionstore. You can run it via 'make peptest' in your obj dir.
Comment 22 :Felipe Gomes (needinfo me!) 2012-02-29 22:27:21 PST
Created attachment 601877 [details] [diff] [review]
Follow-up: display key name on error

Mark: does peptest run xpcshell-tests? The TelemetryStopwatch xpcshell test cause this exception to be logged.
Please use this patch to see what's the key that is triggering this error
Comment 23 :Felipe Gomes (needinfo me!) 2012-02-29 22:34:47 PST
http://hg.mozilla.org/integration/mozilla-inbound/rev/ca22be33f6b8
Comment 24 Marco Bonardo [::mak] 2012-03-01 06:32:30 PST
https://hg.mozilla.org/mozilla-central/rev/ca22be33f6b8
Comment 25 Mark Côté [:mcote] 2012-03-01 13:08:17 PST
No, no xpcshell tests. Here's the new error:

PEP WARNING    | MOZMILL fail {"message":"[JavaScript Error: \"TelemetryStopwatch: key \"FX_SESSION_RESTORE_COLLECT_DATA_MS\" was already initialized\" {file: \"resource:///modules/TelemetryStopwatch.jsm\" line: 53}]"}
Comment 26 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-03-04 18:26:45 PST
Looks like a valid bug - saveState can return early without finish()ing FX_SESSION_RESTORE_COLLECT_DATA_MS.

Mark: can you file a new bug about that? In Firefox::Session Restore, CC me/felipe/zpao.
Comment 27 Mark Côté [:mcote] 2012-03-04 20:10:33 PST
Filed as bug 732874.

Note You need to log in before you can comment on or make changes to this bug.