From 95a1c5b5b414049bdb61b6784c04d6c9e154a1fe Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bazyli=20Brz=C3=B3ska=20=28Zendesk=29?= Date: Thu, 8 Jun 2023 10:28:20 -0700 Subject: [PATCH] feat: allow configuring loadingStages and customizing reportFn (#6) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit also fixes the issue of "$previousStage to $stage" being both reported as the same Co-authored-by: Bazyli Brzóska Co-authored-by: Cynthia Ma --- README.md | 94 ++++++++------- src/ActionLog.ts | 56 ++++----- src/constants.ts | 5 + src/debounce.ts | 14 +-- src/fixtures/actionsFixture.ts | 129 +++++++++++++++++++++ src/generateReport.test.ts | 145 +++--------------------- src/generateReport.ts | 157 +++++++++++++------------- src/getExternalApi.test.ts | 4 +- src/main.ts | 2 +- src/performanceMark.ts | 37 +++--- src/stories/MeasureTiming.stories.tsx | 2 +- src/types.ts | 44 +++++--- src/useTiming.test.tsx | 101 +++++++++-------- src/useTimingMeasurement.ts | 8 +- 14 files changed, 418 insertions(+), 380 deletions(-) create mode 100644 src/fixtures/actionsFixture.ts diff --git a/README.md b/README.md index 072d77ec..8e3f8968 100644 --- a/README.md +++ b/README.md @@ -32,7 +32,10 @@ First, create a file that generates and exports the hooks for your metric ID pre For example: ```typescript -import { generateTimingHooks } from '@zendesk/react-measure-timing-hooks' +import { + generateTimingHooks, + generateReport, +} from '@zendesk/react-measure-timing-hooks' export const { // the name of the hook(s) are generated based on the `name` and the placement names @@ -42,7 +45,8 @@ export const { { name: 'Conversation', idPrefix: 'ticket/conversation', - reportFn: (report, metadata) => { + reportFn: (reportArguments) => { + const defaultReport = generateReport(reportArguments) // do something with the report, e.g. send select data to Datadog RUM or other analytics }, }, @@ -100,8 +104,9 @@ const Conversation = ({ conversationId }) => { ``` An `idSuffix` is required when the component is not expected to be a singleton. If you're uncertain, the following heuristic should help you make the decision whether to add one: -* When the same component is rendered multiple times on a page. -* We expect the component will vary its content (re-render) based on some object variable. For example, its contents change based on another item's selection/visibility, or an action, like opening. + +- When the same component is rendered multiple times on a page. +- We expect the component will vary its content (re-render) based on some object variable. For example, its contents change based on another item's selection/visibility, or an action, like opening. ### Report @@ -172,9 +177,7 @@ If `isActive` is present in at least one of the beacons, timing will start from ```tsx import { generateTimingHooks } from '@zendesk/react-measure-timing-hooks' -export const { - useSomethingLoadingTimingInMyComponent, -} = generateTimingHooks( +export const { useSomethingLoadingTimingInMyComponent } = generateTimingHooks( { name: 'SomethingLoading', idPrefix: 'some/identifier', @@ -201,9 +204,7 @@ import { DEFAULT_STAGES, } from '@zendesk/react-measure-timing-hooks' -export const { - useSomethingLoadingTimingInMyComponent, -} = generateTimingHooks( +export const { useSomethingLoadingTimingInMyComponent } = generateTimingHooks( { name: 'SomethingLoading', idPrefix: 'some/identifier', @@ -237,9 +238,7 @@ import { switchFn, } from '@zendesk/react-measure-timing-hooks' -export const { - useSomethingLoadingTimingInMyComponent, -} = generateTimingHooks( +export const { useSomethingLoadingTimingInMyComponent } = generateTimingHooks( { name: 'SomethingLoading', idPrefix: 'some/identifier', @@ -260,6 +259,8 @@ const MyComponent = () => { { case: isLoading, return: DEFAULT_STAGES.LOADING }, { return: DEFAULT_STAGES.READY }, ), + // we want generateReport to count both of these stages as part of the "loading" process + loadingStages: [DEFAULT_STAGES.LOADING, 'searching'], }) return
Hello!
} @@ -358,19 +359,18 @@ to reset. ```tsx import { generateTimingHooks } from '@zendesk/react-measure-timing-hooks' -export const { - useSomethingLoadingTimingInSomeComponentName, -} = generateTimingHooks( - { - name: 'SomethingLoading', - idPrefix: 'some/identifier', - finalStages: [DEFAULT_STAGES.READY], - reportFn: myCustomReportFunction, - }, - // name of the first placement - // usually the component that mounts first, from which timing should start - 'SomeComponentName', -) +export const { useSomethingLoadingTimingInSomeComponentName } = + generateTimingHooks( + { + name: 'SomethingLoading', + idPrefix: 'some/identifier', + finalStages: [DEFAULT_STAGES.READY], + reportFn: myCustomReportFunction, + }, + // name of the first placement + // usually the component that mounts first, from which timing should start + 'SomeComponentName', + ) const MyComponent = () => { useSomethingLoadingTimingInSomeComponentName( @@ -431,17 +431,16 @@ a dependency has changed (e.g. `ticketId` flipping from `-1` to the actual ID). ```tsx import { generateTimingHooks } from '@zendesk/react-measure-timing-hooks' -export const { - useSomethingLoadingTimingInSomeComponentName, -} = generateTimingHooks( - { - name: 'SomethingLoading', - idPrefix: 'some/identifier', - finalStages: [DEFAULT_STAGES.READY], - reportFn: myCustomReportFunction, - }, - 'SomeComponentName', -) +export const { useSomethingLoadingTimingInSomeComponentName } = + generateTimingHooks( + { + name: 'SomethingLoading', + idPrefix: 'some/identifier', + finalStages: [DEFAULT_STAGES.READY], + reportFn: myCustomReportFunction, + }, + 'SomeComponentName', + ) const MyComponent = () => { useSomethingLoadingTimingInSomeComponentName( @@ -471,17 +470,16 @@ end immediately with the `lastStage: 'error'` and send out a report. ```tsx import { generateTimingHooks } from '@zendesk/react-measure-timing-hooks' -export const { - useSomethingLoadingTimingInSomeComponentName, -} = generateTimingHooks( - { - name: 'SomethingLoading', - idPrefix: 'some/identifier', - finalStages: [DEFAULT_STAGES.READY], - reportFn: myCustomReportFunction, - }, - 'SomeComponentName', -) +export const { useSomethingLoadingTimingInSomeComponentName } = + generateTimingHooks( + { + name: 'SomethingLoading', + idPrefix: 'some/identifier', + finalStages: [DEFAULT_STAGES.READY], + reportFn: myCustomReportFunction, + }, + 'SomeComponentName', + ) const MyComponent = () => { const { data, loading, error } = useQuery(myQuery) diff --git a/src/ActionLog.ts b/src/ActionLog.ts index ce4e6971..f86549bf 100644 --- a/src/ActionLog.ts +++ b/src/ActionLog.ts @@ -10,6 +10,7 @@ import type { DependencyList } from 'react' import { ACTION_TYPE, DEFAULT_DEBOUNCE_MS, + DEFAULT_LOADING_STAGES, DEFAULT_TIMEOUT_MS, ERROR_STAGES, INFORMATIVE_STAGES, @@ -18,14 +19,13 @@ import { } from './constants' import type { DebounceOptionsRef } from './debounce' import { debounce, FlushReason, TimeoutReason } from './debounce' -import type { ReportFn } from './generateReport' -import { generateReport } from './generateReport' import { performanceMark, performanceMeasure } from './performanceMark' import type { Action, ActionWithStateMetadata, DynamicActionLogOptions, - ReportWithInfo, + ReportArguments, + ReportFn, ShouldResetOnDependencyChange, SpanAction, StageChangeAction, @@ -62,7 +62,8 @@ export class ActionLog> { private lastStageBySource: Map = new Map() finalStages: readonly string[] = NO_FINAL_STAGES - immediateSendStages: readonly string[] = NO_IMMEDIATE_SEND_STAGES + loadingStages: readonly string[] = DEFAULT_LOADING_STAGES + immediateSendReportStages: readonly string[] = NO_IMMEDIATE_SEND_STAGES private dependenciesBySource: Map = new Map() private hasReportedAtLeastOnce = false @@ -156,7 +157,8 @@ export class ActionLog> { debounceMs, timeoutMs, finalStages, - immediateSendStages, + loadingStages, + immediateSendReportStages, minimumExpectedSimultaneousBeacons, waitForBeaconActivation, flushUponDeactivation, @@ -177,7 +179,9 @@ export class ActionLog> { this.debounceOptionsRef.debounceMs = debounceMs ?? DEFAULT_DEBOUNCE_MS this.debounceOptionsRef.timeoutMs = timeoutMs ?? DEFAULT_TIMEOUT_MS this.finalStages = finalStages ?? NO_FINAL_STAGES - this.immediateSendStages = immediateSendStages ?? NO_IMMEDIATE_SEND_STAGES + this.loadingStages = loadingStages ?? DEFAULT_LOADING_STAGES + this.immediateSendReportStages = + immediateSendReportStages ?? NO_IMMEDIATE_SEND_STAGES this.flushUponDeactivation = flushUponDeactivation ?? false this.waitForBeaconActivation = waitForBeaconActivation ?? [] } @@ -306,22 +310,22 @@ export class ActionLog> { info: Omit, previousStage: string = INFORMATIVE_STAGES.INITIAL, ) { - const { stage } = info + const { stage, renderEntry } = info const previousStageEntry = this.lastStageEntry const measureName = previousStageEntry ? `${this.id}/${info.source}/${previousStage}-till-${stage}` : `${this.id}/${info.source}/start-${stage}` const entry = previousStageEntry - ? performanceMeasure(measureName, previousStageEntry) - : performanceMark(measureName) + ? performanceMeasure(measureName, previousStageEntry, renderEntry) + : performanceMark(measureName, { startTime: renderEntry?.startTime }) this.addAction({ + ...info, type: ACTION_TYPE.STAGE_CHANGE, marker: MARKER.POINT, entry: Object.assign(entry, { startMark: previousStageEntry }), timestamp: entry.startTime + entry.duration, - ...info, }) } @@ -410,16 +414,13 @@ export class ActionLog> { new PerformanceObserver((entryList: PerformanceObserverEntryList) => { if (!this.isCapturingData) return - const mark = performanceMark(`${this.id}/longTaskEnd`) - const entries = entryList.getEntries() for (const entry of entries) { this.addSpan({ type: ACTION_TYPE.UNRESPONSIVE, source: OBSERVER_SOURCE, - // workaround for the fact that long-task performance measures do not have unique names: - entry: Object.assign(entry, { endMark: mark }), + entry, }) } }) @@ -520,7 +521,7 @@ export class ActionLog> { get isInImmediateSendStage(): boolean { return ( ERROR_STAGES.includes(this.lastStage) || - this.immediateSendStages.includes(this.lastStage) + this.immediateSendReportStages.includes(this.lastStage) ) } @@ -648,19 +649,21 @@ export class ActionLog> { ) } - const report = generateReport({ - actions: this.actions, - timingId: this.id, - isFirstLoad: !this.hasReportedAtLeastOnce, - immediateSendStages: [...ERROR_STAGES, ...this.immediateSendStages], - }) - const metadataValues = [...this.customMetadataBySource.values()] // eslint-disable-next-line @typescript-eslint/no-unsafe-assignment const metadata: CustomMetadata = Object.assign({}, ...metadataValues) - const reportWithMeta: ReportWithInfo = { - ...report, + const reportArgs: ReportArguments = { + actions: this.actions, + metadata, + loadingStages: this.loadingStages, + finalStages: this.finalStages, + immediateSendReportStages: + this.immediateSendReportStages.length > 0 + ? [...ERROR_STAGES, ...this.immediateSendReportStages] + : ERROR_STAGES, + timingId: this.id, + isFirstLoad: !this.hasReportedAtLeastOnce, maximumActiveBeaconsCount: highestNumberOfActiveBeaconsCountAtAnyGivenTime, minimumExpectedSimultaneousBeacons: @@ -676,13 +679,12 @@ export class ActionLog> { new Error( `useTiming: reportFn was not set, please set it to a function that will be called with the timing report`, ), - reportWithMeta, - metadata, + reportArgs, ) } if (hadReachedTheRequiredActiveBeaconsCount) { - this.reportFn(report, metadata, this.actions) + this.reportFn(reportArgs) } // clear slate for next re-render (stop observing) and disable reporting diff --git a/src/constants.ts b/src/constants.ts index 36c24549..5ede3467 100644 --- a/src/constants.ts +++ b/src/constants.ts @@ -14,6 +14,11 @@ export const DEFAULT_STAGES = { READY: 'ready', } as const +export const DEFAULT_LOADING_STAGES = [ + DEFAULT_STAGES.LOADING, + DEFAULT_STAGES.LOADING_MORE, +] as const + export const ERROR_STAGES: readonly string[] = [ DEFAULT_STAGES.ERROR, DEFAULT_STAGES.ERROR_BOUNDARY, diff --git a/src/debounce.ts b/src/debounce.ts index fc036dfa..b5b9aeb9 100644 --- a/src/debounce.ts +++ b/src/debounce.ts @@ -37,17 +37,17 @@ export type DebouncedFn = (( export const debounce = ( optionsRef: DebounceOptionsRef, ): DebouncedFn => { - let timeoutTimer: number | undefined - let debounceTimer: number | undefined + let timeoutTimer: ReturnType | undefined + let debounceTimer: ReturnType | undefined let lastArgs: Args | undefined const cancel = () => { - if (debounceTimer) window.clearTimeout(debounceTimer) + if (debounceTimer) clearTimeout(debounceTimer) debounceTimer = undefined } const reset = () => { cancel() - if (timeoutTimer) window.clearTimeout(timeoutTimer) + if (timeoutTimer) clearTimeout(timeoutTimer) timeoutTimer = undefined const args = lastArgs @@ -77,13 +77,13 @@ export const debounce = ( return Object.assign( (...args: Args) => { lastArgs = args - if (debounceTimer) window.clearTimeout(debounceTimer) - debounceTimer = window.setTimeout( + if (debounceTimer) clearTimeout(debounceTimer) + debounceTimer = setTimeout( () => flush(DebounceReason), optionsRef.debounceMs, ) if (!timeoutTimer && typeof optionsRef.timeoutMs === 'number') { - timeoutTimer = window.setTimeout(() => { + timeoutTimer = setTimeout(() => { flush(TimeoutReason) }, optionsRef.timeoutMs) } diff --git a/src/fixtures/actionsFixture.ts b/src/fixtures/actionsFixture.ts new file mode 100644 index 00000000..1eb7616b --- /dev/null +++ b/src/fixtures/actionsFixture.ts @@ -0,0 +1,129 @@ +import type { ActionWithStateMetadata } from '../types' + +export const id = 'test' +export const mountedPlacements = ['beacon'] + +export const actionsFixture: ActionWithStateMetadata[] = [ + { + type: 'stage-change', + marker: 'point', + timestamp: 100, + stage: 'loading', + source: 'beacon', + mountedPlacements, + timingId: id, + entry: { + duration: 100, + startTime: 0, + entryType: 'mark', + name: id, + toJSON: () => ({}), + }, + } as const, + { + type: 'render', + source: 'beacon', + marker: 'start', + timestamp: 100, + mountedPlacements, + timingId: id, + entry: { + duration: 0, + startTime: 0, + entryType: 'mark', + name: id, + toJSON: () => ({}), + }, + } as const, + { + type: 'render', + source: 'beacon', + marker: 'end', + timestamp: 200, + mountedPlacements, + timingId: id, + entry: { + duration: 100, + startTime: 100, + entryType: 'mark', + name: id, + toJSON: () => ({}), + }, + } as const, + { + type: 'stage-change', + marker: 'point', + timestamp: 200, + stage: 'ready', + source: 'beacon', + mountedPlacements, + timingId: id, + entry: { + duration: 100, + startTime: 100, + entryType: 'mark', + name: id, + toJSON: () => ({}), + }, + } as const, + { + type: 'render', + source: 'beacon', + marker: 'start', + timestamp: 200, + mountedPlacements, + timingId: id, + entry: { + duration: 0, + startTime: 200, + entryType: 'mark', + name: id, + toJSON: () => ({}), + }, + } as const, + { + type: 'render', + source: 'beacon', + marker: 'end', + timestamp: 300, + mountedPlacements, + timingId: id, + entry: { + duration: 100, + startTime: 200, + entryType: 'mark', + name: id, + toJSON: () => ({}), + }, + } as const, + { + type: 'unresponsive', + source: 'observer', + marker: 'start', + timestamp: 400, + mountedPlacements, + timingId: id, + entry: { + duration: 0, + startTime: 300, + entryType: 'mark', + name: id, + toJSON: () => ({}), + }, + } as const, + { + type: 'unresponsive', + source: 'observer', + marker: 'end', + timestamp: 900, + mountedPlacements, + timingId: id, + entry: { + duration: 300, + startTime: 600, + entryType: 'mark', + name: id, + toJSON: () => ({}), + }, + } as const, +] diff --git a/src/generateReport.test.ts b/src/generateReport.test.ts index 06f3b764..16ccae1a 100644 --- a/src/generateReport.test.ts +++ b/src/generateReport.test.ts @@ -5,144 +5,20 @@ * found at http://www.apache.org/licenses/LICENSE-2.0. */ -import { DEFAULT_STAGES } from './constants' +import { DEFAULT_LOADING_STAGES, DEFAULT_STAGES } from './constants' +import { + actionsFixture, + id, + mountedPlacements, +} from './fixtures/actionsFixture' import type { Report } from './generateReport' import { generateReport } from './generateReport' -import type { ActionWithStateMetadata } from './types' jest.mock('./utilities', () => ({ ...jest.requireActual('./utilities'), getCurrentBrowserSupportForNonResponsiveStateDetection: jest.fn(() => true), })) -const id = 'test' -const mountedPlacements = ['beacon'] - -const actionsFixture: ActionWithStateMetadata[] = [ - { - type: 'stage-change', - marker: 'point', - timestamp: 100, - stage: 'loading', - source: 'beacon', - mountedPlacements, - timingId: id, - entry: { - duration: 100, - startTime: 0, - entryType: 'mark', - name: id, - toJSON: () => ({}), - }, - } as const, - { - type: 'render', - source: 'beacon', - marker: 'start', - timestamp: 100, - mountedPlacements, - timingId: id, - entry: { - duration: 0, - startTime: 0, - entryType: 'mark', - name: id, - toJSON: () => ({}), - }, - } as const, - { - type: 'render', - source: 'beacon', - marker: 'end', - timestamp: 200, - mountedPlacements, - timingId: id, - entry: { - duration: 100, - startTime: 100, - entryType: 'mark', - name: id, - toJSON: () => ({}), - }, - } as const, - { - type: 'stage-change', - marker: 'point', - timestamp: 200, - stage: 'ready', - source: 'beacon', - mountedPlacements, - timingId: id, - entry: { - duration: 100, - startTime: 100, - entryType: 'mark', - name: id, - toJSON: () => ({}), - }, - } as const, - { - type: 'render', - source: 'beacon', - marker: 'start', - timestamp: 200, - mountedPlacements, - timingId: id, - entry: { - duration: 0, - startTime: 200, - entryType: 'mark', - name: id, - toJSON: () => ({}), - }, - } as const, - { - type: 'render', - source: 'beacon', - marker: 'end', - timestamp: 300, - mountedPlacements, - timingId: id, - entry: { - duration: 100, - startTime: 200, - entryType: 'mark', - name: id, - toJSON: () => ({}), - }, - } as const, - { - type: 'unresponsive', - source: 'observer', - marker: 'start', - timestamp: 400, - mountedPlacements, - timingId: id, - entry: { - duration: 0, - startTime: 300, - entryType: 'mark', - name: id, - toJSON: () => ({}), - }, - } as const, - { - type: 'unresponsive', - source: 'observer', - marker: 'end', - timestamp: 900, - mountedPlacements, - timingId: id, - entry: { - duration: 300, - startTime: 600, - entryType: 'mark', - name: id, - toJSON: () => ({}), - }, - } as const, -] - describe('generateReport', () => { const originalTimeOrigin = performance.timeOrigin beforeEach(() => { @@ -179,6 +55,7 @@ describe('generateReport', () => { tti, ttr, lastStage: DEFAULT_STAGES.READY, + flushReason: 'test', counts: { beacon: expectedBeaconRenderCount, observer: 1, @@ -286,7 +163,13 @@ describe('generateReport', () => { actions: actionsFixture, timingId: id, isFirstLoad, - immediateSendStages: [], + immediateSendReportStages: [], + loadingStages: DEFAULT_LOADING_STAGES, + metadata: {}, + finalStages: [], + flushReason: 'test', + maximumActiveBeaconsCount: 1, + minimumExpectedSimultaneousBeacons: 1, }) expect(report).toStrictEqual(expectedReport) diff --git a/src/generateReport.ts b/src/generateReport.ts index aac7a643..06acd6e4 100644 --- a/src/generateReport.ts +++ b/src/generateReport.ts @@ -7,28 +7,28 @@ import { ACTION_TYPE, - DEFAULT_STAGES, + DEFAULT_LOADING_STAGES, ERROR_STAGES, INFORMATIVE_STAGES, MARKER, OBSERVER_SOURCE, } from './constants' -import type { ActionWithStateMetadata, Span, StageDescription } from './types' +import type { + ActionWithStateMetadata, + ReportArguments, + Span, + StageDescription, +} from './types' import { getCurrentBrowserSupportForNonResponsiveStateDetection } from './utilities' -export type ReportFn> = ( - report: Report, - metadata: Metadata, - actions: ActionWithStateMetadata[], -) => void - export interface Report { + id: string ttr: number | null + /** TTI will not be present in browsers that do not support tracking long tasks */ tti: number | null timeSpent: Record counts: Record durations: Record - id: string isFirstLoad: boolean lastStage: string includedStages: string[] @@ -36,19 +36,17 @@ export interface Report { handled: boolean spans: Span[] loadingStagesDuration: number + flushReason: string } -export function generateReport({ +export function generateReport>({ actions, timingId, isFirstLoad = true, - immediateSendStages = [], -}: { - readonly actions: readonly ActionWithStateMetadata[] - readonly timingId?: string - readonly isFirstLoad?: boolean - readonly immediateSendStages?: readonly string[] -}): Report { + immediateSendReportStages = [], + loadingStages = DEFAULT_LOADING_STAGES, + flushReason = 'auto', +}: ReportArguments): Report { const lastStart: Record = {} let lastRenderEnd: number | null = null const timeSpent: Record = {} @@ -59,13 +57,12 @@ export function generateReport({ const counts: Record = {} let previousStageEndTime: number | null = null let previousStage: string = INFORMATIVE_STAGES.INITIAL - let lastStageMarkedAsDependencyChange = false const stageDescriptions: StageDescription[] = [] const durations: Record = {} const hasObserverSupport = getCurrentBrowserSupportForNonResponsiveStateDetection() - const allImmediateSendStages = [ - ...immediateSendStages, + const allImmediateSendReportStages = [ + ...immediateSendReportStages, INFORMATIVE_STAGES.TIMEOUT, ] const lastAction = [...actions].reverse()[0] @@ -86,35 +83,38 @@ export function generateReport({ const lastStageTime = previousStageEndTime ?? startTime const timeToStage = action.timestamp - lastStageTime! - const stageDescription: StageDescription = { - type: action.type, - source: action.source, - previousStage, - stage, - timeToStage, - previousStageTimestamp: (lastStageTime ?? 0) - startTime!, - timestamp: action.timestamp - startTime!, - ...(action.metadata - ? { - metadata: action.metadata, - } - : {}), - mountedPlacements: action.mountedPlacements, - timingId: action.timingId, - dependencyChanges, - } const lastStageDescription = stageDescriptions[stageDescriptions.length - 1] if (stage === previousStage && lastStageDescription) { - // update previous description - Object.assign(lastStageDescription, stageDescription, { - metadata: { - ...lastStageDescription.metadata, - ...stageDescription.metadata, - }, - }) + // since we're still in the same stage (possibly set by a different source this time), + // we just update previous stage description: + lastStageDescription.timeToStage = timeToStage + lastStageDescription.timestamp = action.timestamp - startTime! + lastStageDescription.metadata = Object.assign( + lastStageDescription.metadata ?? {}, + action.metadata, + ) + lastStageDescription.mountedPlacements = action.mountedPlacements + lastStageDescription.timingId = action.timingId + lastStageDescription.dependencyChanges = dependencyChanges } else if (stage !== previousStage) { - stageDescriptions.push(stageDescription) + stageDescriptions.push({ + type: action.type, + source: action.source, + previousStage, + stage, + timeToStage, + previousStageTimestamp: (lastStageTime ?? 0) - startTime!, + timestamp: action.timestamp - startTime!, + ...(action.metadata + ? { + metadata: action.metadata, + } + : {}), + mountedPlacements: action.mountedPlacements, + timingId: action.timingId, + dependencyChanges, + }) } } @@ -125,12 +125,7 @@ export function generateReport({ } includedStages.add(stage) - - lastStageMarkedAsDependencyChange = - action.type === ACTION_TYPE.DEPENDENCY_CHANGE - if (!lastStageMarkedAsDependencyChange) { - previousStage = stage - } + previousStage = stage } actions.forEach((action, index) => { @@ -172,8 +167,8 @@ export function generateReport({ action.type === ACTION_TYPE.UNRESPONSIVE ? 'unresponsive' : `<${action.source}> (${sourceDurations.length})`, - startTime: performance.timeOrigin + action.timestamp - duration, - endTime: performance.timeOrigin + action.timestamp, + startTime: action.timestamp - duration, + endTime: action.timestamp, relativeEndTime: action.timestamp - (startTime ?? 0), data: { mountedPlacements: action.mountedPlacements, @@ -191,8 +186,8 @@ export function generateReport({ spans.push({ type: action.type, description: 'dependency change', - startTime: lastDependencyChange! + performance.timeOrigin, - endTime: action.timestamp + performance.timeOrigin, + startTime: lastDependencyChange!, + endTime: action.timestamp, relativeEndTime: action.timestamp - (startTime ?? 0), data: { mountedPlacements: action.mountedPlacements, @@ -218,23 +213,23 @@ export function generateReport({ lastAction && lastAction.type !== ACTION_TYPE.STAGE_CHANGE, ) - const didImmediateSend = allImmediateSendStages.includes(previousStage) + const didImmediateSend = allImmediateSendReportStages.includes(previousStage) - stageDescriptions.forEach( - ({ - type, - previousStage: pStage, - stage, - previousStageTimestamp, - timestamp, - timeToStage, - ...data - }) => { - spans.push({ + spans.push( + ...stageDescriptions.map( + ({ + type, + previousStage: pStage, + stage, + previousStageTimestamp, + timestamp, + timeToStage, + ...data + }): Span => ({ type, description: `${pStage} to ${stage}`, - startTime: startTime! + previousStageTimestamp + performance.timeOrigin, - endTime: startTime! + timestamp + performance.timeOrigin, + startTime: startTime! + previousStageTimestamp, + endTime: startTime! + timestamp, relativeEndTime: timestamp, data: { stage, @@ -246,8 +241,8 @@ export function generateReport({ metadata: data.metadata ?? {}, dependencyChanges: data.dependencyChanges, }, - }) - }, + }), + ), ) const tti = @@ -276,8 +271,8 @@ export function generateReport({ spans.push({ type: 'ttr', description: 'render', - startTime: (startTime as unknown as number) + performance.timeOrigin, - endTime: lastRenderEnd + performance.timeOrigin, + startTime: startTime as unknown as number, + endTime: lastRenderEnd, relativeEndTime: lastRenderEnd - (startTime ?? 0), data: { mountedPlacements: lastAction.mountedPlacements, @@ -297,8 +292,8 @@ export function generateReport({ spans.push({ type: 'tti', description: 'interactive', - startTime: (startTime as unknown as number) + performance.timeOrigin, - endTime: (endTime as unknown as number) + performance.timeOrigin, + startTime: startTime as unknown as number, + endTime: endTime as unknown as number, relativeEndTime: (endTime as unknown as number) - (startTime ?? 0), data: { stage: INFORMATIVE_STAGES.INTERACTIVE, @@ -314,8 +309,8 @@ export function generateReport({ spans.push({ type: 'render', description: 'incomplete render', - startTime: lastRenderEnd + performance.timeOrigin, - endTime: lastRenderEnd + difference + performance.timeOrigin, + startTime: lastRenderEnd, + endTime: lastRenderEnd + difference, relativeEndTime: lastRenderEnd + difference, data: { stage: INFORMATIVE_STAGES.INCOMPLETE_RENDER, @@ -331,12 +326,11 @@ export function generateReport({ } } - const loadingStages = Object.values(spans).filter( + const loadingStagesSpans = Object.values(spans).filter( ({ data: { previousStage: pStage } }) => - pStage === DEFAULT_STAGES.LOADING || - pStage === DEFAULT_STAGES.LOADING_MORE, + pStage && loadingStages.includes(pStage), ) - const loadingStagesDuration = loadingStages.reduce( + const loadingStagesDuration = loadingStagesSpans.reduce( (total, { data: { timeToStage = 0 } }) => total + timeToStage, 0, ) @@ -355,5 +349,6 @@ export function generateReport({ hadError: ERROR_STAGES.includes(previousStage), loadingStagesDuration, spans, + flushReason, } } diff --git a/src/getExternalApi.test.ts b/src/getExternalApi.test.ts index 39e9b8cf..1353bd35 100644 --- a/src/getExternalApi.test.ts +++ b/src/getExternalApi.test.ts @@ -1,4 +1,5 @@ import { ActionLogCache } from './ActionLogCache' +import { generateReport } from './generateReport' import { getExternalApi } from './getExternalApi' const garbageCollectMs = 100_000 @@ -406,7 +407,8 @@ describe('getExternalApi', () => { expect(reportFn).toHaveBeenCalledTimes(1) expect(onInternalError).not.toHaveBeenCalled() expect(actionLog?.getActions()).toHaveLength(0) - expect(reportFn.mock.calls[0][0].spans).toMatchInlineSnapshot(` + expect(generateReport(reportFn.mock.calls[0][0]).spans) + .toMatchInlineSnapshot(` Array [ Object { "data": Object { diff --git a/src/main.ts b/src/main.ts index d7f2ae12..2e3d9135 100644 --- a/src/main.ts +++ b/src/main.ts @@ -9,7 +9,7 @@ export { ActionLog } from './ActionLog' export type { ActionLogRef } from './ActionLogCache' export { ActionLogCache } from './ActionLogCache' export * from './constants' -export type { Report, ReportFn } from './generateReport' +export type { Report } from './generateReport' export { generateReport } from './generateReport' export { generateTimingHooks } from './generateTimingHooks' export { getExternalApi } from './getExternalApi' diff --git a/src/performanceMark.ts b/src/performanceMark.ts index 3f0c605f..4b3fdfbe 100644 --- a/src/performanceMark.ts +++ b/src/performanceMark.ts @@ -5,27 +5,25 @@ * found at http://www.apache.org/licenses/LICENSE-2.0. */ -let uid = 0 -const getUniqueMarkName = (name: string) => `useTiming: ${name}/${uid++}` +const getTimingMarkName = (name: string) => `useTiming: ${name}` -export const performanceMark = (name: string): PerformanceMark => { +export const performanceMark = ( + name: string, + markOptions?: PerformanceMarkOptions, +): PerformanceMark => { // We want to use performance.mark, instead of performance.now or Date.now, // because those named metrics will then show up in the profiler and in Lighthouse audits // see: https://web.dev/user-timings/ // incidentally, this also makes testing waaay easier, because we don't have to deal with timestamps - // Since Firefox (Gecko) unfortunately behaves differently to other browsers, + // Since old browsers (like >1yr old Firefox/Gecko) unfortunately behaves differently to other browsers, // in that it doesn't immediately return the instance of PerformanceMark object // so we sort-of polyfill it cheaply below. // see: https://bugzilla.mozilla.org/show_bug.cgi?id=1724645 - // It does mean we need unique mark names, though. - const markName = getUniqueMarkName(name) + const markName = getTimingMarkName(name) try { - // we know this entry exists, because we created it above - const mark = - performance.mark(markName) ?? performance.getEntriesByName(name)[0] - + const mark = performance.mark(markName, markOptions) if (mark) return mark } catch { // do nothing, polyfill below @@ -35,7 +33,7 @@ export const performanceMark = (name: string): PerformanceMark => { return { name: markName, duration: 0, - startTime: performance.now(), + startTime: markOptions?.startTime ?? performance.now(), entryType: 'mark', toJSON: () => ({}), detail: null, @@ -48,19 +46,16 @@ export const performanceMeasure = ( endMark?: PerformanceEntry, ): PerformanceMeasure => { // same story as above - const measureName = getUniqueMarkName(name) + const measureName = getTimingMarkName(name) + const end = endMark ? endMark.startTime + endMark.duration : performance.now() // some old browsers might not like performance.measure / performance.mark // we don't want to crash due to reporting, so we'll polyfill instead try { - // create a mark of the same name, so we can create future measures from this point: - performance.mark(measureName) - - const measure = - performance.measure(measureName, startMark.name, endMark?.name) ?? - // we know this object exists, because we created it above - - performance.getEntriesByName(name)[0] + const measure = performance.measure(measureName, { + start: startMark.startTime, + end, + }) if (measure) return measure } catch { @@ -69,7 +64,7 @@ export const performanceMeasure = ( return { name: measureName, - duration: performance.now() - startMark.startTime, + duration: end - startMark.startTime, startTime: startMark.startTime, entryType: 'measure', toJSON: () => ({}), diff --git a/src/stories/MeasureTiming.stories.tsx b/src/stories/MeasureTiming.stories.tsx index 8cffa480..6990d107 100644 --- a/src/stories/MeasureTiming.stories.tsx +++ b/src/stories/MeasureTiming.stories.tsx @@ -9,9 +9,9 @@ import { useEffect, useState } from 'react' import * as React from 'react' import type { Meta, StoryObj } from '@storybook/react' -import type { ReportFn } from '../generateReport' import { onActionAddedCallback, useVisualizer } from '../lazyVisualizer' import { DEFAULT_STAGES, generateTimingHooks } from '../main' +import type { ReportFn } from '../types' const { useStoryTimingInA, useStoryTimingInB } = generateTimingHooks( { diff --git a/src/types.ts b/src/types.ts index 93ff74d9..0d15bd4b 100644 --- a/src/types.ts +++ b/src/types.ts @@ -9,7 +9,10 @@ import type { DependencyList } from 'react' import type { ActionLog } from './ActionLog' import type { ActionLogCache } from './ActionLogCache' import type { ACTION_TYPE, MARKER } from './constants' -import type { Report, ReportFn } from './generateReport' + +export type ReportFn> = ( + reportArgs: ReportArguments, +) => void export type ShouldResetOnDependencyChange = ( oldDependencies: DependencyList, @@ -30,8 +33,7 @@ export interface WithOnInternalError< > { onInternalError?: ( error: Error, - report?: Report | ReportWithInfo, - metadata?: CustomMetadata, + reportWithMetadata?: ReportArguments, ) => void } @@ -96,11 +98,16 @@ export interface StaticActionLogOptions< * If an empty array (default), the report will be sent immediately after rendering settles. * */ finalStages?: readonly string[] + /** + * List all the stages that will be considered as "loading stages". + * Used only for the reportFn. Does not affect other functionality. + * */ + loadingStages?: readonly string[] /** * When one of these stages is reached, we will IMMEDIATELY send the report and reset. - * By default this is just the ERROR stage. + * This always includes the error stages. * */ - immediateSendStages?: readonly string[] + immediateSendReportStages?: readonly string[] /** * Will only activate the timing hook after *all* the placements listed in the array were mounted * Specifying this can be useful if you have conditional logic that means only some hooks will get mounted (e.g. timing of opening a menu). @@ -132,10 +139,18 @@ export interface WithMetadata> { metadata?: Metadata } -export interface ReportWithInfo extends Report { - maximumActiveBeaconsCount: number - minimumExpectedSimultaneousBeacons?: number - flushReason: string +export interface ReportArguments> + extends Pick< + StaticActionLogOptions, + 'finalStages' | 'loadingStages' | 'immediateSendReportStages' + > { + readonly actions: readonly ActionWithStateMetadata[] + readonly timingId?: string + readonly isFirstLoad?: boolean + readonly maximumActiveBeaconsCount?: number + readonly minimumExpectedSimultaneousBeacons?: number + readonly flushReason?: string + readonly metadata?: CustomMetadata } export interface DynamicActionLogOptions< @@ -275,12 +290,14 @@ export type Marker = typeof MARKER[keyof typeof MARKER] export type SpanMarker = typeof MARKER['START' | 'END'] export type PointMarker = typeof MARKER['POINT'] +export type CustomPerformanceEntry = PerformanceEntry & { + startMark?: PerformanceEntry + endMark?: PerformanceEntry +} + export interface BaseAction { timestamp: number - entry: PerformanceEntry & { - startMark?: PerformanceEntry - endMark?: PerformanceEntry - } + entry: CustomPerformanceEntry type: NameT marker: MarkerT source: string @@ -297,6 +314,7 @@ export type StageChangeActionType = typeof ACTION_TYPE['STAGE_CHANGE'] export interface StageChangeAction extends BaseAction { stage: string + renderEntry?: CustomPerformanceEntry } export type DependencyChangeActionType = typeof ACTION_TYPE['DEPENDENCY_CHANGE'] diff --git a/src/useTiming.test.tsx b/src/useTiming.test.tsx index 30647865..2d548afb 100644 --- a/src/useTiming.test.tsx +++ b/src/useTiming.test.tsx @@ -14,8 +14,9 @@ import type { ReactTestRenderer } from 'react-test-renderer' import { act, create } from 'react-test-renderer' import { ActionLog } from './ActionLog' import { DEFAULT_STAGES, INFORMATIVE_STAGES } from './constants' -import type { Report, ReportFn } from './generateReport' +import { type Report, generateReport } from './generateReport' import * as performanceMock from './performanceMark' +import type { ReportFn } from './types' import { useTimingMeasurement } from './useTimingMeasurement' import { resetMemoizedCurrentBrowserSupportForNonResponsiveStateDetection } from './utilities' @@ -252,14 +253,14 @@ describe('useTiming', () => { includedStages: [], hadError: false, handled: true, + flushReason: 'debounce', } - expect(mockReportFn.mock.calls.at(-1)).toEqual([ - report, - expect.objectContaining({}), - expect.any(Array), - ]) - expect(mockReportFn.mock.calls.at(-1)?.[0].spans).toMatchInlineSnapshot(` + const reportArgs = mockReportFn.mock.calls.at(-1)?.[0] + expect(reportArgs).toBeDefined() + const generatedReport = generateReport(reportArgs!) + expect(generatedReport).toEqual(report) + expect(generatedReport.spans).toMatchInlineSnapshot(` Array [ Object { "data": Object { @@ -389,10 +390,15 @@ describe('useTiming', () => { includedStages: [], hadError: false, handled: true, + flushReason: 'debounce', } - expect(mockReportFn).toHaveBeenCalledWith(report, {}, expect.any(Array)) - expect(mockReportFn.mock.calls.at(-1)?.[0].spans).toMatchInlineSnapshot(` + expect(mockReportFn).toHaveBeenCalledTimes(1) + const reportArgs = mockReportFn.mock.calls.at(-1)?.[0] + expect(reportArgs).toBeDefined() + const generatedReport = generateReport(reportArgs!) + expect(generatedReport).toEqual(report) + expect(generatedReport.spans).toMatchInlineSnapshot(` Array [ Object { "data": Object { @@ -563,14 +569,15 @@ describe('useTiming', () => { ], hadError: false, handled: false, + flushReason: 'timeout', } - expect(mockReportFn.mock.calls.at(-1)).toEqual([ - report, - expect.objectContaining({}), - expect.any(Array), - ]) - expect(mockReportFn.mock.calls.at(-1)?.[0].spans).toMatchInlineSnapshot(` + expect(mockReportFn).toHaveBeenCalledTimes(1) + const reportArgs = mockReportFn.mock.calls.at(-1)?.[0] + expect(reportArgs).toBeDefined() + const generatedReport = generateReport(reportArgs!) + expect(generatedReport).toEqual(report) + expect(generatedReport.spans).toMatchInlineSnapshot(` Array [ Object { "data": Object { @@ -915,14 +922,15 @@ describe('useTiming', () => { ], hadError: false, handled: true, + flushReason: 'debounce', } - expect(mockReportFn).toHaveBeenLastCalledWith( - report, - expect.objectContaining({}), - expect.any(Array), - ) - expect(mockReportFn.mock.calls.at(-1)?.[0].spans).toMatchInlineSnapshot(` + expect(mockReportFn).toHaveBeenCalledTimes(1) + const reportArgs = mockReportFn.mock.calls.at(-1)?.[0] + expect(reportArgs).toBeDefined() + const generatedReport = generateReport(reportArgs!) + expect(generatedReport).toEqual(report) + expect(generatedReport.spans).toMatchInlineSnapshot(` Array [ Object { "data": Object { @@ -1297,14 +1305,15 @@ describe('useTiming', () => { includedStages: [DEFAULT_STAGES.LOADING, DEFAULT_STAGES.READY], hadError: false, handled: true, + flushReason: 'debounce', } - expect(mockReportFn.mock.calls.at(-1)).toEqual([ - report, - expect.objectContaining({}), - expect.any(Array), - ]) - expect(mockReportFn.mock.calls.at(-1)?.[0].spans).toMatchInlineSnapshot(` + expect(mockReportFn).toHaveBeenCalledTimes(1) + const reportArgs = mockReportFn.mock.calls.at(-1)?.[0] + expect(reportArgs).toBeDefined() + const generatedReport = generateReport(reportArgs!) + expect(generatedReport).toEqual(report) + expect(generatedReport.spans).toMatchInlineSnapshot(` Array [ Object { "data": Object { @@ -1627,14 +1636,15 @@ describe('useTiming', () => { includedStages: [], hadError: false, handled: true, + flushReason: 'debounce', } - expect(mockReportFn.mock.calls.at(-1)).toEqual([ - report, - expect.objectContaining({}), - expect.any(Array), - ]) - expect(mockReportFn.mock.calls.at(-1)?.[0].spans).toMatchInlineSnapshot(` + expect(mockReportFn).toHaveBeenCalledTimes(1) + const reportArgs = mockReportFn.mock.calls.at(-1)?.[0] + expect(reportArgs).toBeDefined() + const generatedReport = generateReport(reportArgs!) + expect(generatedReport).toEqual(report) + expect(generatedReport.spans).toMatchInlineSnapshot(` Array [ Object { "data": Object { @@ -1904,16 +1914,15 @@ describe('useTiming', () => { includedStages: [DEFAULT_STAGES.LOADING, DEFAULT_STAGES.ERROR], hadError: true, handled: true, + flushReason: 'immediate send', } expect(mockReportFn).toHaveBeenCalledTimes(1) - expect(mockReportFn.mock.calls.at(-1)).toEqual([ - report, - expect.objectContaining({}), - expect.any(Array), - ]) - - expect(mockReportFn.mock.calls.at(-1)?.[0].spans).toMatchInlineSnapshot(` + const reportArgs = mockReportFn.mock.calls.at(-1)?.[0] + expect(reportArgs).toBeDefined() + const generatedReport = generateReport(reportArgs!) + expect(generatedReport).toEqual(report) + expect(generatedReport.spans).toMatchInlineSnapshot(` Array [ Object { "data": Object { @@ -2212,15 +2221,15 @@ describe('useTiming', () => { includedStages: [DEFAULT_STAGES.LOADING, DEFAULT_STAGES.ERROR], hadError: true, handled: false, + flushReason: 'immediate send', } expect(mockReportFn).toHaveBeenCalledTimes(1) - expect(mockReportFn.mock.calls.at(-1)).toEqual([ - report, - expect.objectContaining({}), - expect.any(Array), - ]) - expect(mockReportFn.mock.calls.at(-1)?.[0].spans).toMatchInlineSnapshot(` + const reportArgs = mockReportFn.mock.calls.at(-1)?.[0] + expect(reportArgs).toBeDefined() + const generatedReport = generateReport(reportArgs!) + expect(generatedReport).toEqual(report) + expect(generatedReport.spans).toMatchInlineSnapshot(` Array [ Object { "data": Object { diff --git a/src/useTimingMeasurement.ts b/src/useTimingMeasurement.ts index 8c4a4b77..4c972218 100644 --- a/src/useTimingMeasurement.ts +++ b/src/useTimingMeasurement.ts @@ -42,11 +42,11 @@ export const useTimingMeasurement = < }: UseTimingMeasurementHookConfiguration, restartWhenChanged: DependencyList, ): void => { - const timestamp = performanceMark(`${id}/${placement}/render-start`) + const timestampMark = performanceMark(`${id}/${placement}/render-start`) - const lastStartTimeRef = useRef(timestamp) + const lastStartTimeRef = useRef(timestampMark) - lastStartTimeRef.current = timestamp + lastStartTimeRef.current = timestampMark actionLog.updateOptions( { @@ -92,11 +92,13 @@ export const useTimingMeasurement = < error, handled: true, }, + renderEntry: timestampMark, }) } else if (stage) { actionLog.markStage({ stage, source: placement, + renderEntry: timestampMark, }) }