← 回到 infra 主页

DeepSeek Harness · Upstream · Issue #12 草案

控制面一元 RPC 在主线程饱和时被饿死:同一份约 0.5 s CPU 的 session/list,实测被拉长到 34 s – ≥45 s(45 s 是客户端 socket 超时的右截尾;放大已在隔离副本上复现 3.75×、按自身 CPU 归一 5.62×,生产 stall 当刻的配对样本已在 user-d 户补齐(17:48–18:07))

先说结论:session/list 不是「慢查询」,它是一次纯主线程、单发约 0.5 s CPU、成本随会话数线性的全量扫描 —— 本页采纳的唯一权威组 A0(2026-09-15 16:10:06–16:10:09,经网关 5006、rpcId=fixed、6 发,同刻无 stall):wall 中位 517.4 ms(504.6–638.5)、同发主线程 CPU 中位 405.1 ms(375.5–533.6 = 74.4–84.0% of one core)、rows=660、响应 1,578,662 字节(sha256=923a9bf90594c61e…,6/6 逐字节一致)。这里两个口径必须分开写:wall/rows = 0.784 ms/会话(0.765–0.968),cpu/rows = 0.614 ms/会话(0.569–0.809)。这条 JS 线程是进程里唯一的一条(见 #10),被别的会话占满时,扫描里上千次顺序 await 每次都要重新排队:看门狗日志里同一现象要么是「列表返回正确但超预算」(rows=633 latency=44389ms),要么是 timed out(45010–45045 ms)。把 0.5 s 放大成 34 s – ≥45 s 这件事,已在隔离副本上受控复现(127.0.0.1:4099 副本、8 路同刻并发 session/list ⇒ wall_p50 2131.6 ms = K=1 的 3.75×、按自身 CPU 归一 5.62×、窗内主线程 cpu_pct_of_wall=101.3% 已饱和,而最坏一发 2970.3 ms 对同窗轻请求中位 3.4 ms ⇒ 873× 对照;另一轮独立整跑 4.16×)—— 但生产 stall 当刻(13:21:51 / 07:36:46 那些窗口)仍没有进程内样本,而且生产的 34 s – ≥45 s 对应 54–89×(wall 口径)远大于副本 K=8 的 3.75×:副本证明的是「同形状的排队放大确实存在」,不是「生产那 45 s 已被逐毫秒解释」。45 s 本身是客户端 socket 超时(budget 30 s + slack 15 s)的右截尾,真实停顿 ≥45 s。后面是实测锚点、代码锚点(指到行)、已排除与未排除的替代假设、已常驻的现场仪器与判读法、建议修法与英文正文。

一句话判据(只读重放,约 2 分钟):经网关重放一发 session/list,同时每 50 ms 采 /proc/<pid>/task/<pid>/stat 的 utime+stime(HZ=100)。权威组 A0(16:10:06–16:10:09,经网关 5006、rpcId=fixed、6 发)逐发落在 主线程 CPU / wall = 0.744–0.840:wall 638.5 / 517.4 / 521.8 / 522.4 / 505.9 / 504.6 ms × 主线程 CPU 533.6 / 405.1 / 395.3 / 405.1 / 424.9 / 375.5 ms,即时间基本花在这条 JS 线上;首字节也在这条线上 —— 同 6 发 TTFB 中位 510.8 ms(489.3–630.6)⇒ TTFB/wall = 96.97–99.56%,1,578,662 B 的传输只占 2.3–15.3 ms。复跑一条命令:node ops/dsh/stall-instrument/stall-instrument.mjs --authority 6 --rpc-id fixed(逐发原始 JSON:/tmp/stall-instrument-user-a-authority.jsonl)。14:1x / 15:1x 起的其余各组(H1–H4,含 wall 616/572/534 ms、CPU 530/460/400 ms 的 3 发)只用于对比通路与复核旧文,引用一律用 A0;那 3 发的 bytes=1,578,663 属于 rpcId=f"p{i}"(2 字符)的旧脚本:三发只有长度一致、sha256 互异,差异只在 byte 35 起的回显 rpcId;把 rpcId 固定才是 6/6 逐字节一致 —— len=1,578,662、sha256=923a9bf90594c61e…。判读必须三者联读:①同刻 canary(轻请求)延迟 ②本 RPC 的 wall 与主线程 CPU ③目标进程的主线程占用率。只看任一项都可能读反方向:旧探针的 QUEUE_SENSITIVE 判词已废弃(它等价于「探针进程自己的主线程空闲(cpu_pct ≤ 66.7%)」,与「目标进程主线程被占满」正好相反);第三轮修好后的判词是单调的 NORMAL / STALLED / RPC_LOCAL_SLOW / UNCLASSIFIED / RPC_FAILED —— 规则:wall < slow_ms(1000) ⇒ NORMAL;否则 canary_max ≥ canary_slow_ms(300) ⇒ STALLED(目标整体被占),否则 RPC_LOCAL_SLOW(这条 RPC 自己的路径慢);缺 canary 样本时 ⇒ UNCLASSIFIED,cpu_pct 只作旁证、不参与判词(control-plane-starvation-probe.mjs:297、:73)。同一个进程健康时是 571–719 ms(看门狗 14:55–15:09 的 8 轮 OK,rows=659–660;这是独立仪器(生产看门狗走同一条网关通路),不是本页探针),被饿到超时是 RED … latency=45045ms — session/list 未在预算内返回(45045 ms):timed out —— 中间没有「部分可用」的中间态。本判据已由常驻仪器自动化:stall-instrument.mjs 每 2 s 一发 canary、每 60 s 一发 list、1 Hz 按线程采 CPU,list > 5000 ms 或 canary > 2000 ms 即落一条 STALL_CAUGHT(触发点前后各 30 s 现场)。
优先级:中高。①这是控制面可用性问题而不是性能调优:一元 session/list 与所有 agent 工作共享同一条 JS 线程,而它的注册形态就是 invocation: { kind: 'direct' } —— 随包 84 个 RPC 描述符没有第二种 kind(实测),即没有队列、没有优先级、没有第二条执行体可选;②「慢」与「坏」当前同形:DSH 不导出这条 RPC 的等待/执行耗时,唯一的区分是本仓看门狗事后按「超时」猜(session-list-health.py 里「慢 ≠ 坏,不重启」那段注释就是这条,行号会漂移,用 grep -n "慢 ≠ 坏,不重启" ops/dsh/session-list-health.py 定位);③与 #7(零字节永不返回)、#8(脏目录 fail-closed)是同一条 RPC,与 #10(进程是唯一并行单位)同一个根:主线程没有第二次机会。与 #10 的边界见「已排除的替代假设」。判读口径(V6 降级):不要把任何单一阈值当判词 —— 旧探针的 QUEUE_SENSITIVE 看的是探针进程自己的主线程空闲度,与「目标进程主线程被占满」方向相反,已废弃;现行探针判词是单调的 NORMAL / STALLED / RPC_LOCAL_SLOW / UNCLASSIFIED(慢 + 同刻 canary 也慢 ⇒ STALLED;慢 + canary 仍快 ⇒ RPC_LOCAL_SLOW;缺 canary 样本 ⇒ UNCLASSIFIED),正确读法仍是「同刻 canary 延迟 + 本 RPC 的 wall/CPU + 目标进程主线程占用」三者联读。
口径:本页哪些数是谁采的(第四轮起收敛为唯一权威组)。★ 引用一律用 A0:2026-09-15 16:10:06–16:10:09,经网关 127.0.0.1:5006 + Host/X-DSH-Gate/Cookie,rpcId=fixed 连发 6 次,同刻无 stall;逐发原始记录 /tmp/stall-instrument-user-a-authority.jsonl,复跑 node ops/dsh/stall-instrument/stall-instrument.mjs --authority 6 --rpc-id fixed。期间还有一份独立实现的交叉核对(sudo -n python3 + http.client,16:14:5x,3 发):ttfb=553.5/541.7/459.1、wall=559.0/546.7/467.3、main_cpu=450/480/370、rows=660、bytes=1578662、sha=923a9bf90594c61e ⇒ 与 A0 同字节同 sha(证明 A0 不是某一实现的特性)。H1–H4 四组历史测量(含本页 15:10:08–15:10:13 自采 3 发、EVID 14:1x 六发、15:44 直连 4006 三发)只用于对比通路与复核旧文,引用必须带时刻 + 通路,且不得替代 A0(它们的口径并集「wall 483–662 ms、CPU 379–559 ms」已作废,见 FACTS-20260915.md §0.1)。令牌两处只读来源:sudo -n cat [实例目录]/web-url.txt 与 sudo -n grep -E '^[GATE_TOKEN_VAR]=' [app-dir]/gate.env —— 旧稿写的 [app-dir]/gate.sh 在本机不存在(ls [app-dir]/ 只有 gate.env),实际密钥文件是 [app-dir]/gate.env。其余现场数字来自:同仓 ops/dsh/evidence/evid-recheck-20260915-user-a-sessionlist.md(历史组 H2)、/var/log/dsh-session-list-health.log(本页用 awk/grep 复量过,是独立于探针的仪器)、以及本机 /home/user-a/.dsh/logs/web.log(需 sudo;启动次数与命令见「实测锚点」第 6 段)。本页订正 EVID 三处:读超时条数为 20(EVID #22 的条数偏低,本次按 RED 专用正则全量复量为 20)、user-d 的上限为 19515 ms(EVID #13 取的是 13:00 后 38 个样本,max 2633 ms)、启动次数的来源写明是本机 web.log 而不是记在 EVID 名下。会话目录数已由本页复量:sudo -n find /home/user-a/.dsh/sessions -mindepth 2 -maxdepth 2 -type d | wc -l → 660,origin histogram: {"subagent":648,"<none>":12}(ops/dsh/upstream-issue-main-thread-control-plane/FACTS-20260915.md:166、:170;sudo -n true 可用,会话目录读得到)。本页仍未实测的是 4 会话 / 20 条 TOOL_OUTCOME_UNKNOWN 的生产逐条明细(引自 EVID #33,未逐条复测);隔离副本上的同形机制已实测(ops/dsh/graceful-stop-verify/ 的 A/B 跑,见「影响面」第 5 行)。13:21:51 / 07:36:46 当刻的主线程占用率仍然没有样本 —— 放大机制已在隔离副本上受控复现(8 路并发 3.75×),但生产 stall 当刻的进程内样本仍缺,那是常驻仪器 STALL_CAUGHT 要等的东西。两处仓内脚本(session-list-health.py、user-serve.sh)在本页写作期间被并行重写:session-list-health.py 在本页复核期间两次实测 —— 15:39 是 61,433 B / 1,131 行 / md5 70e02ed5ff39a244bcc9bd7dbb9b3baa,15:44 已变成 66,588 B / 1,205 行 / md5 8bf529f43825595cedd12daa447fbe76(5 分钟 +74 行)—— md5 与行号都只是时点参考,本页正文给出的该脚本行号一律以引文 grep 为准(本页引的是 15:44 那一版,且给的是命令而不是承诺)。

一句话结论与三条事实

三条都是实测:现场只读 RPC 重放(权威组 A0=16:10:06–16:10:09 经网关 6 发;历史组 H1–H4 另计,见「口径」)、隔离副本上的受控放大实验(K=1/2/4/8,127.0.0.1:4099)、隔离副本上的关停 A/B/C(SIGTERM 与 session/cancel)、看门狗日志 /var/log/dsh-session-list-health.log、随包代码 0.1.5-rc.1 lib/ 逐行核对。行号与文件指纹见「代码级证据」。

① 这条 RPC 是纯主线程的约 0.5 s CPU 活,成本随会话数线性

本页采纳的唯一权威组 A0(16:10:06–16:10:09,经网关 5006、rpcId=fixed、6 发,同刻无 stall):wall 中位 517.4 ms(逐发 638.5 / 517.4 / 521.8 / 522.4 / 505.9 / 504.6),同发主线程 utime+stime 差 中位 405.1 ms(逐发 533.6 / 405.1 / 395.3 / 405.1 / 424.9 / 375.5),即 74.4–84.0% of one core;rows=660(6 发同值)、响应 1,578,662 字节(6 发同值,rpcId=fixed)、sha256=923a9bf90594c61e… ⇒ 6/6 逐字节一致。字节数必须与所用 rpcId 绑在一起写:它随 rpcId 的长度变,也随当刻会话集漂(同机另一轮 rpcId=stall-instrument-fixed(22 字符)是 1,578,679 B;历史组 rpcId=f"p{i}"(2 字符)是 1,578,663 B)—— 拿旧脚本的 3 发做例子:rpcId=p0/p1/p2 时三发只有长度一致、sha256 互异(23a6ff3a58fee714 / 8d3198fc84bd2f16 / bbcfe709b698507d),差异只在 byte 35 起的回显 rpcId。一份独立实现(sudo -n python3 + http.client,16:14:5x,3 发)给到同字节同 sha:wall 559.0/546.7/467.3、main_cpu 450/480/370、rows=660、bytes=1578662。两个口径分开写:wall/rows = 0.784 ms/会话(0.765–0.968),cpu/rows = 0.614 ms/会话(0.569–0.809)。成本几乎全在主线程、且几乎全在首字节之前:TTFB 中位 510.8 ms(489.3–630.6)⇒ TTFB/wall = 96.97–99.56%,1,578,662 B 的传输只占 2.3–15.3 ms。历史组 H1–H4(含 EVID 14:1x 六发 wall 527–621 ms、CPU 400–520 ms)同量级,只用于对比通路。没有第二个进程、第二条线程在替它干活:代码路径逐会话顺序 await(dsh-session-persistence-jsonl/lib/index.js:2858 listArtifacts() → :2864/:2866 两层 for → :2868 → :2872,每层都是 await),list() 之后还要对每个会话再 await stat() 一次(:2459/:2462);同组复核给出该发全线程 CPU 533.6–1255.0 ms(其中 libuv-worker 只 108.7–138.3 ms、threads=11 恒定)⇒ CPU 主要在 main,但不是只有 main。

② 饱和时它不是「慢」,是「排队」:隔离副本上 8 路并发把同一发 RPC 拉长 3.75×(按自身 CPU 归一 5.62×),而同窗轻请求中位仍 3.4 ms

看门狗日志给出同一台机器上两种结局(user-a 户,截至 15:09 截断):成功样本 n=1429,min=5 / p50=493 / p90=756 / max=28715 ms;RED 37 条,分四类:读超时 timed out 20 条(45010–45045 ms)、网关不可达 10 条(Connection refused,全落在重启窗口)、「算完了但超预算」6 条(hard=False,不重启:21:24:05 rows=531/42396ms、23:36:58 rows=601/36006ms、23:37:11 rows=601/37379ms、07:36:46 rows=633/44389ms、07:38:31 rows=633/34259ms、07:41:27 rows=633/37392ms)、reset 1 条(Connection reset by peer,9/14 15:54:29)。四类相加 20+10+6+1 = 37。45 s 那 20 条是右截尾:客户端 socket 预算 = 30 s + slack 15 s,到点即断,真实停顿 ≥45 s;那 45 s 里有多少是排队、多少是算不完,生产当刻仍然没有样本。放大律已在隔离副本上受控实测(ops/dsh/upstream-issue-main-thread-control-plane/queue-amplification-sweep.mjs,目标 127.0.0.1:4099 的隔离 DSH 实例 pid 41122、665 行副本,生产端口一个字节都没发):同刻发起 K 发 session/list,窗口两端掐目标主线程 utime+stime(标定 clk_tck=96.928),并每 400 ms 并行插一串轻请求 canary(GET /favicon.ico + GET /api/ping,都走同一条主线程):
K=1: wall_p50 509.1 ms(相对 K=1 基线 568.0 = 0.896×)、cpu_per_call 448.8 ms、cpu_pct_of_wall 88.0%、canary_p50 2.8 ms
K=2: 668.9 ms(1.178×)、374.0 ms、100.5%、2.6 ms
K=4: 1093.8 ms(1.926×)、341.8 ms、101.8%、2.8 ms
K=8: 2131.6 ms(3.752×)、330.8 ms、101.3%、3.0 ms —— 判词行 QUEUE_AMPLIFICATION k=8 wall_p50_ms=2131.6 cpu_total_ms=2646.3 cpu_per_call_ms=330.8 canary_p50_ms=3.0 amplification_vs_k1=3.752(完整原文:ops/dsh/upstream-issue-main-thread-control-plane/evidence-queue-amplification.txt;第二轮整跑(原始输出 evidence-queue-amplification-run2.txt)复现同一量级:K=8 wall_p50 2152.7 ms(amp 3.548)、K=4 1172.0、K=2 699.3、K=1 561.0(基线 606.7 ms、684 行))。读法:并发到 8 时单发 wall 是 K=1 的 3.75×,而单发自己烧的 CPU 反而降到 0.668×(495.2→330.8 ms)⇒ 墙钟抬升不是这条 RPC 多烧了 CPU,而是它要跟同进程另外 7 发抢同一条主线程;窗口内 cpu_pct_of_wall=101.3%(>100 是 10 ms tick 粒度 + 两端不同钟,未钳位)说明主线程已饱和。按自身 CPU 归一后放大 amplification_cpu_normalized=5.618×(脚本原字段;其 wall/cpu 比从 K=1 的 1.134 升到 K=8 的 6.445)。同刻 canary 对照就是生产签名的复制:K=8 最坏一发 RPC 2970.3 ms,而同窗 canary 中位只有 3.4 ms ⇒ 873×(QUEUE_AMPLIFICATION_CANARY_CONTRAST … ratio_wall_over_canary_p50=873.618)——「轻的还快、重的慢到秒级」,与「13:21:32 网关探针 OK 而 list 读超时」同形。尾巴如实报:canary_max 随 K 恶化 13.2 → 256.5 → 425.8 → 1233.7 ms,≥200 ms 占比 0/24 → 4/24 → 6/34 → 8/48,K=8 的尖峰 4/4 窗都落在窗内 ~1.3–1.7 s 处(形状提示读完 fs 后有一段几百 ms 的主线程同步块会把轻请求一起堵住;那是观察到的相位,不是已验证的成因)。fs 调用数也从「结构推算」升级为实测(sudo -n strace -f -tt -e trace=openat,read,close -p 41122,窗内含一发 list,空闲头/尾窗的文件 fs 调用均为 0,故全部记在该 RPC 账上):fs_calls_in_call=3333(openat=1334 + pool 线程 read=665 + pool 线程 close=1334)/ rows=665 ⇒ 每会话 5.012 次(openat 2.006 + read 1.000 + close 2.006),实测 3333/665 = 5.012(原始输出 evidence-queue-amplification.txt 第 65 行;第一轮探索性 strace 的另一组 3328/664 未保留原始行,本页不引用) —— 此前推断的「约 3,300 次 / 每会话约 5 次」被证实。但「让出执行权次数」仍没有单独计数(没有 event-loop 层 hook),所以「45 s ÷ 次数」这类槽位时延仍然算不出来,本页不再给 ms/槽:旧稿按 3,300 次算出的 13.6 ms/槽(按 syscr ≈5,300 则是 8.5 ms/槽)已删,因为分母本身就不是「让出次数」。能替代它的是可测的饱和口径(cpu_pct_of_wall 101.3%)与可测的放大倍率(3.75× / 5.62×)。并发摊薄的是事件循环唤醒、不是文件读:8 发串行 list 使 /proc/41122/io 的 syscr +44273(5534/发,单发 +5320),而 K=8 并发窗只有 ~10775(≈1347/发)—— 主线程事件循环 read 是 4661 次/发(7.009/会话),一次唤醒服务多个回调所以越并发越少;而 pool 线程上的文件读按 strace 仍是每发 665 次、线性。

③ 越过 45 s 就从「慢」变「坏」:自愈重启 → 在途调用腰斩 → TOOL_OUTCOME_UNKNOWN

13:21:51 RED … 45045ms timed out → 13:22:01 SESSION_LIST_HEALTH_HEALED user=user-a(重启)→ 13:22:04 RED … 网关不可达(5006):Connection refused;13:38:39 那条读超时 → 13:38:49 HEALED 是第二幕。窗口内的启动次数本页本轮已复量,来源是本机 /home/user-a/.dsh/logs/web.log(需 sudo,见「实测锚点」第 6 段):全文件 15 行 start user=user-a,其中 13 行落在窗口内(≥ 2026-09-14 01:01:23);日志里 SESSION_LIST_HEALTH_HEALED user=user-a 共 11 次。后果是冷加载 resume 合成 4 会话 / 20 条 TOOL_OUTCOME_UNKNOWN(workflow 15 · bash 3 · job_output 2;EVID #33,本页未复测生产会话文件)。这条链的下半段已在隔离副本上逐步实测(ops/dsh/graceful-stop-verify/):SIGTERM 后在飞工具调用确实只有 call 没有 result(seq16 tool/call 之后耐久日志里 0 条 tool/result、也没有 step/end / turn/end),且**必须在下次冷加载 resume 时才补合成** —— 见「影响面」第 5–6 行的 A/B 数字。这一条只算影响面:缺陷是「控制面 RPC 没有第二条执行体」加「慢与坏同形」;即使永不重启,34 s – ≥45 s 的列表也已不可用。

先把「谁慢」说清楚。不是「DSH 每个请求都慢」:同一进程健康时同一条 RPC 是 571–719 ms(看门狗 14:55–15:09 的 8 轮 OK;独立仪器),被饿死时才是 34259 ms – ≥45045 ms(34 s 那端是「算完了但超预算」,45 s 那端是右截尾)。也不是「这台机器忙」:同刻(13:17:33–13:19:36 一整轮)其他户各自的进程都健康(user-c 620–732 / user-d 1736–2277 / user-j 6–7 / user-l 332–404 / user-k 4–6 / user-b 361 ms),13:21:51 只有 user-a 是 45045 ms。期望 vs 实际(压成一句):控制面 RPC 的尾延迟应当与「别人正在干活」解耦、行数不该与单次调用成乘法关系 —— 实际是被放大 54–89× 的全量扫描(34259–45000 ms ÷ 权威组 A0 的 wall 504.6–638.5 ms;若改用 cpu 口径 375.5–533.6 ms 则是 64–120×),无分页、无索引、无缓存(:2858–2872 顺序遍历,:2459/:2462 每会话再 stat)。这个包络是「日志 ÷ 空闲单发」的除法,不是受控实验;受控的那一半在隔离副本上量到的是 3.75×(K=8,按自身 CPU 归一 5.62×) —— 副本的并发模型(8 发全是 list)与生产(混合 agent 工作)不同,所以两者只能并列,不能互相代替。
一次就能定分晓:stall 窗口内的现场仪器 —— 已经做好并常驻,缺的只剩「下一次真 stall」。本页第三轮提出的三样东西,第四轮已按此实现为只读仪器 ops/dsh/stall-instrument/stall-instrument.mjs,并于 2026-09-15 16:09:50 起常驻(pid 98147,目标 user-a 生产 --port 4006 的 pid 2722569;只读:不发写请求、不重启、不 kill):
① canary 延迟直方图:每 2 s 一发经网关 5006 的 GET /favicon.ico(与主线程同一条路);
② 目标进程主线程 CPU:1 Hz 读 /proc/<pid>/task/*/stat,按 comm 分成 main / libuv-worker / other 三组;
③ 完整 list 与 fs 归账:每 60 s 一发 session/list,记 wall / TTFB / rows / bytes / 该发主线程 CPU;fs 调用数则已在副本上用 strace 逐次点清(见②节与「代码级证据」②)。
触发线:list > 5000 ms 或 canary > 2000 ms 即落一条 STALL_CAUGHT,内含触发点前后各 30 s 的 canary 序列 + 1 Hz 主线程 CPU 序列 + 触发那一发的 list 明细;若是 canary 触发,还会补打一发 list 做确认(30 s 冷却)。本轮窗口(16:09:50–16:26:10,16.3 min,1489 条记录)实测全是空闲基线:STALL_CAUGHT=0(max list wall 695.4 ms ≪ 5000 ms 线、max canary 214.7 ms ≪ 2000 ms 线),canary n=491:p50 3.0 / p99 12.9 ms、主线程 CPU n=980:p50 0 / p99 43.5 / max 79.2 % of one core、threads=11 恒定 —— 这些是空闲基线,不是 stall 当刻的数字。判读(触发时):① 在 stall 期间仍健康 + ② 主线程 100% 忙 + ③ 线程池排队 ⇒ 本页结论成立且机制落地;若 ① 也同步恶化 ⇒ 是整条事件循环级别的停顿,应另立一题。剩下的唯一缺口是「等」:生产 stall 事件全在过去(最后一条读超时 09-15 13:38:39),探针是现场仪器、不是历史检测器 ⇒ 生产 stall 当刻的进程内样本,本页仍未采到(理由同「仍未定论」⑥:不在生产上制造 stall)。

实测锚点(含原始输出)

每段都能复制回终端。读数是活账(日志每分钟在长),提交前以当刻读数为准;本页统一用 < "2026-09-15 15:09" 截断。第 0 段有两块:先给权威组 A0(引用一律用这块),再给历史组 H3(第一/二/三轮自采的 3 发,只作通路对照,勿引用)。

# ★ 权威组 A0(引用一律用这条):2026-09-15 16:10:06–16:10:09,经网关 5006,rpcId=fixed,6 发,同刻无 stall
$ node [repo]/ops/dsh/stall-instrument/stall-instrument.mjs --authority 6 --rpc-id fixed
  AUTHORITY_SUMMARY wall_median=517.4 wall_range=504.6-638.5 ttfb_median=510.8 cpu_median=405.1
  # 逐发 wall 638.5/517.4/521.8/522.4/505.9/504.6 ms;TTFB 630.6/510.8/513.2/520.1/502.2/489.3 ms
  # 逐发主线程 CPU 533.6/405.1/395.3/405.1/424.9/375.5 ms(74.4–84.0% of one core);rows=660 ×6
  # bytes=1,578,662 ×6;sha=923a9bf90594c61e ×6(6/6 逐字节一致;rpcId 长度会改字节数)
  # 原始逐发 JSON:/tmp/stall-instrument-user-a-authority.jsonl
  # 独立实现交叉核对(sudo -n python3 + http.client,16:14:5x,3 发):
  #   ttfb=553.5/541.7/459.1 wall=559.0/546.7/467.3 main_cpu=450/480/370 rows=660
  #   bytes=1578662 sha=923a9bf90594c61e  ⇒ 与 A0 同字节同 sha
# 0) 【历史组 H3,只作通路对照,勿引用】第一/二/三轮自采:3 发只读重放(15:10:08–15:10:13,目标 pid 2722569)
$ python3 /tmp/probe3_starvation.py 2722569
target pid=2722569
  cmdline=node [app-dir]/app-[version]/node_modules/.bin/dsh --profile infra --no-open --host 127.0.0.1 --port 4006 --trusted-host [dsh-instance-host]
  start_time=2026-09-15T15:10:08
token exchange: 303 cookie: True
call0 @15:10:08: wall=616ms main_thread_cpu=530ms (86.0% of one core) rows=660 bytes=1578663 http_ok=True
call1 @15:10:09: wall=572ms main_thread_cpu=460ms (80.4% of one core) rows=660 bytes=1578663 http_ok=True
call2 @15:10:11: wall=534ms main_thread_cpu=400ms (74.8% of one core) rows=660 bytes=1578663 http_ok=True
  end_time=2026-09-15T15:10:13

# 1) 成功样本分布(先截断再算:日志每分钟在长,分母会漂)
$ awk '$0<"2026-09-15 15:09" && /OK +user=user-a /' /var/log/dsh-session-list-health.log \
    | grep -oE 'latency=[0-9]+ms' | tr -dc '0-9\n' | sort -n \
    | awk '{a[NR]=$1} END{printf "n=%d min=%d p50=%d p90=%d max=%d\n", NR,a[1],a[int(NR*0.5)],a[int(NR*0.9)],a[NR]}'
n=1429 min=5 p50=493 p90=756 max=28715

# 2) RED 总数:正则必须带尾部空格,否则 user-b 的行会混进来
$ grep -cE 'RED +user=user-a ' /var/log/dsh-session-list-health.log     # 正确
37
$ grep -cE 'RED +user=user-a' /var/log/dsh-session-list-health.log      # 反面教材(含 user-b)
49
$ grep -cE 'user=user-a .*RED' /var/log/dsh-session-list-health.log     # 旧稿的锚点命令:恒为 0
0

# 3) RED 37 条 = 四类(英文正文同此口径)
$ grep -E 'RED +user=user-a ' /var/log/dsh-session-list-health.log | grep -c 'timed out'          # 读超时
20
$ grep -E 'RED +user=user-a ' /var/log/dsh-session-list-health.log | grep -c '网关不可达'          # 网关 refused
10
$ grep -E 'RED +user=user-a ' /var/log/dsh-session-list-health.log | grep -c '列表返回正确但超预算'
6
$ grep -E 'RED +user=user-a ' /var/log/dsh-session-list-health.log | grep -c 'Connection reset'
1

# 4)「算完了但超预算」6 条:hard=False,看门狗不动手
$ grep -E 'RED +user=user-a ' /var/log/dsh-session-list-health.log | grep '列表返回正确但超预算'
2026-09-14 21:24:05 RED  user=user-a rows=531 registered=7 missing=0 latency=42396ms — 列表返回正确但超预算:42396 ms > 30000 ms(531 行)
2026-09-14 23:36:58 RED  user=user-a rows=601 registered=7 missing=0 latency=36006ms — 列表返回正确但超预算:36006 ms > 30000 ms(601 行)
2026-09-14 23:37:11 RED  user=user-a rows=601 registered=7 missing=0 latency=37379ms — 列表返回正确但超预算:37379 ms > 30000 ms(601 行)
2026-09-15 07:36:46 RED  user=user-a rows=633 registered=8 missing=0 latency=44389ms — 列表返回正确但超预算:44389 ms > 30000 ms(633 行)
2026-09-15 07:38:31 RED  user=user-a rows=633 registered=8 missing=0 latency=34259ms — 列表返回正确但超预算:34259 ms > 30000 ms(633 行)
2026-09-15 07:41:27 RED  user=user-a rows=633 registered=8 missing=0 latency=37392ms — 列表返回正确但超预算:37392 ms > 30000 ms(633 行)

# 5) 读超时 20 条:45010–45045 ms —— 右截尾(socket 预算 = 30 s + slack 15 s,到点即断)
$ grep -cE 'RED +user=user-a .*timed out' /var/log/dsh-session-list-health.log   # RED 专用正则
20
$ grep -cE 'user=user-a .*timed out' /var/log/dsh-session-list-health.log        # 旧稿正则:混进 10 行 HEALED 记录
30
$ grep -E 'RED +user=user-a ' /var/log/dsh-session-list-health.log | grep 'timed out'
2026-09-13 20:48:33 RED  user=user-a rows=0 registered=0 missing=0 latency=45044ms — session/list 未在预算内返回(45044 ms):timed out
2026-09-14 01:01:15 RED  user=user-a rows=0 registered=0 missing=0 latency=45023ms — session/list 未在预算内返回(45023 ms):timed out
2026-09-14 15:52:56 RED  user=user-a rows=0 registered=0 missing=0 latency=45010ms — session/list 未在预算内返回(45010 ms):timed out
2026-09-14 16:29:17 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-14 16:31:35 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-14 16:54:02 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-14 16:58:36 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-14 21:28:25 RED  user=user-a rows=0 registered=0 missing=0 latency=45024ms — session/list 未在预算内返回(45024 ms):timed out
2026-09-14 21:40:44 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-14 21:47:04 RED  user=user-a rows=0 registered=0 missing=0 latency=45042ms — session/list 未在预算内返回(45042 ms):timed out
2026-09-14 21:49:23 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-14 22:36:39 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-14 23:42:37 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-14 23:44:56 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-15 00:41:28 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-15 09:08:08 RED  user=user-a rows=0 registered=0 missing=0 latency=45044ms — session/list 未在预算内返回(45044 ms):timed out
2026-09-15 11:45:09 RED  user=user-a rows=0 registered=0 missing=0 latency=45029ms — session/list 未在预算内返回(45029 ms):timed out
2026-09-15 13:21:51 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-15 13:36:20 RED  user=user-a rows=0 registered=0 missing=0 latency=45045ms — session/list 未在预算内返回(45045 ms):timed out
2026-09-15 13:38:39 RED  user=user-a rows=0 registered=0 missing=0 latency=45026ms — session/list 未在预算内返回(45026 ms):timed out

# 6) 启动次数:本机 /home/user-a/.dsh/logs/web.log(需 sudo),以及自愈次数
$ sudo -n grep -cE '^----- .* start user=user-a ' /home/user-a/.dsh/logs/web.log
15
$ sudo -n grep -E '^----- .* start user=user-a ' /home/user-a/.dsh/logs/web.log | awk '$2>="2026-09-14"' | wc -l
13
$ grep -cE 'HEALED +user=user-a ' /var/log/dsh-session-list-health.log
11

# 7) 同刻对照:别的户各自的进程都健康(同一轮,13:17:33 → 13:19:36;13:17 轮 11 行全列)
$ grep -E '2026-09-15 13:(17:3|19:3)' /var/log/dsh-session-list-health.log | grep -v HEALED
2026-09-15 13:17:33 OK   user=user-c rows=776 registered=7 missing=0 latency=732ms
2026-09-15 13:17:34 OK   user=user-d rows=3141 registered=114 missing=0 latency=1736ms
2026-09-15 13:17:34 OK   user=user-j rows=2 registered=0 missing=0 latency=6ms
2026-09-15 13:17:35 OK   user=user-l rows=335 registered=16 missing=0 latency=404ms
2026-09-15 13:17:35 OK   user=user-k rows=1 registered=0 missing=0 latency=4ms
2026-09-15 13:17:36 OK   user=user-a rows=656 registered=8 missing=0 latency=1539ms
2026-09-15 13:17:37 OK   user=user-b rows=333 registered=7 missing=0 latency=361ms
2026-09-15 13:17:37 OK   user=user-e rows=0 registered=0 missing=0 latency=2ms
2026-09-15 13:17:37 OK   user=user-f rows=0 registered=0 missing=0 latency=2ms
2026-09-15 13:17:37 OK   user=user-g rows=0 registered=0 missing=0 latency=3ms
2026-09-15 13:17:37 OK   user=user-h rows=0 registered=0 missing=0 latency=2ms
2026-09-15 13:19:33 OK   user=user-c rows=776 registered=7 missing=0 latency=620ms
2026-09-15 13:19:35 OK   user=user-d rows=3141 registered=114 missing=0 latency=2277ms
2026-09-15 13:19:35 OK   user=user-j rows=2 registered=0 missing=0 latency=7ms
2026-09-15 13:19:36 OK   user=user-l rows=335 registered=16 missing=0 latency=332ms
2026-09-15 13:19:36 OK   user=user-k rows=1 registered=0 missing=0 latency=6ms
# 同一户 user-d 的分布(截至 15:09;只看上面两轮 1736/2277 ms 会低估上限)
$ awk '$0<"2026-09-15 15:09" && /OK +user=user-d /' /var/log/dsh-session-list-health.log | grep -oE 'latency=[0-9]+ms' | tr -dc '0-9\n' | sort -n | awk '{a[NR]=$1} END{printf "n=%d min=%d p50=%d p90=%d max=%d\n", NR,a[1],a[int(NR*0.5)],a[int(NR*0.9)],a[NR]}'
n=1463 min=1633 p50=2023 p90=2352 max=19515

# 8) 同刻网关探针(经同一网关、到同一 web 进程;6 s 超时、path=/favicon.ico)
$ sudo -n grep -E 'user=user-a ' /var/log/dsh-gateway-health.log | grep -E '2026-09-15 13:2[0-2]'
2026-09-15 13:20:32 OK   user=user-a host=[dsh-instance-host] gw=127.0.0.1:5006 path=/favicon.ico
2026-09-15 13:21:32 OK   user=user-a host=[dsh-instance-host] gw=127.0.0.1:5006 path=/favicon.ico
2026-09-15 13:22:32 OK   user=user-a host=[dsh-instance-host] gw=127.0.0.1:5006 path=/favicon.ico

# 9) 代码锚点(逐字回源)
$ sed -n '2858,2872p;2459,2462p' [app-dir]/app-[version]/node_modules/@deepseek-ai/dsh-session-persistence-jsonl/lib/index.js
$ sed -n '811p;837p' [app-dir]/app-[version]/node_modules/@deepseek-ai/dsh-api-gateway/lib/index.js
			let receiver = { kind: "direct" };
		if (descriptor.invocation.kind === "direct") return this.ctx;
$ grep -rho "invocation: { kind: '[a-z-]*'" [app-dir]/app-[version]/node_modules/@deepseek-ai/*/lib/typert.host.js | sort | uniq -c
     84 invocation: { kind: 'direct'}

读法:第 0 段的权威组 A0说明成本在 JS 里而不在盘上(逐发 wall − 主线程 CPU = 104.9 / 112.3 / 126.5 / 117.3 / 81.0 / 129.1 ms,即 16.0–25.6%;反过来 74.4–84.0% 的 wall 时间主线程在烧 CPU),而且几乎全在首字节之前(同 6 发 TTFB/wall = 96.97–99.56%,1,578,662 B 的传输只占 2.3–15.3 ms);A0 的 bytes=1,578,662 / rows=660 / sha256=923a9bf90594c61e… 是与 rpcId=fixed 绑定的(下面历史组 H3 那三个 bytes=1578663 属于该脚本的 rpcId=f"p{i}"(2 字符):三发只有长度一致、sha256 互异 —— 引用字节数必须同时给出 rpcId,详见①);第 4–5 段是同一份活的两个结局 —— 34259–44389 ms 六条正确返回(hard=False),45010–45045 ms 二十条超时(hard=True,右截尾);第 1–3 段是分母与四类拆分(20+10+6+1=37);第 6–8 段排除「机器 / 网关 / 进程整体故障」—— 别的户各自独立进程都健康,而 13:21:32 的网关探针(同一网关、同一 web 进程,只换 path)正落在 timed out 窗口内仍是 OK;第 9 段是代码锚点逐字回源;第 10–12 段(本轮新增)是隔离副本上的两组受控实验 —— 队列放大 K 扫描(3.75× / 按自身 CPU 归一 5.62×、canary 873× 对照(2970.3 ms / 3.4 ms)、strace fs 计数 3333/665)与关停 A/B/C(wrote_cancel_result=no / no / yes)。

分母与量法。n=1429 是成功样本(不含 RED),用 < "2026-09-15 15:09" 截断(命令见第 1 段);14:1x 的 EVID 无截断时是 n=1404 / p50 488.0,差别只是日志在长 —— 引用成功样本数必须写「截至 HH:MM,n=…」并附命令。max=28715 ms 那条不是超时(45 s 才计 RED)—— 28.7 s 但没越过任何线,即 RED 计数低估了被放大的次数。超时样本的 rows=0 是没拿到响应,不是「列表为空」。两个 ms/会话口径不要混用:权威组 A0 的 wall/rows = 0.784 ms(0.765–0.968)、cpu/rows = 0.614 ms(0.569–0.809)。

进程内归因:饱和时的时间到底花在哪(2026-09-16 第五轮)

issue #12 长期缺的就是这一项 —— 前四轮只有「主线程忙」的外部读数,没有「忙在什么」的进程内证据。本轮用 inspector 信号激活 + CDP Profiler(零依赖脚本 /tmp/dsh-scratch/prof/dsh-cpu-profile.js,不重启目标进程)在两类窗口采了 CPU profile:副本受控相位(权威)与 宿主 user-d 的 fan-out 负载窗(边界另注)。

① 副本受控相位(权威):K=16 并发 session/list,主线程 98.6% 饱和,idle 从 30.71% 掉到 2.23%。同一副本、同一脚本:

相位窗口 mssamples主线程 CPU ms占用 %调用
K=16 canonical sweep(3 窗)5828.1 / 5324.9 / 5469.6—5891.2 / 5378.9 / 5532.6101.1 / 101.0 / 101.248
K=16 profile(k16b,权威相位)10246.3922410100.098.638(全 200)
K=1 对照(k1)10219.892158200.080.220(全 200)

同窗轻请求签名照旧:K=16 饱和时 GET /favicon.ico + /api/ping p50 4.3 ms(max 18.9 ms),而重 RPC p50 4232 ms(K=1 对照 RPC p50 506.5 ms)⇒ 轻的还快、重的被排 10 倍。桶占比差(占 total_self_ms 的百分比,K=16 − K=1):

桶k16 %k1 %占比差 ppk16−k1 ms/s
cordis_ioc(IoC 容器属性/包装器)21.0515.65+5.40+53.8
zod_validate(zod v4 schema 校验)16.3513.21+3.14+31.3
fs_syscalls(readdir/stat/open/read/close)11.486.37+5.11+51.0
util_values_snap(walkJsonValue/assign/deepFreeze)11.146.98+4.16+41.4
session_io_parse(持久化/格式/投影/查询)9.276.53+2.73+27.2
gc((garbage collector))7.814.53+3.28+32.8
http_egress(socket write + undici 序列化)5.373.45+1.93+19.2
idle2.2330.71−28.48−284.3

[verified] 账是平的:忙桶 ms/s 增量之和 +284.1 ↔ idle −284.3(缺口 0.2 ms/s = 舍入);占比差之和 +0.01 pp(未舍入加总 −0.00)。结论三句:①饱和时多出来的时间按比例摊在同一批桶上,没有出现新的「元凶帧」;②排在最前的是 框架层(cordis_ioc)与 schema/JSON 校验(zod_validate + util_values_snap = 27.5%),而不是「会话扫描」本身(session_io_parse 只占 9.27%);③fs_syscalls 的占比翻倍(6.37% → 11.48%)与 gc(4.53% → 7.81%)说明并发把文件系统与分配压力也一起抬起来了。报告:ops/dsh/upstream-issue-main-thread-control-plane/attribution-replica-20260916.md(桶表 §3.2)、原始输出 evidence-attribution-replica-raw-20260916.txt。

② 宿主 user-d(本会话自身负载窗):工具执行本身就是主线程负载。窗口前 gate 主线程占用 92.8 / 93.4 / 93.3%(三窗 MAINTHREAD_OCC ticks=465/468/468 wall_ms≈5011–5014,满足 ≥90% 饱和判据),随后 PROFILER_OK pid=2396549 samples=13679 window_ms=15086 total_self_ms=15304,top self-time:readFileUtf8 6958 ms、readdir 2233 ms、parseProcStat 874 ms、spawn 748 ms、alive 366 ms、SafeIterator 294 ms、assign 254 ms、(idle) 241 ms、(garbage collector) 222 ms、walkJsonValue 197 ms。读法:fan-out 期间同进程工具调用(读文件 / 扫目录 / 起子进程)自己就在烧这条主线程,与副本桶表里 fs_syscalls/cordis_ioc 的抬升同向。边界(必须一起读):这是本会话自身制造的负载窗口,它证明「100% CPU 花在什么上」,不等价于 user-a 13:21 那 45 s 的逐毫秒归因;parseProcStat(874 ms)与 alive(366 ms)两个帧的出处未解释(本页不主张它们属于 DSH 还是采样/监控工具链)。原始输出:evidence-attribution-user-d-raw-20260916.txt。

③ 自动捕获与告警(objective ③):捕获链已实测通过,告警已上线(2026-09-16 正门落地上线)[2026-09-19 订正:该规则从未下发到两机 Grafana,且其采集腿已停摆 —— 见文末「第六轮订正」]。首条真实自动捕获(2026-09-16 09:30:16,user-d,仪器 armed 后数秒):list wall=8391.5 ms / ttfb=8381.4 / rows=3235 / bytes=1,869,703 / main_cpu=7562.1 ms / canary p50 27.2 ms(max 39.2)/ main_pct p50 89.5,原始记录 ops/dsh/stall-instrument/evidence-stall-caught-user-d-20260916.json;同刻 user-a 正常(620 ms)。。

仪器:ops/dsh/stall-instrument/stall-instrument.mjs 已多户化(+524 行),每发 STALL_CAUGHT + 每 60 s 心跳原子写 /var/lib/node_exporter/textfile/dsh_stall.prom,指标 10 条(dsh_stall_captured_total、…_last_caught_timestamp_seconds、…_last_caught_list_wall_ms、…_last_caught_canary_p50_ms、…_last_caught_main_pct_max、…_list_wall_ms_last、…_canary_ms_p50_1h、…_main_pct_p50_1h、…_capture_ok、…_capture_last_run_timestamp_seconds,标签 {user,instance,port})。

端到端演练(2026-09-16):ops/dsh/stall-instrument/evidence-drill-20260916.txt(+ .jsonl),判词 DRILL stall_caught=1 prom_written=1 rule_fires=1 prod_untouched=0。如实读:prod_untouched=0 是因为演练期间确实写过生产 textfile(prom_written=1、写 14 次),事后已清成占位行(现内容 # dsh_stall.prom — 演练样本已清除;等生产 stall-instrument 写真实样本);演练经隔离副本 4099、cap 到 1 条 STALL_CAUGHT(trigger=list_wall_ms>1、wall_ms=584.44、rows=711)。

告警规则:已就绪但已上线(2026-09-16 正门落地上线)[2026-09-19 订正:该规则从未下发到两机 Grafana,且其采集腿已停摆 —— 见文末「第六轮订正」]。文件已从 ops/monitoring/dsh/alerts/dsh-stall.yaml 移到 ops/monitoring/dsh/alerts/dsh-stall.yaml —— 原因是 dsh 告警线 P2 预算 6/6 已满,放进去会让 validate-rules.sh 判 dsh=7/6 FAIL 并让整条 dsh 线发不出去(实测);移出后校验器恢复 VERDICT PASS (dsh=6/6)。两条收口路径(都要监控线决策):①砍掉一条现有 P2(或把两条死人开关并成一条)换这条上线;②按政策抬 max_p2 并同步 ALERT-GRADING-POLICY.md §5(registry 注记要求同笔更新)。因此「真 stall 自动告警」目前只有实现 + 规则,尚未生效;user-a 侧真实 STALL_CAUGHT 也仍为 0(该户至今没被真 stall 命中过)。

④ 本轮配套件:上游提案 ops/dsh/upstream-issue-main-thread-control-plane/UPSTREAM-shutdown-cancel-20260916.md(可直接粘贴的英文 issue:dispose 不为在途 tool/call 落收尾结果,含复现与 2–3 个按侵入性排序的修法);一命令复现件 REPRO-20260916.md(放大律 / systemd 路径 A/B / 进程内归因各一条命令 + 判词行 + 期望输出)。

影响面:从「慢」到误杀到腰斩

只写后果链,不重复缺陷本身;每环都有日志或 file:line 锚点。

#环节锚点(日志原文 / 代码 file:line)
1本户的会话把这条线程占满:660 个会话里 648 个是 subagent 会话(98.2%),它们与这条 RPC 抢同一条 JS 线程;会话目录 246 MB。sudo -n find …/sessions -mindepth 2 -maxdepth 2 -type d | wc -l → 660(本页复量);sudo du -sh …/sessions → 246M;origin 直方图 {"subagent":648,"<none>":12}(ops/dsh/upstream-issue-main-thread-control-plane/FACTS-20260915.md:166、:170;sudo -n 之下会话目录可读)。
2扫描里的上千次顺序 await 每次都重新排队 ⇒ 同一份约 0.5 s 的活被拉到 34 s – ≥45 s(45 s 是右截尾)。(放大机制:隔离副本上已受控复现,见②节;生产当刻配对样本已到手(user-d 17:48–18:07),进程内归因见「进程内归因」节)代码:dsh-session-persistence-jsonl/lib/index.js:2858/2864/2866/2868/2872、:2459/:2462;日志:「实测锚点」第 4、5 段;副本实测:queue-amplification-sweep.mjs + evidence-queue-amplification.txt(QUEUE_AMPLIFICATION k=8 wall_p50_ms=2131.6 amplification_vs_k1=3.752,canary 对照 873×(最坏一发 2970.3 ms / canary 中位 3.4 ms)。
3观察期的看门狗把它读成「坏」:socket 超时 = 预算 30 s + slack 15 s = 45 s,到点即 hard=True(那 20 条 45010–45045 ms,右截尾),而「算完了但超预算」只是 hard=False(那 6 条 34–44 s)。日志原文见本页「实测锚点」第 4、5 段。该判据是 EVID 复核时(14:1x)的版本:budget 30000 / slack 15 / 超时 hard=True。这个脚本在本页写作期间被重写(14:45:43),新判据见第 4 行。
4于是重启:连续 2 轮 hard + 冷却 900 s 到期 + 静态体检干净 ⇒ systemctl restart dsh-user-a.service(两天 13 次启动 / 11 次自愈)。现场:13:21:51 timed out → 13:22:01 SESSION_LIST_HEALTH_HEALED user=user-a。重写后的现版已改判据:读超时 hard=False、不重启(session-list-health.py:311 文档、:367 代码、:371「慢 ≠ 坏,不重启」),socket 超时放宽到 30 s + 90 s(:305、:316),heal 多一道闸「同刻网关探针为绿则不重启」(:642;gateway_green() 在 :489)(行号按 15:44 复量的 66,588 B / md5 8bf529f43825595cedd12daa447fbe76 那一版取 —— 同一文件 15:39 还是 61,433 B / 1,131 行、15:44 已 1,205 行;行号以引文 grep 为准)。新判据是否真止住重启,未实测。
5观察期的关停没有收尾窗口:SIGTERM → sleep 0.3 → kill -9,DSH 自己的 5 s 宽限根本没机会用。第四轮曾据此判定「6 s 宽限消灭不了 TOOL_OUTCOME_UNKNOWN」;2026-09-16 第五轮在 web/systemd 载体上把这条推翻(见本行末三点对照)—— 那个结论只对 headless 载体成立。当时脚本就是 kill / sleep 0.3 / kill -9(EVID 复核 #39)。它已在 2026-09-15 14:39:22 被改成有界宽限:STOP_GRACE_SEC=6(user-serve.sh:74),注释明写「旧的 sleep 0.3 太短」(:53)。单元侧前提已补齐(user-serve.sh:64–67):现网 11 个带 DSH_GATEWAY_PORT 的单元全量 KillMode=mixed + TimeoutStopUSec=8s(本轮复量 systemctl show dsh-user-a.service -p KillMode -p TimeoutStopUSec → mixed / 8s;11/11 命中)。▲ 第四轮实测(隔离副本 /tmp/dsh-scratch/.dsh + headless 载体 + 隔离 web 4099;第五轮已给出适用边界;证据 ops/dsh/graceful-stop-verify/evidence-graceful-stop-ab-20260915.txt,判据件 md5 3d0829cfb2813d7be6b25c83453f189d):让 headless 任务跑 bash(sleep 240),轮询到耐久 tool/call 且子进程真在跑,再按臂发信号 —— GRACEFUL_STOP_AB arm=A exit_ms=128 wrote_cancel_result=no resumed_repair=yes、arm=B exit_ms=134 wrote_cancel_result=no resumed_repair=yes(A 臂宽限 300 ms、B 臂宽限 6000 ms)。B 臂就是那 6 s 宽限,一样不写:进程 128–174 ms 内自然退出(4 次独立 A/B 跑:128/129/131/132/134/174 ms;另有一次 B=1025 ms、一次 A 到 300 ms 仍在跑被 SIGKILL),hard_kill_at_ms=0 ⇒ 6 s 宽限一次都没用上;杀后耐久日志末事件是 […, seq15 assistant/message, seq16 tool/call],该 callId 的 tool/result 0 条,也没有 step/end、turn/end;只有在下次冷加载(经 4099 的 session/create adopt ⇒ agent-loop resume)时才补出合成行(ToolOutcomeUnknownError / TOOL_OUTCOME_UNKNOWN、surfaceOp=append、sourceEventSeqs=[16])。对照臂 C(只发 session/cancel、进程不关停)会写:seq17 {"isError":true,"error_code":"ABORTED","error_name":"AbortError","text":"Error: tool call aborted"} → seq18 step/end → seq19 turn/end,web_process_alive_throughout=True。机制:SIGTERM 走的是 interrupt(0)(profile-boot-Dk-7KqJc.js:295–296),进程在 ~0.13 s 内退完,根本没走到 dispose 收尾;在飞子进程还在 dsh 退出之前约 40 ms 被拆掉(时间线 25 ms 采样:t=87ms sleep_alive=0、t=128ms dsh_alive=0)—— 结果既没被写、也没被取消写入。下一步修法:①上游 —— 在 dispose 期间对在途 tool/call 落一条明确收尾事件(这条代码路径已被臂 C 证明存在:取消时写得出 ABORTED);②本仓 —— 关停前先对活动 session 发 session/cancel 再发 SIGTERM(臂 C 已证明会写 ABORTED),而不是只把宽限从 0.3 s 加到 6 s。边界(第五轮更新):上面这一段是 headless 载体上的实测;web/systemd 载体已在 2026-09-16 用 transient 复刻件测过,结论相反 —— dispose 需要 2.1–2.7 s 且会写 ABORTED(见下)。仍未覆盖:真实生产用户实例(未做受控重启)与新增 cancel 步骤在极端负载下的稳定性;生效时点分两层(:70–73)—— mixed/8s 是停止时刻才读的单元属性、下次 stop/restart 即生效,而这段 6 s 宽限要等新版脚本拉起进程树才算数。
▲ 2026-09-16 第五轮:systemd 运维路径三点对照(transient 复刻件;判词原文 ops/dsh/graceful-stop-verify/evidence-systemd-path-ab-20260916.txt 与 …-control-20260916.txt;脚本 sysd-path-ab.sh 新增 --launcher-env):复刻件 = dsh-scratch-4101、真 ops/dsh/user-serve.sh、KillMode=mixed / TimeoutStopSec=8 / KillSignal=15 / FinalKillSignal=9、web 4101 / gateway 5101、冷加载经 4099。三臂逐字:①对照臂(修复前:DSH_STOP_CANCEL_WAIT_SEC=0 DSH_STOP_GRACE_SEC=0.3) SYSTEMD_PATH_AB arm=A stop_ms=403 wrote_cancel=no repair=yes(repair_events=1,合成 TOOL_OUTCOME_UNKNOWN);②Arm A(现状:补丁 launcher,默认 6 s 宽限) SYSTEMD_PATH_AB arm=A stop_ms=2690 wrote_cancel=yes repair=no;③Arm B(显式 cancel + 6 s) SYSTEMD_PATH_AB arm=B stop_ms=2134 cancel_ms=11.2 wrote_cancel=yes repair=no。两臂写出的都是 seq17 {"isError":true,"error":{"name":"AbortError","code":"ABORTED"}} 且 sourceEventSeqs=[16]。⇒ 在 web/systemd 载体上,0.3 s 的硬杀才是丢结果的原因、6 s 宽限正是解药;user-serve.sh 另新增「先 cancel 再 TERM」(DSH_STOP_CANCEL_WAIT_SEC 默认 1.5 s,0=off),Arm B 里 cancel 到结果落盘 11.2 ms。
6在途 tool/call 只有 call 没有 result ⇒ 下次冷加载 resume 时合成 TOOL_OUTCOME_UNKNOWN,用户看到「工具结果丢了」。(这条合成路径已在隔离副本上逐字采到,见第 5 行 A/B)repair.js:23 interruptedTurnClosers(events)、:113 { name: 'ToolOutcomeUnknownError', code: TOOL_OUTCOME_UNKNOWN };触发点 dsh-agent-loop/lib/index.js:1905–1906。副本采到的原文(ops/dsh/graceful-stop-verify/evidence-graceful-stop-ab-20260915.txt):{"type":"tool/result","seq":17,…"error":{"name":"ToolOutcomeUnknownError","code":"TOOL_OUTCOME_UNKNOWN"}},"surfaceOp":"append","sourceEventSeqs":[16] —— 且它只在冷加载时出现(杀后立即读同一份日志:0 条)。web/systemd 载体上这条不会发生:第五轮三点对照里对照臂 repair=yes、Arm A/B repair=no(见第 5 行末)。
7现场代价:窗口内 13 次启动 / 11 次由自愈触发,累计 4 会话 / 20 条工具调用被腰斩(workflow 15 · bash 3 · job_output 2)。启动次数本页本轮已复量:sudo -n grep -E '^----- .* start user=user-a ' /home/user-a/.dsh/logs/web.log → 全文件 15 行、窗口内 13 行(见「实测锚点」第 6 段),来源是本机 web.log(需 sudo);4 会话 / 20 条及工具分布仍只有 EVID #33,本页未复测会话文件;逐条时刻见 ops/dsh/evidence/evid-recheck-20260915-user-a-sessionlist.md「33 的逐条明细」。
为什么这仍然只是影响面 —— 而且本仓补丁没有消掉上游缺陷。第 3–6 环正被本仓自行收敛(看门狗改判「慢 ≠ 坏」、关停给 6 s 宽限),这恰好说明第 3 环的判据本该由上游提供;但第 2 环不动:一次约 0.5 s 的控制面扫描仍会被别人的工作量放大 54–89 倍(34259–45000 ms ÷ 权威组 A0 的 wall 504.6–638.5 ms;副本上的受控值是 3.75×),调用方仍拿不到任何「我正在排队」的信号。药在缺陷侧,不在看门狗侧。第 5 行第五轮已改判:第四轮「加宽限没用」的反例只在 headless 载体成立;在 web/systemd 载体(transient 复刻件 + 真 user-serve.sh)上加宽限正是解药 —— 对照臂(0.3 s、不 cancel)repair=yes,Arm A(6 s 宽限)与 Arm B(显式 cancel + 6 s)都 wrote_cancel=yes、repair=no;本仓 user-serve.sh 也因此新增「先 cancel 再 TERM」。

代码级证据(指到行)

随包行号按 0.1.5-rc.1 lib/ 逐条核对(2026-09-15),指纹:dsh-session-persistence-jsonl/lib/index.js 135,114 B md5 9f672813da6e;dsh-api-gateway/lib/index.js 48,194 B 83d6556dd4b0;dsh-api-session-controller/lib/typert.host.js 158,026 B f557b8f5b313;dsh/lib/profile-boot-Dk-7KqJc.js 14,350 B 913f96eea3f7;dsh-session/lib/types/repair.js 6,026 B ae555da35787;dsh-agent-loop/lib/index.js 71,267 B 95e92f081374。仓内脚本按写作时刻版本,都会漂移。

#事实锚点(逐字)
①session/list 的扫描是逐会话顺序 await:两层 for 各对目录做一次真实 I/O,然后每个会话再顺序解一次 header —— 没有批量、没有并发、没有上限。dsh-session-persistence-jsonl/lib/index.js:2858 async listArtifacts(signal) {;:2860 await this.ensureRootEncoding();;:2864 for (const project of await this.listProjectDirs(signal)) {;:2866 for (const dir of await this.listSessionDirs(project, signal)) {;:2868 await this.resolveGenerationInDirectory(dir, signal);:2872 await this.readGenerationHeader(selected, void 0, signal)。
②每个会话有至少五次走线程池的 fs/promises 调用:list() 拿到 artifact 后还要对每个会话再 await stat() 一次(bigint,为了 sizeBytes),这一层在 listArtifacts 之外。:2459 for (const artifact of await this.listArtifacts(signal)) {;:2462 const identity = await stat(artifact.path, { bigint: true });。全会话链路的 5 次=readdir :3165 + open :3127 + handle.read :3134 + handle.close :3157 + stat :2462。▲ 次数已从「结构推算」升级为 strace 实测(隔离副本 665 行、sudo -n strace -f -tt -e trace=openat,read,close -p 41122,窗内含一发 list、空闲头/尾窗的文件 fs 调用各为 0):fs_calls_in_call=3333(openat=1334 + pool 线程 read=665 + pool 线程 close=1334)/ rows=665 ⇒ 每会话 5.012 次(openat 2.006 + read 1.000 + close 2.006),实测 3333/665 = 5.012(原始输出 evidence-queue-amplification.txt 第 65 行;第一轮探索性 strace 的另一组 3328/664 未保留原始行,本页不引用);-c 汇总同窗 fs_calls_total=7996,差额在 read(主线程事件循环 read(19,…)=8 与套接字读)—— 行模式把主线程的 eventloop_reads_in_call=4661(7.009/会话)单独记账,tids_in_call 显示 openat/read/close 全部来自 4 条 libuv pool 线程。方法坑:4 条 pool 线程复用同一批 fd(都开成 27 并互相 close),按 fd 归属会算出假数(一轮 663、一轮 0),必须按线程分类;「让出执行权次数」仍然没有单独计数。
③冷进程第一次调用要扫两遍:ensureRootEncoding() 是 memo 的 promise,但它的第一份工作 checkRootEncoding() 同样遍历全部 project/session 目录 —— 冷进程等于扫两遍。:3278 this.rootEncodingCheck ??= this.checkRootEncoding();;:3281–3285 for (const project of await this.listProjectDirs()) for (const dir of await this.listSessionDirs(project)) { const incompatible = await this.findOppositeGenerationInDirectory(dir); … }
④header 读取是 JS 侧逐 8 KB 块 read + 逐帧扫描 + 解压:单个会话的成本随文件大小增长,不只是条数 —— 「加会话」与「加长会话」同样有效。:3127 await open(path, "r");:3134 await handle.read(chunk, 0, chunk.length, null);:3138 content = Buffer.concat([content, chunk.subarray(0, bytesRead)]);:3140 scanZstdFrames(content, 1).frames[0];:3146 await decompressZstdFrame(...)。(哪一段占掉那 0.5 s,本页仍无 profile,属推断;)副本给了一条相位旁证(不是成因证明):K=8 的 4/4 个窗口里,canary 尖峰都落在窗内 ~1.3–1.7 s 处(该处 canary 600–1200 ms,而窗内 121/525/928 ms 处的 canary 一律 ≤4.4 ms)⇒ 读完 fs 之后存在一段几百 ms 的主线程同步块(序列化 1.58 MB / 聚合)会连轻请求一起堵住。
⑤这条 RPC 注册形态上就没有第二种执行体:随包 84 个 RPC 描述符全部是 direct,没有 worker / queue / priority 可选项。dsh-api-session-controller/lib/typert.host.js:896–900:id: '…-controller#session/list' / service: 'sessionController' / method: 'list' / invocation: { kind: 'direct' };复量 grep -rho "invocation: { kind: '[a-z-]*'" $P/*/lib/typert.host.js | sort | uniq -c → 84 invocation: { kind: 'direct' }(无其它 kind)。
⑥direct 的含义就是「回到同一个 ctx 上跑」—— 同一个进程、同一条主线程,没有派发到别的执行体。dsh-api-gateway/lib/index.js:811 let receiver = { kind: "direct" };(默认值,本轮 sed -n '811p' 复量);:837 if (descriptor.invocation.kind === "direct") return this.ctx;;对照 :812–820 只有 context 一种分叉,也是同进程解析。
⑦「慢」与「坏」的区分只存在于本仓脚本里,而这条线自己也在挪:写作期间该脚本被重写成「读超时 = 慢 ≠ 坏」(不再重启)、socket 超时从 45 s 放宽到 120 s。旧判据(观察期,EVID 14:1x):budget 30 s + slack 15 s、超时 hard=True。现判据(行号按 15:44 复量的 66,588 B / 1,205 行 / md5 8bf529f43825595cedd12daa447fbe76 那一版取;同文件 15:39 复量还是 61,433 B / 1,131 行 ⇒ md5 与行号都只是时点参考)::311「读超时 ⇒ hard=False/slow=True/ok=False」(文档)、:316「socket 超时 = … 默认 30 s + 90 s」、:367 result.hard = False(读超时代码)、:371「慢 ≠ 坏,不重启(等下一轮复探)」、:424 超预算仍 hard=False。行号会漂移,用引文 grep 复现:grep -n "慢 ≠ 坏,不重启" ops/dsh/session-list-health.py、grep -n "result.hard = False" ops/dsh/session-list-health.py。
⑧触发重启的是连续 hard + 冷却 + 体检(现版再加一道「网关探针非绿」):所以单次 45 s 不会立刻杀进程 —— 但被拉长的活会连续出现。现版(行号按 15:44 复量的 66,588 B / 1,205 行 / md5 8bf529f43825595cedd12daa447fbe76 那一版取;该文件仍在被并行改写,复现请用引文 grep)::595 def heal(...)、:623–625 strikes 闸(if strikes < strikes_needed: → blocked_by = "strikes")、:637 冷却闸、:642 gateway_green() 闸(实现 :489)、静态体检闸 :649 if not integrity_clean():(定义在 :475)、:658 ["systemctl", "restart", …];默认值 :670 --budget-ms 30000、:684 --strikes 2、:685 --cooldown 900。
⑨腰斩的机制:观察期包装脚本在 SIGTERM 后 0.3 s 就 kill -9(DSH 自身给 5 s 宽限,没用上);只有「耐久写了 call 没有 result」的回合才会在下次冷加载被合成 TOOL_OUTCOME_UNKNOWN。▲ 隔离副本 A/B 实测(见「影响面」第 5 行):把宽限从 0.3 s 加到 6 s 仍然写不出取消结果 —— 进程 ~0.13 s 就自然退完,宽限根本没被用上。当时:kill / sleep 0.3 / kill -9(EVID 复核 #39)。现版:user-serve.sh:74 STOP_GRACE_SEC=6、:51–53 注释、:64–67 单元侧前提已补齐(KillMode=mixed / TimeoutStopUSec=8s,11/11 单元实测)、:70–73 生效时点分两层(:63 原来标的「未决」已由本轮副本实验回答:消灭不了)。上游侧:profile-boot-Dk-7KqJc.js:12 PROCESS_SHUTDOWN_TIMEOUT_MS = 5e3、:295–296 SIGTERM → interrupt(0);repair.js:23、:113;dsh-agent-loop/lib/index.js:1905–1906。副本证据:ops/dsh/graceful-stop-verify/evidence-graceful-stop-ab-20260915.txt(arm=A exit_ms=128 wrote_cancel_result=no / arm=B exit_ms=134 wrote_cancel_result=no / 对照 arm=C wrote_cancel_result=yes aborted_by_code=ABORTED)。

已排除的替代假设(H1/H2/H3,都实测过)+ 未排除项

写这一节是为了让「不是这些」也有据可查,避免下一轮重复劳动。三条已排除的假设(H1/H2/H3,编号为本页所加)每一条都给出否掉它的数字;紧随其后是没有排除的三条 —— 引用结论时不要把这两组混读。

未排除(与上面三条「已排除」相对,引用时别混在一起)。
  • libuv 线程池排队 —— 未排除(但「CPU 饱和型阻塞」已被否掉、文件读的线性度已实测)。目录 readdir / stat / read 都走 libuv 的 4 条 worker 线程(UV_THREADPOOL_SIZE 默认 4),而这条路径的 fs/promises 调用已由 strace 点清:实测 fs_calls_in_call=3333 / rows=665 = 5.012 次/会话(详见「代码级证据」②),且 pool 上的文件读每发都是 665 次、线性(K=8 并发窗也一样;被并发摊薄的是主线程事件循环的 read:串行 5534/发 vs 并发 ≈1347/发)。CPU 侧:4 条 libuv-worker 在整发 RPC 里只烧 108.7–138.3 ms(A0 复核)⇒「CPU 饱和型线程池阻塞」与实测不符,但队列深度 / 等待时延仍未量(本轮量的是 CPU 与调用数,不是队列),且 stall 当刻(45 s)依旧没有采样,故保持未排除。
  • 响应侧背压 —— 空闲场景已测(口径已换 A0),stall 场景未排除。权威组 A0 逐发同时记了首字节(ttfb_ms)与总耗时(wall_ms):TTFB 中位 510.8 ms(489.3–630.6)vs wall 中位 517.4 ms(504.6–638.5)⇒ 首字节占 96.97–99.56%(逐发 98.76 / 98.72 / 98.35 / 99.56 / 99.27 / 96.97%),1,578,662 B 的传输只占 2.3–15.3 ms(7.9 / 6.6 / 8.6 / 2.3 / 3.7 / 15.3)⇒ 这条 loopback 链路上「算完发不出去」上界 ≈15 ms / 517 ms(~3%),空闲场景已可排除。历史组 H2 的 python 六发同向(ttfb/wall 98.5–99.7%,首字节只早 6.1–7.1 ms)。但 stall 窗口内的 TTFB 仍未分离(那一轮 body 更大、且经网关走真实网络),45 s 里有多少是「算完发不出去」没有样本。未排除(仅 stall 场景)。
  • #11 follow-fanout 的每事件成本未分离 —— 未排除。同系列 #11 指出 session/follow 的 global 监听器让每事件成本线性增长;660 个会话的事件流本身可能就在消耗这条主线程。本页没有把「扫描自己的成本」与「同刻别人事件流的成本」分开量。未排除。
与 #7 / #8 / #10 的边界(避免重复报同一个 bug)。#7 是 session/list 零字节、永不返回(等到 300 s 也没有首字节);本页的 timed out 是45 s 客户端预算到点,服务端没崩、下一个健康窗口里同一条 RPC 是 571–719 ms(14:55–15:09 的 8 轮 OK;独立仪器)。#8 是一个脏目录把整张列表清空;本页列表内容完全正确(rows=660、rpcId 固定后 sha256 6/6 一致)。#10 是容量模型(一条 JS 线程,加并发只排队);本页是那个模型的控制面后果:同一份约 0.5 s 的活被放大 54–89 倍(wall 口径的除法;隔离副本上的受控值是 3.75×),且放大后的失败模式与「真坏」同形 —— #10 说「为什么只有一条线程」,#12 说「这条线程上的控制面请求会怎样死」。

仍未定论(禁止当结论)

以下每一条都是本页没有证据的部分;写出来是为了让维护者知道哪些话我们没说。

★ 生产 stall 当刻样本(2026-09-15 17:48–18:07,user-d 户 pid 1707984 —— 本轮补齐,此前「生产当刻无样本」的说法作废)。该户当天在跑本仓 4 轮 workflow 扇出(44 个 in-process subagent,全部与它同一条主线程),随后出现与 user-a 13:21 同形的 stall:
①看门狗自己的记录(独立仪器,每 2 min 一轮):17:48:21 / 17:52:24 / 17:56:27 RED user=user-d … latency=240118 / 240024 / 240201 ms(120 s 单发上限 × 2 次复探),判词已是修好的新分类「慢 ≠ 坏,不重启(等下一轮复探)」;同刻 user-a 户 565–619 ms 正常(不同进程)。
②手动只读探针(同一通路:Cookie + Host + Origin):wall=180,039 ms 超时,窗口内目标主线程 CPU = 179,640 ms(≈99.8% of one core);随后两发各 90,091 ms 超时、主线程 CPU 89,940 / 89,910 ms(≈99.8%)。
③同刻轻请求仍被服务:1 Hz 仪器窗口 18:01:49–18:04:24(--port 4002)实测 canary p50 174 ms(112.6–205.4,77 发,0 错),主线程 CPU p50 99.5%(98.4–100.6),libuv ≤4%。
⇒ 「轻的还快、重的饿死、主线程 100% 忙」三件事在生产同刻同时成立 —— 这正是本 issue 的签名,且这次还拿到了超出 45 s 右截尾的形态(180 s / 90 s)。仍未归因:那 100% CPU 的构成(本页只能证「忙」,不能证「忙在什么」;需要进程内 profiler,而 DSH 不导出)。副作用证据:整段 stall 期间该户没有被重启(新判词),因此没有任何在途调用被腰斩;按旧码同一事件会连续触发 --strikes 2 的自愈重启(至少 2 次)。

① 「主线程饱和导致放大」这句话:机制已在隔离副本上受控复现,缺的只剩「生产 stall 当刻的同刻样本」。副本侧已定论的那一半:127.0.0.1:4099 上 8 路同刻并发 session/list ⇒ wall_p50 2131.6 ms = K=1 的 3.75×(按自身 CPU 归一 5.62×),窗内主线程 cpu_pct_of_wall=101.3% 已饱和,而最坏一发 2970.3 ms 对同窗轻请求中位 3.4 ms(873× 对照)⇒「同一份约 0.5 s 的活被别人的工作排队放大」这个机制在受控条件下确实成立,且形状与生产签名同形。仍然未定论的那一半:13:21:51 / 07:36:46(user-a)那些窗口当刻的主线程占用率仍然没有记录(user-d 17:48–18:07 的配对样本与 2026-09-16 的进程内归因已补上,见上一段与「进程内归因」节;本仓与 DSH 都不导出持续指标,见 #10 的同一结论);副本的并发模型(8 发全是 session/list、665 行副本)与生产(混合 agent 工作、660 行、极端值 34–45 s)不同,且生产的 54–89× 远大于副本的 3.75× —— 副本证明的是机制的定性成立,不是那个 45 s 的定量解释。仪器侧已升级:第三轮提的三样(canary 直方图 + 1 Hz 主线程 CPU + list/fs 归账)已实现为常驻只读仪器 ops/dsh/stall-instrument/stall-instrument.mjs(触发线 list>5 s / canary>2 s,落 STALL_CAUGHT,含触发点前后各 30 s 现场;第五轮已多户化并写 dsh_stall.prom,见「进程内归因」节③);user-a 侧 STALL_CAUGHT 仍为 0,端到端演练走的是隔离副本 + 合成阈值。未定论(只剩 user-a 那几个历史窗口当刻的样本;真 stall 自动告警因 P2 预算已上线(2026-09-16 正门落地上线)[2026-09-19 订正:该规则从未下发到两机 Grafana,且其采集腿已停摆 —— 见文末「第六轮订正」])。

② fs 调用次数现在是 strace 实测(3333 / 665 行 = 5.012 次/会话),但「让出执行权次数」仍然没有计数 ⇒ 槽位时延依旧算不出来。已实测:隔离副本一发 session/list 的 fs_calls_in_call=3333(openat=1334 + pool 线程 read=665 + pool 线程 close=1334),rows=665 ⇒ 5.012 次/会话;实测 3333/665 = 5.012(原始输出见 evidence-queue-amplification.txt 第 65 行);空闲头/尾窗的文件 fs 调用各为 0 ⇒ 全部记在该 RPC 账上;主线程事件循环的 read 是另一条账(4661 次/发 = 7.009/会话)。未定论:没有 event-loop 层的 hook,「让出执行权次数」无法计数,所以旧稿那两个「45000 ÷ 次数据」的槽位时延(13.6 ms/槽、8.5 ms/槽)已从本页删除(分母根本不是让出次数)。可替代的可测口径有两个:饱和 cpu_pct_of_wall=101.3%、放大倍率 3.75×(wall)/ 5.62×(按自身 CPU 归一)。未定论(只剩「让出次数」这一项没有计数器)。

③ 放大器到底是 JS 微任务队列还是 libuv 线程池争用 —— 两条线各自的量已经点清,但没有做分段受控分离。已量到的:pool 侧每发 665 次文件读且线性(K=8 并发窗仍线性),4 条 libuv-worker 在整发 RPC 里只烧 108.7–138.3 ms;主线程侧事件循环 read 是 4661 次/发(7.009/会话),而并发只摊薄这一侧(8 发串行 syscr +44273 → 5534/发,K=8 并发窗 ~10775 → ≈1347/发)—— 即一次唤醒服务多个回调。未分离的:副本的 K 扫描是端到端 wall / 主线程 CPU,不含分段计时,所以「哪一段占掉主要放大」仍需 profile(这条同时列在「未排除项」里)。未定论(分歧未分离)。

④ 前端是否过滤 subagent 会话,本页未实测。EVID 只在 dsh-web-frontend bundle 里没搜到 subagent 字样(算旁证);但 session/list 确实返回 660 行、其中 648 个是 subagent 会话(该 648 来自 EVID #17,本页未复测会话文件),扫描成本确定照付。「前端不显示所以应当不返回」是我们对上游的建议,不是已成立的事实。未定论。

⑤ 20:30:06 那次重启的归因未独立取证。EVID 把 web.log 里 9/14 20:30:06 的启动归给「批量部署」(该次既无 HEALED 行、网关日志也无 HEAL),但没有部署记录与之对上 —— (假设,未取证)。未定论。

⑥ 本页没有在生产实例上做加压实验,也不建议做 —— 但同一实验已在隔离副本上做完。立场不变:在生产上「加压到 K 路并发看是否复现 45 s」会人为制造 timed out → 连续两轮 hard → 重启 → 腰斩真实用户的在途工具调用;本页的做法是用只读重放量成本(第 0 段),用日志量结局(第 1–3 段),不制造新的被害者。副本上已经做了:127.0.0.1:4099 的 K=1/2/4/8 受控扫描(3.75× / 5.62×、K=8 绝对墙钟 2.13 s),但没有复现 45 s 量级 —— 副本是 665 行、8 路并发全是 session/list,与生产 stall 时的混合负载不同;K=16/32 未测,其它 RPC(session/get 等)也未测。未定论(生产:不做;副本:做到 K=8 为止)。

⑦ 本仓刚改的两处补丁有没有用 —— 关停那半已被副本实验否掉,看门狗那半仍未实测。session-list-health.py 与 user-serve.sh 都在本页写作期间(14:39–14:46)被重写:前者把读超时改判 hard=False、socket 超时放宽到 120 s,后者把 0.3 s 改成 6 s 宽限。关停那半(第五轮改判:第四轮的「否」被推翻):第四轮 headless A/B/C —— arm=A(300 ms)与 arm=B(6000 ms)都不写取消结果、进程 128 / 134 ms 自然退出、hard_kill_at_ms=0;第五轮 web/systemd 载体(transient 复刻件 dsh-scratch-4101 + 真 user-serve.sh)三点对照:对照臂(DSH_STOP_CANCEL_WAIT_SEC=0 DSH_STOP_GRACE_SEC=0.3)SYSTEMD_PATH_AB arm=A stop_ms=403 wrote_cancel=no repair=yes;Arm A(6 s 宽限)SYSTEMD_PATH_AB arm=A stop_ms=2690 wrote_cancel=yes repair=no;Arm B(显式 cancel + 6 s)SYSTEMD_PATH_AB arm=B stop_ms=2134 cancel_ms=11.2 wrote_cancel=yes repair=no ⇒ 丢结果的根因是 0.3 s 硬杀、6 s 宽限就是解药,第四轮结论的适用边界是 headless。看门狗那半(仍未实测):新判据(读超时 hard=False、不重启、外加「同刻网关探针为绿则不重启」的闸)会不会真的止住重启,要等下一次生产 stall 才知道。单元侧前提已补齐:user-serve.sh:64–67 记「前提已补齐」,本轮 systemctl show 复量现网 11/11 个带 DSH_GATEWAY_PORT 的单元都是 KillMode=mixed + TimeoutStopUSec=8s。部分定论(关停:web/systemd 上「宽限有效」已实测、headless 上无效;看门狗:新判据已在 2026-09-15 17:48–18:07 的 user-d 真 stall 中生效 —— 三轮 RED 判「慢 ≠ 坏,不重启」、该户未被重启;「是否零误杀」仍需更长观察)。

⑧ RED 37 条里混着「网关不在」的窗口效应,引用时必须拆开。四类拆分是:读超时 20 + 网关不可达 10 + 算完了但超预算 6 + reset 1。后 11 条(refused/reset)时刻全部落在启动/重启窗口(例如 13:22:04 在 13:22:01 重启之后 3 s、13:38:52 在 13:38:49 之后 3 s),它们计的是「网关不在」,不是「RPC 慢」;但每次重启的确切停机时长本页未测。口径已定论,时长未定论。

复现:只读重放与判据行

下面没有写操作、没有重启、不碰任何会话文件;需要读的两样东西是 user-a 户的 web URL(含 token)与网关的 X-DSH-Gate,这一步用只读 sudo。本页作者以 user-d 户执行。

# 0) 自检:只读到令牌与网关密钥(两处都只用只读 sudo;密钥文件是 [app-dir]/gate.env —— 旧稿写的 [app-dir]/gate.sh 在本机不存在)
$ sudo -n cat [实例目录]/web-url.txt | tail -1     # 形如 http://127.0.0.1:4006/?token=...
$ sudo -n grep -E '^[GATE_TOKEN_VAR]=' [app-dir]/gate.env | tail -1 | cut -d= -f2- | wc -c
$ pgrep -af 'bin/dsh --profile infra'                   # 核对目标 pid(本轮 2722569,13:38:49 启动)
#   旧稿写的 pgrep -af 'dsh web' 实测 0 命中(唯一一行是 pgrep 命令自身所在的 bash 命令行);按端口定位用 pgrep -af 'port 4006'
# 1) 主实验:3 发只读 session/list 重放 + 主线程 CPU 采样(本轮真实执行的脚本 /tmp/probe3_starvation.py)
$ cat > /tmp/probe3_starvation.py <<'PY'
import http.client, json, subprocess, sys, threading, time, datetime
PID = int(sys.argv[1]) if len(sys.argv) > 1 else 2722569
HOST, GW, HZ = "[dsh-instance-host]", 5006, 100.0
tok  = subprocess.run(["sudo","-n","cat","[实例目录]/web-url.txt"],capture_output=True,text=True).stdout.strip().split("token=")[-1]
gate = subprocess.run(["sudo","-n","bash","-c","grep -E '^[GATE_TOKEN_VAR]=' [app-dir]/gate.env | tail -1 | cut -d= -f2-"],capture_output=True,text=True).stdout.strip()
def jif():
    p = open(f"/proc/{PID}/task/{PID}/stat").read().rsplit(") ",1)[1].split()
    return int(p[11]) + int(p[12])                 # utime + stime(HZ=100)
c = http.client.HTTPConnection("127.0.0.1", GW, timeout=20)
c.request("GET", f"/?token={tok}", headers={"Host": HOST, "X-DSH-Gate": gate}); r = c.getresponse(); r.read()
ck = next((v.split(";")[0] for k,v in r.getheaders() if k.lower()=="set-cookie"), None)
samples, stop = [], threading.Event()
def sampler():
    while not stop.is_set():
        samples.append(jif()); time.sleep(0.05)     # 每 50 ms 采一次目标进程主线程
for i in range(3):
    samples.clear(); stop.clear(); th = threading.Thread(target=sampler); th.start()
    ts = datetime.datetime.now().strftime("%H:%M:%S"); t0 = time.monotonic()
    c2 = http.client.HTTPConnection("127.0.0.1", GW, timeout=120)
    rid = f"p{i}"   # rpcId 会被原样回显 ⇒ 变它会改响应字节数(±rpcId 长度);要逐字节比对请改成固定值
    body = json.dumps({"type":"client-request","rpcId":rid,"method":"session/list","payload":{"args":{"_request":{}}}})
    c2.request("POST", "/api/session/list", body, {"Host": HOST, "X-DSH-Gate": gate,
               "Content-Type":"application/json", "Origin": f"https://{HOST}", **({"Cookie": ck} if ck else {})})
    resp = c2.getresponse(); raw = resp.read(); t1 = time.monotonic(); stop.set(); th.join()
    wall = (t1-t0)*1000; cpu = (samples[-1]-samples[0])*10
    rows = len(json.loads(raw)["result"]["value"]["items"])
    print(f"call{i} @{ts}: wall={wall:.0f}ms main_thread_cpu={cpu:.0f}ms ({cpu/wall*100:.1f}% of one core) rows={rows} bytes={len(raw)} http_ok={resp.status==200}")
    time.sleep(1)
PY
$ python3 /tmp/probe3_starvation.py 2722569
target pid=2722569
  cmdline=node [app-dir]/app-[version]/node_modules/.bin/dsh --profile infra --no-open --host 127.0.0.1 --port 4006 --trusted-host [dsh-instance-host]
  start_time=2026-09-15T15:10:08
token exchange: 303 cookie: True
call0 @15:10:08: wall=616ms main_thread_cpu=530ms (86.0% of one core) rows=660 bytes=1578663 http_ok=True
call1 @15:10:09: wall=572ms main_thread_cpu=460ms (80.4% of one core) rows=660 bytes=1578663 http_ok=True
call2 @15:10:11: wall=534ms main_thread_cpu=400ms (74.8% of one core) rows=660 bytes=1578663 http_ok=True
  end_time=2026-09-15T15:10:13
# 2) 结局分布(日志每分钟在长,先截断再算,否则分母一直变)
$ awk '$0<"2026-09-15 15:09" && /OK +user=user-a /' /var/log/dsh-session-list-health.log \
    | grep -oE 'latency=[0-9]+ms' | tr -dc '0-9\n' | sort -n \
    | awk '{a[NR]=$1} END{printf "n=%d min=%d p50=%d p90=%d max=%d\n", NR,a[1],a[int(NR*0.5)],a[int(NR*0.9)],a[NR]}'
n=1429 min=5 p50=493 p90=756 max=28715

# 3) 四类拆分与「网关不在」的窗口效应(判据行就在这些命令的输出里)
$ grep -E 'RED +user=user-a ' /var/log/dsh-session-list-health.log | grep -c '列表返回正确但超预算'   # 算完了但超预算
6
$ grep -cE 'RED +user=user-a .*timed out' /var/log/dsh-session-list-health.log                     # 读超时(RED 专用正则)
20
$ grep -cE 'user=user-a .*timed out' /var/log/dsh-session-list-health.log                          # 旧稿正则:混进 10 行 HEALED 记录
30
$ grep -E 'RED +user=user-a ' /var/log/dsh-session-list-health.log | grep -c '网关不可达'            # 网关 refused
10

# 4) 代码锚点(逐字回源)
$ sed -n '2858,2872p;2459,2462p' [app-dir]/app-[version]/node_modules/@deepseek-ai/dsh-session-persistence-jsonl/lib/index.js
$ sed -n '811p;837p' [app-dir]/app-[version]/node_modules/@deepseek-ai/dsh-api-gateway/lib/index.js
			let receiver = { kind: "direct" };
		if (descriptor.invocation.kind === "direct") return this.ctx;
$ sed -n '896,900p' [app-dir]/app-[version]/node_modules/@deepseek-ai/dsh-api-session-controller/lib/typert.host.js
      invocation: { kind: 'direct' },

# 判据(末行):下面这组是【历史组 H3】的 3 发 main_thread_cpu/wall = 0.75–0.86(400/534、460/572、530/616),rows 逐发一致;字节数 1,578,663 属于 rpcId=f"p{i}" 这一版(三发只有长度一致,sha256 互异)。
#   ★ 引用一律改用权威组 A0(16:10:06–16:10:09,经网关 5006,rpcId=fixed,6 发):wall 中位 517.4 ms(504.6–638.5)、
#     主线程 CPU 中位 405.1 ms(375.5–533.6 = 74.4–84.0% of one core)、TTFB 中位 510.8 ms、rows=660、bytes=1,578,662、sha256 923a9bf90594c61e ×6;
#     即 main_thread_cpu / wall = 0.744–0.840。复跑:node ops/dsh/stall-instrument/stall-instrument.mjs --authority 6 --rpc-id fixed
#   —— 但单看这一项不足以说「被饿死」:必须与「同刻 canary(轻请求)延迟」「目标进程主线程占用率」三者联读;
#      旧判词 QUEUE_SENSITIVE 已废弃(它看的是探针进程自己的空闲度,与目标进程主线程被占满方向相反);现行判词是单调的:NORMAL / STALLED(canary 也慢)/ RPC_LOCAL_SLOW(canary 仍快)/ UNCLASSIFIED(缺 canary 样本)。
#   n=1429 里 max=28715ms,且 6 条 34–44 s「正确但超预算」+ 20 条 45 s(右截尾)timed out ⇒ 同一现象两种结局。
# 退出码:0 = 复现;1 = 未复现(该户空闲,或列表已分页/已缓存);2 = 判据无效(读不到 token/gate,或 pid 不对)
# 端点:POST /api/session/list(旧稿写的 /rpc 未复测)
result退出码含义
STARVED0复现成功:main_thread_cpu / wall 落在 A0 的 0.744–0.840(历史组 H3 是 0.75–0.86),rows 与响应长度逐发一致(sha256 只在固定 rpcId 时才逐发一致),且同刻 canary(轻请求)仍健康、日志里同一时段既有「正确但超预算」又有 timed out。判读按三者联读,不按单一阈值判词(现行判词 NORMAL / STALLED / RPC_LOCAL_SLOW / UNCLASSIFIED 是这套联读的单调化,不是单阈值)。要判「排队放大」而不是「这条 RPC 自己慢」,按第四轮的副本做法更硬:同刻发 K 路并测窗内主线程 CPU 占比(K=8 时 cpu_pct_of_wall=101.3% 饱和、同窗 canary 中位仍 3.4 ms)。
IDLE1没复现:该户当刻没有并发的 agent 工作,wall 稳定在 0.5–0.6 s —— 这恰好说明成本本身没变,变的是排队。
PAGED1没复现:上游已实现索引/分页(rows 明显小于会话目录数,或响应显著变小)—— 这正是本页建议的修法。
握手 / 鉴权失败2判据无效:读不到 web-url.txt 或 gate.env,或 pid 与当前 web 进程不符(用 pgrep -af 'bin/dsh --profile infra' 或 pgrep -af 'port 4006';旧稿的 pgrep -af 'dsh web' 实测 0 命中)。注意旧稿写的 [app-dir]/gate.sh 在本机不存在,密钥文件是 [app-dir]/gate.env。
两条边界。①别在生产实例上压满:第 1 段是串行只读重放(A0 每发主线程 CPU 0.376–0.534 s;历史组 H3 是 0.4–0.53 s),量的是「一发多少钱」,不是「多少发会崩」;并发压测会人为制造 timed out,连续两轮 hard 即触发 systemctl restart,把真实用户在途的工具调用腰斩成 TOOL_OUTCOME_UNKNOWN。要加压就去隔离副本:queue-amplification-sweep.mjs(K=1/2/4/8)与 verify-graceful-stop.sh --arms A,B,C 都只打 127.0.0.1:4099,生产端口一个字节都不发。②上面第 1 段就是本页实际执行的脚本之一(精简自 /tmp/probe3_starvation.py),不依赖仓内脚本或第三方依赖;唯一的外部输入是两处只读 sudo 令牌,端点用 /api/session/list(旧稿写的 /rpc 未复测);A0 走的是另一条独立实现(ops/dsh/stall-instrument/stall-instrument.mjs --authority 6),两者给到同字节同 sha256。

建议修法(分级)

P0 = 不改就会继续误杀;P1 = 把成本真正降下来;P2 = 让下一次不用靠猜。

级别修法为什么是这条 / 怎么做
P0给控制面 RPC 一条独立执行体或至少一个优先级通道根因是「没有第二条执行体」—— 这是结构判断:84 个描述符全为 direct 是实测的。invocation: { kind: 'direct' } 让 session/list 回到与推理工作同一条主线程(dsh-api-gateway/lib/index.js:837)。放大这一环本轮有进展但仍不完整:隔离副本上 8 路同刻并发把同一发 RPC 拉长 3.75×(按自身 CPU 归一 5.62×),窗内主线程 cpu_pct_of_wall=101.3% 饱和、最坏一发 2970.3 ms 对同窗轻请求中位 3.4 ms(873× 对照)⇒「排队放大」这一机制已受控复现;但生产 stall 当刻(34–45 s 那些窗口)的进程内样本仍缺,且生产的 54–89× 大于副本的 3.75×。两步可做:①把 listArtifacts() 的目录遍历与 header 解码移到 worker / 线程池,主线程只汇总;②或在派发层给控制面方法一条可抢占通道(哪怕只是「一次扫描切成 N 段,段间让出并检查是否有交互式请求在等」)。判据:并发 agent 工作下,这条 RPC 的 p99 不随「别的会话在跑」上升。
P1列表加索引缓存 + 分页 + 服务端 origin 过滤660 行里 648 个是 subagent 且前端不显示(本页未实测前端过滤;648 来自 EVID #17),成本却照付(:2858–2872 全扫 + :2459/:2462 每会话 stat)。做法:sessions/ 旁挂一份 index(mtime+size 失效,目录变更增量更新),session/list 变成一次读 + 游标分页;默认 origin=subagent 不进首屏。判据:rows 与单次耗时不再线性相关。
P2把「慢」与「坏」在可观测面上分开现在唯一的区分是本仓脚本事后按超时猜(session-list-health.py 里「慢 ≠ 坏,不重启」那段注释就是这条;行号会漂移,用 grep -n "慢 ≠ 坏,不重启" ops/dsh/session-list-health.py 定位),上游侧没有任何信号。给这条 RPC 导出三个数就够:排队等待时长(进入执行到第一次被调度)、执行时长、让出次数,按分位暴露。有了它们,「算完了但超预算」与「根本没返回」在仪表上就是两件事,超时预算与自愈策略也才不用跟着猜。本仓已按这个方向改了自己的看门狗(读超时不再判 hard、网关探针为绿则不重启),但那是事后猜,不是上游信号。
P2关停时给在途工具调用一个收尾窗口▲ 第五轮改判(推翻第四轮):web/systemd 载体上加宽限正是解药;「只加宽限没有用」只在 headless 载体成立。arm=B(宽限 6000 ms)与 arm=A(300 ms)一样 wrote_cancel_result=no,进程 134 / 128 ms 就自然退出、hard_kill_at_ms=0 ⇒ 6 s 宽限一次都没被用上;只有 session/cancel 那条路径写得出 ABORTED(arm=C)。证据:ops/dsh/graceful-stop-verify/evidence-graceful-stop-ab-20260915.txt。机制:SIGTERM 走 interrupt(0)(profile-boot-Dk-7KqJc.js:295–296),进程 ~0.13 s 内退完,根本没走到 dispose 收尾。所以修法要换:①上游 —— 在 dispose 期间对在途 tool/call 落一条明确收尾事件(ABORTED 的写法已经存在,臂 C 证明写得出);②本仓 —— 关停前先对活动 session 发 session/cancel 再发 SIGTERM,而不是把 STOP_GRACE_SEC 从 0.3 s 加到 6 s(该值在 user-serve.sh:74;单元侧 KillMode=mixed + TimeoutStopUSec=8s 前提已补齐,11/11 单元实测,说明在 :64–67)。第五轮 systemd 复刻件三点对照:对照臂(DSH_STOP_CANCEL_WAIT_SEC=0 DSH_STOP_GRACE_SEC=0.3)stop_ms=403 wrote_cancel=no repair=yes → Arm A(6 s 宽限)stop_ms=2690 wrote_cancel=yes repair=no → Arm B(显式 cancel + 6 s)stop_ms=2134 cancel_ms=11.2 wrote_cancel=yes repair=no(两臂写 AbortError/ABORTED)。修法收敛为两条:①本仓 user-serve.sh 已加「先 cancel 再 TERM」(DSH_STOP_CANCEL_WAIT_SEC 默认 1.5 s,0=off)并保留 6 s 宽限;②上游仍建议在 dispose 期间对在途 tool/call 落收尾事件(headless 载体今天仍会丢,见 UPSTREAM-shutdown-cancel-20260916.md)。证据:evidence-systemd-path-ab-20260916.txt、evidence-systemd-path-ab-control-20260916.txt、脚本 sysd-path-ab.sh、复现件 REPRO-20260916.md。边界:复刻件是 transient 单元 + 真 user-serve.sh,真实生产用户实例未做受控重启。
不建议的修法。①把看门狗预算从 30 s 调到 60 s —— 只是把误杀推迟,45 s 的列表对交互式前端同样不可用;②给 session/list 加客户端重试 —— 每次重试都是一次 0.5 s 的主线程 CPU,重试风暴正好压在已经被饿死的那条线上;③在用户侧「少开会话」——把上游的容量问题转嫁给用户。

可提交的 issue #12 正文(英文)

整段可直接粘贴,不依赖我们此前任何报告;行号按随包 lib/(0.1.5-rc.1)核对。

Title: Control-plane unary RPCs are starved on the shared JS main thread: the same
       0.5 s-CPU session/list call measures 34 s to >=45 s under load; the queueing
       amplification is REPRODUCED on an isolated replica (3.75x at 8-way concurrency),
       while the production stall itself still has no in-process sample
       (the 45 s bound is a right-censored client socket timeout: 30 s budget + 15 s slack)
Summary
-------
A DSH host is one Node process with a single JS main thread shared by every session,
every subagent and every RPC. `session/list` is a unary, control-plane RPC that walks
the entire session store sequentially, one `await` per session. Measured on an idle
process (AUTHORITY GROUP A0: 2026-09-15 16:10:06-16:10:09, over the gateway on 5006,
`rpcId=fixed`, 6 replays against the same pid): 660 rows, 1,578,662 bytes, 504.6-638.5 ms of
wall time (median 517.4) against 375.5-533.6 ms of main-thread CPU (median 405.1, i.e.
74.4-84.0 % of one core) - that is 0.784 ms per session by wall time and 0.614 ms by CPU
time; keep those two units apart. First byte is 96.97-99.56 % of wall (TTFB median 510.8 ms),
so of the 1,578,662 bytes at most 2.3-15.3 ms is transport. Measured on the same process
while other sessions are running: 34 s to >=45 s. The 45 s bound is a right-censored client
socket timeout (30 s budget + 15 s slack), so the real stall is >=45 s.

That queueing mechanism is now REPRODUCED, under controlled conditions, on an isolated
replica (127.0.0.1:4099, 665 rows, production ports untouched): 8 concurrent `session/list`
calls on the same process give wall_p50 2131.6 ms = 3.75x the K=1 replay (5.62x once
normalised by the call's own CPU, which DROPS to 0.668x), with the main thread at
cpu_pct_of_wall 101.3 % (saturated), while a light canary request in the same window still
has a 3.4 ms median - an 873x contrast (worst call 2970.3 ms vs that 3.4 ms median), the same shape as "gateway probe OK while list times
out" in production. What we still do NOT have is any in-process sample for a PRODUCTION
stall, and production's 54-89x (34,259-45,000 ms over the 504.6-638.5 ms A0 wall) is much
larger than the replica's 3.75x: the replica proves the mechanism, not the 45 s magnitude.

The scan does not get slower - it gets re-queued. `strace` on an isolated 665-row replica
counts the fs work exactly: 3333 fs calls for one `session/list` (openat 1334 + thread-pool
read 665 + thread-pool close 1334) = 5.012 calls per session (2.006 + 1.000 + 2.006); one strace run gives 3333 fs calls / 665 rows = 5.012 per session (raw output: evidence-queue-amplification.txt line 65), and the idle windows before and
after the call show 0 file fs calls, so all of them belong to that RPC. The main thread's
event-loop reads are a separate account (4661 per call = 7.009 per session) and they ARE
amortised by concurrency (5534 per call when serial vs ~1347 per call at K=8), while the
thread-pool file reads stay exactly linear (665 per call). We still do NOT count event-loop
yields, so we no longer quote any "ms per yield": 45,000 ms / 3,300 ~= 13.6 ms per slot used
the wrong denominator and has been removed.

The observable consequence is worse than the latency: on this wire "slow" and "broken"
look identical. The same event yields either a correct response at 34-44 s or a
client-side timeout at 45 s (45010-45045 ms), and only a local script can tell them
apart. We do not claim the front end filters subagent sessions.

Shutdown A/B/C on the same isolated replica (measured, headless carrier): with SIGTERM the
process exits BY ITSELF in 128-134 ms, so a 6 s grace is never used (hard_kill_at_ms=0), and
the durable log ends at the `tool/call` with 0 `tool/result` rows - no step/end, no turn/end.
The synthetic TOOL_OUTCOME_UNKNOWN appears only on the next cold resume. The arm that DOES
write a cancellation result is `session/cancel` (error_code ABORTED, then step/end, turn/end).
In other words: widening the grace from 0.3 s to 6 s does not fix the lost tool result.

Why this matters
----------------
A control-plane RPC that lists metadata should not compete with the work it describes.
The 45 s timeout was not cosmetic: our watchdog treated it as a hard failure and, after
two in a row, restarted the service. Restarting killed in-flight tool calls - the wrapper
sent SIGKILL 0.3 s after SIGTERM while the process itself grants 5 s - and they came back
on the next cold resume as synthetic TOOL_OUTCOME_UNKNOWN results: 13 starts in two days,
11 from this path, 20 results lost across 4 sessions. We have since changed both locally
(a read timeout is no longer a restart trigger, and the grace is 6 s); the starvation is
unchanged, and fixing only the watchdog would hide it - on an idle process the call is
534-616 ms, so under load it is still 56-84x its wall time (65-113x its measured CPU
cost) whenever the process is busy.

Environment
-----------
  DSH 0.1.5-rc.1 (shipped lib/); one systemd unit, one Node process and one gateway per
  user; the measured user returns 660 rows (660 session directories on disk, origin
  histogram {subagent: 648, none: 12}, 246 MB), 648 of them subagent sessions; web on
  127.0.0.1:4006 behind a gateway on 0.0.0.0:5006.

Evidence (measured)
-------------------
  AUTHORITY GROUP A0 (2026-09-15 16:10:06-16:10:09, over the gateway on 5006,
  rpcId=fixed, 6 read-only session/list replays against the same pid; main-thread CPU from
  /proc/PID/task/PID/stat utime+stime; reproduce with:
    node ops/dsh/stall-instrument/stall-instrument.mjs --authority 6 --rpc-id fixed ):
    call0: wall=638.5ms ttfb=630.6ms cpu=533.6ms (83.6% of one core) rows=660 bytes=1578662
    call1: wall=517.4ms ttfb=510.8ms cpu=405.1ms (78.3% of one core) rows=660 bytes=1578662
    call2: wall=521.8ms ttfb=513.2ms cpu=395.3ms (75.8% of one core) rows=660 bytes=1578662
    call3: wall=522.4ms ttfb=520.1ms cpu=405.1ms (77.5% of one core) rows=660 bytes=1578662
    call4: wall=505.9ms ttfb=502.2ms cpu=424.9ms (84.0% of one core) rows=660 bytes=1578662
    call5: wall=504.6ms ttfb=489.3ms cpu=375.5ms (74.4% of one core) rows=660 bytes=1578662
  (median wall 517.4 / TTFB 510.8 / CPU 405.1 ms; sha256 923a9bf90594c61e on all six - pinning
  rpcId=fixed is what makes them byte-identical. An independent python3/http.client
  implementation reproduced the same bytes and sha at 16:14:5x. Historical groups H1-H4 -
  e.g. 15:10:08-15:10:13: wall 616/572/534 ms, cpu 530/460/400 ms, rows=660, bytes=1578663
  under rpcId=f"p{i}" - are kept for path comparison only and must NOT replace A0.)

  Local watchdog log for the same user, truncated at a fixed timestamp (it grows every
  minute; cutoff here: < "2026-09-15 15:09"): n=1429 successes, min=5ms p50=493ms p90=756ms,
  max=28715ms, and 37 RED rows. Per-call CPU was NOT sampled during any stalled window;
  the A0 idle-process numbers above are the only main-thread CPU measurements we have for
  production (the replica K-sweep below is a copy, not production).

  RED rows split into four kinds (20 + 10 + 6 + 1 = 37), not two:
    read timeouts at the client, 20 rows, 45010-45045 ms (hard failure, restart after two
    in a row; right-censored by the 30 s budget + 15 s slack socket timeout):
      45044, 45023, 45010, 45045, 45045, 45045, 45045, 45024, 45045, 45042,
      45045, 45045, 45045, 45045, 45045, 45044, 45029, 45045, 45045, 45026 ms
    gateway unreachable, 10 rows: Connection refused, every one inside a restart window
    (e.g. 13:22:04, three seconds after the 13:22:01 restart).
    correct but over budget (not a hard failure, no restart), 6 rows:
      42396 ms  rows=531
      36006 ms  rows=601
      37379 ms  rows=601
      44389 ms  rows=633
      34259 ms  rows=633
      37392 ms  rows=633

  Same machine, same minute, other users (each with its own process and session store)
  are healthy: 620-732 ms for 776 rows, 1736-2277 ms for 3141 rows, 332-404 ms for 335
  rows, 2-9 ms for 0-2 rows. That 3141-row user measured over the whole window (n=1463
  successes truncated at 15:09) is min 1633 / p50 2023 / p90 2352 / max 19515 ms - the same
  disk-reading work never approaches 45 s. A gateway probe reaching the same web process over the same
  gateway (different path, 6 s timeout) returned OK at 13:20:32, 13:21:32 and 13:22:32 -
  the middle one inside the 45 s timeout window. The process is not hung.

What is measured vs inferred
----------------------------
  * Measured: per-call wall time, per-call main-thread CPU, TTFB, response size, row count,
    the distribution above, the two failure shapes, the fs-call count per call (strace on a
    replica), and the queueing amplification on that replica. Every PRODUCTION CPU number
    here comes from an IDLE process (A0, 16:10:06-16:10:09); no per-call CPU sample exists
    for any stalled window.
  * Reproduced (controlled, isolated replica): 8 concurrent session/list calls re-queue behind
    each other - wall 3.75x, cpu-normalised 5.62x, main thread saturated at cpu_pct_of_wall
    101.3 %, while a light canary in the same window keeps a 3.4 ms median (873x: worst call 2970.3 ms vs 3.4 ms median).
    What is still missing is NOT the mechanism but the production sample: we have no
    concurrent main-thread-utilisation sample for a PRODUCTION stall, and we deliberately did
    not load-test a production process. 45 s is a right-censored client socket timeout
    (30 s budget + 15 s slack), so the real stall is >=45 s.
  * Measured (previously inferred): the fs-call magnitude. strace on a 665-row replica gives
    3333 fs calls per session/list = 5.012 per session (openat 1334 + pool-thread read 665 +
    pool-thread close 1334; raw output in evidence-queue-amplification.txt line 65), with 0 background fs
    calls in the idle windows. Event-loop yields are still NOT counted - therefore no
    "ms per yield" figure is quoted anywhere in this issue.
  * Not excluded: libuv thread-pool QUEUE DEPTH (the pool's own CPU is small - 108.7-138.3 ms
    per call - and its file reads are linear at 665 per call, but queue depth / wait latency
    was never measured and nothing was sampled during a real stall), response-side backpressure
    INSIDE A STALL WINDOW (on an idle process TTFB is 96.97-99.56 % of wall and transport is
    only 2.3-15.3 ms, so it is bounded there), and the per-event cost of the #11
    session/follow fan-out, which shares this thread with all 660 sessions.
  * Field instrumentation for the next stall is now RUNNING, read-only and resident:
    a 2 s canary latency series, 1 Hz per-thread main-thread CPU sampling, and a 60 s
    session/list recording wall/TTFB/rows/bytes. It writes a STALL_CAUGHT record when
    list > 5 s or canary > 2 s, with 30 s of context on either side. 16.3 min window so far:
    0 triggers (all idle baseline). We are waiting for the next real stall instead of
    manufacturing one on a production process.
Code references (0.1.5-rc.1, shipped lib/)
-----------------------------------------
  1. `dsh-session-persistence-jsonl/lib/index.js:2858` - `async listArtifacts(signal) {`,
     `:2864` `for (const project of await this.listProjectDirs(signal)) {`, `:2866` `for
     (const dir of await this.listSessionDirs(project, signal)) {`, `:2868` `const selected
     = await this.resolveGenerationInDirectory(dir, signal);`, `:2872` `header = await
     this.readGenerationHeader(selected, void 0, signal);` - every level is a sequential
     await; no batching, no page size.
  2. `dsh-session-persistence-jsonl/lib/index.js:2459` - `for (const artifact of await
     this.listArtifacts(signal)) {` followed by `:2462` `const identity = await
     stat(artifact.path, { bigint: true });` - a third sequential await per session,
     outside listArtifacts.
  3. `dsh-session-persistence-jsonl/lib/index.js:3278` - `this.rootEncodingCheck ??=
     this.checkRootEncoding();` - memoised, but checkRootEncoding() (`:3281-3285`) walks
     the same tree once, so a cold process scans everything twice.
  4. `dsh-session-persistence-jsonl/lib/index.js:3127-3146` - the header read is a JS
     loop: `await open(...)`, 8 KB `await handle.read(...)` chunks, a `Buffer.concat`
     per chunk, `scanZstdFrames(content, 1)` and `await decompressZstdFrame(...)`.
     Cost grows with file size, not only with session count.
  5. `dsh-api-session-controller/lib/typert.host.js:896-900` - the RPC descriptor:
     `id: '@deepseek-ai/dsh-api-session-controller#session/list'`, `service:
     'sessionController'`, `method: 'list'`, `invocation: { kind: 'direct' }`. All 84
     RPC descriptors in the shipped `typert.host.js` files use `kind: 'direct'`; there
     is no worker/queue/priority alternative to opt into.
  6. `dsh-api-gateway/lib/index.js:811` - `let receiver = { kind: "direct" };` and
     `:837` `if (descriptor.invocation.kind === "direct") return this.ctx;` - "direct"
     means the handler runs on the same ctx, i.e. the same process and the same main
     thread.

Ruled out (all measured)
------------------------
  * Not the scan volume: at 0.784 ms per session by wall time (0.614 ms by CPU time,
    A0) a 45 s budget needs 46,488-79,086 sessions, and this user has 660 rows. Another
    user with 3,141 rows on the same box takes 1.7-2.3 s in its own process (n=1463
    successes, max 19,515 ms) - same slope, two orders of magnitude off.
  * Not disk or filesystem: main-thread CPU is 74.4-84.0 % of wall time on the idle
    process (A0; 73.6-83.7 % across the EVID replays), so time is spent in JS. The remaining
    16-26 % is not decomposed into I/O wait versus scheduling.
  * Not a hung process, machine or gateway: other users' processes are healthy in the
    same round; the gateway probe to the same web process is OK inside the timeout
    window; the response content is identical (A0: rows=660 and bytes=1,578,662 on all six,
    sha256 923a9bf90594c61e identical once the rpcId is pinned - otherwise only the echoed
    rpcId at byte 35 differs).
  * NOT excluded (do not quote these as ruled out): libuv thread-pool QUEUE DEPTH (4 workers;
    strace measures 3333 fs calls per session/list = 5.012 per session with linear 665-per-call
    thread-pool reads, and the pool burns only 108.7-138.3 ms per call, but queue depth and
    wait latency were never measured and nothing was sampled during a real stall);
    response-side backpressure INSIDE A STALL WINDOW, because TTFB there was never separated
    from total time (on the idle process it is 96.97-99.56 % of wall, transport 2.3-15.3 ms);
    and the per-event cost of the #11 session/follow fan-out, which shares this thread with all
    660 sessions.

Not claimed
-----------
  * We do not claim the shared main thread is the only cost in DSH, only that it makes
    this control-plane RPC unusable under load.
  * We do not claim the front end does or does not filter subagent sessions; we only
    observed that session/list returns them and that the scan pays for them.
  * We do not claim any particular decomposition of the amplification (JS queue vs thread
    pool), and we do not claim any yield count: 3333 is a measured syscall count for one call,
    the event-loop read count (4661) is measured too, but neither is an event-loop YIELD
    counter - which is why no ms-per-yield figure appears in this issue.

Suggested fixes
---------------
  1. Give control-plane RPCs their own execution body, or at least a preemptible
     channel. STRUCTURAL JUDGEMENT plus a reproduced mechanism: that all 84 descriptors are
     `kind: 'direct'` is measured, and the queueing amplification is measured on an isolated
     replica (3.75x wall / 5.62x cpu-normalised at 8-way concurrency, main thread saturated);
     the magnitude inside a PRODUCTION stall is still not evidenced.
     `kind: 'direct'` puts session/list on the same main thread as inference
     work; moving the directory walk and header decoding to a worker or thread pool, or
     yielding between scan slices with a way for an interactive request to jump the
     queue, would remove the amplification.
  2. Add an index and pagination for the session store. A sidecar index keyed by
     directory mtime and file size turns the call into one read plus a cursor, and the
     648/660 subagent sessions can be filtered server-side instead of scanned and then
     discarded.
  3. Export the three numbers that separate "slow" from "broken" per RPC, as
     percentiles: queue wait before first scheduling, execution time, yield count. With
     those, a 45 s timeout and a 44 s correct answer become visibly different events.

Reproduction
------------
  Read-only: replay one session/list over the gateway and sample the main thread's
  utime+stime from /proc/PID/task/PID/stat before and after the call. Expect
  main_thread_cpu / wall in the 0.744-0.840 range (AUTHORITY GROUP A0: 16:10:06-16:10:09,
  6 replays, rpcId=fixed, wall median 517.4 ms, TTFB median 510.8 ms), with identical rows and
  identical byte LENGTH across calls (pin the rpcId for equal bytes) - and read the TTFB too,
  because first byte is 96.97-99.56 % of wall - but read it together with
  (a) a concurrent canary request's latency and (b) the
  TARGET process's main-thread utilisation, never as a standalone verdict.
  To reproduce the queueing amplification and the shutdown result without touching production:
  run ops/dsh/upstream-issue-main-thread-control-plane/queue-amplification-sweep.mjs against an
  isolated copy (K sweep: wall_p50 509.1 / 668.9 / 1093.8 / 2131.6 ms for K=1/2/4/8), and
  ops/dsh/graceful-stop-verify/verify-graceful-stop.sh --arms A,B,C for the shutdown A/B/C.
  Do NOT run either against a production process.
  it concurrently against a production process: that manufactures the timeout behind the
  restarts reported above.

Related (not required to read): our earlier notes on the same RPC (a zero-byte stall
and a fail-closed empty list) and on the single-main-thread capacity model. This issue
is self-contained.