test: time each module's evaluation at start-up in builds made for the performance harness

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;

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);

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<string, unknown> = { nativePerformanceNow: () => clock.t };
+  const factories = new Map<number, () => 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<number, number> };
+}
+
+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 });
+  });
+});

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<string, number> }).__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;
+    }
+  });
 });

src/lib/perf-marks.ts

@@ -72,6 +72,26 @@ export function perfOnce(name: string, detail?: Record<string, string | number |
   perfMark(name, detail);
 }
 
+/**
+ * The modules whose own evaluation took longest so far, when the bundle was
+ * built with BULWARK_MODULE_TIMINGS (scripts/perf/module-timings.js): the
+ * 60 slowest as "id:ms" pairs, plus the total. Logged once, at first inbox.
+ */
+export function logModuleTimes(): void {
+  if (!enabled || onceDone.has('module-times')) return;
+  const times = (globalThis as { __bulwarkModuleTimes?: Record<string, number> }).__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();

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(