feat(可观测): plan 引擎补三层耗时日志 —— 一轮跑两小时不该是黑盒

2026-08-29 生产 plan 段从 12 分钟涨到 159 分钟仍未跑完,而引擎从「▶ Running engine」
到最后的统计块之间**什么都不打**,整轮是个黑盒 —— 只能临时起 pg_stat_activity 采样器
反推,才勉强定位到子场景粒度。这组日志就是为了不再重复那个过程。

① 每个子场景一行(常态开启,每轮 11 行):
   [recall] sub=missing_tooth code=K08 sql=1234ms rows=567 post=89ms hits=42
   ⭐ SQL 与 Node 后处理**分开计时** —— 今天最大的困难就是知道慢、却分不清
     慢在 SQL 还是慢在 Node。

② runAllForHost 三段(常态开启,每轮 1 行):
   [plan] 阶段耗时 场景=Xms 预取=Yms 写入=Zms 命中患者=N 总计=Wms
   今天一度误以为瓶颈在预取,有这行就不会跑偏。

③ PAC_RECALL_DUMP_SQL=1(默认关)保留,需要拿 SQL 原文做 EXPLAIN 时才开。

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

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

@@ -241,6 +241,11 @@ export class PlanEngineService {
       );
     }
 
+    // ⏱ 三段计时(场景 / 预取 / 写入)—— 常态开启,每轮 1 行。
+    //   ⛔ 别删:2026-08-29 生产 plan 段从 12 分钟涨到 159 分钟仍未跑完,而引擎从
+    //     「▶ Running engine」到最后的统计块之间**什么都不打**,整轮是个黑盒 ——
+    //     只能靠临时起 pg_stat_activity 采样器反推在哪一段。有这行就不用再猜。
+    const tSelect = Date.now();
     // 1. 各 scenario 跑 selector,汇总 hits
     const hitsByPatient = new Map<string, ScenarioHitWithKey[]>();
     for (const sc of this.scenarios) {
@@ -265,9 +270,13 @@ export class PlanEngineService {
     //     → 逐患复用**同一** upsert 判定(结果等价)→ 写操作**分块并发** → PlanGenerationLog 收集后
     //     一次性 createMany(每患仍一行,审计/监控口径不变,只是写法从 12.5万次 → 几次)。
     //   注:selectHits 的全表扫不在本优化内(时间规则随时可改,每轮必须全量重选才正确)。
+    const selectMs = Date.now() - tSelect;
     const patientIds = [...hitsByPatient.keys()];
+    const tPrefetch = Date.now();
     const { latestByPatient, snoozedByPatient, personaByPatient, lastVisitClinicByPatient, touchedPlanIds } =
       await this.prefetchForBatch(scope, patientIds, now);
+    const prefetchMs = Date.now() - tPrefetch;
+    const tWrite = Date.now();
     const EMPTY_SNOOZE = new Map<string, Date>();
     const logRows: Prisma.PlanGenerationLogCreateManyInput[] = [];
     //   ⭐ 2026-07-26:写操作从「每 N 个一批 await Promise.all」的**栅栏**改成连续调度的
@@ -413,6 +422,10 @@ export class PlanEngineService {
       this.logger.warn(`[标签] 补齐失败（不阻断生成，夜间刷新会兜住）：${e instanceof Error ? e.message : e}`);
     }
 
+    this.logger.log(
+      `[plan] 阶段耗时 场景=${selectMs}ms 预取=${prefetchMs}ms 写入=${Date.now() - tWrite}ms ` +
+        `命中患者=${patientIds.length} 总计=${Date.now() - startedAt.getTime()}ms`,
+    );
     return {
       scenariosRun: this.scenarios.length,
       patientsHit: hitsByPatient.size,

apps/pac-service/src/modules/plan/engine/scenarios/treatment-initiation-recall.scenario.ts

@@ -513,7 +513,13 @@ export class TreatmentInitiationRecallScenario implements PlanScenarioPlugin {
           `[dump-sql-params] ${JSON.stringify(scenarioSql.values)}`,
       );
     }
+    // ⏱ 分段计时 —— SQL 与 Node 后处理**分开算**,这是本组日志最关键的一格:
+    //   2026-08-29 排查时最大的困难,就是知道 plan 段慢、却分不清慢在 SQL 还是慢在 Node,
+    //   只能靠采样 pg_stat_activity 反推。有了这两个数,看一眼日志就知道该往哪查。
+    const sqlStart = Date.now();
     const rows: HitRow[] = await this.prisma.$queryRaw(scenarioSql);
+    const sqlMs = Date.now() - sqlStart;
+    const postStart = Date.now();
 
     // ⭐ 同 patient 同 sub_scenario 的多 sig 按 tooth-overlap 合并(union-find)
     //   跟 chain-composer 的 bucket 合并口径一致 → reason 与 chain 1:1 对齐
@@ -637,6 +643,14 @@ export class TreatmentInitiationRecallScenario implements PlanScenarioPlugin {
         priorityBreakdown: breakdown,
       });
     }
+    // ⏱ 每个子场景一行 —— 常态开启(每轮 11 行,可忽略)。
+    //   ⛔ 别删:没有它,一轮跑两小时也只知道总体慢,既不知道是哪个子场景、
+    //     也不知道是 SQL 还是后处理慢。2026-08-29 生产 plan 段从 12 分钟涨到 159 分钟
+    //     仍未跑完,是临时加采样器才定位到子场景粒度的 —— 那种事不该再来一次。
+    this.logger.log(
+      `[recall] sub=${subKey} code=${cfg.primaryCode} ` +
+        `sql=${sqlMs}ms rows=${rows.length} post=${Date.now() - postStart}ms hits=${hits.length}`,
+    );
     return hits;
   }