Add Telemetry probes for time to send a ping

RESOLVED FIXED in Firefox 41

Status

()

Toolkit
Telemetry
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: vladan, Assigned: John Kang, Mentored)

Tracking

(Blocks: 1 bug)

Trunk
mozilla41
Points:
---

Firefox Tracking Flags

(firefox41 fixed)

Details

(Whiteboard: [good first bug][lang=js])

Attachments

(1 attachment, 4 obsolete attachments)

(Reporter)

Description

3 years ago
We need to break up the time measured by the existing TELEMETRY_PING probe into two new Telemetry probes:

- Time to stringify the Telemetry object and compress the resulting string
- Time to send the compressed string to the Telemetry servers and get a reply back

Instructions for defining a new probe:

https://developer.mozilla.org/en-US/docs/Mozilla/Performance/Adding_a_new_Telemetry_probe

Code that needs to be modified:

http://hg.mozilla.org/mozilla-central/file/6f35b7d9755a/toolkit/components/telemetry/TelemetryPing.jsm#l610
(Assignee)

Comment 1

3 years ago
Hi, I'd like to take on this bug
(Reporter)

Comment 2

3 years ago
(In reply to John Kang from comment #1)
> Hi, I'd like to take on this bug

Hi John please go ahead. You can post here if you have any questions or you can email me at vdjeric@mozilla.com
(Reporter)

Updated

3 years ago
Assignee: nobody → johnkang.h
(Assignee)

Comment 3

3 years ago
Thanks! Should I work on fx-team or mozilla-central or another code base?
(Reporter)

Comment 4

3 years ago
Either will work, I usually work on mozilla-central
(Assignee)

Comment 5

3 years ago
How does one run the telemetry tests?
(Reporter)

Comment 6

3 years ago
(In reply to John Kang from comment #5)
> How does one run the telemetry tests?

From the top of the source tree: ./mach xpcshell-test toolkit/components/telemetry/tests/

A bit more info here: https://developer.mozilla.org/en-US/docs/Mozilla/QA/Writing_xpcshell-based_unit_tests#Running_unit_tests
(Assignee)

Comment 7

3 years ago
So I've been looking through the code in TelemetryPing.js;

Some questions:

-If we are breaking up the time measured by the existing TELEMETRY_PING probe, are we still keeping the TELEMETRY_PING probe? 
-It looks like the TELEMETRY_PING measures the time in onPingRequestFinished. Would it be appropriate to measure the two new probes in there as well?
-I'm not sure how to stringify the Telemetry object and compress the resulting string. Is compression done with gzipCompressString?
(Reporter)

Comment 8

3 years ago
(In reply to John Kang from comment #7)
> -If we are breaking up the time measured by the existing TELEMETRY_PING
> probe, are we still keeping the TELEMETRY_PING probe? 

Let's keep it for now

> -It looks like the TELEMETRY_PING measures the time in
> onPingRequestFinished. Would it be appropriate to measure the two new probes
> in there as well?

The time to send the ping can still be recorded in onPingRequestFinished, but the time to compress the ping should be recorded in doPing()

> -I'm not sure how to stringify the Telemetry object and compress the
> resulting string. Is compression done with gzipCompressString?

You don't need to stringify & compress the Telemetry object, this is already done at the end of doPing() [with the help of gzipCompressString], you just need to measure how long that takes (and how long sending takes)
(Assignee)

Comment 9

3 years ago
Ah, I see.

TelemetryPing.jsm seems to have disappeared when I pulled in the latest changes and rebuilt. Will it be back soon? I can still see it on the GitHub mirror repo but not on the mercurial repo.
(Reporter)

Comment 10

3 years ago
TelemetryPing.jsm was renamed to TelemetryController.jsm, you can make your changes in TelemetryController.jsm
(Assignee)

Comment 11

3 years ago
Created attachment 8600809 [details] [diff] [review]
telemetry.diff

Hi, am I going in the right direction with this patch?
Attachment #8600809 - Flags: review?(vdjeric)
(Reporter)

Comment 12

3 years ago
Comment on attachment 8600809 [details] [diff] [review]
telemetry.diff

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

Yes, this looks like a good start. Don't forget to add a new histogram for the send time as well

::: toolkit/components/telemetry/TelemetryController.jsm
@@ +861,5 @@
>      let payloadStream = Cc["@mozilla.org/io/string-input-stream;1"]
>                          .createInstance(Ci.nsIStringInputStream);
>      payloadStream.data = this.gzipCompressString(utf8Payload);
>      request.send(payloadStream);
> +    let hcompress = Telemetry.getHistogramById("TELEMETRY_COMPRESS");

End the measurement a line higher, after gzipCompressString
Attachment #8600809 - Flags: review?(vdjeric) → feedback+
(Assignee)

Comment 13

3 years ago
Created attachment 8603815 [details] [diff] [review]
telemetry.diff

Here's the second diff. I'm not sure where to put the probe to measure send time because if I put it in onPingRequestFinished it seems like it would've just measured what TELEMETRY_PING was measuring. Would it be appropriate to put it at the end of doPing in order to measure the time to send the payload at the end?
Attachment #8600809 - Attachment is obsolete: true
Flags: needinfo?(vdjeric)
Blocks: 1121467
Status: NEW → ASSIGNED
OS: Windows 7 → All
Hardware: x86_64 → All
Version: unspecified → Trunk
(Reporter)

Comment 14

3 years ago
Comment on attachment 8603815 [details] [diff] [review]
telemetry.diff

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

::: toolkit/components/telemetry/Histograms.json
@@ +364,5 @@
> +    "kind": "exponential",
> +    "high": "3000",
> +    "n_buckets": 10,
> +    "extended_statistics_ok": true,
> +    "description": "Time taken to compress and stringify telemetry object"

add the time units to the description "... (ms)"

@@ +378,5 @@
> +  "TELEMETRY_SEND" : {
> +    "expires_in_version": "never",
> +    "kind": "exponential",
> +    "high": "3000",
> +    "n_buckets": 10, 

remove the trailing space

@@ +380,5 @@
> +    "kind": "exponential",
> +    "high": "3000",
> +    "n_buckets": 10, 
> +    "extended_statistics_ok": true,
> +    "description": "Time to send the compressed string to the Telemetry servers and get a reply back"

add the time units to the description "... (ms)"

::: toolkit/components/telemetry/TelemetryController.jsm
@@ +763,5 @@
>      let hsuccess = Telemetry.getHistogramById("TELEMETRY_SUCCESS");
>  
>      hsuccess.add(success);
>      hping.add(new Date() - startTime);
> +    hsend.add(new Date() - startTime);

this is the wrong place to accumulate TELEMETRY_SEND

@@ +764,5 @@
>  
>      hsuccess.add(success);
>      hping.add(new Date() - startTime);
> +    hsend.add(new Date() - startTime);
> +    

remove the trailing space

@@ +902,2 @@
>      payloadStream.data = this.gzipCompressString(utf8Payload);
> +    hcompress.add(new Date() - startTime);

We want to time the gzipCompressString function with TELEMETRY_COMPRESS, so the measured time begins right before the call to gzipCompressString and it ends right after the call to gzipCompressString

Btw, you can do this as a one liner: 
Telemetry.getHistogramById("TELEMETRY_COMPRESS").add(new Date() - startTime);

@@ +904,2 @@
>      request.send(payloadStream);
> +    hsend.add(new Date() - startTime);

sending isn't complete here, it starts at request.send() and ends in onPingRequestFinished
(Reporter)

Updated

3 years ago
Flags: needinfo?(vdjeric)
(Assignee)

Comment 15

3 years ago
Created attachment 8605756 [details] [diff] [review]
telemetry.diff

How's this one?
Attachment #8603815 - Attachment is obsolete: true
Attachment #8605756 - Flags: review?(vdjeric)
(Reporter)

Comment 16

3 years ago
Comment on attachment 8605756 [details] [diff] [review]
telemetry.diff

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

Thanks for making the changes, it's almost ready

::: toolkit/components/telemetry/Histograms.json
@@ +364,5 @@
> +    "kind": "exponential",
> +    "high": "3000",
> +    "n_buckets": 10,
> +    "extended_statistics_ok": true,
> +    "description": "Time taken to compress and stringify telemetry object (ms)"

let's track time to stringify in a separate histogram

::: toolkit/components/telemetry/TelemetryController.jsm
@@ +755,5 @@
>      return TelemetryStorage.removeAbortedSessionPing();
>    },
>  
>    onPingRequestFinished: function(success, startTime, ping, isPersisted) {
> +    let hsend = Telemetry.getHistogramById("TELEMETRY_SEND").add(new Date() - startTime);

- you don't need hsend at all, you just need the call to add()
- this is a nitpick, but move the add() next to the other add()s in this function

@@ +892,5 @@
>      let converter = Cc["@mozilla.org/intl/scriptableunicodeconverter"]
>                      .createInstance(Ci.nsIScriptableUnicodeConverter);
>      converter.charset = "UTF-8";
>      let utf8Payload = converter.ConvertFromUnicode(JSON.stringify(networkPayload));
>      utf8Payload += converter.Finish();

can you also add histogram to time how long it takes to stringify the payload and convert it utf8? so start timing before "let utf8Payload = .." and finish after "utf8Payload += converter.Finish()"

@@ +900,2 @@
>      payloadStream.data = this.gzipCompressString(utf8Payload);
> +    let hcompress = Telemetry.getHistogramById("TELEMETRY_COMPRESS").add(new Date() - startTime);

don't need hcompress
Attachment #8605756 - Flags: review?(vdjeric)
(Assignee)

Comment 17

3 years ago
Created attachment 8606548 [details] [diff] [review]
telemetry.diff

Here you go! Please let me know if anything else needs to be done.
Attachment #8605756 - Attachment is obsolete: true
Attachment #8606548 - Flags: review?(vdjeric)
(Reporter)

Updated

3 years ago
Attachment #8606548 - Flags: review?(vdjeric) → review+
(Reporter)

Updated

3 years ago
Keywords: checkin-needed
(Reporter)

Comment 18

3 years ago
Looks good, thank you John
(Assignee)

Comment 19

3 years ago
Thanks! Just to make sure, can the check in be attributed to my GitHub account name jkang8? My last patch was attributed to my real name so my GitHub account didn't get credit for the patch.
(Reporter)

Comment 20

3 years ago
Oh I didn't notice you didn't put author info in the patch. Sure so "user: jkank8 <johnkang.h@gmail.com>"?
Keywords: checkin-needed
(Reporter)

Comment 21

3 years ago
*jkang8
(Assignee)

Comment 22

3 years ago
Yes, thank you!
(Reporter)

Comment 23

3 years ago
Created attachment 8607789 [details] [diff] [review]
johnkang_telemetry.patch
Attachment #8607789 - Flags: review+
(Reporter)

Updated

3 years ago
Attachment #8606548 - Attachment is obsolete: true
(Reporter)

Updated

3 years ago
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/a26875481d37
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
status-firefox41: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla41
You need to log in before you can comment on or make changes to this bug.