Fix #3673, instrument response times in shot creation flow #3727

jaredhirsch · 2017-11-07T00:25:43Z

The metrics docs changes cover the basic overview.

The iframe unhide events seem to fire slightly before the UI is updated, but given how horrifyingly slow some of the steps are (especially full-page previews & downloads), I suspect these start and end points will be good enough for a while.

Easiest way to test this is to filter on 'perf' in the browser console, then run through various shot creation + download/upload flows:

jaredhirsch · 2017-11-07T00:27:09Z

addon/bootstrap.js

  } else if (msg.funcName === "incrementUploadCount") {
    Services.telemetry.scalarAdd('screenshots.upload', 1);
+    sendReply({type: "success", value: true});


The changes in this file are the patch from #3726

jaredhirsch · 2017-11-08T17:11:33Z

It occurred to me in the shower this morning that it might be nicer to keep the times inside the uicontrol state object, rather than overload sendEvent to turn it into a quasi-messaging broker with the internal-only events and separate time tracking. Might be something to fix in a refactoring bug later?

ghost · 2017-11-08T19:13:09Z

This is important to land for our OKR :)

ianb

The matching approach seems reasonable, and I like that it uses our existing events for most moments in time. However, I don't think we should submit these as normal events. Google Analytics has a system specifically for these timings: https://github.com/peaksandpies/universal-analytics#user-timing-tracking

We'd have to reintroduce the server /timing endpoint (it was removed in #3254 – it might have been slightly broken at the time), and then add a sendTiming function instead of overloading sendEvent.

jaredhirsch · 2017-11-09T00:28:57Z

@ianb cool, restored /timing (slightly modified) and updated the addon code accordingly. R?

chenba · 2017-11-09T00:51:07Z

addon/webextension/background/analytics.js

+    let matched = false;
+    filters.forEach(filter => {
+      matched = matched || match(filter, action, label);
+    });


Nitpick: since we are only interested in the first matching filter, we can use array.find() here.

chenba · 2017-11-09T01:07:12Z

server/src/server.js

+      userTimingLabel: bodyObj.timingLabel
+    };
+    userAnalytics.timing(params).send();
+    simpleResponse(res, "OK", 200);


Previously /timing allowed batching. That would make the code on the addon side a little more complicated though. Perhaps keep the completed timing data in one object and the in progress ones in another, so whenever teh in progress list is empty and there are completed timing measurements, send those to /timing?

Yeah, I noticed that too. Since sendEvent fires many more pings, and fires each one individually, it didn't seem worth bothering with the extra state management.

If there's a good reason to batch events in general, maybe we can adjust both endpoints in a followup bug?

I made a followup in #3757

chenba · 2017-11-09T16:05:03Z

👍

ianb

Several comments

ianb · 2017-11-13T20:51:22Z

addon/webextension/background/analytics.js

+    let timingCategory = "addon";
+    let url = main.getBackend() + "/timing";
+    let req = new XMLHttpRequest();
+    req.open("POST", url);


We should probably start using fetch() (though I also keep falling back to XHR too ;)

sure, already filed as #2261

ianb · 2017-11-13T20:53:16Z

addon/webextension/background/analytics.js

+        exc.status = req.status;
+        exc.statusText = req.statusText;
+        console.error(exc);
+        // TODO: send the error to sentry, maybe?


This should reject a promise. Also it should create a promise! Same as sendEvent. I'm not sure how consistently we watch the sendEvent promise, arguably we should have a wrapped version of these functions for the not-uncommon case where we want to send-and-forget (with catcher.watchFunction(sendTiming, true))

ianb · 2017-11-13T20:56:54Z

addon/webextension/selector/ui.js

