From 2dd71f8510b7c946665b2657b1fbca356fd9ab9e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mitja=20Bezen=C5=A1ek?= Date: Wed, 8 May 2024 12:06:05 +0200 Subject: [PATCH] Measure action durations and fps for our interactions (#3472) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 - [ ] `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 - [ ] `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 --- apps/examples/src/hooks/usePerformance.ts | 23 ++++++++ apps/examples/src/misc/develop.tsx | 3 ++ packages/editor/api-report.md | 4 ++ packages/editor/src/lib/editor/Editor.ts | 30 ++++++++++- .../editor/src/lib/editor/tools/StateNode.ts | 24 +++++++++ packages/editor/src/lib/utils/debug-flags.ts | 1 + packages/utils/api-report.md | 12 +++++ packages/utils/src/index.ts | 1 + packages/utils/src/lib/PerformanceTracker.ts | 52 +++++++++++++++++++ packages/utils/src/lib/perf.ts | 29 ++++++++--- 10 files changed, 171 insertions(+), 8 deletions(-) create mode 100644 apps/examples/src/hooks/usePerformance.ts create mode 100644 packages/utils/src/lib/PerformanceTracker.ts diff --git a/apps/examples/src/hooks/usePerformance.ts b/apps/examples/src/hooks/usePerformance.ts new file mode 100644 index 000000000..8b626ddf5 --- /dev/null +++ b/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 + }, + } +} diff --git a/apps/examples/src/misc/develop.tsx b/apps/examples/src/misc/develop.tsx index db14ab8cd..bd7206163 100644 --- a/apps/examples/src/misc/develop.tsx +++ b/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 (
{ ;(window as any).app = editor diff --git a/packages/editor/api-report.md b/packages/editor/api-report.md index 1367f1294..611ff56ef 100644 --- a/packages/editor/api-report.md +++ b/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; readonly logPointerCaptures: DebugFlag; readonly logPreventDefaults: DebugFlag; + readonly measurePerformance: DebugFlag; readonly reconnectOnPing: DebugFlag; readonly showFps: DebugFlag; readonly throwToBlob: DebugFlag; @@ -1924,6 +1926,8 @@ export abstract class StateNode implements Partial { // (undocumented) _path: Computed; // (undocumented) + performanceTracker: PerformanceTracker; + // (undocumented) setCurrentToolIdMask(id: string | undefined): void; // (undocumented) shapeType?: string; diff --git a/packages/editor/src/lib/editor/Editor.ts b/packages/editor/src/lib/editor/Editor.ts index b85d05399..949ffecaf 100644 --- a/packages/editor/src/lib/editor/Editor.ts +++ b/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 { requestAnimationFrame(() => { this._tickManager.start() }) + + this.performanceTracker = new PerformanceTracker() } /** @@ -8232,6 +8236,12 @@ export class Editor extends EventEmitter { /** @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 { 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 { ), { immediate: true } ) + this.maybeTrackPerformance('Zooming') return } case 'pan': { @@ -8479,6 +8490,7 @@ export class Editor extends EventEmitter { 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 { // 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 { 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 { 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()) { diff --git a/packages/editor/src/lib/editor/tools/StateNode.ts b/packages/editor/src/lib/editor/tools/StateNode.ts index ed09dc469..3089be5e8 100644 --- a/packages/editor/src/lib/editor/tools/StateNode.ts +++ b/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 { + performanceTracker: PerformanceTracker constructor( public editor: Editor, parent?: StateNode @@ -60,6 +76,7 @@ export abstract class StateNode implements Partial { this._current.set(this.children[this.initial]) } } + this.performanceTracker = new PerformanceTracker() } static id: string @@ -159,6 +176,10 @@ export abstract class StateNode implements Partial { // 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 { // 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) diff --git a/packages/editor/src/lib/utils/debug-flags.ts b/packages/editor/src/lib/utils/debug-flags.ts index 19d801de7..88081f052 100644 --- a/packages/editor/src/lib/utils/debug-flags.ts +++ b/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 }, }), diff --git a/packages/utils/api-report.md b/packages/utils/api-report.md index a88194d0e..f206fe4f5 100644 --- a/packages/utils/api-report.md +++ b/packages/utils/api-report.md @@ -242,6 +242,18 @@ export function omitFromStackTrace, Return>(fn: (... // @internal export function partition(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) diff --git a/packages/utils/src/index.ts b/packages/utils/src/index.ts index 90273933b..b3b2ce6d8 100644 --- a/packages/utils/src/index.ts +++ b/packages/utils/src/index.ts @@ -1,3 +1,4 @@ +export { PerformanceTracker } from './lib/PerformanceTracker' export { areArraysShallowEqual, compact, diff --git a/packages/utils/src/lib/PerformanceTracker.ts b/packages/utils/src/lib/PerformanceTracker.ts new file mode 100644 index 000000000..1c15f9512 --- /dev/null +++ b/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 + } +} diff --git a/packages/utils/src/lib/perf.ts b/packages/utils/src/lib/perf.ts index 2f9283fd9..b97e50ef3 100644 --- a/packages/utils/src/lib/perf.ts +++ b/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( - `${propertyKey} took ${(end - start).toFixed(2)}ms | average ${(total / count).toFixed(2)}ms` + console.debug( + `%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