Skip to content

Commit

Permalink
Chore(metrics): add new timer for full preview load time tracking (#922)
Browse files Browse the repository at this point in the history
  • Loading branch information
@JustinHoldstock
JustinHoldstock authored Feb 12, 2019
1 parent 9256dcc commit 7da1899
Show file tree
Hide file tree
Showing 5 changed files with 56 additions and 63 deletions.
46 changes: 26 additions & 20 deletions src/lib/Preview.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -753,6 +753,10 @@ class Preview extends EventEmitter {
);
}

// Start the preview duration timer when the user starts to perceive preview's load
const tag = Timer.createTag(this.file.id, LOAD_METRIC.previewLoadTime);
Timer.start(tag);

// If file version ID is specified, increment retry count if it matches current file version ID
if (fileVersionId) {
if (fileVersionId === currentFileVersionId) {
Expand Down Expand Up @@ -1245,8 +1249,10 @@ class Preview extends EventEmitter {
*/
finishLoading(data = {}) {
if (this.file && this.file.id) {
const tag = Timer.createTag(this.file.id, LOAD_METRIC.fullDocumentLoadTime);
Timer.stop(tag);
const contentLoadTag = Timer.createTag(this.file.id, LOAD_METRIC.contentLoadTime);
Timer.stop(contentLoadTag);
const previewLoadTag = Timer.createTag(this.file.id, LOAD_METRIC.previewLoadTime);
Timer.stop(previewLoadTag);
}

// Log now that loading is finished
Expand Down Expand Up @@ -1530,34 +1536,34 @@ class Preview extends EventEmitter {
return;
}

const infoTag = Timer.createTag(this.file.id, LOAD_METRIC.fileInfoTime);
const convertTag = Timer.createTag(this.file.id, LOAD_METRIC.convertTime);
const downloadTag = Timer.createTag(this.file.id, LOAD_METRIC.downloadResponseTime);
const fullLoadTag = Timer.createTag(this.file.id, LOAD_METRIC.fullDocumentLoadTime);
const { id } = this.file;

const infoTag = Timer.createTag(id, LOAD_METRIC.fileInfoTime);
const convertTag = Timer.createTag(id, LOAD_METRIC.convertTime);
const downloadTag = Timer.createTag(id, LOAD_METRIC.downloadResponseTime);
const contentLoadTag = Timer.createTag(id, LOAD_METRIC.contentLoadTime);
const previewLoadTag = Timer.createTag(id, LOAD_METRIC.previewLoadTime);

const timerList = [
Timer.get(infoTag) || {},
Timer.get(convertTag) || {},
Timer.get(downloadTag) || {},
Timer.get(fullLoadTag) || {}
];
const times = timerList.map((timer) => parseInt(timer.elapsed, 10) || 0);
const total = times.reduce((acc, current) => acc + current);
const infoTime = Timer.get(infoTag) || {};
const convertTime = Timer.get(convertTag) || {};
const downloadTime = Timer.get(downloadTag) || {};
const contentLoadTime = Timer.get(contentLoadTag) || {};
const previewLoadTime = Timer.get(previewLoadTag) || {};

const event = {
encoding,
event_name: LOAD_METRIC.previewLoadEvent,
value: total, // Sum of all available load times.
[LOAD_METRIC.fileInfoTime]: times[0],
[LOAD_METRIC.convertTime]: times[1],
[LOAD_METRIC.downloadResponseTime]: times[2],
[LOAD_METRIC.fullDocumentLoadTime]: times[3],
value: previewLoadTime.elapsed || 0,
[LOAD_METRIC.fileInfoTime]: infoTime.elapsed || 0,
[LOAD_METRIC.convertTime]: convertTime.elapsed || 0,
[LOAD_METRIC.downloadResponseTime]: downloadTime.elapsed || 0,
[LOAD_METRIC.contentLoadTime]: contentLoadTime.elapsed || 0,
...this.createLogEvent()
};

this.emit(PREVIEW_METRIC, event);

Timer.reset([infoTag, convertTag, downloadTag, fullLoadTag]);
Timer.reset([infoTag, convertTag, downloadTag, contentLoadTag, previewLoadTag]);
}

/**
Expand Down
60 changes: 23 additions & 37 deletions src/lib/__tests__/Preview-test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1061,6 +1061,18 @@ describe('lib/Preview', () => {
);
});

it('should start a timer for the total preview load time, for the file', () => {
const id = 'my_file_id';
const tag = Timer.createTag(id, LOAD_METRIC.previewLoadTime);

preview.load({ id });

const timer = Timer.get(tag);

expect(timer).to.exist;
expect(timer.start).to.exist;
});

it('should get the tokens when file id is available', () => {
preview.previewOptions.token = 'token';

Expand Down Expand Up @@ -1951,7 +1963,15 @@ describe('lib/Preview', () => {

it('should stop the timer for full document load if a file exists', () => {
preview.file.id = 1234;
const expectedTag = Timer.createTag(preview.file.id, LOAD_METRIC.fullDocumentLoadTime);
const expectedTag = Timer.createTag(preview.file.id, LOAD_METRIC.contentLoadTime);
sandbox.stub(Timer, 'stop');
preview.finishLoading();
expect(Timer.stop).to.be.calledWith(expectedTag);
});

it('should stop the timer for preview load if a file exists', () => {
preview.file.id = 1234;
const expectedTag = Timer.createTag(preview.file.id, LOAD_METRIC.previewLoadTime);
sandbox.stub(Timer, 'stop');
preview.finishLoading();
expect(Timer.stop).to.be.calledWith(expectedTag);
Expand Down Expand Up @@ -2299,17 +2319,11 @@ describe('lib/Preview', () => {

describe('emitLoadMetrics()', () => {
const fileId = 123456;
const fileInfoTag = Timer.createTag(fileId, LOAD_METRIC.fileInfoTime);

beforeEach(() => {
preview.file = {
id: fileId
};

// Make sure the first milestone (fileInfoTime) has been met
Timer.start(fileInfoTag);
Timer.stop(fileInfoTag);
Timer.get(fileInfoTag).elapsed = 20;
});

afterEach(() => {
Expand Down Expand Up @@ -2340,29 +2354,13 @@ describe('lib/Preview', () => {
preview.emitLoadMetrics();
});

it('should emit a preview_metric event where the value property equals the sum of all load events', (done) => {
const tag = Timer.createTag(preview.file.id, LOAD_METRIC.fullDocumentLoadTime);
Timer.start(tag);
Timer.stop(tag);

Timer.get(tag).elapsed = 10;
Timer.get(fileInfoTag).elapsed = 20;

const expectedTime = 30; // 10ms + 20ms

preview.once(PREVIEW_METRIC, (metric) => {
expect(metric.value).to.equal(expectedTime);
done();
});
preview.emitLoadMetrics();
});

it('should emit a preview_metric event with an object, with all of the proper load properties', (done) => {
preview.once(PREVIEW_METRIC, (metric) => {
expect(metric[LOAD_METRIC.fileInfoTime]).to.exist;
expect(metric[LOAD_METRIC.convertTime]).to.exist;
expect(metric[LOAD_METRIC.downloadResponseTime]).to.exist;
expect(metric[LOAD_METRIC.fullDocumentLoadTime]).to.exist;
expect(metric[LOAD_METRIC.contentLoadTime]).to.exist;
expect(metric.value).to.exist;
done();
});
preview.emitLoadMetrics();
Expand All @@ -2376,18 +2374,6 @@ describe('lib/Preview', () => {
expect(preview.emit).to.be.called;
});

it('should default all un-hit milestones, after the first, to 0, and cast float values to ints', (done) => {
Timer.get(fileInfoTag).elapsed = 1.00001236712394687;
preview.once(PREVIEW_METRIC, (metric) => {
expect(metric[LOAD_METRIC.fileInfoTime]).to.equal(1); // Converted to int
expect(metric[LOAD_METRIC.convertTime]).to.equal(0);
expect(metric[LOAD_METRIC.downloadResponseTime]).to.equal(0);
expect(metric[LOAD_METRIC.fullDocumentLoadTime]).to.equal(0);
done();
});
preview.emitLoadMetrics();
});

it('should append encoding field to load metric, when provided', (done) => {
preview.once(PREVIEW_METRIC, (metric) => {
expect(metric.encoding).to.equal(ENCODING_TYPES.GZIP);
Expand Down
5 changes: 3 additions & 2 deletions src/lib/events.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -55,8 +55,9 @@ export const LOAD_METRIC = {
fileInfoTime: 'file_info_time', // Round trip time from file info request to received file info.
convertTime: 'convert_time', // Time it took from receiving file info to being able to request the rep.
downloadResponseTime: 'download_response_time', // Time it took for TTFB when requesting a rep.
fullDocumentLoadTime: 'full_document_load_time', // How long it took to load the document so it could be previewed.
preloadTime: 'preload_time' // How long it takes to preload the document.
contentLoadTime: 'full_document_load_time', // How long it took to load the document so it could be previewed.
preloadTime: 'preload_time', // How long it takes to preload the document.
previewLoadTime: 'preview_loading' // Total preview load time. Maps to "value" of load event
};

export const DURATION_METRIC = 'preview_duration_metric';
Expand Down
4 changes: 2 additions & 2 deletions src/lib/viewers/BaseViewer.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -285,14 +285,14 @@ class BaseViewer extends EventEmitter {
}

/**
* Start the load timer for fullDocumentLoad event.
* Start the load timer for contentLoadTime event.
*
* @protected
* @return {void}
*/
startLoadTimer() {
const { file } = this.options;
const tag = Timer.createTag(file.id, LOAD_METRIC.fullDocumentLoadTime);
const tag = Timer.createTag(file.id, LOAD_METRIC.contentLoadTime);
Timer.start(tag);
}

Expand Down
4 changes: 2 additions & 2 deletions src/lib/viewers/__tests__/BaseViewer-test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -195,11 +195,11 @@ describe('lib/viewers/BaseViewer', () => {
});

describe('startLoadTimer()', () => {
it('should start a timer for the fullDocumentLoadTime metric', () => {
it('should start a timer for the contentLoadTime metric', () => {
base.options.file.id = '1234';
base.startLoadTimer();

const tag = Timer.createTag(base.options.file.id, LOAD_METRIC.fullDocumentLoadTime);
const tag = Timer.createTag(base.options.file.id, LOAD_METRIC.contentLoadTime);
expect(Timer.get(tag)).to.exist;
});
});
Expand Down

0 comments on commit 7da1899

Please sign in to comment.