日志与可定位性设计：级别、刷盘与真实成本
环境：Windows 11 x64，GCC 13.1.0（MinGW-w64），
gcc -std=c11 -O2 -Wall -Wextra，计时用QueryPerformanceCounter（本机频率 10,000,000 Hz，分辨率 100ns）。字节数、行数、落盘量是确定性的、逐次可复现的；纳秒级耗时是 3–5 次重复的中位数（区间），同期机器上还有其他任务在跑，比值比绝对值可靠。日志目的地都是本机 NTFS 文件（进系统页缓存），未计磁盘实际落盘时间。
一、级别必须挡在格式化之前：0.2ns 与 181ns
同一份代码，5 万行，只改”在哪一层丢弃”：
| 写法 | ns/行 中位（区间） |
|---|---|
级别判断在 snprintf 之前，整条跳过 | 0.2（0.2–0.2，5 次一致） |
snprintf 已经做完，级别判断只挡住输出 | 186.3（171.7–242.0） |
snprintf 做完、也没挡住，写进默认 4KB 缓冲 | 769.3（648.8–2071.1） |
171.7–242.0 这一档的实测输出是 fmt_bytes=4588890 file_bytes=0——一行没写出去，但 50,000 次格式化全做完了，合计 9.1ms 白烧（同一程序单独用运行期级别过滤再测一次是 180.5ns/行，10 万行规模，两者同一量级）。这就是”用 if (level) 包住输出、而不是包住整条日志语句”的典型写法。约 900 倍差距不需要讨论，只需要把宏写成：
#define LOG(lvl, ...) do { if ((lvl) <= BUILD_LEVEL) { snprintf __VA_ARGS__; sink(...); } } while (0)BUILD_LEVEL 是编译期常量时更彻底：mode=10 的 0.2ns 就是循环本身的下限。级别系统的价值全在它站在 snprintf 的哪一边。
二、上下文行该放什么：取本地时间和取 UTC 差 19 倍
每行日志都要的时间戳/线程号，单次调用成本（每项 2–10 万次累计，共 6 轮）：
| API | ns/次 中位（区间） | 备注 |
|---|---|---|
GetTickCount64 | 1.3（1.0–1.9） | 16ms 粒度，只够算”多久之前” |
GetCurrentThreadId | 1.6（1.2–1.9） | 读 TEB，无系统调用，想加就加 |
GetSystemTimeAsFileTime | 2.4（1.7–2.5） | 100ns 精度的 UTC，首选 |
time(NULL) | 8.2（7.6–8.9） | 1 秒粒度 |
QueryPerformanceCounter | 12.8（12.1–14.3） | 单调，适合量耗时而不是打时间戳 |
GetSystemTimePreciseAsFileTime | 16.2（15.5–22.8） | 比 AsFileTime 贵近 7 倍，只在真要亚毫秒对齐时用 |
GetLocalTime | 45.2（42.7–47.7） | 填 SYSTEMTIME + 时区换算，最贵的一个 |
把 GetLocalTime 换成 GetSystemTimeAsFileTime，每行省约 43ns；一天 1 亿行 = 省 4.3 秒纯 CPU，而且时区换算本来就该在展示端做。“日志里放什么上下文”的成本排序：线程号近乎免费(1.6) < UTC(2.4) < 单调计数(12.8) < 本地时间(45.2)。
顺带：本机 QPC 频率 10 MHz ⇒ 计数器粒度 100ns，所以上面这些”单次 1–2ns”的数字只能靠几万次数累计摊出来，单次计时毫无意义。
三、结构化不是免费的，但也不贵
同一条记录（id/code/bytes/msg）五种布局，20 万次格式化 × 9 轮：
| 布局 | 样例行 | 字节/行（普通 msg / msg 含引号） | ns/snprintf 中位（区间） |
|---|---|---|---|
| csv | 1234567890,5,1087,advance slot | 31 / 34 | 78.4（75.6–110.2） |
| plain | id=… code=5 bytes=1087 msg=advance slot | 49 / 52 | 102.8（100.8–117.4） |
| kv（msg 外加引号） | … msg="advance slot" | 51 / 54 | 104.7（98.6–114.7） |
| json（手拼，不转义） | {"id":…,"msg":"advance slot"} | 61 / 64 | 119.0（112.4–131.1） |
| json + 手工转义 | {"id":…,"msg":"he said \"hi\" ok"} | 61 / 66 | 125.1（118.9–135.2） |
三点要从表里读出来：
- JSON 比 csv 贵 97% 的体积（61 vs 31 字节）、只贵 52% 的时间（119.0 vs 78.4ns）。相对第五节 260–8,195ns/行的输出成本，格式化那 40.6ns 是零头。选布局的理由是可查询性和体积，不是 CPU。
- 手拼 JSON 会产出坏数据。
msg里带两个引号时，不转义的输出实测是：
{"id":1234567890,"code":5,"bytes":1087,"msg":"he said "hi" ok"}这不是合法 JSON（引号提前闭合）。加了转义循环后是 66 字节且合法："msg":"he said \"hi\" ok"，代价 +5 字节、+6.1ns。结论：结构化日志必须走带转义的格式化函数，不能只写一个 printf 模板。
- 还有一条静默的坑：行缓冲按”典型行长”分配，长行被
snprintf截掉尾部，而且返回值骗人。 同一份日志（每条本该 91.8 字节）把行缓冲从 128 依次改小，5 万条实测：
slot=128：应写 4,588,890 实际 4,588,890 截断行数 0 文件 4,588,890 字节 / 50,000 行
slot= 64：应写 4,588,890 返回值 4,588,890 截断行数 50,000 文件 3,150,000 字节 / 按 \n 只能切出 1 段
slot= 32：应写 4,588,890 返回值 4,588,890 截断行数 50,000 文件 1,550,000 字节 / 按 \n 只能切出 1 段snprintf 返回的是”如果缓冲够大本该写多少”，所以截断时它照样报 91——看返回值判断截断是错的，必须 if (len >= slot) 报警。更糟的是截断点正好吃掉行尾的 \n：slot=64 时每行实写 63 字节，整个 3.15MB 文件按换行切只有 1 段，所有按行解析的工具当场失效。行长上限要作为日志模块的自检项（和第七节”入队数==落盘数”同一类断言）。
四、刷盘策略决定崩溃时你还剩几行
这是本节的核心实验，也是纯确定性的。写入 3,001 行（113,728 字节）后立刻制造访问违例，然后数文件里还剩多少：
| 策略 | 落盘字节 | 落盘行数 | 丢失 |
|---|---|---|---|
| 默认 4KB 全缓冲，无 handler | 110,592 | 2,918 | 83 行 / 3,136 字节 |
同上，但 signal(SIGSEGV, h) 里 fflush | 113,810 | 3,003 | 0（多出的 2 行是 handler 自己写的） |
setvbuf(_IONBF) 无缓冲 | 113,728 | 3,001 | 0 |
setvbuf(_IOFBF, 1MB) 大缓冲 | 0 | 0 | 全部 3,001 行 |
每行 fflush | 113,728 | 3,001 | 0 |
默认 4KB 那一行的落盘量 110,592 = 27 × 4,096，1MB 那一行是 0 × 1MB——规律一句话讲完：
落盘字节 = ⌊已写入字节 ÷ 缓冲区大小⌋ × 缓冲区大小。
同一场景换成”硬终止”（OpenProcess(PROCESS_TERMINATE) + TerminateProcess，等价于任务管理器结束进程 / 被控制器杀掉），并且这次把 handler 装上：
| 策略（都是硬终止） | 落盘字节 | 落盘行数（应为 3,001） |
|---|---|---|
| 默认 4KB 缓冲，未装 handler | 110,592 | 2,918 |
默认 4KB 缓冲，装了 SIGSEGV handler | 110,592 | 2,918（一模一样，文件里也没有 handler 那行） |
每行 fflush | 113,728 | 3,001 |
| 对照：同一份程序改成访问违例（handler 能跑） | 113,747 | 3,002 |
110,592 / 2,918 这一格连跑 3 次完全一致。
四条工程结论：
- handler 里的
fflush只救”自杀”，不救”他杀”：TerminateProcess、断电、看门狗复位下它一行都不多留（上表第二行与第一行逐字节相同）。 - “崩溃时一行不丢”只有每行
fflush这一条路，实测 8,195ns/行，是 1MB 缓冲的 31 倍（第五节）。高频路径上全量同步刷盘不成立。 - 可行的折中是**“小缓冲 + 关键锚点”：缓冲宁可用默认 4KB（至多丢 83 行）也别为了快开到 1MB（丢光全部），并在状态机跃迁、外部调用、释放资源之前**显式
fflush——锚点行一定在，丢的只是最后一次跃迁之后的行。 - 丢多少是可预测的（只取决于崩溃时刻缓冲里剩多少），所以”缓冲区多大 = 最多丢多少行”可以直接写进设计文档。
五、生产环境的日志成本：同一行落在不同 sink 上差 40 倍
同一份代码（snprintf 91.9 字节/行），5 万行，只换输出方式，交错跑 5 轮：
| 方式 | ns/行 中位（区间） | 说明 |
|---|---|---|
| 级别短路，不格式化 | 0.2（0.2–0.2） | 第一节 |
snprintf 之后什么都不做 | 181.2（171.7–242.0） | 格式化税 |
fwrite + 1MB 全缓冲 | 260.1（245.2–311.0） | 每 ~11,400 行一次 WriteFile |
fputs 到 stderr（重定向到文件） | 523.1（496.2–827.8） | 见下方字节注记 |
fwrite + 默认 4KB 缓冲 | 769.3（648.8–2071.1） | 每 ~44 行一次 WriteFile |
fwrite + _IOLBF 行缓冲 | 1232.6（717.4–2801.4） | 比全缓冲贵 1.6 倍，且区间很大 |
每行一次 WriteFile | 6766.0（6334.0–9904.0） | |
fwrite + 每行 fflush | 8195.2（6510.5–15104.1） | 第四节里”崩溃不丢”的代价 |
_IONBF 无缓冲 fwrite | 8754.7（7461.0–13357.3） |
- 缓冲区大小本身就是性能参数：4KB → 1MB 是 769 → 260ns（3.0 倍），因为
WriteFile次数从 1,121 次降到 5 次（4,588,890 ÷ 4,096 vs ÷ 1MB）。但它和第四节直接冲突：缓冲越大越快、崩得越干净率越低。这就是为什么”缓冲 1MB”必须配”独立崩溃恢复手段”，不能只靠 handler。 - 为什么
_IONBF和”每行 fflush”都比”每行WriteFile”慢、而 stderr 反而快 3 倍——本机没有系统调用追踪工具（无 ETW/xperf/wtfdebug），没实测到WriteFile的真实次数，这条不解释，只记住排序。 - stderr 那条的确定性收获：同一批 50,000 行，
slog7.err是 4,638,890 字节，而二进制模式文件是 4,588,890 字节——正好多 50,000 字节：文本模式把\n换成\r\n，每行多 1 字节（+1.09%）。日志量按 TB 算的公司，这一条就够写进规范。
六、多线程：全局锁 + 共享 FILE 是 8.5 倍税
4 个线程各写 10 万行（共 40 万行），三种形态：
| 形态 | ns/行 中位（区间） | 相对 |
|---|---|---|
只格式化 + memcpy 到各自缓冲（无 IO 无锁下限） | 59.9（50.5–62.7） | 1.0× |
每线程独立 FILE* + 256KB 缓冲，无锁 | 95.6（94.6–103.1） | 1.6× |
全局 CRITICAL_SECTION + 共享 FILE*（默认缓冲） | 811.6（514.8–1296.7） | 13.5× |
全局锁 + 共享 FILE* + 每行 fflush | 13,623.4（11,756.2–15,087.5） | 227× |
同一台机器同样的行，“共享一个 FILE 并加锁”比”每线程一个 FILE”贵 8.5 倍（811.6 / 95.6），而且区间宽 2.5 倍——锁的排队在他人手里，你自己的基准测不出来。每行 fflush 再叠 17 倍。多线程日志的正确默认形状是：每线程私有的缓冲（文件或内存环），由退出时或后台线程合并，而不是把 printf 包在一把全局锁里。
限流/采样用的计数器也一样：4 线程 × 200 万次 atomic_fetch_add：
| 布局 | ns/次（3 轮） | 计数结果 |
|---|---|---|
| 4 线程共享一个原子变量 | 12.4 / 12.5 / 12.0 | 8,000,000（正确） |
同一变量但 __attribute__((aligned(64))) | 12.3 / 11.5 / 11.9 | 8,000,000 |
| 每线程一个、各自填满缓存行 | 2.2 / 2.1 / 2.0 | 8,000,000 |
贵的是共享不是未对齐：把共享变量对齐到 64 字节毫无改善（12.3 vs 12.4），改成每线程独占才降到 2.1ns（5.9 倍）。三种写法结果都对——原子性从来没坏，坏的是吞吐。
七、异步队列：省的是阻塞，不是吞吐
每线程一个 SPSC 环（160 字节槽、65,536 槽）+ 每线程一个搬运线程，4 生产者 × 20 万行 = 80 万行：
| 形态 | ns/行（3 轮） | 丢失 | 产物 |
|---|---|---|---|
异步：搬运线程写共享 FILE*（1MB 缓冲） | 214.5 / 218.9 / 222.0 | 0 | ring_out.txt 44,800,000 字节 |
| 异步：搬运线程各写独立文件（1MB 缓冲） | 90.2 / 90.8 / 91.5 | 0 | 4 × 11,200,000 字节 |
同步：单线程直接 fwrite + 1MB 缓冲（对照） | 229.6 / 231.2 / 233.5 | — | 9,188,890 字节/10 万行 |
异步 + 每线程独立文件（90.8ns）和同步 + 每线程独立文件（95.6ns）基本打平——异步并没有白捡的收益，因为总工作量不变，只是从业务线程转移到了搬运线程。所以”要不要异步”的判据不是快慢，而是”业务线程绝不能在这里阻塞”：日志目标在网络、控制台、慢盘上时才必须异步；本机的实测就是”共享 FILE 的异步仍要 219ns，因为串行点还在”。
一条踩坑实录值得留：第一版把消费者的 atomic_store(&ring->tail, t + 1) 写成了 atomic_fetch_add(&ring->tail, t + 1)，程序不崩、不报错、跑得很欢，产出文件是 4,956 行、行长 55–388 字节不等，而应有 800,000 行——无锁队列的错在日志系统里的表现是静默把日志搅乱并丢掉大半，不是崩溃。改对之后连续三轮 lost=0、行长恒定 56 字节（44,800,000 ÷ 800,000）。所以异步日志必须自带”入队计数 == 落盘计数”的自检，光看文件在不在长是没有用的。
八、体积账：压缩比采样更划算
实测字节（确定性）：
长日志（91.9 字节/行） 100,000 行 = 9,188,890 字节
短日志（57.0 字节/行） 400,000 行 = 4,560,000 字节（每线程独立文件 100,000 行 = 5,700,000 字节）
1/1024 采样 100,000 行只落 9,003 字节（98 行）
zlib level 6 压缩后：
9,188,890 → 485,983 字节（5.3%）
5,700,000 → 279,374 字节（4.9%）
113,728 → 10,773 字节（9.5%）- 采样把体积削到 1/1020，但每行成本只从 769ns 降到 212.7ns（3.6 倍），因为
snprintf照做（fmt_bytes=9188890与不采样时一模一样）。想靠采样省钱，判断必须在格式化之前——和第一节同一个道理。 - 文本日志压缩后只剩 5%–9%（本机 zlib，吞吐 100–434 MB/s，区间受同期任务干扰，只当量级看）。也就是说：“少打日志”换来的磁盘，靠”落盘后压缩”几乎能全拿回来；真正省不回来的是格式化与
WriteFile的 CPU 和”该有却没有的那一行”。所以压缩该默认开，级别该按锚点设计，而不是为了省磁盘把 DEBUG 行删掉。
九、小结
- 级别要挡在格式化前面：0.2ns vs 181.2ns，900 倍；
file_bytes=0但fmt_bytes=4588890就是”日志已关、成本照付”的铁证。 - 上下文字段的单价：线程号 1.6ns、UTC 2.4ns、QPC 12.8ns、
GetLocalTime45.2ns（19 倍差距）；QPC 粒度 100ns，所以微基准必须累计。 - 布局：csv 31 / plain 49 / json 61 / json+转义 66 字节每行，格式化 78–125ns。手拼 JSON 遇到消息里的引号会产出非法 JSON（实测样本），必须走转义；行缓冲小于行长时
snprintf静默截断且返回值照样报”本该写的字节数”，slot=64 时 5 万行连\n都被吃掉，整个文件切不出第二段。 - 崩溃可回溯的唯一硬规律：落盘字节 = ⌊已写 ÷ 缓冲大小⌋ × 缓冲大小。4KB 崩了剩 2,918/3,001 行，1MB 崩了剩 0 行；
handler+fflush只救自杀不救他杀（TerminateProcess下同样剩 2,918 行）；“一行不丢”的代价是每行fflush（8,195ns，31 倍）。 - 成本排序：短路 0.2 < 只格式化 181 < 1MB 缓冲 260 < 默认 4KB 769 < 每行 WriteFile 6,766 < 每行 fflush 8,195 < 无缓冲 8,754（ns/行）；文本模式重定向每行多 1 字节（+1.09%）。
- 并发：每线程私有缓冲 95.6ns vs 全局锁共享 FILE 811.6ns（8.5 倍）；共享原子计数器 12.4ns vs 每线程独占缓存行 2.1ns（5.9 倍），对齐共享变量没用，独占才有用。
- 异步：入队 + 搬运端到端 90.8ns/行，与同步打平；它的价值是”业务线程不阻塞”，代价是必须自带”入队数 == 落盘数”自检——本机实测一次 tail 协议写错的 bug 表现成”80 万行只剩 4,956 行、行长 55–388 不等”的静默损坏。
- 体积：1/1024 采样只把每行成本降 3.6 倍（格式化没省）；文本日志 zlib 后 4.9%–9.5%，压缩比删日志更划算。
- 本机未实测：真实磁盘写入延迟（未用
FILE_FLAG_WRITE_THROUGH/FlushFileBuffers分离测试）、WriteFile系统调用次数（无 ETW/xperf）、网络 syslog 采集管道成本、perf/火焰图/valgrind/任何 sanitizer（MinGW GCC 13.1 三个 sanitizer 都链不上，见上一节原文）。