fix(plan): 阶段耗时分段口径 —— 「写入=」原本把「预取=」又算了一遍

2026-09-04 测试机实跑发现:改造后 `写入=` 取的是整个批循环的墙钟(tWrite 设在循环外),
而批内预取也在这个循环里 ⇒ 两段重叠、`场景+预取+写入` 远大于 `总计`。
实测那轮 `写入=1,243,665ms` 里有 **983,448ms 其实是预取**,真正写库只有 260,217ms。

误导性的度量比没有度量更糟 —— 而这几个数正是判断本次改造成败的依据:
照原样读会得出"写入段劣化 886%"的结论,实际是 105%(而且那一轮的对照本身也不干净,
未被修改的场景段同时涨了 49%,说明外部条件不同,当轮数据不足以判劣化)。

改:批内单独累计 writeMs(只含 runPool + createMany),与 prefetchMs 不重叠。
顺带修掉一个死变量:初版声明过 writeMs 但从未使用(tsc 没报是因为没开 noUnusedLocals)。

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

apps/pac-service/src/modules/plan/engine/plan-engine.service.ts

@@ -325,6 +325,8 @@ export class PlanEngineService {
     const snoozedByPatient = await this.prefetchSnoozeAnchors(scope, now);
     let prefetchMs = Date.now() - tPrefetch;
     const tWrite = Date.now();
+    // 只累计真正的写库段(runPool + createMany),不含批内预取 —— 否则与 预取= 重叠
+    let writeMs = 0;
     const EMPTY_SNOOZE = new Map<string, Date>();
     //   ⭐ 2026-07-26:写操作从「每 N 个一批 await Promise.all」的**栅栏**改成连续调度的
     //   worker pool(见 common/run-pool.ts)。栅栏每批都要等本批最慢那个,快的 worker 干等。
@@ -350,6 +352,7 @@ export class PlanEngineService {
       const { latestByPatient, personaByPatient, lastVisitClinicByPatient, touchedPlanIds } =
         await this.prefetchOneBatch(scope, ids);
       prefetchMs += Date.now() - tb;
+      const tw = Date.now();
       const logRows: Prisma.PlanGenerationLogCreateManyInput[] = [];
       // hit 的所有权交给本批的局部数组,随即从 Map 里删掉 —— 批末连同 latest/persona/visit/logRows
       // 一起出作用域被回收。这是本次改造真正省内存的那一下(hitsByPatient 满载约 1.06GB)。
@@ -407,6 +410,7 @@ export class PlanEngineService {
       for (let i = 0; i < logRows.length; i += 5000) {
         await this.prisma.planGenerationLog.createMany({ data: logRows.slice(i, i + 5000) });
       }
+      writeMs += Date.now() - tw;
       // 内存水位:沿用 cold-import 的 `rss=` 字样便于跟历史并排 grep;额外带 heapUsed ——
       // 判 8G 堆上限还剩多少余量只能看 heapUsed,rss 含 Prisma Rust 引擎与碎片,不够精确。
       // 每批一行太吵:每 5 批 + 末批各打一次(同 cold-import 的做法)。
@@ -508,10 +512,15 @@ export class PlanEngineService {
       this.logger.warn(`[标签] 补齐失败（不阻断生成，夜间刷新会兜住）：${e instanceof Error ? e.message : e}`);
     }
 
-    // ⚠️ 「预取=」现在是 N 批之和(含整轮一次的 snooze),「写入=」含批循环全部开销;
-    //   加 `批=` 便于跟历史对照。判据仍只看整轮墙钟,别拿分段和历史逐项比。
+    // ⚠️ 分段口径(2026-09-04 修正):「预取=」是 N 批预取之和 + 整轮一次的 snooze,
+    //   「写入=」只算真正写库那段(runPool + createMany),**两者不重叠**,
+    //   场景+预取+写入 ≈ 总计。初版把「写入=」写成整个批循环的墙钟(把预取又算了一遍),
+    //   实测那轮显示 写入=1,243,665ms 里有 983,448ms 其实是预取 —— 误导性的度量比没有度量更糟,
+    //   而这几个数正是判断本次改造成败的依据。
+    //   `批=` 便于跟历史对照;判据仍以整轮墙钟为准。
+    void tWrite;
     this.logger.log(
-      `[plan] 阶段耗时 场景=${selectMs}ms 预取=${prefetchMs}ms 写入=${Date.now() - tWrite}ms ` +
+      `[plan] 阶段耗时 场景=${selectMs}ms 预取=${prefetchMs}ms 写入=${writeMs}ms ` +
         `批=${batches}(size=${batchSize}) ` +
         `命中患者=${hitPatientIds.size} 总计=${Date.now() - startedAt.getTime()}ms`,
     );