From 57ca1c8083a0412fcc799dbdb222d4a625afcfc9 Mon Sep 17 00:00:00 2001 From: Linus Rath <139418639+rathlinus@users.noreply.github.com> Date: Thu, 22 Oct 2026 03:09:17 +0200 Subject: [PATCH] test: log timing marks for the performance harness when launched with -perfMarks --- App.tsx | 5 ++ index.ts | 4 + src/components/EmailBodyView.tsx | 3 + src/components/RichTextEditor.tsx | 2 + src/lib/__tests__/perf-marks.test.ts | 62 +++++++++++++++ src/lib/perf-marks.ts | 112 +++++++++++++++++++++++++++ src/screens/EmailListScreen.tsx | 20 ++++- 7 files changed, 206 insertions(+), 2 deletions(-) create mode 100644 src/lib/__tests__/perf-marks.test.ts create mode 100644 src/lib/perf-marks.ts diff --git a/App.tsx b/App.tsx index 15a8134a..14571410 100644 --- a/App.tsx +++ b/App.tsx @@ -94,6 +94,7 @@ import { useOfflineCacheStore } from './src/stores/offline-cache-store'; import { useOutboxStore } from './src/stores/outbox-store'; import { runOfflineSync } from './src/lib/offline-sync'; import { spacing, typography, type ThemePalette } from './src/theme/tokens'; +import { perfEndAfterPaint, perfMarksEnabled, perfStart } from './src/lib/perf-marks'; import { useColors } from './src/theme/colors'; const Stack = createNativeStackNavigator(); @@ -261,6 +262,10 @@ function MainTabsNavigator({ navigation }: NativeStackScreenProps ({ + tabPress: () => perfStart('tab-switch'), + focus: () => perfEndAfterPaint('tab-switch', { to: route.name }), + }) : undefined} screenOptions={{ headerShown: false, // Tabs out of view stop re-rendering until they are shown again. diff --git a/index.ts b/index.ts index 965b95a4..5ad23c22 100644 --- a/index.ts +++ b/index.ts @@ -6,6 +6,10 @@ import { registerWidgetTaskHandler } from 'react-native-android-widget'; import { pushBackgroundTask } from './src/lib/push-background-task'; import { widgetTaskHandler } from './src/widgets/task-handler'; import { refreshWidgetsInBackground } from './src/widgets/sync'; +import { perfMark } from './src/lib/perf-marks'; + +// Every import above has run: the bundle is loaded (performance harness). +perfMark('bundle-loaded'); import { markUiStarted } from './src/widgets/ui-presence'; // Runs in a fresh headless JS runtime when BulwarkPushTaskService is started diff --git a/src/components/EmailBodyView.tsx b/src/components/EmailBodyView.tsx index 091f0088..addfc435 100644 --- a/src/components/EmailBodyView.tsx +++ b/src/components/EmailBodyView.tsx @@ -19,6 +19,7 @@ import { useContactsStore } from '../stores/contacts-store'; import { useLocaleStore } from '../stores/locale-store'; import { spacing, typography, type ThemePalette } from '../theme/tokens'; import { useColors, useResolvedTheme } from '../theme/colors'; +import { perfEndAfterPaint } from '../lib/perf-marks'; import type { RootStackParamList } from '../navigation/types'; type Nav = NativeStackNavigationProp; @@ -685,6 +686,8 @@ export default function EmailBodyView({ const onMessage = (e: WebViewMessageEvent) => { const data = e.nativeEvent.data; + // The body reported its size: it is laid out (performance harness). + perfEndAfterPaint('open-message'); // Swipe/zoom messages arrive as JSON; the height reporter posts a bare number. if (data.charCodeAt(0) === 123 /* '{' */) { try { diff --git a/src/components/RichTextEditor.tsx b/src/components/RichTextEditor.tsx index a730647b..4295ca25 100644 --- a/src/components/RichTextEditor.tsx +++ b/src/components/RichTextEditor.tsx @@ -3,6 +3,7 @@ import { StyleSheet, View, Platform } from 'react-native'; import { WebView, type WebViewMessageEvent } from 'react-native-webview'; import { useColors } from '../theme/colors'; import type { ThemePalette } from '../theme/tokens'; +import { perfEndAfterPaint } from '../lib/perf-marks'; import { buildEditorHtml, MIN_EDITOR_HEIGHT } from '../lib/editor-html'; export type RichTextCommand = @@ -202,6 +203,7 @@ const RichTextEditor = React.forwardRef(function Ri } if (!readyRef.current) { readyRef.current = true; + perfEndAfterPaint('compose-open'); const queued = queuedRef.current; queuedRef.current = []; for (const script of queued) webViewRef.current?.injectJavaScript(`${script}; true;`); diff --git a/src/lib/__tests__/perf-marks.test.ts b/src/lib/__tests__/perf-marks.test.ts new file mode 100644 index 00000000..fe3d7ef9 --- /dev/null +++ b/src/lib/__tests__/perf-marks.test.ts @@ -0,0 +1,62 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; + +// The module reads its switch once at load, so each case loads it fresh +// with its own react-native mock. +async function load(os: 'ios' | 'android', setting: unknown) { + vi.resetModules(); + vi.doMock('react-native', () => ({ + Platform: { OS: os }, + Settings: { get: vi.fn(() => setting) }, + })); + return import('../perf-marks'); +} + +describe('perf marks', () => { + let log: ReturnType; + beforeEach(() => { + log = vi.spyOn(console, 'log').mockImplementation(() => undefined); + }); + afterEach(() => { + log.mockRestore(); + vi.doUnmock('react-native'); + }); + + it('logs nothing without the launch argument', async () => { + const m = await load('ios', undefined); + m.perfMark('bundle-loaded'); + m.perfStart('open-message'); + m.perfEnd('open-message'); + m.perfOnce('inbox-rendered'); + expect(m.perfMarksEnabled()).toBe(false); + expect(log).not.toHaveBeenCalled(); + }); + + it('stays off on Android even when the setting is there', async () => { + const m = await load('android', 'YES'); + m.perfMark('bundle-loaded'); + expect(log).not.toHaveBeenCalled(); + }); + + it('logs marks and span durations with -perfMarks YES', async () => { + const m = await load('ios', 'YES'); + vi.useFakeTimers(); + vi.setSystemTime(1_000); + m.perfStart('open-message'); + vi.setSystemTime(1_250); + m.perfEnd('open-message', { id: 'x' }); + vi.useRealTimers(); + expect(log).toHaveBeenCalledTimes(1); + const line = String(log.mock.calls[0][0]); + expect(line.startsWith('[perf] ')).toBe(true); + expect(JSON.parse(line.slice(7))).toEqual({ n: 'open-message', t: 1_250, ms: 250, id: 'x' }); + }); + + it('logs a once-mark only once and ignores an end without a start', async () => { + const m = await load('ios', true); + m.perfOnce('inbox-rendered', { rows: 3 }); + m.perfOnce('inbox-rendered', { rows: 9 }); + m.perfEnd('never-started'); + expect(log).toHaveBeenCalledTimes(1); + expect(String(log.mock.calls[0][0])).toContain('"rows":3'); + }); +}); diff --git a/src/lib/perf-marks.ts b/src/lib/perf-marks.ts new file mode 100644 index 00000000..7bfd634e --- /dev/null +++ b/src/lib/perf-marks.ts @@ -0,0 +1,112 @@ +// Timing marks for the performance harness (scripts/e2e/perf.mjs). +// +// Off unless the app was launched with the `-perfMarks YES` launch argument +// (iOS puts launch arguments into NSUserDefaults, which React Native's +// Settings module reads). When on, every mark is one `[perf]` line on the +// console; on iOS that lands in the system log, where the harness reads it +// with `log show --info`. Nothing is stored or sent anywhere. + +import { Platform, Settings } from 'react-native'; + +function readEnabled(): boolean { + if (Platform.OS !== 'ios') return false; + try { + const value = Settings.get('perfMarks') as unknown; + return value === true || value === 'YES' || value === 'true' || value === 1 || value === '1'; + } catch { + return false; + } +} + +const enabled = readEnabled(); + +export function perfMarksEnabled(): boolean { + return enabled; +} + +/** Log a mark with the wall-clock time (the harness compares across processes). */ +export function perfMark(name: string, detail?: Record): void { + if (!enabled) return; + console.log(`[perf] ${JSON.stringify({ n: name, t: Date.now(), ...detail })}`); +} + +const started = new Map(); + +/** Start a timed span; `perfEnd` with the same name logs its duration. */ +export function perfStart(name: string): void { + if (!enabled) return; + started.set(name, Date.now()); +} + +export function perfEnd(name: string, detail?: Record): void { + if (!enabled) return; + const t0 = started.get(name); + if (t0 === undefined) return; + started.delete(name); + perfMark(name, { ms: Date.now() - t0, ...detail }); +} + +/** + * End a span once the next frames are drawn: two animation frames after the + * state change that rendered the result, so the time includes commit and + * paint, not just the JS render. + */ +export function perfEndAfterPaint(name: string, detail?: Record): void { + if (!enabled || !started.has(name)) return; + requestAnimationFrame(() => requestAnimationFrame(() => perfEnd(name, detail))); +} + +let onceDone = new Set(); +/** A mark that is logged once per process (first inbox render, ...). */ +export function perfOnce(name: string, detail?: Record): void { + if (!enabled || onceDone.has(name)) return; + onceDone.add(name); + perfMark(name, detail); +} + +/** Test hook. */ +export function resetPerfMarks(): void { + started.clear(); + onceDone = new Set(); +} + +/** + * Frame monitor for scrolling: counts animation frames between `start` and + * `stop` and how many of them took longer than two vsyncs (a visible hitch + * at 60 Hz). JS-thread frames, so it shows JS work blocking during a scroll. + */ +export function createFrameMonitor(name: string): { start: () => void; stop: () => void } { + let raf: number | null = null; + let last = 0; + let frames = 0; + let long = 0; + let worst = 0; + let t0 = 0; + const tick = (now: number) => { + if (last) { + const dt = now - last; + frames += 1; + if (dt > 34) long += 1; + if (dt > worst) worst = dt; + } + last = now; + raf = requestAnimationFrame(tick); + }; + return { + start() { + if (!enabled || raf !== null) return; + frames = 0; + long = 0; + worst = 0; + last = 0; + t0 = Date.now(); + raf = requestAnimationFrame(tick); + }, + stop() { + if (raf === null) return; + cancelAnimationFrame(raf); + raf = null; + perfMark(name, { ms: Date.now() - t0, frames, long, worst: Math.round(worst) }); + }, + }; +} diff --git a/src/screens/EmailListScreen.tsx b/src/screens/EmailListScreen.tsx index e472bf2b..c74f64b3 100644 --- a/src/screens/EmailListScreen.tsx +++ b/src/screens/EmailListScreen.tsx @@ -56,6 +56,7 @@ import { getFullEmail, emptyMailbox as apiEmptyMailbox } from '../api/email'; import type { RootStackParamList } from '../navigation/types'; import { usePendingMailSearch } from '../navigation/pending-mail-search'; import type { Attachment, Email } from '../api/types'; +import { createFrameMonitor, perfOnce, perfStart } from '../lib/perf-marks'; import { MODAL_ORIENTATIONS } from '../lib/modal-orientations'; function getSenderName(email: Email, unknownLabel: string): string { @@ -473,6 +474,13 @@ export default function EmailListScreen({ () => collapseThreads(emails, disableThreading), [emails, disableThreading], ); + // Performance harness (off unless launched with -perfMarks YES). + const scrollMonitor = React.useMemo(() => createFrameMonitor('list-scroll'), []); + React.useEffect(() => { + if (visibleEmails.length > 0) { + requestAnimationFrame(() => perfOnce('inbox-rendered', { rows: visibleEmails.length })); + } + }, [visibleEmails.length]); const threadGroups = React.useMemo( () => groupByThread(emails, disableThreading), [emails, disableThreading], @@ -645,7 +653,10 @@ export default function EmailListScreen({ const email = emailsRef.current.find((e) => rowKeyOf(e) === id); if (!email) return; if (isDraftEmail(email, currentRoleRef.current)) void openDraftRef.current(email); - else onEmailPressRef.current?.(email); + else { + perfStart('open-message'); + onEmailPressRef.current?.(email); + } } }, [toggleSelect]); @@ -1563,6 +1574,8 @@ export default function EmailListScreen({ contentContainerStyle={styles.listContent} onEndReached={handleEndReached} onEndReachedThreshold={0.3} + onScrollBeginDrag={scrollMonitor.start} + onMomentumScrollEnd={scrollMonitor.stop} refreshing={loading} onRefresh={handleRefresh} /> @@ -1570,7 +1583,10 @@ export default function EmailListScreen({ {/* Compose FAB - matches webmail mobile: PenSquare, h-14 w-14, rounded-full, shadow-lg */} { + perfStart('compose-open'); + onComposePress?.(); + }} style={({ pressed }) => [ styles.fab, // Lifted over the phone's undo bar, which used to cover it.