Measure action durations and fps for our interactions (#3472)

Adds a feature flag `Measure performance` that allows us to:
- Measure the performance of all the actions (it wraps them into
`measureCbDuration`).
- Measure the frame rate of certain interactions like resizing,
erasing,....

Example of how it looks like:

![CleanShot 2024-04-17 at 18 04
05](https://github.com/tldraw/tldraw/assets/2523721/0fb69745-f7b2-4b55-ac01-27ea26963d9a)


### Change Type

<!-- ❗ Please select a 'Scope' label ❗️ -->

- [ ] `sdk` — Changes the tldraw SDK
- [ ] `dotcom` — Changes the tldraw.com web app
- [ ] `docs` — Changes to the documentation, examples, or templates.
- [ ] `vs code` — Changes to the vscode plugin
- [x] `internal` — Does not affect user-facing stuff

<!-- ❗ Please select a 'Type' label ❗️ -->

- [ ] `bugfix` — Bug fix
- [ ] `feature` — New feature
- [ ] `improvement` — Improving existing features
- [ ] `chore` — Updating dependencies, other boring stuff
- [ ] `galaxy brain` — Architectural changes
- [ ] `tests` — Changes to any test code
- [x] `tools` — Changes to infrastructure, CI, internal scripts,
debugging tools, etc.
- [ ] `dunno` — I don't know
=

---------

Co-authored-by: Mime Čuvalo <mimecuvalo@gmail.com>

apps/examples/src/hooks/usePerformance.ts

@@ -0,0 +1,23 @@
+import { TLUiEventSource, TLUiOverrides, debugFlags, measureCbDuration, useValue } from 'tldraw'
+
+export function usePerformance(): TLUiOverrides {
+	const measurePerformance = useValue(
+		'measurePerformance',
+		() => debugFlags.measurePerformance.get(),
+		[debugFlags]
+	)
+	if (!measurePerformance) return {}
+	return {
+		actions(_editor, actions) {
+			Object.keys(actions).forEach((key) => {
+				const action = actions[key]
+				const cb = action.onSelect
+				action.onSelect = (source: TLUiEventSource) => {
+					return measureCbDuration(`Action ${key}`, () => cb(source))
+				}
+			})
+
+			return actions
+		},
+	}
+}

apps/examples/src/misc/develop.tsx

@@ -1,10 +1,13 @@
 import { Tldraw } from 'tldraw'
 import 'tldraw/tldraw.css'
+import { usePerformance } from '../hooks/usePerformance'
 
 export default function Develop() {
+	const performanceOverrides = usePerformance()
 	return (
 		<div className="tldraw__editor">
 			<Tldraw
+				overrides={[performanceOverrides]}
 				persistenceKey="tldraw_example"
 				onMount={(editor) => {
 					;(window as any).app = editor

packages/editor/api-report.md

@@ -23,6 +23,7 @@ import { JSX as JSX_2 } from 'react/jsx-runtime';
 import { LegacyMigrations } from '@tldraw/store';
 import { MigrationSequence } from '@tldraw/store';
 import { NamedExoticComponent } from 'react';
+import { PerformanceTracker } from '@tldraw/utils';
 import { PointerEventHandler } from 'react';
 import { react } from '@tldraw/state';
 import { default as React_2 } from 'react';
@@ -450,6 +451,7 @@ export const debugFlags: {
     readonly logElementRemoves: DebugFlag<boolean>;
     readonly logPointerCaptures: DebugFlag<boolean>;
     readonly logPreventDefaults: DebugFlag<boolean>;
+    readonly measurePerformance: DebugFlag<boolean>;
     readonly reconnectOnPing: DebugFlag<boolean>;
     readonly showFps: DebugFlag<boolean>;
     readonly throwToBlob: DebugFlag<boolean>;
@@ -1924,6 +1926,8 @@ export abstract class StateNode implements Partial<TLEventHandlers> {
     // (undocumented)
     _path: Computed<string>;
     // (undocumented)
+    performanceTracker: PerformanceTracker;
+    // (undocumented)
     setCurrentToolIdMask(id: string | undefined): void;
     // (undocumented)
     shapeType?: string;

packages/editor/src/lib/editor/Editor.ts

@@ -41,6 +41,7 @@ import {
 import {
 	IndexKey,
 	JsonObject,
+	PerformanceTracker,
 	annotateError,
 	assert,
 	compact,
@@ -98,6 +99,7 @@ import { PI2, approximately, areAnglesCompatible, clamp, pointInPolygon } from '
 import { ReadonlySharedStyleMap, SharedStyle, SharedStyleMap } from '../utils/SharedStylesMap'
 import { WeakMapCache } from '../utils/WeakMapCache'
 import { dataUrlToFile } from '../utils/assets'
+import { debugFlags } from '../utils/debug-flags'
 import { getIncrementedName } from '../utils/getIncrementedName'
 import { getReorderingShapesChanges } from '../utils/reorderShapes'
 import { applyRotationToSnapshotShapes, getRotationSnapshot } from '../utils/rotation'
@@ -676,6 +678,8 @@ export class Editor extends EventEmitter<TLEventMap> {
 		requestAnimationFrame(() => {
 			this._tickManager.start()
 		})
+
+		this.performanceTracker = new PerformanceTracker()
 	}
 
 	/**
@@ -8232,6 +8236,12 @@ export class Editor extends EventEmitter<TLEventMap> {
 	/** @internal */
 	capturedPointerId: number | null = null
 
+	/** @internal */
+	private readonly performanceTracker: PerformanceTracker
+
+	/** @internal */
+	private performanceTrackerTimeout = -1 as any
+
 	/**
 	 * Dispatch an event to the editor.
 	 *
@@ -8318,7 +8328,7 @@ export class Editor extends EventEmitter<TLEventMap> {
 		if (info.ctrlKey) {
 			clearInterval(this._ctrlKeyTimeout)
 			this._ctrlKeyTimeout = -1
-			inputs.ctrlKey = true /** @internal */ /** @internal */ /** @internal */
+			inputs.ctrlKey = true
 		} else if (!info.ctrlKey && inputs.ctrlKey && this._ctrlKeyTimeout === -1) {
 			this._ctrlKeyTimeout = setTimeout(this._setCtrlKeyTimeout, 150)
 		}
@@ -8472,6 +8482,7 @@ export class Editor extends EventEmitter<TLEventMap> {
 									),
 									{ immediate: true }
 								)
+								this.maybeTrackPerformance('Zooming')
 								return
 							}
 							case 'pan': {
@@ -8479,6 +8490,7 @@ export class Editor extends EventEmitter<TLEventMap> {
 								this._setCamera(new Vec(cx + (dx * panSpeed) / cz, cy + (dy * panSpeed) / cz, cz), {
 									immediate: true,
 								})
+								this.maybeTrackPerformance('Panning')
 								return
 							}
 						}
@@ -8552,7 +8564,6 @@ export class Editor extends EventEmitter<TLEventMap> {
 						// If the user is in pen mode, but the pointer is not a pen, stop here.
 						if (!isPen && isPenMode) return
 
-						// If we've started panning, then clear any long press timeout
 						if (this.inputs.isPanning && this.inputs.isPointing) {
 							// Handle spacebar / middle mouse button panning
 							const { currentScreenPoint, previousScreenPoint } = this.inputs
@@ -8563,6 +8574,7 @@ export class Editor extends EventEmitter<TLEventMap> {
 								new Vec(cx + (offset.x * panSpeed) / cz, cy + (offset.y * panSpeed) / cz, cz),
 								{ immediate: true }
 							)
+							this.maybeTrackPerformance('Panning')
 							return
 						}
 
@@ -8719,6 +8731,20 @@ export class Editor extends EventEmitter<TLEventMap> {
 
 		return this
 	}
+
+	/** @internal */
+	private maybeTrackPerformance(name: string) {
+		if (debugFlags.measurePerformance.get()) {
+			if (this.performanceTracker.isStarted()) {
+				clearTimeout(this.performanceTrackerTimeout)
+			} else {
+				this.performanceTracker.start(name)
+			}
+			this.performanceTrackerTimeout = setTimeout(() => {
+				this.performanceTracker.stop()
+			}, 50)
+		}
+	}
 }
 
 function alertMaxShapes(editor: Editor, pageId = editor.getCurrentPageId()) {

packages/editor/src/lib/editor/tools/StateNode.ts

@@ -1,4 +1,6 @@
 import { Atom, Computed, atom, computed } from '@tldraw/state'
+import { PerformanceTracker } from '@tldraw/utils'
+import { debugFlags } from '../../utils/debug-flags'
 import type { Editor } from '../Editor'
 import {
 	EVENT_NAME_MAP,
@@ -10,6 +12,19 @@ import {
 } from '../types/event-types'
 
 type TLStateNodeType = 'branch' | 'leaf' | 'root'
+const STATE_NODES_TO_MEASURE = [
+	'brushing',
+	'cropping',
+	'dragging',
+	'dragging_handle',
+	'drawing',
+	'erasing',
+	'lasering',
+	'resizing',
+	'rotating',
+	'scribble_brushing',
+	'translating',
+]
 
 /** @public */
 export interface TLStateNodeConstructor {
@@ -21,6 +36,7 @@ export interface TLStateNodeConstructor {
 
 /** @public */
 export abstract class StateNode implements Partial<TLEventHandlers> {
+	performanceTracker: PerformanceTracker
 	constructor(
 		public editor: Editor,
 		parent?: StateNode
@@ -60,6 +76,7 @@ export abstract class StateNode implements Partial<TLEventHandlers> {
 				this._current.set(this.children[this.initial])
 			}
 		}
+		this.performanceTracker = new PerformanceTracker()
 	}
 
 	static id: string
@@ -159,6 +176,10 @@ export abstract class StateNode implements Partial<TLEventHandlers> {
 
 	// todo: move this logic into transition
 	enter = (info: any, from: string) => {
+		if (debugFlags.measurePerformance.get() && STATE_NODES_TO_MEASURE.includes(this.id)) {
+			this.performanceTracker.start(this.id)
+		}
+
 		this._isActive.set(true)
 		this.onEnter?.(info, from)
 
@@ -171,6 +192,9 @@ export abstract class StateNode implements Partial<TLEventHandlers> {
 
 	// todo: move this logic into transition
 	exit = (info: any, from: string) => {
+		if (debugFlags.measurePerformance.get() && this.performanceTracker.isStarted()) {
+			this.performanceTracker.stop()
+		}
 		this._isActive.set(false)
 		this.onExit?.(info, from)
 

packages/editor/src/lib/utils/debug-flags.ts

@@ -41,6 +41,7 @@ export const debugFlags = {
 	showFps: createDebugValue('showFps', {
 		defaults: { all: false },
 	}),
+	measurePerformance: createDebugValue('measurePerformance', { defaults: { all: false } }),
 	throwToBlob: createDebugValue('throwToBlob', {
 		defaults: { all: false },
 	}),

packages/utils/api-report.md

@@ -242,6 +242,18 @@ export function omitFromStackTrace<Args extends Array<unknown>, Return>(fn: (...
 // @internal
 export function partition<T>(arr: T[], predicate: (item: T) => boolean): [T[], T[]];
 
+// @public (undocumented)
+export class PerformanceTracker {
+    // (undocumented)
+    isStarted(): boolean;
+    // (undocumented)
+    recordFrame: () => void;
+    // (undocumented)
+    start(name: string): void;
+    // (undocumented)
+    stop(): void;
+}
+
 // @public (undocumented)
 export class PngHelpers {
     // (undocumented)

packages/utils/src/index.ts

@@ -1,3 +1,4 @@
+export { PerformanceTracker } from './lib/PerformanceTracker'
 export {
 	areArraysShallowEqual,
 	compact,

packages/utils/src/lib/PerformanceTracker.ts

@@ -0,0 +1,52 @@
+import { PERFORMANCE_COLORS, PERFORMANCE_PREFIX_COLOR } from './perf'
+
+/** @public */
+export class PerformanceTracker {
+	private startTime = 0
+	private name = ''
+	private frames = 0
+	private started = false
+	private frame: number | null = null
+
+	recordFrame = () => {
+		this.frames++
+		if (!this.started) return
+		this.frame = requestAnimationFrame(this.recordFrame)
+	}
+
+	start(name: string) {
+		this.name = name
+		this.frames = 0
+		this.started = true
+		if (this.frame !== null) cancelAnimationFrame(this.frame)
+		this.frame = requestAnimationFrame(this.recordFrame)
+		this.startTime = performance.now()
+	}
+
+	stop() {
+		this.started = false
+		if (this.frame !== null) cancelAnimationFrame(this.frame)
+		const duration = (performance.now() - this.startTime) / 1000
+		const fps = duration === 0 ? 0 : Math.floor(this.frames / duration)
+		const background =
+			fps > 55
+				? PERFORMANCE_COLORS.Good
+				: fps > 30
+					? PERFORMANCE_COLORS.Mid
+					: PERFORMANCE_COLORS.Poor
+		const color = background === PERFORMANCE_COLORS.Mid ? 'black' : 'white'
+		const capitalized = this.name[0].toUpperCase() + this.name.slice(1)
+		// eslint-disable-next-line no-console
+		console.debug(
+			`%cPerf%c ${capitalized} %c${fps}%c fps`,
+			`color: white; background: ${PERFORMANCE_PREFIX_COLOR};padding: 2px;border-radius: 3px;`,
+			'font-weight: normal',
+			`font-weight: bold; padding: 2px; background: ${background};color: ${color};`,
+			'font-weight: normal'
+		)
+	}
+
+	isStarted() {
+		return this.started
+	}
+}

packages/utils/src/lib/perf.ts

@@ -1,9 +1,21 @@
+export const PERFORMANCE_COLORS = {
+	Good: '#40C057',
+	Mid: '#FFC078',
+	Poor: '#E03131',
+}
+
+export const PERFORMANCE_PREFIX_COLOR = PERFORMANCE_COLORS.Good
+
 /** @internal */
 export function measureCbDuration(name: string, cb: () => any) {
-	const now = performance.now()
+	const start = performance.now()
 	const result = cb()
 	// eslint-disable-next-line no-console
-	console.log(`${name} took`, performance.now() - now, 'ms')
+	console.debug(
+		`%cPerf%c ${name} took ${performance.now() - start}ms`,
+		`color: white; background: ${PERFORMANCE_PREFIX_COLOR};padding: 2px;border-radius: 3px;`,
+		'font-weight: normal'
+	)
 	return result
 }
 
@@ -13,9 +25,12 @@ export function measureDuration(_target: any, propertyKey: string, descriptor: P
 	descriptor.value = function (...args: any[]) {
 		const start = performance.now()
 		const result = originalMethod.apply(this, args)
-		const end = performance.now()
 		// eslint-disable-next-line no-console
-		console.log(`${propertyKey} took ${end - start}ms `)
+		console.debug(
+			`%cPerf%c ${propertyKey} took: ${performance.now() - start}ms`,
+			`color: white; background: ${PERFORMANCE_PREFIX_COLOR};padding: 2px;border-radius: 3px;`,
+			'font-weight: normal'
+		)
 		return result
 	}
 	return descriptor
@@ -41,8 +56,10 @@ export function measureAverageDuration(
 			const count = value.count + 1
 			averages.set(descriptor.value, { total, count })
 			// eslint-disable-next-line no-console
-			console.log(
+			console.debug(
-				`${propertyKey} took ${(end - start).toFixed(2)}ms | average ${(total / count).toFixed(2)}ms`
+				`%cPerf%c ${propertyKey} took ${(end - start).toFixed(2)}ms | average ${(total / count).toFixed(2)}ms`,
+				`color: white; background: ${PERFORMANCE_PREFIX_COLOR};padding: 2px;border-radius: 3px;`,
+				'font-weight: normal'
 			)
 		}
 		return result