perf(startup): prioritize tokenization warmups with stage debug logs

backlog/tasks/task-74 - Startup-warmups-configurable-warmup-vs-defer-with-low-power-mode.md

@@ -15,9 +15,12 @@ references:
   - src/main/runtime/startup-warmups.ts
   - src/main/runtime/startup-warmups-main-deps.ts
   - src/main/runtime/composers/mpv-runtime-composer.ts
+  - src/core/services/startup.ts
   - src/main.ts
   - src/config/config.test.ts
   - src/main/runtime/startup-warmups.test.ts
+  - src/main/runtime/startup-warmups-main-deps.test.ts
+  - src/core/services/app-ready.test.ts
 priority: medium
 ---
 
@@ -48,4 +51,18 @@ Validation:
 - `bun run test:config:src`
 - `bun run test:core:src`
 - `tsc --noEmit`
+
+Follow-up updates:
+- Startup now triggers warmups earlier in app-ready flow (right after config validation/log-level setup) instead of waiting for initial args/overlay actions. Goal: tokenization warmup is already done or mostly done by first visible-subs toggle.
+- Tokenization warmup scheduling consolidated as `subtitle-tokenization` stage; when enabled by toggles, it runs Yomitan extension first, then MeCab/dictionary warmups.
+- Added per-stage debug logs for warmup progress and skip reasons:
+  - `stage start/ready: yomitan-extension`
+  - `stage start/ready: mecab`
+  - `stage start/ready: subtitle-dictionaries`
+  - `stage start/ready: jellyfin-remote-session`
+  - `stage skipped: jellyfin-remote-session (disabled|auto-connect off)`
+- Added regression tests for stage-level logging and earlier startup ordering:
+  - `src/main/runtime/startup-warmups.test.ts`
+  - `src/main/runtime/startup-warmups-main-deps.test.ts`
+  - `src/core/services/app-ready.test.ts`
 <!-- SECTION:FINAL_SUMMARY:END -->

src/core/services/app-ready.test.ts

@@ -131,12 +131,30 @@ test('runAppReadyRuntime does not await background warmups', async () => {
   });
 
   await runAppReadyRuntime(deps);
-  assert.deepEqual(calls.slice(0, 2), ['handleInitialArgs', 'startBackgroundWarmups']);
+  assert.ok(calls.includes('startBackgroundWarmups'));
+  assert.ok(calls.includes('handleInitialArgs'));
+  assert.ok(calls.indexOf('startBackgroundWarmups') < calls.indexOf('handleInitialArgs'));
   assert.equal(calls.includes('warmupDone'), false);
   assert.ok(releaseWarmup);
   releaseWarmup();
 });
 
