Merge pull request #7 from zendesk/next

feat: expose tti and ttr PerformanceMeasures and add debugging metadata to them

Author: bbrzoska

src/ActionLog.ts

@@ -85,6 +85,22 @@ export class ActionLog<CustomMetadata extends Record<string, unknown>> {
     return this.actions
   }
 
+  /**
+   * Clear performance marks that were added by this ActionLog instance.
+   */
+  private clearPerformanceMarks(): void {
+    this.actions.forEach((action) => {
+      if (!action.entry.name) return
+      try {
+        if (action.entry instanceof PerformanceMeasure) {
+          performance.clearMeasures(action.entry.name)
+        }
+      } catch {
+        // ignore
+      }
+    })
+  }
+
   /**
    * Clear parts of the internal state, so it's ready for the next measurement.
    */
@@ -99,6 +115,7 @@ export class ActionLog<CustomMetadata extends Record<string, unknown>> {
       this.debouncedTrigger.cancel()
     }
     this.stopObserving()
+    this.clearPerformanceMarks()
     this.actions = []
     this.lastStage = INFORMATIVE_STAGES.INITIAL
     this.lastStageUpdatedAt = performance.now()
@@ -627,6 +644,27 @@ export class ActionLog<CustomMetadata extends Record<string, unknown>> {
 
     const { lastRenderAction } = this
 
+    const metadataValues = [...this.customMetadataBySource.values()]
+    // eslint-disable-next-line @typescript-eslint/no-unsafe-assignment
+    const metadata: CustomMetadata = Object.assign({}, ...metadataValues)
+
+    const detail = {
+      metadata,
+      timingId: this.id,
+      isFirstLoad: !this.hasReportedAtLeastOnce,
+      maximumActiveBeaconsCount:
+        highestNumberOfActiveBeaconsCountAtAnyGivenTime,
+      minimumExpectedSimultaneousBeacons:
+        this.minimumExpectedSimultaneousBeacons,
+      flushReason:
+        typeof flushReason === 'symbol'
+          ? flushReason.description ?? 'manual'
+          : flushReason,
+    }
+
+    let tti: PerformanceMeasure | undefined
+    let ttr: PerformanceMeasure | undefined
+
     if (timedOut) {
       this.addStageChange(
         {
@@ -637,41 +675,30 @@ export class ActionLog<CustomMetadata extends Record<string, unknown>> {
       )
     } else if (lastRenderAction) {
       // add a measure so we can use it in Lighthouse runs
-      performanceMeasure(
+      tti = performanceMeasure(
         `${this.id}/tti`,
         firstAction.entry.startMark ?? firstAction.entry,
         lastAction.entry.endMark ?? lastAction.entry,
+        detail,
       )
-      performanceMeasure(
+      ttr = performanceMeasure(
         `${this.id}/ttr`,
         firstAction.entry.startMark ?? firstAction.entry,
         lastRenderAction.entry.endMark ?? lastRenderAction.entry,
+        detail,
       )
     }
 
-    const metadataValues = [...this.customMetadataBySource.values()]
-    // eslint-disable-next-line @typescript-eslint/no-unsafe-assignment
-    const metadata: CustomMetadata = Object.assign({}, ...metadataValues)
-
     const reportArgs: ReportArguments<CustomMetadata> = {
+      ...detail,
       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:
-        this.minimumExpectedSimultaneousBeacons,
-      flushReason:
-        typeof flushReason === 'symbol'
-          ? flushReason.description ?? 'manual'
-          : flushReason,
+      measures: { tti, ttr },
     }
 
     if (this.reportFn === noop) {

src/TimingDisplay.tsx

@@ -174,7 +174,7 @@ function getPoints<A extends Action>(
 }
 
 function getChartPoints(actions: ActionWithStateMetadata[]) {
-  const report = generateReport({ actions })
+  const report = generateReport({ actions, measures: {} })
   const sources = Object.keys(report.counts)
   const sourceToColor = Object.fromEntries(
     sources.map((source, index) => [

src/generateReport.test.ts

@@ -170,6 +170,7 @@ describe('generateReport', () => {
       flushReason: 'test',
       maximumActiveBeaconsCount: 1,
       minimumExpectedSimultaneousBeacons: 1,
+      measures: {},
     })
 
     expect(report).toStrictEqual(expectedReport)

src/performanceMark.ts

@@ -10,23 +10,24 @@ const getTimingMarkName = (name: string) => `useTiming: ${name}`
 export const performanceMark = (
   name: string,
   markOptions?: PerformanceMarkOptions,
+  realMark = false,
 ): 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 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
   const markName = getTimingMarkName(name)
 
-  try {
-    const mark = performance.mark(markName, markOptions)
-    if (mark) return mark
-  } catch {
-    // do nothing, polyfill below
+  // default to a "fake performance.mark", to improve UX in the profiler
+  // (otherwise we have thousands of little marks sprinkled everywhere)
+  if (realMark) {
+    // 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
+
+    try {
+      const mark = performance.mark(markName, markOptions)
+      if (mark) return mark
+    } catch {
+      // do nothing, polyfill below
+    }
   }
 
   // polyfill:
@@ -36,25 +37,32 @@ export const performanceMark = (
     startTime: markOptions?.startTime ?? performance.now(),
     entryType: 'mark',
     toJSON: () => ({}),
-    detail: null,
+    // eslint-disable-next-line @typescript-eslint/no-unsafe-assignment
+    detail: markOptions?.detail ?? null,
   }
 }
 
 export const performanceMeasure = (
   name: string,
   startMark: PerformanceEntry,
   endMark?: PerformanceEntry,
+  detail?: unknown,
 ): PerformanceMeasure => {
-  // same story as above
+  // 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
+
   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 {
     const measure = performance.measure(measureName, {
-      start: startMark.startTime,
+      start: startMark.startTime + startMark.duration,
       end,
+      detail,
     })
 
     if (measure) return measure
@@ -68,6 +76,6 @@ export const performanceMeasure = (
     startTime: startMark.startTime,
     entryType: 'measure',
     toJSON: () => ({}),
-    detail: null,
+    detail: detail ?? null,
   }
 }

src/stories/MeasureTiming.stories.tsx

@@ -49,6 +49,8 @@ const RenderImmediately = ({
   return <div>Rendering immediately</div>
 }
 
+RenderImmediately.displayName = 'RenderImmediately'
+
 const TakesAWhileB = ({
   setStage,
 }: {
@@ -73,6 +75,8 @@ const TakesAWhileB = ({
   return <div>Something else that loads for a while... {progress}%</div>
 }
 
+TakesAWhileB.displayName = 'TakesAWhileB'
+
 const TakesAWhile = ({
   reportFn,
   isActive,
@@ -110,6 +114,8 @@ const TakesAWhile = ({
   )
 }
 
+TakesAWhile.displayName = 'TakesAWhile'
+
 const VisualizerExample = ({ mounted, ...props }: IArgs) => {
   const { content, visualizer } = props
 
@@ -128,6 +134,8 @@ const VisualizerExample = ({ mounted, ...props }: IArgs) => {
   )
 }
 
+VisualizerExample.displayName = 'VisualizerExample'
+
 export const MeasureTimingStory: StoryObj<IArgs> = {
   render: (props) => <VisualizerExample {...props} />,
   args: {
@@ -168,7 +176,7 @@ export const MeasureTimingStory: StoryObj<IArgs> = {
   },
 }
 
-const Component: React.FunctionComponent<{}> = () => <>'Hello world'</>
+const Component: React.FunctionComponent<{}> = () => <>Hello world</>
 
 const meta: Meta<{}> = {
   // title: 'Packages/MeasureTiming',

src/types.ts

@@ -151,6 +151,10 @@ export interface ReportArguments<CustomMetadata extends Record<string, unknown>>
   readonly minimumExpectedSimultaneousBeacons?: number
   readonly flushReason?: string
   readonly metadata?: CustomMetadata
+  readonly measures: {
+    tti?: PerformanceMeasure
+    ttr?: PerformanceMeasure
+  }
 }
 
 export interface DynamicActionLogOptions<