New: Emit preview metric messages #648

JustinHoldstock · 2018-02-09T00:46:56Z

The intention of this PR is to

Provide setup for emitting preview_metric events
Emit a preview_metric event with load related metrics

How to use

Timer Mechanism
To begin timing the load events, we call Timer.start(tag), the tag being a unique tag for that event. I've been using the name of the event, paired with the file id of the file we're tracking. ie) Timer.start('file_info_time_1234545')

To stop a timer, to get an accurate reading of how long it took, call Timer.stop(tag) with the same tag. ie) Timer.stop('file_info_time_1234545')

To get timer values, call Timer.get(tag), and you'll receive an object with start, end, and elapsed values. If the tag has been started and not stopped, no end or elapsed will exist. If you've never started the tag, then you will receive either an object with undefined values OR undefined.

I've been using Timer.start() either right before a GET is made on the URL, or right before the function call that does so. I've been using Timer.stop() when the asset is received, parsed, and usable. IE) For full_document_load_time and DocBaseViewer, I start when we get the PDF loading task (in initViewer()) and I stop inside of finishLoading(), (in Preview.), when we emit 'load'.

Finally, on Preview.destroy() or Preview.finishLoading() (guarantees we log either when the document loads or errored out along the way), we emit the message with the relevant props.

Relies of PR #619

…ew into Emit-preview_error-messsages

boxcla · 2018-02-09T00:46:58Z

Verified that @JustinHoldstock has signed the CLA. Thanks for the pull request!

JustinHoldstock · 2018-02-09T00:47:24Z

Note that this is unfinished. I want to get some eyes on it before I continue

tonyjin · 2018-02-09T01:00:09Z

src/lib/Preview.js

