test: log timing marks for the performance harness when launched with -perfMarks

This commit is contained in:
Linus Rath
2026-10-22 22:04:28 +02:00
parent 32a41f42d3
commit 57ca1c8083
7 changed files with 206 additions and 2 deletions
+5
View File
@@ -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<RootStackParamList>();
@@ -261,6 +262,10 @@ function MainTabsNavigator({ navigation }: NativeStackScreenProps<RootStackParam
<PushOnboardingPrompt />
<AppIconBadge />
<Tab.Navigator
screenListeners={perfMarksEnabled() ? ({ route }) => ({
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.
+4
View File
@@ -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
+3
View File
@@ -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<RootStackParamList>;
@@ -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 {
+2
View File
@@ -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<RichTextEditorHandle, Props>(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;`);
+62
View File
@@ -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<typeof vi.spyOn>;
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');
});
});
+112
View File
@@ -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<string, string | number | boolean>): void {
if (!enabled) return;
console.log(`[perf] ${JSON.stringify({ n: name, t: Date.now(), ...detail })}`);
}
const started = new Map<string, number>();
/** 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<string, string | number | boolean>): 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<string, string | number | boolean>): void {
if (!enabled || !started.has(name)) return;
requestAnimationFrame(() => requestAnimationFrame(() => perfEnd(name, detail)));
}
let onceDone = new Set<string>();
/** A mark that is logged once per process (first inbox render, ...). */
export function perfOnce(name: string, detail?: Record<string, string | number | boolean>): 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) });
},
};
}
+18 -2
View File
@@ -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 */}
<Pressable
onPress={onComposePress}
onPress={() => {
perfStart('compose-open');
onComposePress?.();
}}
style={({ pressed }) => [
styles.fab,
// Lifted over the phone's undo bar, which used to cover it.