From 533f176e88c1bfe7176e10805cdaaaaefb6a884c Mon Sep 17 00:00:00 2001 From: Linus Rath <139418639+rathlinus@users.noreply.github.com> Date: Thu, 22 Oct 2026 22:02:56 +0200 Subject: [PATCH] test: time each module's evaluation at start-up in builds made for the performance harness --- metro.config.js | 31 ++++++++++++++++++++++++ scripts/perf/module-timings.js | 30 +++++++++++++++++++++++ src/lib/__tests__/module-timings.test.ts | 31 ++++++++++++++++++++++++ src/lib/__tests__/perf-marks.test.ts | 16 ++++++++++++ src/lib/perf-marks.ts | 20 +++++++++++++++ src/screens/EmailListScreen.tsx | 7 ++++-- 6 files changed, 133 insertions(+), 2 deletions(-) create mode 100644 scripts/perf/module-timings.js create mode 100644 src/lib/__tests__/module-timings.test.ts diff --git a/metro.config.js b/metro.config.js index 32938e89..733f21e8 100644 --- a/metro.config.js +++ b/metro.config.js @@ -1,5 +1,36 @@ +const path = require('path'); +const fs = require('fs'); const { getDefaultConfig } = require('expo/metro-config'); const config = getDefaultConfig(__dirname); +// Performance harness (the iOS simulator tests, .github/workflows/e2e-ios.yml): +// with BULWARK_MODULE_TIMINGS set, the bundle times each module's +// evaluation (scripts/perf/module-timings.js), and BULWARK_MODULE_MAP names +// a file that receives the module ids with their source paths, so the +// harness can tell which module is which. Release builds set neither. +if (process.env.BULWARK_MODULE_TIMINGS) { + const basePolyfills = config.serializer.getPolyfills; + config.serializer.getPolyfills = (ctx) => [ + ...basePolyfills(ctx), + path.join(__dirname, 'scripts/perf/module-timings.js'), + ]; + const mapFile = process.env.BULWARK_MODULE_MAP; + if (mapFile) { + const baseFactory = config.serializer.createModuleIdFactory; + config.serializer.createModuleIdFactory = () => { + const idOf = baseFactory(); + const names = {}; + process.on('exit', () => { + try { fs.writeFileSync(mapFile, JSON.stringify(names)); } catch { /* best effort */ } + }); + return (modulePath) => { + const id = idOf(modulePath); + names[id] = path.relative(__dirname, modulePath).split(path.sep).join('/'); + return id; + }; + }; + } +} + module.exports = config; diff --git a/scripts/perf/module-timings.js b/scripts/perf/module-timings.js new file mode 100644 index 00000000..3a233942 --- /dev/null +++ b/scripts/perf/module-timings.js @@ -0,0 +1,30 @@ +// Metro polyfill for the performance harness (metro.config.js adds it only +// when BULWARK_MODULE_TIMINGS is set at bundle time; release builds don't +// have it). It wraps every module factory and adds up how long each module's +// own code ran when it was first evaluated, without the modules it required +// meanwhile. src/lib/perf-marks.ts logs the slowest ones at first inbox. +(function (g) { + var define = g.__d; + if (typeof define !== 'function') return; + var now = typeof g.nativePerformanceNow === 'function' + ? g.nativePerformanceNow + : function () { return Date.now(); }; + var times = {}; + var stack = []; + g.__bulwarkModuleTimes = times; + g.__d = function (factory, moduleId, dependencyMap, verboseName) { + var timed = function () { + var start = now(); + stack.push(0); + try { + return factory.apply(this, arguments); + } finally { + var total = now() - start; + var nested = stack.pop(); + times[moduleId] = (times[moduleId] || 0) + (total - nested); + if (stack.length > 0) stack[stack.length - 1] += total; + } + }; + return define(timed, moduleId, dependencyMap, verboseName); + }; +})(typeof globalThis !== 'undefined' ? globalThis : this); diff --git a/src/lib/__tests__/module-timings.test.ts b/src/lib/__tests__/module-timings.test.ts new file mode 100644 index 00000000..1932f1f9 --- /dev/null +++ b/src/lib/__tests__/module-timings.test.ts @@ -0,0 +1,31 @@ +import { describe, expect, it } from 'vitest'; +import fs from 'node:fs'; +import path from 'node:path'; + +// scripts/perf/module-timings.js wraps Metro's module definitions and adds +// up each module's own evaluation time, without the time of the modules it +// required while it ran. + +function install(clock: { t: number }) { + const g: Record = { nativePerformanceNow: () => clock.t }; + const factories = new Map void>(); + g.__d = (factory: () => void, id: number) => { factories.set(id, factory); }; + const src = fs.readFileSync(path.resolve(__dirname, '../../../scripts/perf/module-timings.js'), 'utf8'); + new Function('globalThis', src)(g); + (g.__d as (f: () => void, id: number) => void)(() => { clock.t += 5; }, 2); + (g.__d as (f: () => void, id: number) => void)(() => { + clock.t += 10; + factories.get(2)!(); + clock.t += 3; + }, 1); + return { run: (id: number) => factories.get(id)!(), times: () => g.__bulwarkModuleTimes as Record }; +} + +describe('module timings polyfill', () => { + it('counts a module without the modules it required', () => { + const clock = { t: 0 }; + const m = install(clock); + m.run(1); + expect(m.times()).toEqual({ 1: 13, 2: 5 }); + }); +}); diff --git a/src/lib/__tests__/perf-marks.test.ts b/src/lib/__tests__/perf-marks.test.ts index fe3d7ef9..ea2cd3c0 100644 --- a/src/lib/__tests__/perf-marks.test.ts +++ b/src/lib/__tests__/perf-marks.test.ts @@ -59,4 +59,20 @@ describe('perf marks', () => { expect(log).toHaveBeenCalledTimes(1); expect(String(log.mock.calls[0][0])).toContain('"rows":3'); }); + it('logs the slowest modules once, with the total', async () => { + const m = await load('ios', true); + (globalThis as { __bulwarkModuleTimes?: Record }).__bulwarkModuleTimes = { 7: 12.34, 3: 50, 9: 1 }; + try { + m.logModuleTimes(); + m.logModuleTimes(); + const lines = log.mock.calls.map((c: unknown[]) => String(c[0])).filter((l: string) => l.includes('module-times')); + expect(lines).toHaveLength(1); + const mark = JSON.parse(lines[0].slice('[perf] '.length)); + expect(mark.total).toBe(63); + expect(mark.count).toBe(3); + expect(mark.top).toBe('3:50,7:12.3,9:1'); + } finally { + delete (globalThis as { __bulwarkModuleTimes?: unknown }).__bulwarkModuleTimes; + } + }); }); diff --git a/src/lib/perf-marks.ts b/src/lib/perf-marks.ts index 6fb3cdc4..50ab3510 100644 --- a/src/lib/perf-marks.ts +++ b/src/lib/perf-marks.ts @@ -72,6 +72,26 @@ export function perfOnce(name: string, detail?: Record }).__bulwarkModuleTimes; + if (!times) return; + onceDone.add('module-times'); + const entries = Object.entries(times); + const total = entries.reduce((sum, [, ms]) => sum + ms, 0); + const top = entries + .sort((a, b) => b[1] - a[1]) + .slice(0, 60) + .map(([id, ms]) => `${id}:${Math.round(ms * 10) / 10}`) + .join(','); + perfMark('module-times', { total: Math.round(total), count: entries.length, top }); +} + /** Test hook. */ export function resetPerfMarks(): void { started.clear(); diff --git a/src/screens/EmailListScreen.tsx b/src/screens/EmailListScreen.tsx index 29b5d964..097eb83a 100644 --- a/src/screens/EmailListScreen.tsx +++ b/src/screens/EmailListScreen.tsx @@ -56,7 +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 { createFrameMonitor, logModuleTimes, perfOnce, perfStart } from '../lib/perf-marks'; import { MODAL_ORIENTATIONS } from '../lib/modal-orientations'; function getSenderName(email: Email, unknownLabel: string): string { @@ -479,7 +479,10 @@ export default function EmailListScreen({ React.useEffect(() => { perfOnce('list-mounted'); }, []); React.useEffect(() => { if (visibleEmails.length > 0) { - requestAnimationFrame(() => perfOnce('inbox-rendered', { rows: visibleEmails.length })); + requestAnimationFrame(() => { + perfOnce('inbox-rendered', { rows: visibleEmails.length }); + logModuleTimes(); + }); } }, [visibleEmails.length]); const threadGroups = React.useMemo(