1155272 - Add Telemetry probes for time to send a ping

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Vladan Djeric (:vladan)]

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

Comment 1

[John Kang]

Hi, I'd like to take on this bug

Comment 2

[Vladan Djeric (:vladan)]

(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 [e-mail]

Comment 3

[John Kang]

Thanks! Should I work on fx-team or mozilla-central or another code base?

Comment 4

[Vladan Djeric (:vladan)]

Either will work, I usually work on mozilla-central

Comment 5

[John Kang]

How does one run the telemetry tests?

Comment 6

[Vladan Djeric (:vladan)]

(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

Comment 7

[John Kang]

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?

Comment 8

[Vladan Djeric (:vladan)]

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

Comment 9

[John Kang]

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.

Comment 10

[Vladan Djeric (:vladan)]

TelemetryPing.jsm was renamed to TelemetryController.jsm, you can make your changes in TelemetryController.jsm

Comment 11

[John Kang]

Attachment: telemetry.diff

Hi, am I going in the right direction with this patch?

Comment 12

[Vladan Djeric (:vladan)]

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

Comment 13

[John Kang]

Attachment: 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?

Comment 14

[Vladan Djeric (:vladan)]

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

Comment 15

[John Kang]

Attachment: telemetry.diff

How's this one?

Comment 16

[Vladan Djeric (:vladan)]

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

Comment 17

[John Kang]

Attachment: telemetry.diff

Here you go! Please let me know if anything else needs to be done.

Comment 18

[Vladan Djeric (:vladan)]

Looks good, thank you John

Comment 19

[John Kang]

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.

Comment 20

[Vladan Djeric (:vladan)]

Oh I didn't notice you didn't put author info in the patch. Sure so "user: jkank8 <[e-mail]>"?

Comment 21

[Vladan Djeric (:vladan)]

*jkang8

Comment 22

[John Kang]

Yes, thank you!

Comment 23

[Vladan Djeric (:vladan)]

Attachment: johnkang_telemetry.patch

Comment 24

[Pulsebot]

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

Comment 25

[Carsten Book [:Tomcat]]

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