From 782b7fb706df9087a2c3c019849d4ee6f341152c Mon Sep 17 00:00:00 2001 From: Kiera Ada <1320156+kierrrrra@users.noreply.github.com> Date: Wed, 13 Sep 2023 16:12:38 +0100 Subject: [PATCH] Adding measurement cancellation reason diagnostics (#77) Adding a way to diagnose TTVC measurement cancellations by providing an optional callback that will be called when measurement is cancelled --- .gitignore | 3 + README.md | 66 +++++++++++ src/index.ts | 18 ++- src/visuallyCompleteCalculator.ts | 167 ++++++++++++++++++++++++---- test/e2e/interaction1/index.spec.ts | 14 ++- test/e2e/interaction2/index.spec.ts | 14 ++- test/e2e/interaction3/index.spec.ts | 6 +- test/e2e/interaction4/index.html | 14 +++ test/e2e/interaction4/index.spec.ts | 27 +++++ test/server/public/analytics.js | 17 ++- test/util/entries.ts | 12 +- 11 files changed, 312 insertions(+), 46 deletions(-) create mode 100644 test/e2e/interaction4/index.html create mode 100644 test/e2e/interaction4/index.spec.ts diff --git a/.gitignore b/.gitignore index 3fb3146..8af6cc1 100644 --- a/.gitignore +++ b/.gitignore @@ -109,6 +109,9 @@ lib # VS Code settings .vscode +# IntelliJ Settings +.idea + # Playwright test-results/ playwright-report/ \ No newline at end of file diff --git a/README.md b/README.md index 8180a55..cc25018 100644 --- a/README.md +++ b/README.md @@ -14,6 +14,7 @@ - [Report metrics to a collection endpoint](#report-metrics-to-a-collection-endpoint) - [Record a PerformanceTimeline entry](#record-a-performancetimeline-entry) - [Client-side navigation with React Router](#client-side-navigation-with-react-router) + - [Attributing TTVC measurement cancellations](#attributing-ttvc-measurement-cancellations) - [API](#api) - [Types](#types) - [Functions](#functions) @@ -164,6 +165,31 @@ const App = () => { }; ``` +### Attributing TTVC measurement cancellations + +In certain cases, @dropbox/ttvc might discard the measurement before it is captured. + +This can happen if a user interacts with or navigates away from the page, or the page is put in the background before it has reached a state ot visual completeness. + +This is done to obtain a higher confidence of the measurement's accuracy, as interaction with a page can cause it to change in ways that invalidate the measurement. + +However, @dropbox/ttvc provides a way to monitor these cancellations and attribute them to a specific cause. A second callback function provided to `onTTVC` will be called when the measurement is cancelled. + +```js +import {init, onTTVC} from '@dropbox/ttvc'; + +init(); + +onTTVC( + (measurement) => { + console.log('TTVC measurement captured:', measurement.duration); + }, + (error) => { + console.log('TTVC measurement cancelled:', error.cancellationReason); + } +); +``` + ## API ### Types @@ -212,6 +238,46 @@ export type Metric = { }; ``` +#### `CancellationError` + +```typescript +export type CancellationError = { + // time since timeOrigin that the navigation was triggered + start: number; + + // time since timeOrigin that cancellation occurred + end: number; + + // reason for cancellation + cancellationReason: CancellationReason; + + // Optional type of event that triggered cancellation + eventType?: string; + + // Optional target of event that triggered cancellation + eventTarget?: EventTarget; + + // the most recent visual update; this can be either a mutation or a load event target + lastVisibleChange?: HTMLElement | TimestampedMutationRecord; + + navigationType: NavigationType; +}; + +export enum CancellationReason { + // navigation has occurred + NEW_NAVIGATION = 'NEW_NAVIGATION', + + // page was put in background + VISIBILITY_CHANGE = 'VISIBILITY_CHANGE', + + // user interaction occurred + USER_INTERACTION = 'USER_INTERACTION', + + // manual cancellation via API happened + MANUAL_CANCELLATION = 'MANUAL_CANCELLATION', +} +``` + #### `TtvcOptions` ```typescript diff --git a/src/index.ts b/src/index.ts index cab746f..92b1d9b 100644 --- a/src/index.ts +++ b/src/index.ts @@ -3,12 +3,18 @@ import {TtvcOptions, setConfig} from './util/constants'; import {Logger} from './util/logger'; import { getVisuallyCompleteCalculator, - MetricSubscriber, + MetricSuccessSubscriber, + MetricErrorSubscriber, VisuallyCompleteCalculator, } from './visuallyCompleteCalculator.js'; export type {TtvcOptions}; -export type {Metric, MetricSubscriber} from './visuallyCompleteCalculator'; +export type { + Metric, + CancellationError, + MetricSuccessSubscriber, + MetricErrorSubscriber, +} from './visuallyCompleteCalculator'; let calculator: VisuallyCompleteCalculator; @@ -53,10 +59,14 @@ export const init = (options?: TtvcOptions) => { * @example * const unsubscribe = onTTVC(ms => console.log(ms)); * - * @param callback Triggered once for each navigation instance. + * @param successCallback Triggered once for each navigation instance when TTVC was successfully captured. + * @param [errorCallback] Triggered when TTVC failed to capture * @returns A function that unsubscribes the callback from this metric. */ -export const onTTVC = (callback: MetricSubscriber) => calculator?.onTTVC(callback); +export const onTTVC = ( + successCallback: MetricSuccessSubscriber, + errorCallback?: MetricErrorSubscriber +) => calculator?.onTTVC(successCallback, errorCallback); /** * Begin measuring a new navigation. diff --git a/src/visuallyCompleteCalculator.ts b/src/visuallyCompleteCalculator.ts index ea538f7..db704ba 100644 --- a/src/visuallyCompleteCalculator.ts +++ b/src/visuallyCompleteCalculator.ts @@ -10,6 +10,10 @@ export type NavigationType = // Navigation was triggered with a script operation, e.g. in a single page application. | 'script'; +/** + * TTVC `Metric` type uses `PerformanceMeasure` type as it's guideline + * https://developer.mozilla.org/en-US/docs/Web/API/PerformanceMeasure + */ export type Metric = { // time since timeOrigin that the navigation was triggered // (this will be 0 for the initial pageload) @@ -33,15 +37,59 @@ export type Metric = { }; }; -export type MetricSubscriber = (measurement: Metric) => void; +/** + * At the moment, the only error that can occur is measurement cancellation + */ +export type CancellationError = { + // time since timeOrigin that the navigation was triggered + start: number; + + // time since timeOrigin that cancellation occurred + end: number; + + // reason for cancellation + cancellationReason: CancellationReason; + + // Optional type of event that triggered cancellation + eventType?: string; + + // Optional target of event that triggered cancellation + eventTarget?: EventTarget; + + // the most recent visual update; this can be either a mutation or a load event target + lastVisibleChange?: HTMLElement | TimestampedMutationRecord; + + navigationType: NavigationType; +}; + +export const enum CancellationReason { + // navigation has occurred + NEW_NAVIGATION = 'NEW_NAVIGATION', + + // page was put in background + VISIBILITY_CHANGE = 'VISIBILITY_CHANGE', + + // user interaction occurred + USER_INTERACTION = 'USER_INTERACTION', + + // manual cancellation via API happened + MANUAL_CANCELLATION = 'MANUAL_CANCELLATION', +} + +export type MetricSuccessSubscriber = (measurement: Metric) => void; +export type MetricErrorSubscriber = (error: CancellationError) => void; /** - * TODO: Document + * Core of the TTVC calculation that ties viewport observers and network monitoring + * into a singleton that facilitates communication of TTVC metric measurement and error + * information to subscribers. */ class VisuallyCompleteCalculator { + // configuration public debug = false; public idleTimeout = 200; + // observers private inViewportMutationObserver: InViewportMutationObserver; private inViewportImageObserver: InViewportImageObserver; @@ -49,10 +97,13 @@ class VisuallyCompleteCalculator { private lastMutation?: TimestampedMutationRecord; private lastImageLoadTimestamp = -1; private lastImageLoadTarget?: HTMLElement; - private subscribers = new Set(); private navigationCount = 0; private activeMeasurementIndex?: number; // only one measurement should be active at a time + // subscribers + private successSubscribers = new Set(); + private errorSubscribers = new Set(); + /** * Determine whether the calculator should run in the current environment */ @@ -84,8 +135,11 @@ class VisuallyCompleteCalculator { }); } - /** abort the current TTVC measurement */ - cancel() { + /** + * expose a method to abort the current TTVC measurement + * @param eventType - type of event that triggered cancellation (note that cancellationReason will be set to "manual" regardless of this value). + */ + cancel(eventType?: string) { Logger.info( 'VisuallyCompleteCalculator.cancel()', '::', @@ -93,6 +147,15 @@ class VisuallyCompleteCalculator { this.activeMeasurementIndex ); this.activeMeasurementIndex = undefined; + + this.error({ + start: getActivationStart(), + end: performance.now(), + cancellationReason: CancellationReason.MANUAL_CANCELLATION, + eventType: eventType, + navigationType: getNavigationType(), + lastVisibleChange: this.getLastVisibleChange(), + }); } /** begin measuring a new navigation */ @@ -114,20 +177,34 @@ class VisuallyCompleteCalculator { } // setup - const cancel = () => { + const cancel = (e: Event, cancellationReason: CancellationReason) => { if (this.activeMeasurementIndex === navigationIndex) { this.activeMeasurementIndex = undefined; + + this.error({ + start, + end: performance.now(), + cancellationReason, + eventType: e.type, + eventTarget: e.target || undefined, + navigationType, + lastVisibleChange: this.getLastVisibleChange(), + }); } }; + const cancelOnInteraction = (e: Event) => cancel(e, CancellationReason.USER_INTERACTION); + const cancelOnNavigation = (e: Event) => cancel(e, CancellationReason.NEW_NAVIGATION); + const cancelOnVisibilityChange = (e: Event) => cancel(e, CancellationReason.VISIBILITY_CHANGE); + this.inViewportImageObserver.observe(); this.inViewportMutationObserver.observe(document.documentElement); - window.addEventListener('pagehide', cancel); - window.addEventListener('visibilitychange', cancel); + window.addEventListener('pagehide', cancelOnNavigation); + window.addEventListener('visibilitychange', cancelOnVisibilityChange); // attach user interaction listeners next tick (we don't want to pick up the SPA navigation click) window.setTimeout(() => { - window.addEventListener('click', cancel); - window.addEventListener('keydown', cancel); + window.addEventListener('click', cancelOnInteraction); + window.addEventListener('keydown', cancelOnInteraction); }, 0); // wait for page to be definitely DONE @@ -136,7 +213,7 @@ class VisuallyCompleteCalculator { // - wait for simultaneous network and CPU idle const didNetworkTimeOut = await new Promise(requestAllIdleCallback); - // if this navigation's measurment hasn't been cancelled, record it. + // if this navigation's measurement hasn't been cancelled, record it. if (navigationIndex === this.activeMeasurementIndex) { // identify timestamp of last visible change const end = Math.max(start, this.lastImageLoadTimestamp, this.lastMutation?.timestamp ?? 0); @@ -149,10 +226,7 @@ class VisuallyCompleteCalculator { detail: { navigationType, didNetworkTimeOut, - lastVisibleChange: - this.lastImageLoadTimestamp > (this.lastMutation?.timestamp ?? 0) - ? this.lastImageLoadTarget - : this.lastMutation, + lastVisibleChange: this.getLastVisibleChange(), }, }); } else { @@ -162,13 +236,23 @@ class VisuallyCompleteCalculator { 'index =', navigationIndex ); + + if (this.activeMeasurementIndex) { + this.error({ + start, + end: performance.now(), + cancellationReason: CancellationReason.NEW_NAVIGATION, + navigationType, + lastVisibleChange: this.getLastVisibleChange(), + }); + } } // cleanup - window.removeEventListener('pagehide', cancel); - window.removeEventListener('visibilitychange', cancel); - window.removeEventListener('click', cancel); - window.removeEventListener('keydown', cancel); + window.removeEventListener('pagehide', cancelOnNavigation); + window.removeEventListener('visibilitychange', cancelOnVisibilityChange); + window.removeEventListener('click', cancelOnInteraction); + window.removeEventListener('keydown', cancelOnInteraction); // only disconnect observers if this is the most recent navigation if (navigationIndex === this.navigationCount) { this.inViewportImageObserver.disconnect(); @@ -200,16 +284,51 @@ class VisuallyCompleteCalculator { this.activeMeasurementIndex ); Logger.info('TTVC:', measurement, '::', 'index =', this.activeMeasurementIndex); - this.subscribers.forEach((subscriber) => subscriber(measurement)); + this.successSubscribers.forEach((subscriber) => subscriber(measurement)); + } + + private error(error: CancellationError) { + Logger.debug( + 'VisuallyCompleteCalculator.error()', + '::', + 'cancellationReason =', + error.cancellationReason, + '::', + 'eventType =', + error.eventType || 'none', + '::', + 'index =', + this.activeMeasurementIndex + ); + this.errorSubscribers.forEach((subscriber) => subscriber(error)); + } + + private getLastVisibleChange() { + return this.lastImageLoadTimestamp > (this.lastMutation?.timestamp ?? 0) + ? this.lastImageLoadTarget + : this.lastMutation; } /** subscribe to Visually Complete metrics */ - onTTVC = (subscriber: MetricSubscriber) => { - // register subscriber callback - this.subscribers.add(subscriber); + onTTVC = ( + successSubscriber: MetricSuccessSubscriber, + errorSubscriber?: MetricErrorSubscriber + ) => { + // register subscriber callbacks + this.successSubscribers.add(successSubscriber); + + if (errorSubscriber) { + this.errorSubscribers.add(errorSubscriber); + } // return an unsubscribe function - return () => this.subscribers.delete(subscriber); + return () => { + this.successSubscribers.delete(successSubscriber); + + if (errorSubscriber) { + this.errorSubscribers.delete(errorSubscriber); + } + }; }; } diff --git a/test/e2e/interaction1/index.spec.ts b/test/e2e/interaction1/index.spec.ts index 93e7124..892e41b 100644 --- a/test/e2e/interaction1/index.spec.ts +++ b/test/e2e/interaction1/index.spec.ts @@ -1,6 +1,6 @@ import {test, expect} from '@playwright/test'; -import {entryCountIs, getEntries} from '../../util/entries'; +import {entryCountIs, getEntriesAndErrors} from '../../util/entries'; const MUTATION_DELAY = 500; @@ -13,15 +13,19 @@ test.describe('TTVC', () => { // user interaction should abort calculation await page.click('body', {delay: MUTATION_DELAY / 2}); + // assert that no metric has been reported + const {entries, errors} = await getEntriesAndErrors(page); + expect(entries.length).toBe(0); + + expect(errors.length).toBe(1); + expect(errors[0].cancellationReason).toBe('USER_INTERACTION'); + expect(errors[0].eventType).toBe('click'); + // wait long enough to ensure ttvc would have been logged try { await entryCountIs(page, 1, 3000); } catch (e) { // pass } - - // assert that no metric has been reported - const entries = await getEntries(page); - expect(entries.length).toBe(0); }); }); diff --git a/test/e2e/interaction2/index.spec.ts b/test/e2e/interaction2/index.spec.ts index f36f445..c1c258f 100644 --- a/test/e2e/interaction2/index.spec.ts +++ b/test/e2e/interaction2/index.spec.ts @@ -1,6 +1,6 @@ import {test, expect} from '@playwright/test'; -import {entryCountIs, getEntries} from '../../util/entries'; +import {entryCountIs, getEntriesAndErrors} from '../../util/entries'; test.describe('TTVC', () => { test('tab is backgrounded before page completes loading', async ({page}) => { @@ -18,15 +18,19 @@ test.describe('TTVC', () => { document.dispatchEvent(new Event('visibilitychange', {bubbles: true})); }); + // assert that no metric has been reported + const {entries, errors} = await getEntriesAndErrors(page); + expect(entries.length).toBe(0); + + expect(errors.length).toBe(1); + expect(errors[0].cancellationReason).toBe('VISIBILITY_CHANGE'); + expect(errors[0].eventType).toBe('visibilitychange'); + // wait long enough to ensure ttvc would have been logged try { await entryCountIs(page, 1, 3000); } catch (e) { // pass } - - // assert that no metric has been reported - const entries = await getEntries(page); - expect(entries.length).toBe(0); }); }); diff --git a/test/e2e/interaction3/index.spec.ts b/test/e2e/interaction3/index.spec.ts index 809708c..7cd086d 100644 --- a/test/e2e/interaction3/index.spec.ts +++ b/test/e2e/interaction3/index.spec.ts @@ -1,7 +1,7 @@ import {test, expect} from '@playwright/test'; import {FUDGE} from '../../util/constants'; -import {getEntries, entryCountIs} from '../../util/entries'; +import {entryCountIs, getEntriesAndErrors} from '../../util/entries'; const PAGELOAD_DELAY = 500; @@ -15,10 +15,12 @@ test.describe('TTVC', () => { await entryCountIs(page, 1); - const entries = await getEntries(page); + const {entries, errors} = await getEntriesAndErrors(page); expect(entries.length).toBe(1); expect(entries[0].duration).toBeGreaterThanOrEqual(PAGELOAD_DELAY); expect(entries[0].duration).toBeLessThanOrEqual(PAGELOAD_DELAY + FUDGE); + + expect(errors.length).toBe(0); }); }); diff --git a/test/e2e/interaction4/index.html b/test/e2e/interaction4/index.html new file mode 100644 index 0000000..bbd3a47 --- /dev/null +++ b/test/e2e/interaction4/index.html @@ -0,0 +1,14 @@ + + + + + + +

Hello world!

+ + + + + diff --git a/test/e2e/interaction4/index.spec.ts b/test/e2e/interaction4/index.spec.ts new file mode 100644 index 0000000..9bf3926 --- /dev/null +++ b/test/e2e/interaction4/index.spec.ts @@ -0,0 +1,27 @@ +import {test, expect} from '@playwright/test'; + +import {getEntriesAndErrors, entryCountIs} from '../../util/entries'; + +const PAGELOAD_DELAY = 500; + +test.describe('TTVC', () => { + test('measurement manually cancelled', async ({page}) => { + await page.goto(`/test/interaction4?delay=${PAGELOAD_DELAY}`, { + waitUntil: 'domcontentloaded', + }); + + const {entries, errors} = await getEntriesAndErrors(page); + + expect(entries.length).toBe(0); + + expect(errors[0].cancellationReason).toBe('MANUAL_CANCELLATION'); + expect(errors.length).toBe(1); + + // wait long enough to ensure ttvc would have been logged + try { + await entryCountIs(page, 1, 3000); + } catch (e) { + // pass + } + }); +}); diff --git a/test/server/public/analytics.js b/test/server/public/analytics.js index dafd9e5..619dba5 100644 --- a/test/server/public/analytics.js +++ b/test/server/public/analytics.js @@ -1,5 +1,6 @@ -// use window.entries to communicate between browser and test runner processes +// use window.entries and window.errors to communicate between browser and test runner processes window.entries = []; +window.errors = []; // patch window.fetch const oldFetch = window.fetch; @@ -10,7 +11,13 @@ window.fetch = (...args) => { TTVC.init({debug: true, networkTimeout: window.NETWORK_TIMEOUT ?? 3000}); -TTVC.onTTVC((measurement) => { - console.log('TTVC:', measurement); - window.entries.push(measurement); -}); +TTVC.onTTVC( + (measurement) => { + console.log('TTVC:SUCCESS', measurement); + window.entries.push(measurement); + }, + (error) => { + console.log('TTVC:ERROR', error); + window.errors.push(error); + } +); diff --git a/test/util/entries.ts b/test/util/entries.ts index 940fb07..97ba069 100644 --- a/test/util/entries.ts +++ b/test/util/entries.ts @@ -1,16 +1,26 @@ import type {Page} from '@playwright/test'; -import type {Metric} from '../../src'; +import type {Metric, CancellationError} from '../../src'; // Use window.entries to communicate between browser and test processes declare global { interface Window { entries: Metric[]; + errors: CancellationError[]; } } /** Get the list of performance entries that have been recorded from the browser */ export const getEntries = (page: Page) => page.evaluate(() => window.entries); +/** Get the list of performance entries and errors that have been recorded from the browser */ +export const getEntriesAndErrors = (page: Page) => + page.evaluate(() => { + return { + entries: window.entries, + errors: window.errors, + }; + }); + /** * Wait until at least {count} performance entries have been logged. */