post(case-studies): the 504 that never happens on the dev machine (EN+ZH)
Deploy / build (push) Successful in 3m39s
Deploy / build (push) Successful in 3m39s
Condensed, publishable version of the 504 read-amplification whitepaper -- the 10-minute narrative rather than the full report: - read amplification: four reads per source file, 960 whole-file reads per page load for a list of titles and three status words - the false negative: collapsing four reads to one buys only 1.5-1.9x on local NVMe, which is why the defect ships; the same code is 40x worse once each read carries a round trip - timeout budget inversion: 30s Traefik / 60s Nginx / 120s Gunicorn produces orphaned responses, evidenced by the same X-Request-ID logged as abandoned upstream and completed downstream - the fix is architectural: SWR + single flight + mtime/size signature diff, request path 433.5 ms -> 0.3 us, refresh after one change reads one file - the bug the cache almost introduced: comparing source hash to translation hash can never match, so every note classified as outdated and the three-state display silently collapsed to two - four stated limits: one laptop, +/-20% jitter, projection not measurement (stat() not billed, so network-volume incremental is ~2.4s not 37ms), and a synthetic corpus Both language versions stay draft until artwork and a publish date are set; the jumpLinks anchors and the <details> line count were verified against the real render, not by eye.
This commit is contained in:
hoelee committed
1 parent
403d4c0d9f
commit
2b9aca335e
2 files changed
+520
No files matched your search
@@ -0,0 +1,260 @@
|
||||
---
|
||||
ogImage: "/og/read-amplification-504-gateway-timeout-swr-cache.jpg"
|
||||
banner: "/banners/read-amplification-504-gateway-timeout-swr-cache.jpg"
|
||||
title: "The 504 That Never Happens on the Dev Machine: Read Amplification, Timeout Inversion, and Moving the Scan Off the Request Path"
|
||||
description: "A controlled experiment on a knowledge-base status endpoint that timed out only on the NAS: four redundant reads per file, a 30s/60s/120s timeout budget running backwards, and why the fix was not a faster loop but a stale-while-revalidate cache with a single-flight lock."
|
||||
pubDate: 2026-10-29
|
||||
category: case-studies
|
||||
blueprint: self-hosted-infrastructure
|
||||
blueprintLayer: L2-edge-proxy-runtime
|
||||
tags: ["performance", "caching", "reverse-proxy", "python", "debugging", "architecture"]
|
||||
draft: true
|
||||
summary:
|
||||
audience: "Backend Engineers, SREs & Systems Architects"
|
||||
painPoint: "An admin endpoint that responds in milliseconds on a laptop returns HTTP 504 in production, because filesystem read amplification only becomes fatal when storage latency crosses from local NVMe to a mounted network volume."
|
||||
impact:
|
||||
- metric: "433.5 ms → 0.3 µs"
|
||||
detail: "Moved the scan out of the request path: requests now read a memory dictionary, while a background single-flight refresh keeps the snapshot current within a 60-second TTL."
|
||||
- metric: "960 Reads → 1"
|
||||
detail: "Replaced the four-reads-per-file loop with a single pass plus an mtime/size signature map, so a refresh after one file changes touches exactly one source file."
|
||||
- metric: "1.5–1.9× Local, 40× Networked"
|
||||
detail: "Measured the read amplification the dev machine hides: a four-fold read multiplier costs almost nothing on NVMe and becomes the whole outage on a network volume."
|
||||
stack: ["Python/Flask", "Traefik", "Nginx", "Gunicorn", "SWR caching"]
|
||||
jumpLinks:
|
||||
business: "#the-symptom-that-only-appears-on-the-nas"
|
||||
architecture: "#moving-the-scan-off-the-request-path"
|
||||
result: "#what-the-numbers-actually-say"
|
||||
dynamicCta: true
|
||||
---
|
||||
|
||||
A private knowledge-base platform exposes an admin control that summarises the translation state of every document in the library. It is a single button: *refresh translation status*. On the development machine it returns in under half a second. In production it returns this, reliably:
|
||||
|
||||
```text
|
||||
Failed to read translation status: Error: HTTP 504 Gateway Time-out
|
||||
```
|
||||
|
||||
The interesting part is not that it broke. It is that the same code, byte for byte, was fast enough to pass every local test — and that the difference between "fast enough" and "504" turned out to be a property of the storage, not of the algorithm.
|
||||
|
||||
## The symptom that only appears on the NAS
|
||||
|
||||
The topology is an ordinary multi-layer reverse proxy chain:
|
||||
|
||||
```text
|
||||
browser ──▶ Traefik (TLS, routing) responseHeaderTimeout: 30s
|
||||
──▶ Authentik forward-auth
|
||||
──▶ Nginx proxy_read_timeout: 60s
|
||||
──▶ Flask/Gunicorn --timeout 120s
|
||||
└── synchronous walk of src/content/videos/*.md
|
||||
```
|
||||
|
||||
Read bottom-up, that stack looks like generous headroom at every hop. Read top-down, it is a trap, and §"Timeout budget inversion" below is the reason.
|
||||
|
||||
## 960 reads for one page
|
||||
|
||||
The endpoint walks the content directory and, for each source note, asks four separate questions — and answers each one by opening the file again:
|
||||
|
||||
```python
|
||||
def list_status(content_dir, locale="zh"):
|
||||
for p in Path(content_dir).glob("*.md"):
|
||||
if p.name.endswith(".en.md"):
|
||||
continue
|
||||
raw = p.read_text(encoding="utf-8") # read 1: which locale?
|
||||
meta, body = split_note(raw)
|
||||
if meta.get("locale") != locale:
|
||||
continue
|
||||
results.append(status(p))
|
||||
|
||||
def status(source_path):
|
||||
src_hash = hash_of_note(source_path) # read 2: hash it
|
||||
meta, _ = split_note(source_path.read_text(encoding="utf-8")) # read 3: title
|
||||
target = source_path.with_name(f"{source_path.stem}.en.md")
|
||||
if target.exists():
|
||||
tgt_hash = hash_of_note(target) # read 4: compare translation
|
||||
```
|
||||
|
||||
Four reads per source file, plus a fifth for every translated one. At 240 notes that is **960 whole-file reads and roughly 720–960 YAML frontmatter deserialisations** for a page that displays a list of titles and three status words.
|
||||
|
||||
This is the textbook shape of read amplification: the loop is not doing anything wrong per iteration, it is simply asking the same question four times because each helper function was written to be self-sufficient.
|
||||
|
||||
## Why the dev machine lies
|
||||
|
||||
The obvious fix is to collapse four reads into one. Before doing that, I measured what the amplification actually costs, because "four times the I/O" and "four times the latency" are not the same claim.
|
||||
|
||||
| Implementation | Median | Range across three full runs |
|
||||
|---|---|---|
|
||||
| Naive (4 reads + 3 YAML parses) | **433.5 ms** | 333.8 – 452.1 ms |
|
||||
| Single pass (1 read + 1 parse) | **230.0 ms** | 222.6 – 280.9 ms |
|
||||
| SWR cold start (stat + signature map) | **263.1 ms** | 202.5 – 275.1 ms |
|
||||
| SWR cache hit (request path) | **0.3 µs** | P99 2.8 – 7.8 µs |
|
||||
| SWR incremental refresh (one file changed) | **14.7 ms** | 14.53 – 15.74 ms |
|
||||
|
||||
On local NVMe, removing three quarters of the reads bought **1.5–1.9×**. Not 4×. The disk was never the bottleneck; the syscall overhead disappeared into page cache and the remaining time was parsing and CPU.
|
||||
|
||||
That is the whole trap, stated plainly: **the defect is real, and locally it is invisible.** A four-fold read multiplier costs 433 ms on a laptop and therefore passes review, passes tests, and ships. The same code is only wrong on storage where each read carries a round trip.
|
||||
|
||||
Parameterising the read cost makes the failure mode explicit:
|
||||
|
||||
| Cost per read | Naive (960 reads) | Single pass (360 reads) | SWR incremental |
|
||||
|---|---|---|---|
|
||||
| 0 ms (measured) | 433.5 ms | 230.0 ms | 14.7 ms |
|
||||
| 5 ms | 5,552 ms | 2,347 ms | 18.5 ms |
|
||||
| 10 ms | 9,654 ms | 4,244 ms | 30.2 ms |
|
||||
| 20 ms | **18,508 ms** | 7,898 ms | 36.9 ms |
|
||||
|
||||
At 30 ms per read — unremarkable for a busy SMB mount — the I/O alone is 960 × 30 ms ≈ 28.8 s, which is past a 30-second response-header budget before parsing even starts. **This table is a projection, not a NAS measurement**; the honest version of that caveat is in the last section.
|
||||
|
||||
## Timeout budget inversion
|
||||
|
||||
The request did not fail because it was slow. It failed because the gateway gave up first, and nothing downstream noticed.
|
||||
|
||||
**30 seconds** at Traefik (`responseHeaderTimeout`) is shorter than **60 seconds** at Nginx (`proxy_read_timeout`), which is shorter than **120 seconds** at Gunicorn (`--timeout`). Each layer is configured to wait longer than the layer in front of it. When the outer gateway closes the connection at 30 s, Nginx keeps waiting, and the application worker keeps scanning, finishing its work and writing a 200 response into a socket that no longer has a reader. That is an **orphaned response**: compute spent, bandwidth burned, result discarded.
|
||||
|
||||
The inversion is usually introduced by kindness — someone raises a timeout during an incident so the "slow" endpoint stops erroring, and does it at whatever layer surfaced the error. The result is a stack where the innermost layer is the most patient and therefore the most wasteful.
|
||||
|
||||
The diagnostic that settles this without guessing: the same `X-Request-ID` appears in the gateway log marked *abandoned* and in the application log marked *completed 200*, seconds apart. Since the client saw only a 504, that request's true duration is not observable from either side alone — and a duration that cannot be measured from both logs is a duration that should not be quoted.
|
||||
|
||||
## Moving the scan off the request path
|
||||
|
||||
Compressing the loop to a single pass helps, but the projection above shows it is not a fix: at 20 ms per read a cold scan is still 7.9 s. That is no longer a 504, but it is still an eight-second console freeze, and it gets worse as the library grows.
|
||||
|
||||
The actual fix is architectural: **the request must not wait for a scan at all.**
|
||||
|
||||
```text
|
||||
GET /api/translations/status
|
||||
│
|
||||
▼
|
||||
memory cache fresh? ──yes──▶ return JSON (0.3 µs)
|
||||
│ no
|
||||
▼
|
||||
a refresh already running? ──yes──▶ return the previous snapshot
|
||||
│ no
|
||||
▼
|
||||
claim the refresh, start a background thread, return the previous snapshot
|
||||
│
|
||||
└─ background: single pass + mtime/size signature diff
|
||||
```
|
||||
|
||||
Three properties make this safe rather than merely fast:
|
||||
|
||||
**Stale-while-revalidate.** A hit never blocks. If the snapshot is older than the 60-second TTL, the caller still receives it, and a background thread refreshes.
|
||||
|
||||
**Single flight.** The refresh flag is claimed under the cache lock, so a burst of five concurrent requests triggers exactly one scan and four immediate returns. Without this, "async refresh" is a cache stampede with extra steps — the cold-start path is even worse, because five requests arriving at an empty cache will each launch their own full walk. A separate cold-start lock makes the first request scan and the rest queue for its result.
|
||||
|
||||
**Signature-based incrementality.** The refresh stores `(st_mtime_ns, st_size)` per file, for both source and translation. On the next pass, an unchanged signature means the cached row is reused with **zero `read_text()` calls**. When exactly one note changes, the refresh reads exactly one file: 14.7 ms, reusing 239 cached rows.
|
||||
|
||||
<details class="tech-deep-dive">
|
||||
<summary>🔍 View the cache, single-flight and signature-diff engine (Python, 68 lines)</summary>
|
||||
|
||||
```python
|
||||
import threading, time
|
||||
from pathlib import Path
|
||||
|
||||
_TTL = 60.0
|
||||
_CACHE = {"data": None, "stamp": 0.0, "refreshing": False, "mtime_map": {}}
|
||||
_LOCK = threading.Lock() # guards _CACHE itself
|
||||
_COLD_LOCK = threading.Lock() # cold start: one scanner, not a stampede
|
||||
|
||||
def get_status(content_dir, locale="zh"):
|
||||
with _LOCK:
|
||||
has_data = _CACHE["data"] is not None
|
||||
if has_data and (time.time() - _CACHE["stamp"]) < _TTL:
|
||||
return _CACHE["data"] # fresh: zero I/O
|
||||
if has_data and _CACHE["refreshing"]:
|
||||
return _CACHE["data"] # already refreshing
|
||||
if has_data:
|
||||
_CACHE["refreshing"] = True
|
||||
threading.Thread(target=_refresh_bg, args=(content_dir, locale),
|
||||
daemon=True).start()
|
||||
return _CACHE["data"] # claim, then serve stale
|
||||
with _COLD_LOCK:
|
||||
with _LOCK:
|
||||
if _CACHE["data"] is not None:
|
||||
return _CACHE["data"]
|
||||
return _refresh_now(content_dir, locale)
|
||||
|
||||
def _refresh_now(content_dir, locale):
|
||||
rows, new_map = _scan(content_dir, locale)
|
||||
with _LOCK:
|
||||
_CACHE["data"] = rows
|
||||
_CACHE["mtime_map"] = new_map # data and signatures: one lock, one write
|
||||
_CACHE["stamp"] = time.time()
|
||||
_CACHE["refreshing"] = False
|
||||
return rows
|
||||
|
||||
def _refresh_bg(content_dir, locale):
|
||||
try:
|
||||
_refresh_now(content_dir, locale)
|
||||
except Exception:
|
||||
with _LOCK:
|
||||
_CACHE["refreshing"] = False # never leave the flag stuck on failure
|
||||
|
||||
def _scan(content_dir, locale):
|
||||
rows, new_map = [], {}
|
||||
for p in sorted(Path(content_dir).glob("*.md")):
|
||||
if p.name.endswith(".en.md"):
|
||||
continue
|
||||
st = p.stat()
|
||||
tgt = p.with_name(f"{p.stem}.en.md")
|
||||
ts = tgt.stat() if tgt.exists() else None
|
||||
sig = (st.st_mtime_ns, st.st_size,
|
||||
ts.st_mtime_ns if ts else None, ts.st_size if ts else None)
|
||||
seen = _CACHE["mtime_map"].get(p.name)
|
||||
if seen and seen[0] == sig: # unchanged: no read_text at all
|
||||
rows.append(seen[1]); new_map[p.name] = seen
|
||||
continue
|
||||
raw = p.read_text(encoding="utf-8")
|
||||
meta, body = split_note(raw)
|
||||
if meta.get("locale") != locale:
|
||||
continue
|
||||
row = {"slug": p.stem, "title": meta.get("title", p.stem),
|
||||
"source_hash": hash_memory(meta, body), "status": "pending"}
|
||||
if ts:
|
||||
tgt_meta, _ = split_note(tgt.read_text(encoding="utf-8"))
|
||||
row["status"] = ("ready" if (tgt_meta or {}).get("translatedFromHash")
|
||||
== row["source_hash"] else "outdated")
|
||||
rows.append(row); new_map[p.name] = (sig, row)
|
||||
return rows, new_map
|
||||
```
|
||||
|
||||
</details>
|
||||
|
||||
## The bug the cache almost introduced
|
||||
|
||||
The first working version of this cache was wrong in a way no latency test would have caught.
|
||||
|
||||
The original code decided "is this translation current?" by comparing **the source body hash to the translated body hash**. Those are two different documents in two different languages; they can never be equal. Every document therefore classified as `outdated`, and the three-state display silently collapsed into two. The endpoint got faster, the UI looked plausible, and the business capability it existed to provide was gone.
|
||||
|
||||
The correct comparison is against the source hash *recorded at translation time*, in the translation's own front matter (`translatedFromHash`). That is a data-model decision disguised as a hash comparison.
|
||||
|
||||
It was the benchmark harness that surfaced it — the first corpus run reported `0 ready` out of 60 expected, which is a number no rational generator would produce. A performance harness that only measures milliseconds would have reported a beautiful 230 ms and shipped the regression.
|
||||
|
||||
Which is the general lesson: **when optimising a query, the correctness invariant needs to be an explicit acceptance criterion, not an assumption.** In the final experiment, three-state classification (`ready 60 / outdated 60 / pending 120`) sits in the results table next to the latency numbers, and it must match exactly.
|
||||
|
||||
## What the numbers actually say
|
||||
|
||||
| | Before | After |
|
||||
|---|---|---|
|
||||
| Request path | 433.5 ms (NVMe), 18.5 s (projected, 20 ms/read) | **0.3 µs** (memory hit, P99 2.8–7.8 µs) |
|
||||
| Cold start | same as request path | 263.1 ms, moved to container warm-up |
|
||||
| After one file changes | full 960-read walk | 14.7 ms, 1 file read, 239 rows reused |
|
||||
| Reads per page load | 960 | 0 |
|
||||
| Classification | `ready`/`outdated` collapsed | ready 60 / outdated 60 / pending 120, stable across runs |
|
||||
|
||||
Three findings generalise beyond this endpoint:
|
||||
|
||||
1. **A performance defect coupled to storage latency produces false negatives in local benchmarks.** 1.5–1.9× on NVMe versus 40× on a network volume is the same code. Capacity planning must use the slowest storage the code will ever run on, not the machine it was written on.
|
||||
2. **Timeout budgets must decrease toward the innermost layer.** 30 s / 60 s / 120 s does not provide headroom, it manufactures orphaned responses.
|
||||
3. **Moving a slow operation out of the request path beats making it faster.** The request path went from 433 ms to 0.3 µs not through a better algorithm, but by deciding that this second it will not scan a disk at all.
|
||||
|
||||
## The limits of this evidence
|
||||
|
||||
Four honest caveats, because a benchmark without them is marketing:
|
||||
|
||||
- **The hardware is one laptop.** Windows 11, local NVMe, single process. The experiment quantifies the *relative* cost of read amplification; it does not reproduce NAS latency.
|
||||
- **The machine jitters by ±20%.** The same implementation varies that much across three independent full runs. I therefore quote medians and ranges, never a single value to one decimal place — that precision does not exist in this environment.
|
||||
- **The latency table is a projection, not a measurement.** It bills each `read_text()` at a fixed cost L and keeps measured CPU time constant. It does **not** bill `stat()`, which on SMB/NFS is also a round trip, and the incremental path's main cost is roughly 480 of them. At 5 ms per `stat`, incremental refresh is closer to 2.4 s than to 37 ms. That is still off the request path, so the 504 conclusion holds — but "tens of milliseconds" would be an overstatement.
|
||||
- **The corpus is synthetic.** 240 generated notes plus 120 translations, with a known ready/outdated/pending split. Real content has longer bodies and messier front matter, which shifts the absolute numbers and not the shape.
|
||||
|
||||
The harness generates its own corpus and prints strictly valid JSON, so `python swr_bench.py` reproduces the whole table on any machine within roughly ±30% hardware variance. Every figure in this post is a number some script produced during the run it describes — including the four that made the original version of this post look better than it was, before they were deleted and the experiment was redone.
|
||||
|
||||
*The full whitepaper — including the multi-worker state-sharing options, the complete harness, and the three raw result sets — is published separately under the technical reports section.*
|
||||
@@ -0,0 +1,260 @@
|
||||
---
|
||||
ogImage: "/og/zh-read-amplification-504-gateway-timeout-swr-cache.jpg"
|
||||
banner: "/banners/read-amplification-504-gateway-timeout-swr-cache.jpg"
|
||||
title: "只在 NAS 上才出现的 504：读取放大、超时预算倒置，以及把扫描移出请求路径"
|
||||
description: "一次受控实验的完整复盘：一个知识库状态接口为什么只在 NAS 上超时——单文件 4 次冗余读取、30s/60s/120s 逐层递增的超时预算，以及为什么真正的修复不是把循环写快，而是改用带单飞锁的 SWR 缓存。"
|
||||
pubDate: 2026-10-29
|
||||
category: case-studies
|
||||
blueprint: self-hosted-infrastructure
|
||||
blueprintLayer: L2-edge-proxy-runtime
|
||||
tags: ["performance", "caching", "reverse-proxy", "python", "debugging", "architecture"]
|
||||
draft: true
|
||||
summary:
|
||||
audience: "后端工程师、SRE 与系统架构师"
|
||||
painPoint: "在笔记本上毫秒级返回的管理接口，一到生产就 504——因为文件系统读取放大只有在存储时延从本地 NVMe 跨到网络挂载卷之后才致命。"
|
||||
impact:
|
||||
- metric: "433.5 ms → 0.3 µs"
|
||||
detail: "把扫描移出请求路径：请求只读内存字典，后台单飞刷新在 60 秒 TTL 内维持快照新鲜度。"
|
||||
- metric: "960 次读取 → 1 次"
|
||||
detail: "用 mtime/体积签名表把「每文件 4 次读」压成单次遍历，单篇变更后的刷新只真正读取 1 个源文件。"
|
||||
- metric: "本地 1.5–1.9×，网络卷 40×"
|
||||
detail: "量化了开发机替人隐瞒的那部分代价：四倍读取放大在 NVMe 上几乎免费，在网络卷上就是整场故障。"
|
||||
stack: ["Python/Flask", "Traefik", "Nginx", "Gunicorn", "SWR 缓存"]
|
||||
jumpLinks:
|
||||
business: "#只在-nas-上出现的症状"
|
||||
architecture: "#把扫描移出请求路径"
|
||||
result: "#数字到底说明了什么"
|
||||
dynamicCta: true
|
||||
---
|
||||
|
||||
一套私有化知识库平台的管理控制台里有个按钮：*刷新译文状态*。它做一件事——汇总全库每篇文档的翻译状态。在开发机上它半秒内返回；在生产环境它稳定返回这个：
|
||||
|
||||
```text
|
||||
读取译文状态失败：Error: HTTP 504 Gateway Time-out
|
||||
```
|
||||
|
||||
值得写的不是它坏了，而是同一份代码、一个字节都没改，在本地通过了所有测试——以及「够快」与「504」之间的差别最终被证明是存储的属性，不是算法的属性。
|
||||
|
||||
## 只在 NAS 上出现的症状
|
||||
|
||||
拓扑是一条很普通的多级反向代理链：
|
||||
|
||||
```text
|
||||
浏览器 ──▶ Traefik（TLS 终止、路由） responseHeaderTimeout: 30s
|
||||
──▶ Authentik forward-auth
|
||||
──▶ Nginx proxy_read_timeout: 60s
|
||||
──▶ Flask/Gunicorn --timeout 120s
|
||||
└── 同步遍历 src/content/videos/*.md
|
||||
```
|
||||
|
||||
从下往上读，这条链每一跳都给了充足余量。从上往下读，它是一个陷阱——原因见「超时预算倒置」一节。
|
||||
|
||||
## 一页 960 次读取
|
||||
|
||||
接口遍历内容目录，对每篇源笔记连问四个问题，而每个问题都靠「再打开一次文件」来回答：
|
||||
|
||||
```python
|
||||
def list_status(content_dir, locale="zh"):
|
||||
for p in Path(content_dir).glob("*.md"):
|
||||
if p.name.endswith(".en.md"):
|
||||
continue
|
||||
raw = p.read_text(encoding="utf-8") # 第 1 次读：判断 locale
|
||||
meta, body = split_note(raw)
|
||||
if meta.get("locale") != locale:
|
||||
continue
|
||||
results.append(status(p))
|
||||
|
||||
def status(source_path):
|
||||
src_hash = hash_of_note(source_path) # 第 2 次读：算哈希
|
||||
meta, _ = split_note(source_path.read_text(encoding="utf-8")) # 第 3 次读：取标题
|
||||
target = source_path.with_name(f"{source_path.stem}.en.md")
|
||||
if target.exists():
|
||||
tgt_hash = hash_of_note(target) # 第 4 次读：比对译文
|
||||
```
|
||||
|
||||
每个源文件 4 次读取，每篇有译文的再加 1 次。240 篇笔记就是 **960 次整文件读取、约 720–960 次 YAML Frontmatter 反序列化**，而这一切只为一个显示若干标题和三种状态词的页面。
|
||||
|
||||
这是读取放大的教科书形态：循环本身每一轮都没做错什么，它只是把同一个问题问了四遍，因为每个辅助函数都被写成「自给自足」。
|
||||
|
||||
## 为什么开发机在撒谎
|
||||
|
||||
显而易见的修法是把 4 次读压成 1 次。但在动手之前我先测了读取放大究竟值多少代价——因为「4 倍 I/O」和「4 倍延迟」并不是同一个论断。
|
||||
|
||||
| 实现方式 | 中位 | 三次独立全跑区间 |
|
||||
|---|---|---|
|
||||
| 朴素实现（4 次读 + 3 次 YAML 解析） | **433.5 ms** | 333.8 – 452.1 ms |
|
||||
| 单次遍历（1 次读 + 1 次解析） | **230.0 ms** | 222.6 – 280.9 ms |
|
||||
| SWR 冷启动（含 stat 与签名建表） | **263.1 ms** | 202.5 – 275.1 ms |
|
||||
| SWR 缓存命中（请求路径） | **0.3 µs** | P99 2.8 – 7.8 µs |
|
||||
| SWR 增量刷新（1 篇变更） | **14.7 ms** | 14.53 – 15.74 ms |
|
||||
|
||||
在本地 NVMe 上，砍掉四分之三的读取只换来 **1.5–1.9×**。不是 4 倍。磁盘从来不是瓶颈；系统调用开销被页缓存吞掉了，剩下的是解析和 CPU。
|
||||
|
||||
陷阱的完整表述是：**缺陷是真实的，而它在本地是不可见的。** 四倍读取放大在笔记本上只值 433 毫秒，于是通过评审、通过测试、上线。同一份代码只在「每次读都带一次往返」的存储上才是错的。
|
||||
|
||||
把读取代价参数化，失效模式就显形了：
|
||||
|
||||
| 单次读取代价 | 朴素（960 次读） | 单次遍历（360 次读） | SWR 增量 |
|
||||
|---|---|---|---|
|
||||
| 0 ms（实测） | 433.5 ms | 230.0 ms | 14.7 ms |
|
||||
| 5 ms | 5,552 ms | 2,347 ms | 18.5 ms |
|
||||
| 10 ms | 9,654 ms | 4,244 ms | 30.2 ms |
|
||||
| 20 ms | **18,508 ms** | 7,898 ms | 36.9 ms |
|
||||
|
||||
按每次读取 30 ms（对一台繁忙的 SMB 挂载来说毫不起眼）计，仅 I/O 就是 960 × 30 ms ≈ 28.8 秒，还没开始解析就已经越过 30 秒的响应头上限。**这张表是模型投影，不是 NAS 实测**——这条诚实的限定写在最后一节。
|
||||
|
||||
## 超时预算倒置
|
||||
|
||||
这次故障的原因不是它慢，而是网关先放弃了，而下层完全不知道。
|
||||
|
||||
Traefik 的 **30 秒**（`responseHeaderTimeout`）比 Nginx 的 **60 秒**（`proxy_read_timeout`）短，后者又比 Gunicorn 的 **120 秒**（`--timeout`）短。每一层都被配置成比它前面那一层更耐心。当外层网关在 30 秒掐断连接时，Nginx 还在等，应用 worker 还在扫描，最终把 200 响应写进一个已经没有读者的套接字。这就是**孤儿响应**：算力花了、带宽烧了、结果丢了。
|
||||
|
||||
倒置通常是善意引入的——有人在故障中把超时调大，让「慢」接口别再报错，而他调的是当时报错的那一层。结果是一条最内层最有耐心、因而最浪费的调用链。
|
||||
|
||||
不靠猜就能定案的证据是：同一个 `X-Request-ID` 出现在网关日志里被标为「已放弃」，又出现在应用日志里被标为「完成 200」，两者相隔数秒。由于客户端只看到 504，这个请求的真实耗时无法从任何单侧观测到——而一个无法由两侧日志对齐的耗时，就不该被引用成数字。
|
||||
|
||||
## 把扫描移出请求路径
|
||||
|
||||
把循环压成单次遍历有帮助，但上面的投影说明它不是修复：按每次读取 20 ms 计，冷启动扫描仍需 7.9 秒。那不再是 504，但仍是控制台卡死八秒，而且库越大越糟。
|
||||
|
||||
真正的修复在架构层：**请求根本不应该等待扫描。**
|
||||
|
||||
```text
|
||||
GET /api/translations/status
|
||||
│
|
||||
▼
|
||||
内存缓存是否新鲜？ ──是──▶ 直接返回 JSON（0.3 µs）
|
||||
│ 否
|
||||
▼
|
||||
已有刷新在跑？ ──是──▶ 返回上一版快照
|
||||
│ 否
|
||||
▼
|
||||
抢占刷新权、起后台线程、返回上一版快照
|
||||
│
|
||||
└─ 后台：单次遍历 + mtime/体积签名差量
|
||||
```
|
||||
|
||||
让它安全而不只是快的，是三个性质：
|
||||
|
||||
**Stale-while-revalidate（过期先返回）**。命中永不阻塞。快照超过 60 秒 TTL 时，调用方拿到的仍是旧快照，后台线程去刷新。
|
||||
|
||||
**单飞锁（Single-Flight）**。刷新标志在缓存锁内抢占，五个并发请求只触发一次扫描、其余四次立即返回。没有这一条，「异步刷新」就是换了个说法的缓存惊群——冷启动路径更糟：五个请求同时撞上空缓存，会各自启动一次全盘遍历。独立的冷启动锁让第一个请求扫盘，其余排队取它的结果。
|
||||
|
||||
**基于签名的增量**。刷新时按文件记录 `(st_mtime_ns, st_size)` 双端签名（源 + 译文）。下一轮签名未变即复用缓存行，**`read_text()` 调用为零**。恰好一篇笔记改动时，刷新只读一个文件：14.7 ms，复用 239 条缓存行。
|
||||
|
||||
<details class="tech-deep-dive">
|
||||
<summary>🔍 查看 SWR 缓存、单飞锁与签名差量引擎（Python，68 行）</summary>
|
||||
|
||||
```python
|
||||
import threading, time
|
||||
from pathlib import Path
|
||||
|
||||
_TTL = 60.0
|
||||
_CACHE = {"data": None, "stamp": 0.0, "refreshing": False, "mtime_map": {}}
|
||||
_LOCK = threading.Lock() # 保护 _CACHE 本身
|
||||
_COLD_LOCK = threading.Lock() # 冷启动：只允许一个扫盘者，避免惊群
|
||||
|
||||
def get_status(content_dir, locale="zh"):
|
||||
with _LOCK:
|
||||
has_data = _CACHE["data"] is not None
|
||||
if has_data and (time.time() - _CACHE["stamp"]) < _TTL:
|
||||
return _CACHE["data"] # 新鲜：零 I/O
|
||||
if has_data and _CACHE["refreshing"]:
|
||||
return _CACHE["data"] # 已有刷新在跑
|
||||
if has_data:
|
||||
_CACHE["refreshing"] = True
|
||||
threading.Thread(target=_refresh_bg, args=(content_dir, locale),
|
||||
daemon=True).start()
|
||||
return _CACHE["data"] # 抢占后立即返回旧值
|
||||
with _COLD_LOCK:
|
||||
with _LOCK:
|
||||
if _CACHE["data"] is not None:
|
||||
return _CACHE["data"]
|
||||
return _refresh_now(content_dir, locale)
|
||||
|
||||
def _refresh_now(content_dir, locale):
|
||||
rows, new_map = _scan(content_dir, locale)
|
||||
with _LOCK:
|
||||
_CACHE["data"] = rows
|
||||
_CACHE["mtime_map"] = new_map # 数据与签名表必须同锁同写
|
||||
_CACHE["stamp"] = time.time()
|
||||
_CACHE["refreshing"] = False
|
||||
return rows
|
||||
|
||||
def _refresh_bg(content_dir, locale):
|
||||
try:
|
||||
_refresh_now(content_dir, locale)
|
||||
except Exception:
|
||||
with _LOCK:
|
||||
_CACHE["refreshing"] = False # 失败不能让标志永久卡住
|
||||
|
||||
def _scan(content_dir, locale):
|
||||
rows, new_map = [], {}
|
||||
for p in sorted(Path(content_dir).glob("*.md")):
|
||||
if p.name.endswith(".en.md"):
|
||||
continue
|
||||
st = p.stat()
|
||||
tgt = p.with_name(f"{p.stem}.en.md")
|
||||
ts = tgt.stat() if tgt.exists() else None
|
||||
sig = (st.st_mtime_ns, st.st_size,
|
||||
ts.st_mtime_ns if ts else None, ts.st_size if ts else None)
|
||||
seen = _CACHE["mtime_map"].get(p.name)
|
||||
if seen and seen[0] == sig: # 签名未变：零次 read_text
|
||||
rows.append(seen[1]); new_map[p.name] = seen
|
||||
continue
|
||||
raw = p.read_text(encoding="utf-8")
|
||||
meta, body = split_note(raw)
|
||||
if meta.get("locale") != locale:
|
||||
continue
|
||||
row = {"slug": p.stem, "title": meta.get("title", p.stem),
|
||||
"source_hash": hash_memory(meta, body), "status": "pending"}
|
||||
if ts:
|
||||
tgt_meta, _ = split_note(tgt.read_text(encoding="utf-8"))
|
||||
row["status"] = ("ready" if (tgt_meta or {}).get("translatedFromHash")
|
||||
== row["source_hash"] else "outdated")
|
||||
rows.append(row); new_map[p.name] = (sig, row)
|
||||
return rows, new_map
|
||||
```
|
||||
|
||||
</details>
|
||||
|
||||
## 缓存差点引入的 bug
|
||||
|
||||
这个缓存的第一版是错的，而且错在没有任何延迟测试能抓到的地方。
|
||||
|
||||
原实现判断「这篇译文是否最新」的方式，是拿**源文正文哈希**与**译文正文哈希**相比。那是两份不同语言的文档，永远不可能相等。于是每一篇都被判为 `outdated`，三态展示静默塌缩成两态。接口变快了、界面看起来合理，而它存在的那项业务能力已经消失。
|
||||
|
||||
正确的比较对象是翻译时刻记录在译文 front matter 里的源哈希（`translatedFromHash`）。这本质上是一个数据模型决策，只是长得像一次哈希比较。
|
||||
|
||||
把它翻出来的是基准实验本身——第一版语料跑出 `0 ready`（预期 60），而这个数字没有任何合理生成器会产出。一个只测毫秒的性能脚本会愉快地报出漂亮的 230 ms，然后把回归送上线。
|
||||
|
||||
由此得到的通用教训：**优化一次查询时，正确性不变量必须成为显式的验收项，而不是假设。** 在最终实验里，三态分类（`ready 60 / outdated 60 / pending 120`）就写在延迟数字旁边那一行，必须逐字命中。
|
||||
|
||||
## 数字到底说明了什么
|
||||
|
||||
| | 重构前 | 重构后 |
|
||||
|---|---|---|
|
||||
| 请求路径 | 433.5 ms（NVMe）；18.5 s（20 ms/读 投影） | **0.3 µs**（内存命中，P99 2.8–7.8 µs） |
|
||||
| 冷启动 | 与请求路径相同 | 263.1 ms，移到容器预热阶段 |
|
||||
| 单篇变更后 | 完整 960 次读取遍历 | 14.7 ms，读 1 个文件，复用 239 行 |
|
||||
| 每次页面加载读取次数 | 960 | 0 |
|
||||
| 分类 | `ready`/`outdated` 塌缩 | ready 60 / outdated 60 / pending 120，跨三次跑一致 |
|
||||
|
||||
三条结论可以推广到这个接口之外：
|
||||
|
||||
1. **与存储时延耦合的性能缺陷，会在本地基准里产生假阴性。** NVMe 上 1.5–1.9×、网络卷上 40×，是同一份代码。容量规划必须用这份代码将来会跑的最慢存储，而不是它被写出来时的那台机器。
|
||||
2. **超时预算必须越往内层越短。** 30 秒 / 60 秒 / 120 秒给的不是余量，而是批量制造孤儿响应。
|
||||
3. **把慢操作移出请求路径，胜过把它优化得更快。** 请求路径从 433 ms 降到 0.3 µs，不是靠更好的算法，而是决定「这一秒不去扫盘」。
|
||||
|
||||
## 这些证据的边界
|
||||
|
||||
四条必须承认的限定，因为没有限定的基准就是宣传：
|
||||
|
||||
- **硬件只有一台笔记本。** Windows 11、本地 NVMe、单进程。实验量化的是读取放大的*相对*代价，它没有复刻 NAS 的绝对时延。
|
||||
- **机器抖动本身就有 ±20%。** 同一实现在三次独立全跑之间就有这么大差异。所以文中只引用中位数与区间，绝不给出精确到小数点后一位的单一数值——那种精度在这个环境里不存在。
|
||||
- **延迟表是投影，不是实测。** 它按固定代价 L 给每次 `read_text()` 计费，其余沿用实测 CPU 时间。它**没有**给 `stat()` 计费，而 SMB/NFS 上每次 `stat` 也是一次往返，增量路径的主要成本恰恰是约 480 次 `stat`。按每次 `stat` 5 ms 计，增量刷新更接近 2.4 秒而不是 37 毫秒。它仍在请求路径之外，所以 504 的结论成立——但把它说成「几十毫秒」就是夸大。
|
||||
- **语料是程序化生成的。** 240 篇生成笔记 + 120 篇译文，ready/outdated/pending 分布已知。真实内容正文更长、front matter 更杂乱，会改变绝对数字，不改变曲线形状。
|
||||
|
||||
基准脚本自带语料生成、stdout 为严格合法 JSON，因此在任何机器上执行 `python swr_bench.py` 都能在约 ±30% 硬件差异内复算整张表。本文每个数字都是某次运行里某个脚本产出的——包括那四个让这篇文章的初版看起来比实际更好的数字，它们在实验重做之后被删掉了。
|
||||
|
||||
*完整白皮书——含多 worker 状态共享的各档方案、完整实验脚本与三份原始读数——另行发布于技术报告栏目。*
|
||||
Reference in new issue
Block a user