diff --git a/src/lib/Preview.js b/src/lib/Preview.js index ffb50cfe6..f91c5a337 100644 --- a/src/lib/Preview.js +++ b/src/lib/Preview.js @@ -11,6 +11,7 @@ import loaderList from './loaders'; import Cache from './Cache'; import PreviewError from './PreviewError'; import PreviewErrorViewer from './viewers/error/PreviewErrorViewer'; +import PreviewPerf from './PreviewPerf'; import PreviewUI from './PreviewUI'; import getTokens from './tokens'; import Timer from './Timer'; @@ -198,18 +199,16 @@ class Preview extends EventEmitter { const previewDurationTag = Timer.createTag(this.file.id, DURATION_METRIC); const previewDurationTimer = Timer.get(previewDurationTag); Timer.stop(previewDurationTag); + const previewDuration = previewDurationTimer ? previewDurationTimer.elapsed : null; + Timer.reset(previewDurationTag); - const event = { + this.emitLogEvent(PREVIEW_METRIC, { event_name: PREVIEW_END_EVENT, value: { - duration: previewDurationTimer ? previewDurationTimer.elapsed : null, + duration: previewDuration, viewer_status: this.viewer.getLoadStatus(), }, - ...this.createLogEvent(), - }; - - Timer.reset(previewDurationTag); - this.emit(PREVIEW_METRIC, event); + }); } // Eject http interceptors @@ -241,6 +240,9 @@ class Preview extends EventEmitter { throw new Error('Bad access token!'); } + // Initalize performance observers + this.perf = new PreviewPerf(); + // Update the optional file navigation collection and caches // if proper valid file objects were passed in. this.updateCollection(options.collection); @@ -265,6 +267,11 @@ class Preview extends EventEmitter { // Destroy the viewer and cleanup preview this.destroy(); + // Destroy pefromance observers + if (this.perf) { + this.perf.destroy(); + } + // Clean the UI this.ui.cleanup(); @@ -560,13 +567,10 @@ class Preview extends EventEmitter { }); } - const downloadAttemptEvent = { + this.emitLogEvent(PREVIEW_METRIC, { event_name: PREVIEW_DOWNLOAD_ATTEMPT_EVENT, value: this.viewer ? this.viewer.getLoadStatus() : null, - ...this.createLogEvent(), - }; - - this.emit(PREVIEW_METRIC, downloadAttemptEvent); + }); } /** @@ -1266,13 +1270,10 @@ class Preview extends EventEmitter { * @return {void} */ handleViewerMetrics(data) { - const formattedEvent = { + this.emitLogEvent(PREVIEW_METRIC, { event_name: data.event, value: data.data, - ...this.createLogEvent(), - }; - - this.emit(PREVIEW_METRIC, formattedEvent); + }); } /** @@ -1316,8 +1317,8 @@ class Preview extends EventEmitter { }); // Explicit preview failure - this.handleViewerMetrics({ - event: 'failure', + this.emitLogEvent(PREVIEW_METRIC, { + event_name: 'failure', }); // Hookup for phantom JS health check @@ -1336,10 +1337,13 @@ class Preview extends EventEmitter { }); // Explicit preview success - this.handleViewerMetrics({ - event: 'success', + this.emitLogEvent(PREVIEW_METRIC, { + event_name: 'success', }); + // Emit performance metrics after rendering has settled + setTimeout(this.emitPerfMetrics.bind(this), 3000); + // If there wasn't an error and event logging is not disabled, use Events API to log a preview if (!this.options.disableEventLog) { this.logPreviewEvent(this.file.id, this.options); @@ -1518,28 +1522,6 @@ class Preview extends EventEmitter { this.viewer.load(err); } - /** - * Create a generic log Object. - * - * @private - * @return {Object} Log details for viewer session and current file. - */ - createLogEvent() { - const file = this.file || {}; - const log = { - timestamp: getISOTime(), - file_id: getProp(file, 'id', ''), - file_version_id: getProp(file, 'file_version.id', ''), - content_type: getProp(this.viewer, 'options.viewer.NAME', ''), - extension: file.extension || '', - locale: getProp(this.location, 'locale', ''), - rep_type: getProp(this.viewer, 'options.representation.representation', '').toLowerCase(), - ...getClientLogDetails(), - }; - - return log; - } - /** * Message, to any listeners of Preview, that an error has occurred. * @@ -1558,12 +1540,9 @@ class Preview extends EventEmitter { sanitizedError.displayMessage = stripAuthFromString(displayMessage); sanitizedError.message = stripAuthFromString(message); - const errorLog = { + this.emitLogEvent(PREVIEW_ERROR, { error: sanitizedError, - ...this.createLogEvent(), - }; - - this.emit(PREVIEW_ERROR, errorLog); + }); } /** @@ -1594,7 +1573,7 @@ class Preview extends EventEmitter { const contentLoadTime = Timer.get(contentLoadTag) || {}; const previewLoadTime = Timer.get(previewLoadTag) || {}; - const event = { + this.emitLogEvent(PREVIEW_METRIC, { encoding, event_name: LOAD_METRIC.previewLoadEvent, value: previewLoadTime.elapsed || 0, @@ -1602,14 +1581,58 @@ class Preview extends EventEmitter { [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, contentLoadTag, previewLoadTag]); } + /** + * Emit events to log preview-specific performance metrics if they exist and are non-zero + * + * @private + * @return {void} + */ + emitPerfMetrics() { + const { fcp, lcp } = this.perf.report(); + + if (fcp) { + this.emitLogEvent(PREVIEW_METRIC, { + event_name: 'preview_perf_fcp', + value: fcp, + }); + } + + if (lcp) { + this.emitLogEvent(PREVIEW_METRIC, { + event_name: 'preview_perf_lcp', + value: lcp, + }); + } + } + + /** + * Emit an event that includes a standard set of preview-specific properties for logging + * + * @private + * @param {string} name - event name + * @param {Object} payload - event payload object + */ + emitLogEvent(name, payload = {}) { + const file = this.file || {}; + + this.emit(name, { + ...payload, + content_type: getProp(this.viewer, 'options.viewer.NAME', ''), + extension: file.extension || '', + file_id: getProp(file, 'id', ''), + file_version_id: getProp(file, 'file_version.id', ''), + locale: getProp(this.location, 'locale', ''), + rep_type: getProp(this.viewer, 'options.representation.representation', '').toLowerCase(), + timestamp: getISOTime(), + ...getClientLogDetails(), + }); + } + /** * Builds a list of required XHR headers. * diff --git a/src/lib/PreviewPerf.ts b/src/lib/PreviewPerf.ts new file mode 100644 index 000000000..85d1b36fa --- /dev/null +++ b/src/lib/PreviewPerf.ts @@ -0,0 +1,73 @@ +interface PerformancePaintTiming { + loadTime?: DOMHighResTimeStamp; + renderTime?: DOMHighResTimeStamp; +} + +interface PerformanceReport { + fcp?: number; + lcp?: number; +} + +export default class PreviewPerf { + private fcpObserver: PerformanceObserver; + + private lcpObserver: PerformanceObserver; + + private performanceReport: PerformanceReport = {}; + + /** + * Performance metrics are recorded in a global context. We use only unbuffered metrics to avoid skewed data, + * as buffered values can be set based on whatever page the user *first* landed on, which may not be preview. + * + * Glossary: + * - FCP - First Contentful Paint (usually loading screen) + * - LCP - Largest Contentful Paint (usually full content preview) + */ + constructor() { + // Bind handlers to the current instance + this.handleFcp = this.handleFcp.bind(this); + this.handleLcp = this.handleLcp.bind(this); + + // Intialize the performance observers + this.fcpObserver = new window.PerformanceObserver(this.handleFcp); + this.lcpObserver = new window.PerformanceObserver(this.handleLcp); + + try { + this.fcpObserver.observe({ entryTypes: ['paint'] }); + this.lcpObserver.observe({ entryTypes: ['largest-contentful-paint'] }); + } catch (e) { + // We're unable to collect these metrics from legacy browsers, such as IE11/Edge (non-Chromium) + } + } + + /** + * Disconnect active observers to avoid memory leaks + */ + public destroy(): void { + this.fcpObserver.disconnect(); + this.lcpObserver.disconnect(); + } + + /** + * Returns defined metrics if the following conditions are satisfied: + * 1) it's recorded by the browser at all (some are Chrome-only, for now) + * 2) if it was logged *after* the Preview SDK was loaded (not buffered) + */ + public report(): PerformanceReport { + return this.performanceReport; + } + + protected handleFcp(list: PerformanceObserverEntryList): void { + const fcpEntries = list.getEntriesByName('first-contentful-paint') || []; + const fcpEntry = fcpEntries[0] || {}; + + this.performanceReport.fcp = Math.round(fcpEntry.startTime || 0); + } + + protected handleLcp(list: PerformanceObserverEntryList): void { + const lcpEntries = (list.getEntriesByType('largest-contentful-paint') as PerformancePaintTiming[]) || []; + const lcpEntry = lcpEntries[lcpEntries.length - 1] || {}; + + this.performanceReport.lcp = Math.round(lcpEntry.renderTime || lcpEntry.loadTime || 0); + } +} diff --git a/src/lib/__tests__/Preview-test.js b/src/lib/__tests__/Preview-test.js index 54e6060e6..8ff708735 100644 --- a/src/lib/__tests__/Preview-test.js +++ b/src/lib/__tests__/Preview-test.js @@ -11,6 +11,7 @@ import * as util from '../util'; import { API_HOST, CLASS_NAVIGATION_VISIBILITY, PERMISSION_PREVIEW, ENCODING_TYPES } from '../constants'; import { VIEWER_EVENT, ERROR_CODE, LOAD_METRIC, PREVIEW_METRIC } from '../events'; import Timer from '../Timer'; +import PreviewPerf from '../PreviewPerf'; const tokens = require('../tokens'); @@ -105,31 +106,24 @@ describe('lib/Preview', () => { id: 1, }; stubs.viewer.getLoadStatus.returns('loaded'); - sandbox.stub(preview, 'createLogEvent'); - const durationTimer = { - elapsed: 7, - }; - - const mockEventObject = { - event_name: 'preview_end', - value: { - duration: durationTimer.elapsed, - viewer_status: 'loaded', - }, - }; - + sandbox.stub(preview, 'emitLogEvent'); sandbox.stub(Timer, 'createTag').returns('duration_tag'); - sandbox.stub(Timer, 'get').returns(durationTimer); + sandbox.stub(Timer, 'get').returns({ elapsed: 7 }); sandbox.stub(Timer, 'stop'); sandbox.stub(Timer, 'reset'); - sandbox.stub(preview, 'emit'); preview.viewer = stubs.viewer; preview.destroy(); expect(Timer.createTag).to.be.called; expect(Timer.stop).to.be.calledWith('duration_tag'); expect(stubs.viewer.getLoadStatus).to.be.called; - expect(preview.emit).to.be.calledWith(PREVIEW_METRIC, mockEventObject); + expect(preview.emitLogEvent).to.be.calledWith(PREVIEW_METRIC, { + event_name: 'preview_end', + value: { + duration: 7, + viewer_status: 'loaded', + }, + }); }); it('should clear the viewer', () => { @@ -236,6 +230,12 @@ describe('lib/Preview', () => { expect(stubs.parseOptions).to.be.calledWith({ ...options, token }); }); + + it('should initialize performance observers', () => { + preview.show(file, 'token'); + + expect(preview.perf).to.be.instanceOf(PreviewPerf); + }); }); describe('hide()', () => { @@ -267,6 +267,15 @@ describe('lib/Preview', () => { preview.hide(); expect(preview.file).to.equal(undefined); }); + + it('should initialize performance observers', () => { + preview.perf = { + destroy: sandbox.stub(), + }; + preview.hide(); + + expect(preview.perf.destroy).to.be.called; + }); }); describe('reload()', () => { @@ -1812,19 +1821,18 @@ describe('lib/Preview', () => { describe('handleViewerMetrics()', () => { it('should create a formatted event and emit a preview_metric', () => { - sandbox.stub(preview, 'createLogEvent'); - sandbox.stub(preview, 'emit'); + sandbox.stub(preview, 'emitLogEvent'); const fakeEvent = { event: 'test', data: 7, }; - const fakeLog = { + preview.handleViewerMetrics(fakeEvent); + + expect(preview.emitLogEvent).to.be.calledWith(PREVIEW_METRIC, { event_name: fakeEvent.event, value: fakeEvent.data, - }; - preview.handleViewerMetrics(fakeEvent); - expect(preview.emit).to.be.calledWith(PREVIEW_METRIC, fakeLog); + }); }); }); @@ -1845,16 +1853,18 @@ describe('lib/Preview', () => { stubs.logger = { done: sandbox.stub(), }; + stubs.perf = { + report: sandbox.stub().returns({}), + }; preview.file = { id: 0, }; - + preview.logger = stubs.logger; + preview.perf = stubs.perf; preview.viewer = { getPointModeClickHandler: sandbox.stub(), }; - - preview.logger = stubs.logger; }); it('should show download button if file can be downloaded', () => { @@ -1899,22 +1909,20 @@ describe('lib/Preview', () => { it('should emit a metrics message for successful preview', () => { const eventName = 'success'; - - const handleViewerMetrics = sandbox.stub(preview, 'handleViewerMetrics'); + const emitLogEvent = sandbox.stub(preview, 'emitLogEvent'); preview.finishLoading(); - expect(handleViewerMetrics).to.be.calledWith({ event: eventName }); + expect(emitLogEvent).to.be.calledWith(PREVIEW_METRIC, { event_name: eventName }); }); it('should emit a metrics message for failed preview', () => { const eventName = 'failure'; - - const handleViewerMetrics = sandbox.stub(preview, 'handleViewerMetrics'); + const emitLogEvent = sandbox.stub(preview, 'emitLogEvent'); preview.finishLoading({ error: {} }); - expect(handleViewerMetrics).to.be.calledWith({ event: eventName }); + expect(emitLogEvent).to.be.calledWith(PREVIEW_METRIC, { event_name: eventName }); }); it('should emit the load event', () => { @@ -2241,28 +2249,36 @@ describe('lib/Preview', () => { }); }); - describe('createLogEvent()', () => { - it('should create a log object containing correct file info properties', () => { - const id = '12345'; - preview.file = { - id, - }; + describe('emitLogEvent()', () => { + beforeEach(() => { + sandbox.stub(preview, 'emit'); + }); - const log = preview.createLogEvent(); - expect(log.timestamp).to.exist; - expect(log.file_id).to.equal(id); - expect(log.file_version_id).to.exist; - expect(log.content_type).to.exist; - expect(log.extension).to.exist; - expect(log.locale).to.exist; - expect(log.rep_type).to.exist; + it('should emit an event containing correct file info properties', () => { + preview.file = { id: '12345' }; + preview.emitLogEvent('test'); + + expect(preview.emit).to.be.calledWith( + 'test', + sinon.match({ + content_type: '', + extension: '', + file_id: '12345', + file_version_id: '', + }), + ); }); it('should use empty string for file_id, if no file', () => { preview.file = undefined; - const log = preview.createLogEvent(); + preview.emitLogEvent('test'); - expect(log.file_id).to.equal(''); + expect(preview.emit).to.be.calledWith( + 'test', + sinon.match({ + file_id: '', + }), + ); }); it('should use empty string for file_version_id, if no file version', () => { @@ -2270,21 +2286,29 @@ describe('lib/Preview', () => { id: '12345', file_version: undefined, }; - const log = preview.createLogEvent(); + preview.emitLogEvent('test'); - expect(log.file_version_id).to.equal(''); + expect(preview.emit).to.be.calledWith( + 'test', + sinon.match({ + file_version_id: '', + }), + ); }); it('should use empty string for rep_type, if no representation type available in viewer options', () => { preview.file = { id: '12345', }; - preview.viewer = {}; + preview.emitLogEvent('test'); - const log = preview.createLogEvent(); - - expect(log.rep_type).to.equal(''); + expect(preview.emit).to.be.calledWith( + 'test', + sinon.match({ + rep_type: '', + }), + ); }); }); diff --git a/src/lib/__tests__/PreviewPerf-test.js b/src/lib/__tests__/PreviewPerf-test.js new file mode 100644 index 000000000..d9ad2d4b1 --- /dev/null +++ b/src/lib/__tests__/PreviewPerf-test.js @@ -0,0 +1,108 @@ +import PreviewPerf from '../PreviewPerf'; + +describe('lib/PreviewPerf', () => { + const getPerfEntries = (entries = []) => { + return { + getEntries: () => entries, + getEntriesByName: name => entries.filter(entry => entry.name === name), + getEntriesByType: type => entries.filter(entry => entry.type === type), + }; + }; + const sandbox = sinon.sandbox.create(); + let previewPerf; + + beforeEach(() => { + sandbox.stub(window, 'PerformanceObserver').returns({ + disconnect: sandbox.stub(), + observe: sandbox.stub(), + }); + + previewPerf = new PreviewPerf(); + }); + + afterEach(() => { + sandbox.verifyAndRestore(); + + if (previewPerf) { + previewPerf.destroy(); + previewPerf = null; + } + }); + + describe('constructor', () => { + it('should create performance observers for applicable metrics', () => { + expect(window.PerformanceObserver).to.be.calledWith(previewPerf.handleFcp); + expect(window.PerformanceObserver).to.be.calledWith(previewPerf.handleLcp); + }); + }); + + describe('report', () => { + it('should return the current performance report', () => { + expect(previewPerf.report()).to.deep.equal(previewPerf.performanceReport); + }); + }); + + describe('handleFcp', () => { + it('should update the performance report the first rounded FCP metric', () => { + previewPerf.handleFcp( + getPerfEntries([ + { + name: 'first-contentful-paint', + startTime: 500.5, + }, + ]), + ); + + expect(previewPerf.report()).to.include({ fcp: 501 }); + }); + + it('should update the performance report with a zero value if the metric is not present', () => { + previewPerf.handleFcp( + getPerfEntries([ + { + type: 'nonsense', + loadTime: 1000.0, + }, + ]), + ); + + expect(previewPerf.report()).to.include({ fcp: 0 }); + }); + }); + + describe('handleLcp', () => { + it('should update the performance report with the last rounded LCP metric', () => { + previewPerf.handleLcp( + getPerfEntries([ + { + type: 'largest-contentful-paint', + renderTime: 1000.5, + }, + { + type: 'largest-contentful-paint', + renderTime: 2000.5, + }, + { + type: 'largest-contentful-paint', + renderTime: 3000.5, + }, + ]), + ); + + expect(previewPerf.report()).to.include({ lcp: 3001 }); + }); + + it('should update the performance report with a zero value if the metric is not present', () => { + previewPerf.handleLcp( + getPerfEntries([ + { + type: 'nonsense', + responseEnd: 1000.0, + }, + ]), + ); + + expect(previewPerf.report()).to.include({ lcp: 0 }); + }); + }); +}); diff --git a/src/lib/polyfill.js b/src/lib/polyfill.js index b48d88d86..3fc3f7e23 100644 --- a/src/lib/polyfill.js +++ b/src/lib/polyfill.js @@ -398,4 +398,14 @@ if (!String.prototype.startsWith) { if (window.NodeList && !NodeList.prototype.forEach) { NodeList.prototype.forEach = Array.prototype.forEach; } + +// PerformanceObserver no-op polyfill for IE11 and Edge (not supported) +if (!window.PerformanceObserver) { + window.PerformanceObserver = function PerformanceObserverNoop() { + return { + disconnect: () => {}, + observe: () => {}, + }; + }; +} /* eslint-enable */ diff --git a/tsconfig.json b/tsconfig.json index 19a790f74..fbd6700ba 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -1,5 +1,5 @@ { "extends": "@box/frontend/ts/tsconfig.json", - "include": ["./src/**/*"], + "include": ["./src/**/*.ts", "./src/**/*.tsx"], "exclude": ["node_modules", "dist"] }