+     * @param {Error} error - The error that occurred.
+     * @return {void}
+     */
+    logPreviewError(error) {


Maybe different names to differentiate from logPreviewEvent() since this isn't actually logging anything while the other function is actually making a log call?

I'll rename both to emitPreviewError() and emitLoadMetric()

tonyjin · 2018-02-09T01:12:52Z

src/lib/Preview.js

@@ -867,6 +888,8 @@ class Preview extends EventEmitter {
        const { apiHost, queryParams } = this.options;
        const fileVersionId = this.getFileOption(this.file.id, FILE_OPTION_FILE_VERSION_ID) || '';

+        Timer.start(`${LOAD_METRIC.fileInfoTime}_${this.file.id}`);


Let's use file_${this.file.id}_XXX since we're using file_${this.file.id} for the internal file object key. We probably don't need to worry about file versions for now but this will disambiguate if we choose to do so in the future.

tonyjin · 2018-02-09T01:13:38Z

src/lib/Preview.js

+
+        const event = {
+            event_name: 'preview_load',
+            value: total, // Sum of all available load times.


Have you tested whether this value matches the legacy total_load_time?

From the handful of tests I've run, this total is closer to Chrome's Network tab

tonyjin · 2018-02-09T01:16:59Z

src/lib/RepStatus.js

@@ -80,6 +83,8 @@ class RepStatus extends EventEmitter {
            return Promise.resolve();
        }

+        // Using content.url_template to guarantee uniqueness
+        Timer.start(`${LOAD_METRIC.convertTime}_${this.representation.content.url_template}`);


This is going to get started multiple times since when we hit pending as a status, we call this function again.

Also, we don't really need to key on the url template right? We just care about 'How long did this file spend converting'. Doesn't matter which representation (or does it?)

I've made it so start only starts the timer once. I'm now extracting the file id from the template URL, for a similar tag name to the rest

tonyjin · 2018-02-09T01:17:13Z

src/lib/Timer.js

+        Object.keys(this.times).forEach((key) => {
+            delete this.times[key];
+        });
+    }


JSDoc when you get a chance :)

tonyjin · 2018-02-09T01:18:39Z

src/lib/Preview.js

+
+        // Do nothing if there is nothing worth logging.
+        const infoTime = Timer.get(`${LOAD_METRIC.fileInfoTime}_${this.file.id}`) || {};
+        if (!infoTime.elapsed) {


Could elapsed be 0 here? e.g. if something is already cached we don't spend any time fetching file info?

If file info is in the cache already, will the representation asset that it belongs to be loaded into browser cache? If that's the case, we don't want to log how fast the browser can load things from cache

DanDeMicco · 2018-02-09T01:40:55Z

src/lib/Preview.js

@@ -163,6 +166,13 @@ class Preview extends EventEmitter {
        this.navigateLeft = this.navigateLeft.bind(this);
        this.navigateRight = this.navigateRight.bind(this);
        this.keydownHandler = this.keydownHandler.bind(this);
+
+        this.on(PREVIEW_ERROR, (msg) => {


Arrow function is unnecessary here

This section is for debugging purposes only

jeremypress · 2018-02-09T01:56:18Z

src/lib/Preview.js

@@ -163,6 +166,13 @@ class Preview extends EventEmitter {
        this.navigateLeft = this.navigateLeft.bind(this);
        this.navigateRight = this.navigateRight.bind(this);
        this.keydownHandler = this.keydownHandler.bind(this);
+
+        this.on(PREVIEW_ERROR, (msg) => {


Does this mean we need to remove the console.error from everywhere else in the code base?

This section is for debugging purposes only

jeremypress · 2018-02-09T01:56:32Z

src/lib/Preview.js

+            console.error(msg);
+        });
+        this.on(PREVIEW_METRIC, (msg) => {
+            console.log(msg);


Do we always want to log these?

This section is for debugging purposes only, but yes, we will always want to log PREVIEW_METRICs

jeremypress · 2018-02-09T01:58:56Z

src/lib/viewers/BaseViewer.js

@@ -260,6 +262,16 @@ class BaseViewer extends EventEmitter {
        }, this.loadTimeout);
    }

+    /**
+     * Start the laod timer for fullDocumentLoad event.


DanDeMicco · 2018-02-09T02:34:41Z

src/lib/Timer.js

+    }
+
+    reset() {
+        Object.keys(this.times).forEach((key) => {


Could you just set it back to {}?

Would there ever be a case that you would want to reset only a single timer?

I've decided to just reset the values in the struct to undefined. Also added case to target a single timer.

DanDeMicco · 2018-02-09T02:42:06Z

src/lib/__tests__/Preview-test.js

+            expect(log.timestamp).to.exist;
+            expect(log.file_id).to.equal(id);
+            expect(log.file_version_id).to.exist;
+            expect(log.content_type).to.exsit;


I want to know why these tests passed, locally, if this was here :O

jeremypress · 2018-02-09T17:04:51Z

src/lib/Preview.js

+     * @private
+     * @return {Object} Log details for viewer session and current file.
+     */
+    createLog() {


to follow Tony's comment below, maybe this becomes createEvent?

createLogEvent()? Since it contains relevant logging values?

jeremypress · 2018-02-09T17:05:50Z

src/lib/Preview.js

+     * @private
+     * @return {void}
+     */
+    logLoadMetrics() {


this and the above function both actually emit as opposed to log. How do you feel about emitLoadMetrics and emitPreviewError instead?

See above response to Tony's comment. It's exactly that :)

jeremypress · 2018-02-09T17:19:25Z

src/lib/Preview.js

+            error: err,
+            ...this.createLog()
+        };
+


We could move all of our console.errors here whenever we call logPreview error (or maybe in triggerError), to reduce console.error clutter.

jeremypress · 2018-02-09T17:21:16Z

src/lib/viewers/media/MediaBaseViewer.js

@@ -129,6 +129,7 @@ class MediaBaseViewer extends BaseViewer {
        return this.getRepStatus()
            .getPromise()
            .then(() => {
+                this.startLoadTimer();


Could we move the startLoadTimer to a part of the promise chain in RepStatus.js? We could then it over there once and avoid doing it everywhere else. Basically if the repstatus is success then we want to start timing the content load.

This is not meant to track time for RepStatus. This begins the timer for when we setup and send the GET request for the representation. Inside of RepStatus, you'll see a timer related to representation conversion time

Right, but since we want to track from once rep status comes back to success until the file is done loading, why not append to the end of rep status so we only have to add it in one place?

Oh, I see, I misunderstood your Q. We don't want to do that because we don't want to include the time to process the JS between the rep coming back and then making the request for the rep. We ONLY want to be tracking network related times, for that metric.

…ew into Emit-preview_metric-messages

pramodsum

Some tiny nit-picky things but this is AWESOME 🎉

pramodsum · 2018-02-10T01:31:40Z

src/lib/Preview.js

@@ -882,6 +899,9 @@ class Preview extends EventEmitter {
     */
    handleFileInfoResponse(response) {
        let file = response;
+        // Stop timer for file info time event.


pramodsum · 2018-02-10T01:36:56Z

src/lib/Preview.js

@@ -1096,7 +1128,6 @@ class Preview extends EventEmitter {
        } else {
            // Bump up preview count
            this.count.success += 1;
-


leave this newline

pramodsum · 2018-02-10T01:38:18Z

src/lib/Preview.js

@@ -1195,12 +1226,15 @@ class Preview extends EventEmitter {

        // Check if hit the retry limit
        if (this.retryCount > RETRY_COUNT) {
+            let errorCode = ERROR_CODE.retriesExceeded;
            let errorMessage = __('error_refresh');
            if (err.response && err.response.status === 429) {


pramodsum · 2018-02-12T06:42:51Z

src/lib/Preview.js

+     */
+    emitPreviewError(error) {
+        const err = error;
+        // If we haven't supplied a code, then it was thrown by the browser


newline before comments

pramodsum · 2018-02-12T06:45:38Z

src/lib/Timer.js

+     */
+    stop(tag) {
+        const time = this.get(tag);
+        // The timer has already been stopped, or hasn't started. Don't stop it again.


pramodsum · 2018-02-12T06:46:28Z

src/lib/Timer.js

+    reset(tag) {
+        if (tag) {
+            const time = this.get(tag);
+            // We don't need to clean up nothin'


newline and maybe cleanup the comment :P

pramodsum · 2018-02-12T06:47:02Z

src/lib/Timer.js

+            time.end = undefined;
+            time.elapsed = undefined;
+        } else {
+            Object.keys(this.times).forEach((timeTag) => {


Object.keys(this.times).forEach(this.reset);

pramodsum · 2018-02-12T06:48:41Z

src/lib/viewers/BaseViewer.js

-        /* global BoxAnnotations */
-        const boxAnnotations = this.options.boxAnnotations || new BoxAnnotations(viewerOptions);
+        if (!global.BoxAnnotations) {
+            const error = createPreviewError(ERROR_CODE.annotationsLoadFail);


…ew into Emit-preview_metric-messages

Justin Holdstock added 13 commits January 31, 2018 15:44

New: Log preview_error message from Preview

28c1cc2

Chore: Docs for ERROR_CODE

4fa127c

Chore: Strip auth from message and displayMessage

f8d7960

Chore: use .code for error code. Extracted util methods

5bffa55

Merge branch 'master' of github.com:JustinHoldstock/box-content-previ…

d8e7a3f

…ew into Emit-preview_error-messsages

Merge branch 'master' of github.com:JustinHoldstock/box-content-previ…

7464a4a

…ew into Emit-preview_error-messsages

Chore: tests for logPreviewError, createLog

f9463c5

Chore: update and added new tests

5a299f1

Merge branch 'master' of github.com:JustinHoldstock/box-content-previ…

73cb72a

…ew into Emit-preview_error-messsages

Chore: empty case for error event. safety check before token strip

6236dc5

Chore: Removed debug statement

0394df8

Merge branch 'master' of github.com:JustinHoldstock/box-content-previ…

82c4e0a

…ew into Emit-preview_error-messsages

New: Emit preview_metric event for load metrics

08ca3f7

tonyjin reviewed Feb 9, 2018

View reviewed changes

tonyjin requested review from DanDeMicco, jeremypress and pramodsum February 9, 2018 01:36

DanDeMicco reviewed Feb 9, 2018

View reviewed changes

jeremypress reviewed Feb 9, 2018

View reviewed changes

DanDeMicco reviewed Feb 9, 2018

View reviewed changes

Justin Holdstock added 3 commits February 8, 2018 21:25

Chore: more accurate reporting. More work to be done

8edc134

Chore: Docs for Timer and typo

e451e05

Chore: Create utility for tag creation, follows format

37ad931

jeremypress reviewed Feb 9, 2018

View reviewed changes

Justin Holdstock added 3 commits February 9, 2018 14:04

Chore: Typos, feedback, and adding more start timers for load

769fb38

Chore: Tests update for Preview

360fde0

Chore: RepStatus and Preview tests

d9eb1b7

Justin Holdstock added 4 commits February 9, 2018 17:17

Chore: Timer tests

7b29ecf

Chore: remaining tests

04a1de9

Chore: Fix flakey emitLoadMetrics() tests

94ad93f

Merge branch 'master' of github.com:JustinHoldstock/box-content-previ…

4f013ce

…ew into Emit-preview_metric-messages

pramodsum approved these changes Feb 12, 2018

View reviewed changes

Justin Holdstock added 4 commits February 12, 2018 13:26

Chore: Newlines

d91484d

Merge branch 'master' of github.com:JustinHoldstock/box-content-previ…

4ac2f85

…ew into Emit-preview_metric-messages

Chore: missed one

be53b3f

Merge branch 'master' of github.com:JustinHoldstock/box-content-previ…

e3cc54e

…ew into Emit-preview_metric-messages

JustinHoldstock merged commit d5606d1 into box:master Feb 13, 2018

New: Emit preview metric messages #648

New: Emit preview metric messages #648

Conversation

JustinHoldstock commented Feb 9, 2018 • edited Loading

How to use

boxcla commented Feb 9, 2018

JustinHoldstock commented Feb 9, 2018

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

JustinHoldstock Feb 9, 2018 • edited Loading

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

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

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

JustinHoldstock Feb 9, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pramodsum 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

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

JustinHoldstock commented Feb 9, 2018 •

edited

Loading

JustinHoldstock Feb 9, 2018 •

edited

Loading

JustinHoldstock Feb 9, 2018 •

edited

Loading