@@ -446,6 +448,7 @@ this.ui = (function() { // eslint-disable-line no-unused-vars

    unhide() {
      this.element.style.display = "";
+      catcher.watchPromise(callBackground("sendEvent", "internal", "unhide-preview-frame"));


I'm a little concerned that callBackground is going to confound the timing measurements a little. But... eh?

Yeah, the time to send a message seems pretty small, <=10ms (for short messages), and some of these steps take several seconds, so it seemed fine for now.

ianb · 2017-11-13T20:57:37Z

docs/METRICS.md

+
+Internal-only events are used to measure the time from user input to user-visible UI response.
+
+*NOTE: Internal-only events are not submitted to GA.*


Probably these don't even need to be documented, but... well, no harm.

ianb · 2017-11-13T20:59:24Z

docs/METRICS.md

+
+##### First step: starting the shot
+
+1. [x] Time from clicking the page action (or toolbar button) to displaying the preselection iframe, `addon/perf-response-time/page-action` with `cd1: {ms response time}`


I think these need to be adjusted to reflect they aren't events, but timings.

ianb

One note, which you could resolve or not, eh. Otherwise 👍 – want to squash and merge?

ianb · 2017-11-14T17:46:48Z

addon/webextension/background/analytics.js

+      let req = new XMLHttpRequest();
+      req.open("POST", url);
+      req.setRequestHeader("content-type", "application/json");
+      req.onload = catcher.watchFunction(() => {


Technically I don't think this will reject the promise, if there's an exception in the function then the promise will just hang. But it will report something to Sentry.

jaredhirsch commented Nov 7, 2017

View reviewed changes

jaredhirsch force-pushed the shot-creation-response-times branch from a2b7d10 to fc1853f Compare November 7, 2017 19:34

jaredhirsch requested a review from ianb November 8, 2017 17:11

ghost added the perf Performance-related label Nov 8, 2017

ianb suggested changes Nov 8, 2017

View reviewed changes

jaredhirsch requested a review from ianb November 9, 2017 00:29

jaredhirsch added 3 commits November 8, 2017 16:29

Fix #3673, instrument response times in shot creation flow

769748e

Add a /timing route to record performance analytics

efcfcde

Send response timings to the /timing endpoint

f6b29d6

jaredhirsch force-pushed the shot-creation-response-times branch from ecb9877 to f6b29d6 Compare November 9, 2017 00:30

chenba reviewed Nov 9, 2017

View reviewed changes

review feedback

20738a0

ianb mentioned this pull request Nov 13, 2017

Batch events and timings #3757

Closed

ianb suggested changes Nov 13, 2017

View reviewed changes

more review feedback

08bffd5

jaredhirsch requested a review from ianb November 13, 2017 23:59

ianb approved these changes Nov 14, 2017

View reviewed changes

jaredhirsch merged commit 82cb4b7 into master Nov 15, 2017

jaredhirsch deleted the shot-creation-response-times branch November 15, 2017 16:43

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix #3673, instrument response times in shot creation flow #3727

Fix #3673, instrument response times in shot creation flow #3727

jaredhirsch commented Nov 7, 2017

jaredhirsch Nov 7, 2017

jaredhirsch commented Nov 8, 2017

ghost commented Nov 8, 2017

ianb left a comment

jaredhirsch commented Nov 9, 2017

chenba Nov 9, 2017

chenba Nov 9, 2017

jaredhirsch Nov 9, 2017

ianb Nov 13, 2017

chenba commented Nov 9, 2017

ianb left a comment

ianb Nov 13, 2017

jaredhirsch Nov 13, 2017

ianb Nov 13, 2017

ianb Nov 13, 2017

jaredhirsch Nov 13, 2017

ianb Nov 13, 2017

ianb Nov 13, 2017

ianb left a comment

ianb Nov 14, 2017


		Internal-only events are used to measure the time from user input to user-visible UI response.

		NOTE: Internal-only events are not submitted to GA.


		##### First step: starting the shot

		1. [x] Time from clicking the page action (or toolbar button) to displaying the preselection iframe, `addon/perf-response-time/page-action` with `cd1: {ms response time}`

Fix #3673, instrument response times in shot creation flow #3727

Fix #3673, instrument response times in shot creation flow #3727

Conversation

jaredhirsch commented Nov 7, 2017

Choose a reason for hiding this comment

jaredhirsch commented Nov 8, 2017

ghost commented Nov 8, 2017

ianb left a comment

Choose a reason for hiding this comment

jaredhirsch commented Nov 9, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

chenba commented Nov 9, 2017

ianb left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ianb left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment