适用读者：线上排过障、被 grep 和时间窗口折磨过的后端工程师；正在纠结"日志要不要上 JSON""要不要引 OTel"的架构决策者
技术栈：Python 3.13（CPython）实测；结论与语言无关，Java / Go 的 logging 库有同样的形状
阅读时间：约 32 分钟 | 难度：中级到高级 | 收获：一组可复现的实测数字 + 一个"该优化哪里"的排序 + 一份落地清单
前置阅读：无。所有数字都由 tools/bench_observability.py 在本机跑出，脚本随文附上
目录
- 前言：凌晨两点，300 行日志里找 6 行
- 日志有三笔账，别混在一起算
- JSON 比文本贵 40%，不是数量级
- 真正贵的不是 JSON，是时间戳
- 真正的大头：写路径贵 24.5 倍
- logging 的每条开销：55% 花在"猜自己是谁"
- 批量大小：一个被证伪的假设
- 这台机器上的数字，要打几折
- 读日志的速度不是选型理由
- request-id：13 倍的生成成本，但绝对值不重要
- 六行日志 vs 300 行噪声
- 采样：随机丢 1%，你就丢了 98% 的错误
- 落地清单
- FAQ
- 结语
前言：凌晨两点，300 行日志里找 6 行
线上报了个 500。你知道大概是 20 分钟前的事，知道是
GET /api/articles/ 这个接口。然后你打开日志文件，敲下：
grep "api/articles" app.log | grep "ERROR"
出来一堆。你缩小时间窗口，加了
sed -n 取行号范围，翻到那一刻，看到几十条交错的记录——因为这台机器同时还在处理别的请求。你得靠"感觉"去判断哪几行属于同一个请求。
我模拟了这个场景。一条
gateway → article-svc → db-proxy 的三跳链路，400 个请求，每个请求产生 6 行日志。然后我去捞其中
某一个请求：
不用 request-id，只能按时间窗口捞（+/-1s）：
捞出来 : 300 行
其中属于这个请求的 : 6 行
噪声比 : 50 : 1
你捞出来 300 行，真正要看的只有 6 行。这还是我为了演示刻意把并发压到 400 个请求的情况；线上 QPS 高一个数量级，这个比例就再差一个数量级。
这篇文章要回答三个问题，都用实测数字：
- 日志写成 JSON 到底贵多少？——比文本贵 40%，不是数量级
- 日志真正的成本在哪里？——在写路径，
logging.FileHandler 比缓冲裸写贵 24.5 倍
- 加上 request-id 之后，能不能真的定位到一个请求？——能，而且这是唯一可靠的办法
先说结论，如果你只想看排序：
下面逐个说，每个数字都告诉你它是怎么测出来的。
1. 先说清楚：日志有三笔账，别混在一起算
大部分"日志性能"的讨论之所以吵不出结果，是因为把三件不同的事混成了一个数：
- 格式成本：把一条记录变成一行字符串。纯 CPU，与磁盘无关。
- 写路径成本：把这行字符串送进文件。系统调用、缓冲、flush 策略。
- 关联成本：让这行日志能被找到、被串起来。request-id、trace-id、上下文。
三笔账的量级差得很远。混在一起测，你会得到"日志慢"这种没有信息量的结论。所以我的基准脚本把实验也拆开：E1a 测格式，E1b 测写路径，E1c 解剖
logging 自己的开销，E2 测读回，E3 测关联，E4 测 id 生成，E5 测采样。
数据是一条真实形状的请求日志记录：
{
"ts": 1756000000.123, # 浮点时间戳
"level": "INFO",
"req": "a3f9c1e08b2d4756", # 16 hex 字符的 request-id
"logger": "api.views",
"method": "GET",
"path": "/api/articles",
"status": 200,
"duration_ms": 12.34,
"user_id": 12345,
}
两种写法：
# 文本（logfmt 风格，带标签）
def as_text(r):
ts = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(r["ts"]))
ms = int((r["ts"] % 1) * 1000)
return (
f"{ts},{ms:03d} {r['level']} "
f"req={r['req']} logger={r['logger']} method={r['method']} "
f"path={r['path']} status={r['status']} "
f"duration_ms={r['duration_ms']} user_id={r['user_id']}"
)
# JSON
def as_json(r):
return json.dumps(r, ensure_ascii=False, separators=(",", ":"))
2. JSON 比文本贵 40%，不是数量级
先看 E1a，纯 CPU，100,000 次，完全不落盘：
方式 total ns/rec vs 文本 离散度
-------------------------------------------------------------------
as_text(r) f-string 0.262s 2617 1.00x 48%
as_json(r) json.dumps 0.367s 3670 1.40x 43%
logging TextFormatter 0.264s 2639 1.01x 95%
logging JsonFormatter 0.402s 4023 1.54x 67%
JSON 序列化比 f-string 文本贵 +40%，绝对值差 1053 ns/条
这个数字推翻了一个很常见的说法。网上经常看到"JSON 日志性能差一个数量级"，但这个说法要么是在拿
json.dumps 跟最省的字符串拼接比（连时间格式化都省掉），要么是测量本身被别的东西污染了。
我自己就被污染过一次。同一段代码，早先测出来是
as_text 3762 / as_json 8077，
2.15 倍。我差点就这么写进文章。后来发现那次运行整轮都落在机器的负载尖峰里——校准任务显示机器比正常慢 1.68 倍，而且四个 case 的离散度分别是 107% / 181% / 122% / 141%。同一个实验在干净窗口重跑，比值稳定在 1.31–1.40 倍。
这就是为什么我在每个实验里都塞了一个固定的纯 CPU 校准任务。它不参与结论，只回答一个问题：这次运行的机器状态，配不配让我相信这些数字。
顺带一提，
logging.JsonFormatter 比裸
json.dumps 又贵一点（4023 vs 3670），因为要先从
LogRecord 上把字段
getattr 出来拼一个 dict。这 350 纳秒是
logging 框架的过路费。
2.1 字段顺序几乎不影响，别在这上面纠结
json.dumps 的编码器是 C 实现的，9 个字段的 dict 序列化本身很快。你把字段按长度排序、按访问频率排序，省下来的时间在噪声里根本看不出来。真想让 JSON 更快，
separators=(",", ":") 去掉空格是有效的（我一直在用），
ensure_ascii=False 避免中文转义也是有效的——但这都属于"顺手做对"，不是优化项。
3. 真正贵的不是 JSON，是时间戳
继续看 E1a 的最后一行：
其中 time.localtime + strftime 占 1514 ns/条（文本路径的 58%）
而 JSON 路径直接把浮点
ts 塞进输出，根本不转换。所以如果把时间格式化从文本路径里去掉，两者的差距会瞬间消失。
这解释了一个反直觉的现象：
很多人以为"JSON 日志更慢"，其实是因为文本日志在偷偷做时间格式化，而 JSON 日志没做。你比的是两件不同的事。
如果你的日志量大到需要优化格式，正确的问题不是"JSON 还是文本"，而是：
- 时间戳真的需要人类可读吗？存 Unix 时间戳（浮点或毫秒整数），让查看工具去格式化。这一项就能砍掉一半以上的格式成本。
- 需要人类可读的话，能不能缓存？同一秒内的日志用同一个格式化结果——大多数日志系统的秒级时间戳，一秒内几千条是常态。
# 秒级时间戳缓存：一秒内只格式化一次
_last_sec, _last_str = None, None
def fast_ts(ts):
global _last_sec, _last_str
sec = int(ts)
if sec != _last_sec:
_last_sec = sec
_last_str = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(sec))
return f"{_last_str},{int((ts - sec) * 1000):03d}"
这不是什么高深技巧，只是"知道自己钱花在哪"的直接结果。而 90% 的性能优化讨论之所以空转，就是因为没人先去看那 58%。
4. 真正的大头：写路径贵 24.5 倍
格式之争只值 1 微秒。接下来这个值
12 微秒。
E1b 把内容固定成同一条 JSON 行，只变写路径。每轮 2,000 行，7 轮交错取最优：
写盘方式 最快 us/行 vs 缓冲 离散度
-----------------------------------------------------------------
裸写 + 64KB 缓冲 1.01ms 0.50 1.00x 13%
裸写 + 每条 flush 5.44ms 2.72 5.41x 9%
logging FileHandler 24.67ms 12.33 24.51x 5%
logging 批量 flush 17.70ms 8.85 17.59x 10%
拆开看：
- 裸写 + 64KB 缓冲：0.50 微秒/行。这是地板——数据进内存缓冲，
write() 系统调用每 64KB 才发生一次。
- 裸写 + 每条 flush：2.72 微秒/行，5.4 倍。只多做了一件事：每条写完就
flush()。成本全在系统调用。
logging.FileHandler：12.33 微秒/行，24.5 倍。
第三行是这篇文章最想让你记住的一行。
Python 的 logging.FileHandler 默认每写一条记录就 flush 一次。这不是配置项，是硬编码的行为：
# CPython logging/__init__.py, StreamHandler
def emit(self, record):
try:
msg = self.format(record)
stream = self.stream
stream.write(msg + self.terminator)
self.flush() # ← 每一条记录都调用
except RecursionError:
raise
except Exception:
self.handleError(record)
self.flush() 在
StreamHandler.emit 里，不在
FileHandler 里。也就是说
logging.StreamHandler 的所有子类——
FileHandler、
RotatingFileHandler、
TimedRotatingFileHandler——全都继承了"每条 flush"这个行为。
它为什么这么设计？因为日志的语义是"出事了要能立刻看到"。进程被
kill -9，缓冲里的日志就没了。对于"崩溃前的最后一条日志"这种场景，逐条 flush 是对的。
但代价是：你的日志写入比它需要的慢 17 倍。
第四行给了出路：
同一个 logging 框架，只把 handler 换成自己写的批量 flush 版本，从 24.5 倍降到 17.6 倍。
class BufferedHandler(logging.Handler):
"""批量 flush，而不是每条 flush。"""
def __init__(self, path, batch=1000):
super().__init__()
self.stream = open(path, "w", encoding="utf-8", buffering=1 << 16)
self.batch = batch
self.n = 0
def emit(self, record):
self.stream.write(self.format(record) + "\n")
self.n += 1
if self.n >= self.batch:
self.stream.flush()
self.n = 0
def close(self):
self.stream.flush()
super().close()
注意这里还有个细节：
logging.Handler 的
emit 不应该自己吞掉 flush 语义，而应该把它交给一个明确的策略。"丢最多 1,000 行日志"和"慢 17 倍"，大多数服务会选前者——但前提是你
知道自己在做这个选择。
4.1 为什么剩下的 17.6 倍降不下来
批量 flush 之后还有 17.6 倍，说明
logging 框架本身也在收费。这就引到 E1c。
5. logging 的每条开销：55% 花在"猜自己是谁"
E1c 用
NullHandler——零 I/O，纯测框架开销，50,000 次：
变体 total ns/条
--------------------------------------------------------------
纯 Python 循环（基线） 0.001s 29
log.info(msg) 默认 0.350s 6993
log.info(msg) _srcfile=None 0.158s 3168
log.info(msg) + logThreads/Processes 关掉 0.142s 2843
绕过 Logger，直接 handler.handle(LogRecord) 0.086s 1717
logging 净开销（减去基线） : 6964 ns/条
findCaller() : 3825 ns/条 （占 55%）
thread/pid/进程名 : 325 ns/条 （占 5%）
剩下的 Logger/handler : 2814 ns/条
直接 handler.handle() 只要 : 1688 ns/条 —— 比走 Logger 快 4.1x
log.info("...") 一条 6993 纳秒。其中 3825 纳秒——55%——花在 findCaller() 上。
findCaller() 是干什么的？它要回答"这条日志是从哪个文件、哪一行打出来的"。为了这个，它得从当前栈帧往回走，找到第一个不属于
logging 模块自己的帧，取它的文件名和行号：
# CPython logging/__init__.py, Logger.findCaller
def findCaller(self, stack_info=False, stacklevel=1):
f = currentframe()
if f is not None:
f = f.f_back
orig_f = f
while f and stacklevel > 1:
f = f.f_back
stacklevel -= 1
if not f:
f = orig_f
rv = "(unknown file)", 0, "(unknown function)", None
while hasattr(f, "f_code"):
co = f.f_code
filename = os.path.normcase(co.co_filename)
if filename == _srcfile: # ← 一路跳过 logging 自己的帧
f = f.f_back
continue
...
在 Windows 上
os.path.normcase 还要把
/ 换成
\ 并转小写。栈越深，走得越久。
_srcfile = None 之后，
findCaller 第一行就短路返回
(None, 0, None, None)，于是从 6993 掉到 3168 纳秒。
所以"要不要关掉它"？
这里有个真实的取舍。文件名和行号是排障时最有用的字段之一——
api.views:142 直接把你送到那一行。为了省 3.8 微秒把它关掉，换来"日志里只有 logger 名字，得自己去搜代码"，通常不划算。
但有个例外值得说：
如果你的日志里已经带了足够的结构化字段（request-id、路径、状态码），行号的价值会下降。排查时你先按 request-id 把链路捞出来，看到
db-proxy 报了超时，然后你去那个服务的代码里找——这时候
logger=db_proxy 就够了，行号是锦上添花。
最后一个数字：
绕过 Logger，直接 handler.handle(LogRecord)，只要 1717 纳秒，比走 Logger 快 4.1 倍。这 4.1 倍里，3.8 微秒是
findCaller，剩下的是 filters 和
callHandlers 的遍历。如果你在写高频日志（比如每请求几十条），用
handler.handle() 自己构造
LogRecord 是能拿到真实收益的——代价是你自己负责格式和字段。
6. 批量大小：一个被证伪的假设
我原本以为"批量越大测量越准"，写了个实验去验证，结果
假设被自己的数据推翻了，但推翻的过程本身有价值，所以留着。
E1d 扫批量大小，测每行 flush 成本：
行数 raw us/行 flush us/行 比值 离散度
----------------------------------------------
500 1.01 13.96 13.8x 21%
2,000 0.52 13.65 26.3x 7%
10,000 0.38 13.06 34.4x 4%
50,000 0.34 12.94 37.6x 2%
每行 flush 成本 12.9–14.0 us，跨 100x 批量基本不变
这直接证明了成本来自"每行一次系统调用"，与字节数无关——所以你在小批量上测出来的数，可以放心外推到生产规模。
那为什么比值从 13.8 倍涨到 37.6 倍？因为分母在变。裸写的 open/close 是一个固定开销，行数越多，摊到每行越少；而
flush() 是纯每行成本，不会跟着变便宜。
比值上升是分母的现象，不是分子的。
至于我原来那个"大批量导致不稳定"的假设——有一次运行确实在 50,000 行处给出 179% 的离散度，看着像验证。后来在更安静的机器上重跑，同一段代码同一个批量，离散度 13%。
那次 179% 是负载尖峰恰好砸在大批量那一轮上，不是大批量的性质。
7. 这台机器上的数字，要打几折
必须单独说这一节，因为上面所有数字都来自同一台机器，而这台机器的测量环境
不受我控制。
我写了个探针：一段固定的纯 CPU 循环，重复 12 次。
us per call, 12 sequential reps:
9339 9023 8858 9129 9059 9360 9450 9337 9543 9339 9382 9922
min=8858 median=9339 max=9922 spread=12.0%
再看跨会话的同一段代码：
min=8858 （第一次）
min=9514
min=9149
min=8948
连"取 12 次的最小值"这个估计量本身，跨进程都有
7% 的不确定度。
有一次更夸张：同一段纯 CPU 循环，噪声底从 12% 涨到
56.9%，min 从 8858 涨到 9627 微秒。二十分钟后，同一台机器，同一个脚本。
结论：这台机器分辨不出小于约 10% 的差异。
这个事实约束了这篇文章的写法：
- 只引用大比值。JSON/文本 1.40 倍、FileHandler/缓冲 24.5 倍、findCaller 占 55%——这些都远在噪声之上。任何 10% 以内的差异，我一律不写成结论。
- 每个计时结果旁边都标离散度。你能看到那次运行有多可信。
- 每个实验里放一个校准任务。它测的是机器状态，不是被测代码。
- 取多轮交错的最小值。不是平均值——平均值包含干扰，最小值最接近"没有干扰时的真实成本"。
关于第 4 点，我踩过一个坑值得说：
最初我是"一个 case 跑到底，再跑下一个 case"，结果排名会翻转。同一个 logging 模式，三次运行分别测出 19、20.5、27 微秒/行——单调变差，因为进程在运行过程中越来越慢（机器上别的东西在抢 CPU）。后来的做法是
交错：每一轮把每个 case 各跑一次，这样所有 case 承受同样的漂移，再取每轮的最优。
def interleaved_series(cases, rounds=3):
"""交错跑，保留全部样本。"""
series = {label: [] for label, _ in cases}
gc_was_on = gc.isenabled()
gc.disable()
try:
for _ in range(rounds):
for label, fn in cases:
t0 = time.perf_counter()
fn()
series[label].append(time.perf_counter() - t0)
finally:
if gc_was_on:
gc.enable()
return series
还有个更隐蔽的坑：
E1a 里的 only_time 一开始是单独测的，没并进交错集合。干净机器上它给出 54% 的合理占比，机器一忙就给出
91% 这种荒谬数字——因为两个数字来自不同的轮次、不同的负载状态。并进同一个集合之后就稳定在 54–58%。
如果你只能从这篇文章带走一件事，就带走这个：先测你的噪声底，再谈你的优化。一个不知道噪声底的性能数字，不是一个数字。
8. 读日志的速度不是选型理由
E2 回答一个运维问题：
path == /api/articles 的
duration_ms 的 p99 是多少？100,000 行，两种读法：
approach time us/line result
--------------------------------------------- ------
纯文本 + 正则 0.11s 1.08 p99=101.17ms
JSON + json.loads 0.28s 2.81 p99=101.17ms
真实值（内存里算的） p99=101.17ms
正则 比 json.loads 快 2.59x —— 扫 100,000 行的绝对值差距只有 0.17s
两种都算对了（
p99=101.17ms，和内存里的真值一致）。正则快 2.59 倍，但绝对值差
0.17 秒。
0.17 秒。这是你扫 10 万行日志的差距。而日志分析通常跑在离线任务里，或者按需触发——0.17 秒不值得作为选型依据。
"文本日志读起来更快"这个论点，在这组数字面前站不住。
那什么才是选型依据？同一个实验的第二部分：
schema 漂移：上游把 duration_ms 改名成 dur_ms，对前 20,000 条重新跑一遍
纯文本 + 正则 : 命中 0 条，抛错 0 次 <- 静默。pipeline 里看起来只是「这段时间没数据」
JSON 取值 : 命中 0 条，抛错 20,000 次 <- 响。炸得难看，但至少炸了
上游把字段名从
duration_ms 改成
dur_ms。你的正则还在找
duration_ms=([\d.]+)，于是：
- 纯文本：正则不匹配，
vals 列表为空，你的代码算出 p99 = 0 或者直接跳过。没有异常，没有告警，没有日志。你在 dashboard 上看到的是"这个接口这段时间没有数据"——你会以为是流量掉了，去查网关，查 LB，查了三个小时。
- JSON：
d["duration_ms"] 抛 KeyError，20,000 次。炸得很难看。但你五分钟内就知道字段改名了。
在日志这件事上，"安静地错"比"响亮地错"贵得多。因为日志系统是你在出故障时唯一的依靠，一个会静默失效的日志 pipeline 比没有日志更危险——它让你以为你有数据。
这就是 JSON 日志真正的理由。不是为了快（它更慢），不是为了时髦，是为了
schema 变更会立刻暴露。你为此付出 40% 的格式开销，换来的是"数据不对时你能知道"。
如果你想保留文本日志的可读性又想要这个保障，有个折中：
用文本格式，但每条日志带一个 schema 版本号，读的时候校验。
2026-09-21 02:14:03,412 INFO schema=v2 req=a3f9... path=/api/articles duration_ms=12.34
读的时候先检查
schema=v2 在不在，不在就报警。成本是一点格式时间，收益是"不会静默失效"。
9. request-id：13 倍的生成成本，但绝对值不重要
要串起链路，先得有 id。E4 测了五种生成方式，200,000 次，7 轮交错：
方式 最快 ns/op 离散度
----------------------------------------------------------------
uuid.uuid4() (36 字符) 0.352s 1761 10%
uuid.uuid4().hex (32 字符) 0.271s 1357 11%
secrets.token_hex(8) (16 字符) 0.043s 216 4%
os.urandom(8).hex() (16 字符) 0.026s 132 4%
进程号 + 计数器 (短) 0.049s 243 4%
uuid4 比 os.urandom(8).hex() 贵 13.3x
uuid.uuid4() 1761 纳秒，
os.urandom(8).hex() 132 纳秒，
差 13.3 倍。
但先别急着换。
13.3 倍的绝对值差是 1.6 微秒。一个请求打一次 request-id，1.6 微秒在请求总耗时（通常是毫秒级）里的占比是千分之一。这个优化对绝大多数服务毫无意义。
真正该看的是另一件事——
碰撞概率：
碰撞概率（生日问题，n 个随机 id 全部互不相同的概率）：
16 hex 字符 每天 100 万 个 id -> 撞一次的概率约 2.71e-08
16 hex 字符 每天 10 亿 个 id -> 撞一次的概率约 2.71e-02
uuid4 每天 100 万 个 id -> 撞一次的概率约 1.47e-27
uuid4 每天 10 亿 个 id -> 撞一次的概率约 1.47e-21
16 个 hex 字符 = 64 bit。按生日问题，每天 10 亿个 id 时碰撞概率约
2.7%。
2.7% 听起来很小，但注意这是
每天的概率。累积一个月，撞一次的概率是 1 - (1-0.027)^30 ≈
56%。
而撞了之后会怎样？
两条不同的请求会共享一个 request-id，你把它们的日志混在一起看。排查时你会看到一条自相矛盾的链路：两个
enter 没有对应的
exit，或者时间顺序颠倒。你会怀疑代码有 bug，而实际上是 id 撞了。
uuid4 是 128 bit，同样的量级下碰撞概率是 1.47e-21——
小到可以忽略。
所以这里的选择是：
- 如果日志要跨机器聚合、要长期保留（几十亿条），用 128 bit。
uuid.uuid4() 或 secrets.token_hex(16)。
- 如果只在单机、短期窗口内排查（每天百万级），16 hex 字符够用，且便宜 13 倍。
唯一不能选的是"进程号 + 计数器"这种方案跨机器用——两个进程重启后会从同一个计数器开始，必然碰撞。它只在单机、单进程生命周期内有效。
顺便说个实际的用法：
uuid4().hex 比
str(uuid4()) 快 22%（1357 vs 1761），因为省掉了加连字符的格式化。日志里带不带连字符无所谓，用
.hex 就好。
10. 六行日志 vs 300 行噪声
回到开头那个问题。E3 起了一个真的三跳链路——
gateway → article-svc → db-proxy，每跳是一个真实的 HTTP server，请求在跳之间透传
X-Request-Id：
全链路日志总行数 : 2,400（400 个请求 x 6.0 行）
单个请求的完整链路 : 6 行
gateway enter
article-svc enter
db-proxy enter
db-proxy exit 0.002
article-svc exit 0.853
gateway exit 2.223
而且每一跳的耗时是自明的：
db-proxy 花了 0.002ms，
article-svc 花了 0.853ms——
问题在 article-svc，不在数据库。这个判断在 3 秒内完成。
不带 request-id 的话：
不用 request-id，只能按时间窗口捞（+/-1s）：
捞出来 : 300 行
其中属于这个请求的 : 6 行
噪声比 : 50 : 1
而且这 300 行
没有顺序保证——你的 gateway、article-svc、db-proxy 是三个不同的进程，各自写各自的文件（或者同一个文件但交错）。你得先按进程分开，再按时间排序，再靠"这个 enter 和哪个 exit 配对"去猜。
"给每个请求加一个 id"是这篇文章里性价比最高的建议。它不需要换日志格式，不需要引入任何中间件，不需要 OTel，不需要 Jaeger。就一个 header，一个
contextvars 或者一个
threading.local，加一个
logging.Filter：
import contextvars, uuid, logging
_request_id = contextvars.ContextVar("request_id", default="-")
class RequestIdFilter(logging.Filter):
def filter(self, record):
record.req = _request_id.get()
return True
# 应用启动时挂一次
logging.getLogger().addFilter(RequestIdFilter())
# 每个请求进来时
def handle(request):
_request_id.set(uuid.uuid4().hex[:16])
...
contextvars 在 asyncio 和线程池下都是对的，比
threading.local 安全——这是很多人踩过的坑：用
threading.local 存 request-id，在
async def 里会因为协程切换而串号。
10.1 别用端到端延迟去量一个 header 的成本
我在 E3 里顺手测了"带 request-id vs 不带"的端到端延迟。为了让"带 id"那一趟不是永远最后一个跑（那样任何冷热变化都会被算到 header 头上），我把不带 id 的 pass 跑了
三次，夹住中间那趟带 id 的：
p50 p99 mean (ms)
--------------------------------------------------------
不带 id（第 1 次） 2.80 41.60 9.33
不带 id（第 2 次） 2.66 39.42 8.26
带 X-Request-Id 7.78 41.49 11.80
不带 id（第 3 次） 19.36 52.76 17.87
三次「不带 id」之间的抖动 : p50 16.70ms / p99 13.34ms
「带 id」相对三者均值的偏移 : p50 -0.50ms / p99 -3.11ms
看第 1 行和第 4 行：
它们跑的是完全相同的代码，p50 差了 7 倍（2.80 vs 19.36）。而"带 id"相对均值的偏移是
-0.50ms，远小于这个抖动。
结论很清楚：
- 同一配置的三次运行之间，抖动有 16.70ms。你要测的信号（一个 header 的解析成本）是微秒级。噪声比信号大三个数量级。
- "带 id"的偏移（-0.50ms）比抖动（16.70ms）小 33 倍，所以这个实验根本测不出任何东西。
而在另一次运行里，同样的代码给出的偏移是
+12.21ms——符号都是反的。
符号会翻转，就说明你测的是机器冷热，不是 header。
想用端到端延迟去量一个 header 的成本，噪声比信号大好几个数量级。这类问题只能在 E4 那种微基准里回答。这是我见过最多人浪费时间的地方——花两天时间做 A/B 压测，最后测出来的是自己机器的负载曲线。
11. 采样：随机丢 1%，你就丢了 98% 的错误
日志量太大的标准答案是"采样"。E5 模拟 10,000 个请求，1% 出错，正常请求 4 行日志，出错请求额外 3 行：
策略 行数 相对 A 体积 错误保留
--------------------------------------------------------------
A 全量 40,318 100.0% 6.8MB 100.0%
B 随机 1% 418 1.0% 0.1MB 1.9%
C 随机 1% + 错误全留 1,146 2.8% 0.2MB 100.0%
D C + 慢请求全留 1,190 3.0% 0.2MB 100.0%
这就是随机采样的陷阱。它看起来公平（每条日志被保留的概率一样），但你的目标是"出故障时要有数据"，而故障恰恰是稀有事件。均匀采样会按比例地丢掉它们。
策略 C 才是对的：随机采样 1%，但错误级别的日志全部保留。
def should_log(level, sampled_ok):
if level >= logging.ERROR:
return True # 错误永远保留
return sampled_ok # 其余按 1% 采
效果：日志量 2.8%，
错误保留 100%。比全量省了 97% 的体积，一个错误都没丢。
策略 D 再进一步：慢请求（比如 p99 以上）也全留。日志量 3.0%，多花 0.2 个百分点，换来"性能问题也有完整现场"。
这 0.2% 是整篇文章里最便宜的一笔投资。
还有一点值得说：
采样决策要在请求入口做一次，然后在整个请求生命周期内保持。不能在每条日志上独立掷骰子——那样一个请求的 4 行日志会有的被留有的被丢，你拿到的是残缺的链路，比没有更让人困惑。
# 每个请求进来时决定一次，然后全程复用
sampled = rng.random() < 0.01
_request_sampled.set(sampled)
12. 落地清单
按性价比排序，每条都对应上面某个实测数字：
立刻做（收益大、风险低）
- [ ] 把逐条 flush 换成批量 flush。自定义 handler，
batch=1000 或按时间（比如 1 秒）。实测 17.6x。代价是崩溃时可能丢最后一批。
- [ ] 给每个请求加 request-id。一个 header +
contextvars + logging.Filter。噪声比从 50:1 降到 1:1。这是排障体验的分水岭。
- [ ] 采样时错误全留。
level >= ERROR 直接放行，其余按比例。日志量 2.8%，错误保留 100%。
- [ ] 检查你的时间戳格式化。如果它在格式成本里占 50% 以上（很可能），考虑存 Unix 时间戳，或者按秒缓存格式化结果。
值得做（需要一点改动）
- [ ] 日志写 JSON，理由是可解析性不是性能。它会慢 40%，但它会在 schema 漂移时报错而不是静默给出空结果。
- [ ] request-id 用 128 bit 还是 64 bit，按保留周期和聚合范围决定。跨机器长期保留就用 128 bit；64 bit 在每天 10 亿条的量级上，一个月的碰撞概率约 56%。
- [ ] 确认采样决策在请求入口做一次。别在每条日志上独立掷骰子。
看情况（有坑）
- [ ] 关掉
findCaller()（logging._srcfile = None）省 55% 的 logging 开销。但你会失去文件名和行号。只在日志字段足够丰富、且你在写高频日志时才考虑。
- [ ] 绕过
Logger 直接用 handler.handle()，快 4.1 倍。适合高频日志路径，代价是手动构造 LogRecord。
别做
- [ ] 别为了性能从 JSON 换回文本。省下的 40% 格式成本是 1 微秒，代价是失去 schema 校验。
- [ ] 别用正则 vs
json.loads 的速度做选型。差 0.17 秒，两种都能接受。
- [ ] 别用端到端压测去量一个 header 或一个日志字段的成本。噪声比信号大三个数量级。
- [ ] 别在没有噪声底的情况下相信任何性能数字。包括这篇文章的——先跑一次
tools/bench_observability.py，看你的机器给什么数。
13. FAQ
Q：为什么不直接上 OpenTelemetry / Jaeger / ELK？
A：可以上，而且如果团队规模够，应该上。但这篇文章测的所有量——格式成本、写路径成本、id 生成成本、关联效果——
在这些系统底下依然存在。Filebeat / Promtail / OTel Collector 最终也是调
write()；它们解决的是"日志去哪"的问题，不是"写一条日志要花多少微秒"的问题。而且很多团队的实际路径是：先加 request-id（零依赖），发现 80% 的排障问题解决了，再决定要不要引入完整栈。
先做那个零依赖的版本，你才知道自己缺什么。
Q：批量 flush 会丢日志，怎么权衡？
A：看你怕什么。怕"进程被 kill -9 时丢最后 1000 条"——那就用较短的时间窗口而不是条数窗口（比如每 200ms flush 一次），最坏丢 200ms 的日志。怕"日志写入拖慢请求"——那就用条数窗口。
两个都怕的话，关键路径（错误、支付、认证）用同步 flush，其余用批量。logging 支持按 logger 名挂不同 handler，很容易做到。
Q：JSON 日志人眼没法读，怎么办？
A：工具链问题，不是格式问题。
jq 一行就能美化：
tail -f app.log | jq -c 'select(.level=="ERROR")'
比
grep "ERROR" | grep "api/articles" | sed -n '1200,1400p' 好用得多。
"文本日志更好读"这个直觉，通常来自还没配工具。
Q：contextvars 和 threading.local 到底差在哪？
A：
threading.local 按线程隔离，
contextvars 按协程上下文隔离。在
async def 里，多个协程跑在同一个线程上，
threading.local 会被它们互相覆盖——A 请求的 id 出现在 B 请求的日志里。这种 bug 极难发现，因为它只在并发时出现。
用 contextvars，不要用 threading.local。
Q：这套数字能直接套到我的服务上吗？
A：
比值可以，绝对值不要。"FileHandler 比缓冲裸写贵 24.5 倍"这个结论来自 CPython 的实现（
emit 里硬编码了
self.flush()），换语言后机制不同但形状类似。而"12.33 微秒/行"这个绝对值，取决于你的磁盘、文件系统、杀毒软件、机器负载——我这台机器上同样的代码测出过 12.33 和 20.88 两个值，差 1.7 倍。
跑一次脚本，拿你自己机器的数。
Q：为什么文章里到处是"离散度"和"校准任务"？
A：因为这台机器的噪声底是 12%，跨会话能涨到 57%。不标出来，读者会把噪声当成结论。
校准任务是我在一个被污染的运行里差点写出"JSON 慢 2.15 倍"之后加的。那次运行的校准显示机器慢 1.68 倍，四个 case 的离散度 107%–181%——如果我没看这两个数，这篇文章里就会有一条错的结论。
结语
这篇文章最想说的其实不是"用 JSON"或者"用 request-id"，而是一个顺序问题：
先测量，再优化。而且要知道你的测量有多可信。
上面那些数字里，最反直觉的两个是：
- JSON 只贵 40%（我一开始以为是 2 倍，那是测量污染）
logging.FileHandler 贵 24.5 倍（几乎没人讨论这个，因为它在标准库的 emit() 里，不在文档里）
如果只能改一处，改写路径——17.6 倍的收益，几行代码，不动业务逻辑。如果只能加一样东西，加 request-id——零依赖，把 50:1 的噪声比降到 1:1。
至于格式之争，放过它吧。那 1 微秒不值得。
所有数字由
tools/bench_observability.py 在本机跑出，脚本随文附上，可直接运行：
python tools/bench_observability.py
python tools/bench_observability.py --only e1b,e4 # 单跑某个实验
环境：Windows 11 (10.0.26200)，Python 3.13.14 (CPython)，AMD64，12 逻辑核。
注意：这台机器的噪声底是 12%（跨会话最高 57%）。脚本里每个计时实验都带离散度，并且每个实验都会跑一个固定的校准任务。
请先看这两个数，再决定要不要相信任何一行的绝对值。比值比绝对值稳得多——同样的实验跑两遍，绝对值漂 15%，比值稳在 10% 以内。