+test('runAppReadyRuntime starts background warmups before core runtime services', async () => {
+  const calls: string[] = [];
+  const { deps } = makeDeps({
+    startBackgroundWarmups: () => {
+      calls.push('startBackgroundWarmups');
+    },
+    loadSubtitlePosition: () => calls.push('loadSubtitlePosition'),
+    createMpvClient: () => calls.push('createMpvClient'),
+  });
+
+  await runAppReadyRuntime(deps);
+
+  assert.ok(calls.indexOf('startBackgroundWarmups') < calls.indexOf('loadSubtitlePosition'));
+  assert.ok(calls.indexOf('startBackgroundWarmups') < calls.indexOf('createMpvClient'));
+});
+
 test('runAppReadyRuntime exits before service init when critical anki mappings are invalid', async () => {
   const capturedErrors: string[][] = [];
   const { deps, calls } = makeDeps({

src/core/services/startup.ts

@@ -184,6 +184,7 @@ export async function runAppReadyRuntime(deps: AppReadyRuntimeDeps): Promise<voi
   for (const warning of deps.getConfigWarnings()) {
     deps.logConfigWarning(warning);
   }
+  deps.startBackgroundWarmups();
 
   deps.loadSubtitlePosition();
   deps.resolveKeybindings();
@@ -217,6 +218,5 @@ export async function runAppReadyRuntime(deps: AppReadyRuntimeDeps): Promise<voi
   }
 
   deps.handleInitialArgs();
-  deps.startBackgroundWarmups();
   deps.logDebug?.(`App-ready critical path finished in ${now() - startupStartedAtMs}ms.`);
 }

src/main/runtime/composers/mpv-runtime-composer.test.ts

@@ -202,6 +202,7 @@ test('composeMpvRuntimeHandlers returns callable handlers and forwards to inject
   assert.equal(typeof composed.tokenizeSubtitle, 'function');
   assert.equal(typeof composed.createMecabTokenizerAndCheck, 'function');
   assert.equal(typeof composed.prewarmSubtitleDictionaries, 'function');
+  assert.equal(typeof composed.startTokenizationWarmups, 'function');
   assert.equal(typeof composed.launchBackgroundWarmupTask, 'function');
   assert.equal(typeof composed.startBackgroundWarmups, 'function');
 
@@ -209,6 +210,7 @@ test('composeMpvRuntimeHandlers returns callable handlers and forwards to inject
   assert.equal(client.connected, true);
 
   composed.updateMpvSubtitleRenderMetrics({ subPos: 90 });
+  await composed.startTokenizationWarmups();
   const tokenized = await composed.tokenizeSubtitle('subtitle text');
   await composed.createMecabTokenizerAndCheck();
   await composed.prewarmSubtitleDictionaries();

src/main/runtime/overlay-visibility-actions-main-deps.test.ts

@@ -7,11 +7,15 @@ import {
 
 test('overlay visibility action main deps builders map callbacks', () => {
   const calls: string[] = [];
+  let warmupStarts = 0;
 
   const setVisible = createBuildSetVisibleOverlayVisibleMainDepsHandler({
     setVisibleOverlayVisibleCore: () => calls.push('visible-core'),
     setVisibleOverlayVisibleState: (visible) => calls.push(`visible-state:${visible}`),
     updateVisibleOverlayVisibility: () => calls.push('update-visible'),
+    onVisibleOverlayEnabled: () => {
+      warmupStarts += 1;
+    },
   })();
   setVisible.setVisibleOverlayVisibleCore({
     visible: true,
@@ -20,6 +24,7 @@ test('overlay visibility action main deps builders map callbacks', () => {
   });
   setVisible.setVisibleOverlayVisibleState(true);
   setVisible.updateVisibleOverlayVisibility();
+  setVisible.onVisibleOverlayEnabled?.();
 
   const toggleVisible = createBuildToggleVisibleOverlayMainDepsHandler({
     getVisibleOverlayVisible: () => false,
@@ -34,4 +39,5 @@ test('overlay visibility action main deps builders map callbacks', () => {
     'update-visible',
     'toggle-visible:true',
   ]);
+  assert.equal(warmupStarts, 1);
 });

src/main/runtime/overlay-visibility-actions-main-deps.ts

@@ -13,6 +13,7 @@ export function createBuildSetVisibleOverlayVisibleMainDepsHandler(
     setVisibleOverlayVisibleCore: (options) => deps.setVisibleOverlayVisibleCore(options),
     setVisibleOverlayVisibleState: (visible: boolean) => deps.setVisibleOverlayVisibleState(visible),
     updateVisibleOverlayVisibility: () => deps.updateVisibleOverlayVisibility(),
+    onVisibleOverlayEnabled: deps.onVisibleOverlayEnabled,
   });
 }
 

src/main/runtime/overlay-visibility-actions.test.ts

@@ -7,6 +7,7 @@ import {
 
 test('set visible overlay handler forwards dependencies to core', () => {
   const calls: string[] = [];
+  let warmupStarts = 0;
   const setVisible = createSetVisibleOverlayVisibleHandler({
     setVisibleOverlayVisibleCore: (options) => {
       calls.push(`core:${options.visible}`);
@@ -15,6 +16,9 @@ test('set visible overlay handler forwards dependencies to core', () => {
     },
     setVisibleOverlayVisibleState: (visible) => calls.push(`state:${visible}`),
     updateVisibleOverlayVisibility: () => calls.push('update-visible'),
+    onVisibleOverlayEnabled: () => {
+      warmupStarts += 1;
+    },
   });
 
   setVisible(true);
@@ -23,6 +27,10 @@ test('set visible overlay handler forwards dependencies to core', () => {
     'state:true',
     'update-visible',
   ]);
+  assert.equal(warmupStarts, 1);
+
+  setVisible(false);
+  assert.equal(warmupStarts, 1);
 });
 
 test('toggle visible overlay flips current visible state', () => {

src/main/runtime/overlay-visibility-actions.ts

@@ -6,8 +6,12 @@ export function createSetVisibleOverlayVisibleHandler(deps: {
   }) => void;
   setVisibleOverlayVisibleState: (visible: boolean) => void;
   updateVisibleOverlayVisibility: () => void;
+  onVisibleOverlayEnabled?: () => void;
 }) {
   return (visible: boolean): void => {
+    if (visible) {
+      deps.onVisibleOverlayEnabled?.();
+    }
     deps.setVisibleOverlayVisibleCore({
       visible,
       setVisibleOverlayVisibleState: deps.setVisibleOverlayVisibleState,

src/main/runtime/overlay-visibility-runtime.test.ts

@@ -5,6 +5,7 @@ import { createOverlayVisibilityRuntime } from './overlay-visibility-runtime';
 test('overlay visibility runtime wires set/toggle handlers through composed deps', () => {
   let visible = false;
   let setVisibleCoreCalls = 0;
+  let warmupStarts = 0;
 
   const runtime = createOverlayVisibilityRuntime({
     setVisibleOverlayVisibleDeps: {
@@ -17,6 +18,9 @@ test('overlay visibility runtime wires set/toggle handlers through composed deps
         visible = nextVisible;
       },
       updateVisibleOverlayVisibility: () => {},
+      onVisibleOverlayEnabled: () => {
+        warmupStarts += 1;
+      },
     },
     getVisibleOverlayVisible: () => visible,
   });
@@ -34,4 +38,5 @@ test('overlay visibility runtime wires set/toggle handlers through composed deps
   assert.equal(visible, false);
 
   assert.equal(setVisibleCoreCalls, 4);
+  assert.equal(warmupStarts, 2);
 });

src/main/runtime/startup-warmups-main-deps.test.ts

@@ -42,6 +42,7 @@ test('startup warmups main deps builders map callbacks', async () => {
     startJellyfinRemoteSession: async () => {
       calls.push('jellyfin');
     },
+    logDebug: (message) => calls.push(`start-debug:${message}`),
   })();
   assert.equal(start.getStarted(), false);
   start.setStarted(true);
@@ -58,6 +59,7 @@ test('startup warmups main deps builders map callbacks', async () => {
   assert.equal(start.shouldWarmupJellyfinRemoteSession(), true);
   assert.equal(start.shouldAutoConnectJellyfinRemote(), true);
   await start.startJellyfinRemoteSession();
+  start.logDebug?.('z');
 
   assert.deepEqual(calls, [
     'debug:x',
@@ -69,5 +71,6 @@ test('startup warmups main deps builders map callbacks', async () => {
     'yomitan',
     'dict',
     'jellyfin',
+    'start-debug:z',
   ]);
 });

src/main/runtime/startup-warmups-main-deps.ts

@@ -31,5 +31,6 @@ export function createBuildStartBackgroundWarmupsMainDepsHandler(deps: StartBack
     shouldWarmupJellyfinRemoteSession: () => deps.shouldWarmupJellyfinRemoteSession(),
     shouldAutoConnectJellyfinRemote: () => deps.shouldAutoConnectJellyfinRemote(),
     startJellyfinRemoteSession: () => deps.startJellyfinRemoteSession(),
+    logDebug: deps.logDebug,
   });
 }

src/main/runtime/startup-warmups.test.ts

@@ -83,7 +83,7 @@ test('startBackgroundWarmups respects per-integration warmup toggles', () => {
 
   startWarmups();
   assert.equal(started, true);
-  assert.deepEqual(labels, ['yomitan-extension']);
+  assert.deepEqual(labels, ['subtitle-tokenization']);
 });
 
 test('startBackgroundWarmups schedules jellyfin warmup when all jellyfin flags are enabled', () => {
@@ -116,12 +116,7 @@ test('startBackgroundWarmups schedules jellyfin warmup when all jellyfin flags a
 
   startWarmups();
   assert.equal(started, true);
-  assert.deepEqual(labels, [
-    'mecab',
-    'yomitan-extension',
-    'subtitle-dictionaries',
-    'jellyfin-remote-session',
-  ]);
+  assert.deepEqual(labels, ['subtitle-tokenization', 'jellyfin-remote-session']);
 });
 
 test('startBackgroundWarmups skips jellyfin warmup when warmup is deferred', () => {
@@ -154,5 +149,48 @@ test('startBackgroundWarmups skips jellyfin warmup when warmup is deferred', ()
 
   startWarmups();
   assert.equal(started, true);
-  assert.deepEqual(labels, ['yomitan-extension']);
+  assert.deepEqual(labels, ['subtitle-tokenization']);
+});
+
+test('startBackgroundWarmups logs per-stage progress for enabled tokenization warmups', async () => {
+  const debugLogs: string[] = [];
+  const labels: string[] = [];
+  let started = false;
+  const startWarmups = createStartBackgroundWarmupsHandler({
+    getStarted: () => started,
+    setStarted: (value) => {
+      started = value;
+    },
+    isTexthookerOnlyMode: () => false,
+    launchTask: (label, task) => {
+      labels.push(label);
+      void task();
+    },
+    createMecabTokenizerAndCheck: async () => {},
+    ensureYomitanExtensionLoaded: async () => {},
+    prewarmSubtitleDictionaries: async () => {},
+    shouldWarmupMecab: () => true,
+    shouldWarmupYomitanExtension: () => true,
+    shouldWarmupSubtitleDictionaries: () => true,
+    shouldWarmupJellyfinRemoteSession: () => true,
+    shouldAutoConnectJellyfinRemote: () => true,
+    startJellyfinRemoteSession: async () => {},
+    logDebug: (message) => {
+      debugLogs.push(message);
+    },
+  });
+
+  startWarmups();
+  await Promise.resolve();
+  await Promise.resolve();
+
+  assert.deepEqual(labels, ['subtitle-tokenization', 'jellyfin-remote-session']);
+  assert.ok(debugLogs.includes('[startup-warmup] stage start: yomitan-extension'));
+  assert.ok(debugLogs.includes('[startup-warmup] stage ready: yomitan-extension'));
+  assert.ok(debugLogs.includes('[startup-warmup] stage start: mecab'));
+  assert.ok(debugLogs.includes('[startup-warmup] stage ready: mecab'));
+  assert.ok(debugLogs.includes('[startup-warmup] stage start: subtitle-dictionaries'));
+  assert.ok(debugLogs.includes('[startup-warmup] stage ready: subtitle-dictionaries'));
+  assert.ok(debugLogs.includes('[startup-warmup] stage start: jellyfin-remote-session'));
+  assert.ok(debugLogs.includes('[startup-warmup] stage ready: jellyfin-remote-session'));
 });

src/main/runtime/startup-warmups.ts

@@ -30,31 +30,63 @@ export function createStartBackgroundWarmupsHandler(deps: {
   shouldWarmupJellyfinRemoteSession: () => boolean;
   shouldAutoConnectJellyfinRemote: () => boolean;
   startJellyfinRemoteSession: () => Promise<void>;
+  logDebug?: (message: string) => void;
 }) {
   return (): void => {
     if (deps.getStarted()) return;
     if (deps.isTexthookerOnlyMode()) return;
 
+    const warmupMecab = deps.shouldWarmupMecab();
+    const warmupYomitanExtension = deps.shouldWarmupYomitanExtension();
+    const warmupSubtitleDictionaries = deps.shouldWarmupSubtitleDictionaries();
+    const warmupJellyfinRemoteSession = deps.shouldWarmupJellyfinRemoteSession();
+    const autoConnectJellyfinRemote = deps.shouldAutoConnectJellyfinRemote();
+
     deps.setStarted(true);
-    if (deps.shouldWarmupMecab()) {
-      deps.launchTask('mecab', async () => {
-        await deps.createMecabTokenizerAndCheck();
+    const shouldWarmupTokenization =
+      warmupMecab || warmupYomitanExtension || warmupSubtitleDictionaries;
+    if (shouldWarmupTokenization) {
+      deps.launchTask('subtitle-tokenization', async () => {
+        if (warmupYomitanExtension) {
+          deps.logDebug?.('[startup-warmup] stage start: yomitan-extension');
+          await deps.ensureYomitanExtensionLoaded();
+          deps.logDebug?.('[startup-warmup] stage ready: yomitan-extension');
+        } else {
+          deps.logDebug?.('[startup-warmup] stage skipped: yomitan-extension');
+        }
+
+        await Promise.all([
+          warmupMecab
+            ? (async () => {
+                deps.logDebug?.('[startup-warmup] stage start: mecab');
+                await deps.createMecabTokenizerAndCheck();
+                deps.logDebug?.('[startup-warmup] stage ready: mecab');
+              })()
+            : Promise.resolve().then(() => {
+                deps.logDebug?.('[startup-warmup] stage skipped: mecab');
+              }),
+          warmupSubtitleDictionaries
+            ? (async () => {
+                deps.logDebug?.('[startup-warmup] stage start: subtitle-dictionaries');
+                await deps.prewarmSubtitleDictionaries();
+                deps.logDebug?.('[startup-warmup] stage ready: subtitle-dictionaries');
+              })()
+            : Promise.resolve().then(() => {
+                deps.logDebug?.('[startup-warmup] stage skipped: subtitle-dictionaries');
+              }),
+        ]);
       });
     }
-    if (deps.shouldWarmupYomitanExtension()) {
-      deps.launchTask('yomitan-extension', async () => {
-        await deps.ensureYomitanExtensionLoaded();
-      });
-    }
-    if (deps.shouldWarmupSubtitleDictionaries()) {
-      deps.launchTask('subtitle-dictionaries', async () => {
-        await deps.prewarmSubtitleDictionaries();
-      });
-    }
-    if (deps.shouldWarmupJellyfinRemoteSession() && deps.shouldAutoConnectJellyfinRemote()) {
+    if (warmupJellyfinRemoteSession && autoConnectJellyfinRemote) {
       deps.launchTask('jellyfin-remote-session', async () => {
+        deps.logDebug?.('[startup-warmup] stage start: jellyfin-remote-session');
         await deps.startJellyfinRemoteSession();
+        deps.logDebug?.('[startup-warmup] stage ready: jellyfin-remote-session');
       });
+    } else if (!warmupJellyfinRemoteSession) {
+      deps.logDebug?.('[startup-warmup] stage skipped: jellyfin-remote-session (disabled)');
+    } else {
+      deps.logDebug?.('[startup-warmup] stage skipped: jellyfin-remote-session (auto-connect off)');
     }
   };
 }