背景六小时排查卡在没有证据这一环事情发生在一个普通工作日的下午。有人反馈某批推送消息在两点到三点之间集体延迟部分用户到四点多才收到。不算严重故障但用户能感知到所以要给出说明。我从下午三点二十开始查一直查到晚上九点半。四个多小时后我在日志里什么都没找到。注意不是找到的日志说明没问题而是根本没有那个时间段的日志。日志目录里只有从当天十六点开始的文件再往前的都被轮转删掉了。那六个小时的产出是一份三行的说明而且上面这句话我写得非常心虚——因为我没有证据我只有没找到证据。### 我先猜错了方向以为问题在队列我的初始假设是队列积压。理由是延迟是集体的一批用户同时受影响这通常意味着某个共享资源被卡住了。我先看了消费端的处理速率正常。又看了队列的堆积深度那个时间段的曲线确实有一个小凸起但很快就回落了。我甚至写了个脚本去对比消息的入队时间和出队时间做差值分布差值的中位数是 42 毫秒尾部 P99 也就 800 多毫秒。这个数据看起来非常健康健康到让我怀疑反馈本身是不是搞错了。后来我才意识到这份健康的数据本身就是残缺的——我只统计了那段时间里还在日志里的消息。没能进日志的那些恰好就是有问题的那些。用幸存者偏差去证明系统没问题这是我在这件事上犯的第一个方法性错误。### 真正的问题证据在那三个小时里被删掉了晚上八点多我放弃了从应用日志里找线索转而去翻文件系统的修改记录。日志目录下当时的文件列表是这样的app.log 2026-09-24 21:04 48.2 MBapp.log.1 2026-09-24 18:11 50.0 MBapp.log.2 2026-09-24 15:02 50.0 MBapp.log.3 2026-09-24 11:37 50.0 MBapp.log.4 2026-09-24 08:02 50.0 MB问题一眼就看出来了。app.log.2 的时间戳是 15:02也就是说十四点到 fifteen 点这个窗口的内容跨越了 app.log.2 和 app.log.3 的边界——而 app.log.3 是 11:37 到 15:02 的内容。但我用 grep 去搜那批延迟消息的标识一条都没有。再仔细看这五个文件加起来是 248 MB而我当天的写入量按速率反推大约是每小时 62 MB。也就是说这个日志目录能容纳的内容不到四小时。故障发生在十四点我开始查是十五点二十。等到我晚上八点真正去翻文件的时候十四点的日志已经滚了两轮被覆盖掉了。我盯着那五个文件看了很久。感受不是日志不够多而是我们明明配了日志但它在关键的那几小时里是个摆设。这一篇记录的就是从那次事故开始我陆续改掉的三个盲区。图日志系统的三个盲区与对应处置## 盲区一日志轮转把关键证据覆盖了日志轮转是我以前从没认真想过的东西。它太常规了几条配置写上去就再也没人碰。但它的默认行为里藏着一条很硬的规则轮转的存储空间是有限的超出部分必然被丢弃。### 轮转策略是怎么把证据吃掉的当时的配置大致是这样/path/app.log { size 50M rotate 5 missingok notifempty compress delaycompress copytruncate}这里面有三个参数共同决定了证据能活多久-size 50M单个文件到 50 MB 就切-rotate 5保留 5 个历史文件-compressdelaycompress压缩的是从.2开始的文件所以理论上限就是 50 × 6 300 MB实际上因为压缩已归档的部分会小一些但热数据仍然是 50 MB 一个文件。真正致命的是后面两条rotate 5决定了只有 5 份历史而写入速率决定了这 5 份能撑多久。### 按大小轮转的算术题把这件事算清楚只需要三个数写入速率、单文件上限、保留份数。写入速率 R 62 MB/h单文件上限 S 50 MB保留份数 N 6含当前文件可回溯时长 T S × N / R 50 × 6 / 62 ≈ 4.84 小时4.84 小时。这是一个我在配置轮转时从没算过的数。更糟的是这个数字会随着系统负载漂移业务量翻倍或者某天多打了一些调试日志R 涨到 120 MB/hT 就掉到 2.5 小时。我在事故之后做了件很简单的事把这三个数写进配置文件旁边的一行注释并且加了一个定时任务每小时把当前的回溯窗口算出来打到监控指标里。回溯窗口低于 8 小时就告警。这个改动一共没写二十行代码但它把日志能留多久从一个没人知道的隐变量变成了一个被监控的数。### 正确做法环形缓冲 关键事件单独落库改法分两层。一层是把轮转从保留份数改成保留时长。按大小切文件但归档文件按日期命名只删超过 N 天的。这样负载高的时候文件数量自动变多而不是把时间窗口压缩掉。另一层才是关键不再指望主日志承担关键事件的举证责任。我给自己定了一个判据——“如果这条记录丢了我需要用什么去重建它“如果要靠它去证明某个副作用发生过比如这条消息确实发出去了”那它就不该只躺在会被覆盖的文件里。它应该写进一张表。所以现在的结构是热日志文本/JSON滚动保留 7 天 └── 用于排查过程性问题为什么慢了、为什么重试了环形缓冲内存固定 4096 条进程内有界队列 └── 用于崩溃瞬间的快照进程挂掉时把缓冲刷到磁盘审计表数据库不参与轮转 └── 用于证明关键动作发生过发送、状态变更、异常环形缓冲那段代码很短核心是写满就覆盖头部永远不报错、永远不阻塞”pythonfrom collections import dequeclass RingTrace: def __init__(self, cap4096): self._buf deque(maxlencap) self._dropped 0 def push(self, item): if len(self._buf) self._buf.maxlen: self._dropped 1 # 不阻塞 self._buf.append(item) def dump(self, path): # 异常退出时落盘 with open(path, a, encodingutf-8) as f: for rec in self._buf: f.write(rec \n) f.write(f# dropped{self._dropped}\n)这里有个细节值得说deque(maxlenN)在满员时自动丢弃头部而且这个操作是 O(1) 的不会因为日志写入把业务线程拖慢。我一开始自己用 list 加切片实现每次满了做一次self._buf self._buf[1:]在高频写入下这部分的开销吃掉了 3% 左右的 CPU换成 deque 之后这个数字降到了噪声水平。## 盲区二时区错乱让我查了一个空的时间段如果说轮转是证据被删了那时区问题就是我站在错误的地方找证据。它的表现更隐蔽因为查询会正常返回结果——返回零行。零行和没有异常长得一模一样。### 八小时偏差是怎么被发现的还是那次十四点的故障。我在轮转改好之后回头补查历史问题时踩到了这个坑。我按运维同事给的时间下午两点十分左右去查日志查询语句大概是sqlSELECT ts, msg_id, status, latency_ms FROM app_logs WHERE ts 2026-09-24 14:10:00 AND ts 2026-09-24 14:20:00 AND msg_id LIKE MSG20260924%;返回 0 行。我的判断是那段时间没有这个批次的消息。于是在结论里写了两点十到二十之间没有相关记录问题可能发生在更早的环节。这个结论后来被证明是错的。转折来自一个很偶然的动作我不死心直接把时间范围放大到整个下午再按分钟聚合看分布。sqlSELECT substr(ts, 12, 5) AS minute, count(*) FROM app_logs WHERE msg_id LIKE MSG20260924% AND ts 2026-09-24 00:00:00 AND ts 2026-09-25 00:00:00 GROUP BY minute ORDER BY minute;结果里 06:10 到 06:20 这一段有个明显的尖峰计数是其余分钟的四倍多。六点十分。我当时想的是早上六点有另一批消息和这件事无关。直到我把那条记录的完整内容打出来看了一眼发现它的msg_id里嵌着0924而且处理耗时字段是 5 万多毫秒——这和反馈里的延迟了很久对得上。到这里八小时偏差才对上**应用写库时用的是 UTC运维同事报的时间是本地时间UTC8我按本地时间去查 UTC 字段正好查到了八小时前。**我一开始没有怀疑时区理由说出来有点丢人我看了下表结构字段名是ts类型是timestamp没有时区信息我就默认它是本地时间了。数据库里存的值其实一直是 UTC只是从来没人把它写出来过。### 三个时区同时存在的现场把这次排查涉及的环节列一遍就知道为什么会乱环节 1 应用进程 写库用 UTCdatetime.now(timezone.utc)环节 2 数据库 字段类型无时区存进去的值原样保留UTC 数值环节 3 命令行客户端 会话时区为 UTC显示出来还是 UTC环节 4 图形化查询工具 默认按操作系统本地时区渲染显示成 8 小时环节 5 日志文件 用的是本地时间因为 logging 默认用 localtime环节 6 运维同学报障 说的是墙上的钟本地时间六个环节三种时间基准。同一个事件在应用日志里是14:12在数据库里是06:12在图形工具里又显示成14:12。而我去 grep 文本日志的时候搜的是06:12当然搜不到。我当时的错误是把两个地方显示的时间一样当成了它们存的是同一个东西。图形工具显示 14:12 是因为它自己加上了 8 小时和文本日志里的 14:12 完全是两回事。### 统一时区的三条硬规定改完之后我定了三条规矩写进了团队约定1.存储层只存 UTC字段名带_utc后缀。不再是含糊的ts而是created_at_utc。名字本身就是文档。2.日志输出带明确的时区偏移。格式串从%Y-%m-%d %H:%M:%S改成%Y-%m-%dT%H:%M:%S%z输出形如2026-09-24T06:12:310000。多出来的 5 个字符换来的是不需要猜。3.只在展示层做换算而且换算的位置集中在一个函数里。pythonfrom datetime import datetime, timezone, timedeltaCST timezone(timedelta(hours8))def to_local(dt_utc: datetime) - str: 只在展示时调用入库、比对、聚合一律用 UTC if dt_utc.tzinfo is None: raise ValueError(naive datetime is not allowed) return dt_utc.astimezone(CST).strftime(%Y-%m-%d %H:%M:%S%z)# 入库row[created_at_utc] datetime.now(timezone.utc).isoformat()那个raise是故意留的。朴素时间不带时区的时间对象在系统里出现过两次每次都是 bug。与其在比较时静默出错不如在写入时就崩掉。## 盲区三按时刻筛选会捞进前一天同一时刻的行时区改完之后我以为时间相关的问题都解决了。结果第三个坑紧接着就来了而且它比前两个更难发现——因为它返回的数据是看起来正常的。### 一次典型的误捞现场场景是这样的我要统计某天上午十点到十一点之间某个接口的失败次数。日志是滚动文件一天有二十多个文件。我用一个通配把多天的文件一起 grepbash# 统计 09-24 10:00-11:00 的失败grep -h 10:[0-9][0-9]:[0-9][0-9] app.log.2026-09-2[0-9] \ | grep -c statusFAIL输出的数是 312。我拿这个数去做同比感觉那天失败偏多。后来为了写报告我按天拆开统计得到的是这样的09-22 10:00-11:00 FAIL 4709-23 10:00-11:00 FAIL 5309-24 10:00-11:00 FAIL 4909-25 10:00-11:00 FAIL 5109-26 10:00-11:00 FAIL 112五天加起来正好 312。也就是说我那条 grep 根本没有按天筛选——它匹配的是小时:分钟:秒这个形状而通配符把所有天的文件都读进来了。我算的是五天的合计却当成了当天的数。更麻烦的是当天的 112 也不一定干净按大小轮转时一个文件跨越午夜是常态。09-24 03:00 创建的那个文件里既没有 09-24 凌晨的内容也可能混进 09-25 凌晨的行。### 为什么时间戳不足以做归因把这件事抽象一下时间戳是值不是身份。两行日志如果有相同的时分秒它们在按时刻筛选时是不可区分的。而在跨天拼接的场景里这种碰撞是必然发生的不是小概率。我算过这个碰撞的概率有多高。假设一次查询的时间窗口是 1 小时日志跨越 D 天的文件采样精度到秒那窗口内的每一秒在每一天都有一行。窗口有 3600 秒D 5 天那你捞到的行数是单个日期的 5 倍——误捞率是 400%。这就是为什么312这个数看起来像模像样实际上没有意义。### 正确做法行号 / 递增序号 会话标识改法是把归因依据从时间戳换成必然单调的东西。第一个是文件内的行号。大多数文本日志都能拿到行内偏移或者行号如果是自己控制格式就在每行前面加一个进程内单调递增的序号json{seq:1042871,ts_utc:2026-09-24T06:12:31.4020000,lvl:ERROR,mod:dispatcher,msg_id:MSG20260924...,status:FAIL,latency_ms:51204}有了seq跨文件拼接之后我可以按seq排序判断这一行是不是在上一次的断点之后。断点续读、去重、定位都能做而且不依赖时间。第二个是批次标识。跨进程、跨文件、跨机器的场景里seq不够用两个进程的seq会互相穿插。所以每个业务批次带一个独立标识所有相关日志行都打上它sql-- 按批次标识归因而不是按时间SELECT count(*) AS fail_cnt FROM app_logs WHERE batch_id B20260924-1410-A AND status FAIL;-- 需要当天统计时显式带上日期边界SELECT date(created_at_utc) AS d, count(*) FROM app_logs WHERE status FAIL AND created_at_utc 2026-09-24T00:00:00Z AND created_at_utc 2026-09-25T00:00:00Z GROUP BY d;注意第二个查询里日期边界是写死的不是靠LIKE去匹配文本形状。写死边界这件事看起来很笨但它把我要的是哪一天变成了一个显式参数而不是一个隐含在正则里的假设。## 日志分级与采样不是所有日志都值得落盘前面三个盲区都和日志不够用有关。但第四个问题正好相反日志太多了。### 四级分级的具体判据我用的分级不是照搬教科书而是按这条日志在什么场景下会被读来定的ERROR 需要人介入或有副作用失败。任何一条都必须能独立看懂 判据如果不处理会有人受影响WARN 自动恢复但值得计数。不单独告警只看速率 判据出现了但系统还活着且我能忍受到它一直存在INFO 关键路径的状态迁移。是排障时的主要读物 判据能回答走到哪一步了且每个请求不超过 5 条DEBUG 参数细节。默认关闭只在定位到具体模块后临时开 判据单独一行没有意义必须和其他行一起看判据里作用明显的是 INFO 那一条。以前我们把 INFO 当什么都打一个请求打十几行结果真正的状态迁移被淹在参数打印里。改成每个请求不超过 5 条 INFO之后日志总量降了 68%但排障时读起来反而更快——因为跳跃感消失了从上到下能顺着读完一条链路。### 采样比例怎么定高频重复日志的抑制有些日志天然高频且高度重复比如轮询未发现新数据“缓存命中”。这类日志不该按条写该按统计写。我用的方式是按窗口聚合pythonimport timefrom collections import Counterclass Sampler: 同一 key 在一个窗口内只记首条其余计数 def __init__(self, window_sec60): self.window window_sec self._state {} # key - (window_id, cnt) def hit(self, key): wid int(time.time() // self.window) cur self._state.get(key) if cur is None or cur[0] ! wid: self._state[key] (wid, 1) return True # 落盘 self._state[key] (wid, cur[1] 1) return False # 抑制 def flush(self, emit): for key, (wid, cnt) in self._state.items(): if cnt 1: emit(f{key} suppressed{cnt - 1} window{wid})采样比例方面我按类别定了几档调试类参数明细 采样 1/20且在 DEBUG 关闭时全部丢弃轮询类空转探测 每 60 秒保留 1 条 抑制计数重试类单次重试 全部保留重试是异常信号批量类批处理进度 按 10% 进度点保留其余丢弃审计类副作用发生 不采样100% 落表这五档里重试类全部保留是刻意定高的一档。因为重试率很能反映下游健康采样会直接破坏它的可计算性。反过来轮询类占日志量的比例当时是 41%抑制之后降到 2% 以下。## 结构化日志的收益从 grep 到字段查询从文本日志换成 JSON 行之后感受明显的是排查节奏变了。文本时代我需要先想这条日志长什么样再用正则去描述它的形状结构化之后我只需要想我要哪个字段。### 改造前后的对比数据同一类排查任务在两周日志里定位某批消息的处理链路我记录了两组数据文本 grep JSON 字段查询定位到首条相关行 11 分钟 40 秒平均尝试的正则条数 6.3 条 0不需要漏捞事后发现 3 次 / 20 次 0 次 / 20 次准确率 85% 100%同一口径单次查询耗时全量 18-35 秒 2-4 秒跨字段关联 不支持 原生支持准确率那一项的差别主要来自构造正则时的形状假设。文本时代我写了 6.3 条正则里至少有 2 条是因为字段顺序变了或者多了个空格而失效的——它们不报错只是安静地少返回几行。查询耗时从 20 多秒降到 3 秒左右原因不在解析而在可以只扫需要的字段。文本模式必须读全行字段模式下如果底层是按列存的过滤只需要读少数字段。### 字段命名踩过的坑换成 JSON 之后我们踩了几个命名上的坑这些坑不大但会反复咬人坑 1 同一含义用多个名字msg_id / messageId / mid 同时存在 → 约定一律 snake_case全小写下划线写进 lint坑 2 时间字段不带时区后缀见第二部分的那个坑 → 约定时间字段一律 _utc 后缀值为带偏移的 ISO 串坑 3 布尔字段用字符串true / True / 1 都有 → 约定真正的布尔且禁止用字符串表达坑 4 数值字段混入单位latency 有的毫秒有的秒 → 约定字段名带单位latency_ms / size_bytes坑 5 可选字段缺失时整个 key 消失查询要写很多 IS NULL → 约定缺失时写 null保持 schema 稳定字段缺失和字段为 null在查询层面是两回事前者会让按字段存在性过滤的逻辑失效。我们有次统计retry_count 0的行数因为大部分行没有这个字段聚合直接少算了一大截。后来改成所有行的 schema 一致、缺值写 null这类问题就没了。## 关键事件审计表设计这是那六个小时教给我的东西里落成代码的部分。### 哪些事件必须单独存表筛选标准只有一个这个事件发生后我需要能证明它发生过。具体落到四类1. 副作用成功 消息已发出、文件已写、外部调用已返回2. 副作用失败 调用被拒、超时耗尽、状态不允许3. 状态变更 从 A 到 B何时、由谁触发、依据什么4. 异常 未预期分支、断言失败、数据不一致这四类的共同点是不可从其他数据推导出来。比如消息已发出这个事实从消息表的状态字段能推断出结果但推断不出什么时候发的、发了几次、每次的结果。审计表存的是过程。### 字段设计与索引取舍建表语句大致是这样sqlCREATE TABLE event_audit ( id INTEGER PRIMARY KEY AUTOINCREMENT, event_id TEXT NOT NULL, -- 事件自身标识 occurred_at_utc TEXT NOT NULL, -- ISO8601 带偏移 event_type TEXT NOT NULL, -- send_ok / send_fail / state_change ... subject_type TEXT NOT NULL, -- 主体类型 subject_id TEXT NOT NULL, -- 主体标识 from_state TEXT, -- 变更前可空 to_state TEXT, -- 变更后可空 attempt INTEGER NOT NULL DEFAULT 1, detail TEXT, -- JSON 快照只放排查需要的 batch_id TEXT, actor TEXT NOT NULL -- 触发来源);CREATE INDEX idx_ea_subject ON event_audit(subject_type, subject_id, occurred_at_utc);CREATE INDEX idx_ea_batch ON event_audit(batch_id);CREATE INDEX idx_ea_type_t ON event_audit(event_type, occurred_at_utc);三个索引对应三种问法按主体查它的完整历史、按批次查一次作业的全部动作、按类型和时间查总体速率。detail字段存 JSON 是个折中它让我不用为每种事件建一张表代价是查不了里面的字段。判断标准是这个字段只用来给人看还是也要参与查询——只给人看的放 detail。写入时机上我犯过一次错一开始我是在业务事务里同步写审计表。结果外部调用超时的时候事务回滚审计记录也一起没了——恰好丢的是需要的那条。后来改成审计先写、业务后做审计表不参与业务事务pythondef send_with_audit(conn, msg): # 先落意图崩掉也有痕迹 conn.execute( INSERT INTO event_audit(event_id, occurred_at_utc, event_type, subject_type, subject_id, attempt, actor) VALUES(?,?,?,?,?,?,?), (msg.id, now_utc_iso(), send_attempt, message, msg.id, msg.attempt, dispatcher)) conn.commit() try: resp do_send(msg) except Exception as e: write_audit(conn, msg, send_fail, detailstr(e)) raise write_audit(conn, msg, send_ok, detailresp.summary())这里有个取舍要说明审计表不参与业务事务意味着可能出现审计说尝试了但业务其实没开始的记录。对排查来说这是可以接受的——多一条痕迹比少一条痕迹代价小得多。## 排障时段的准备先备份再动手这一节和日志本身没太大关系但它是那次事故里另一件我学到的、收益立竿见影的事。### 一次装包之后原始状态没了的教训那次排查进行到一半我为了加一些临时日志打了个新包替换上去。替换的时候顺手把旧包删了日志目录也没动。问题在于新包启动时会重新初始化本地存储。它的初始化逻辑是如果表不存在就建表如果存在就跳过——听起来很安全。但当时那份存储是旧版本创建的字段少两个新版本检测到表存在就跳过了建表于是启动之后每次写都报字段不存在的错。更麻烦的是新进程在启动阶段把几份陈旧状态做了修复其中一步是把一个计数表清零了。等我发现要回退的时候旧包没了原始数据也被改过了。那次之后我给自己定了条规矩事故现场的处置顺序永远是备份 → 快照 → 再动手。顺序不能换也不能合并。### 备份清单现在我的备份清单是固定的五步1. 进程元信息 ps 输出、启动参数、环境变量脱敏后、当前工作目录 → 这些决定了当时的进程到底是怎么起来的2. 配置快照 应用配置文件、日志轮转配置、数据库连接配置 → 现场改了配置之后你就再也回不到原来的解释3. 数据快照 本地库文件整体复制不是导出是文件级复制 → 导出会丢索引和 WAL也丢当时的状态4. 日志整体归档 整个日志目录打包包含已经轮转的历史文件 → 打包不要 gzip 单文件后再删原文件5. 时间锚点 记录当前 UTC 时间、本地时间、各机器的时钟偏移 → 这一条是给时区坑买的保险执行就是几行命令bashTS$(date -u %Y%m%dT%H%M%SZ)mkdir -p /backup/$TScp -a /srv/app/config /backup/$TS/configcp -a /srv/app/data /backup/$TS/datatar -czf /backup/$TS/logs.tar.gz -C /srv/app logps -ef /backup/$TS/ps.txtdate -u /backup/$TS/clock_utc.txtdate /backup/$TS/clock_utc.txtsha256sum /backup/$TS/data/* /backup/$TS/data.sha256最后一行是校验和。它不是为了安全是为了事后能证明我分析的就是当时那份数据。有一次我基于备份得出的结论被人质疑把校验和拿出来核对之后争议就结束了。## 踩坑日志写得太详细把磁盘写满导致服务不可用前面说日志不够用但过度记录的代价我同样付过而且那次的后果比查不到严重得多。### 日志量与磁盘配额的算术那次是我给一个批量处理模块加了逐条明细日志一条记录约 380 字节单批处理 12 万条单批日志量 380 B × 120000 45.6 MB批次数高峰期 每小时 8 批每小时日志量 45.6 MB × 8 364.8 MB磁盘剩余空间 12 GB理论上限 12288 / 364.8 ≈ 33.7 小时理论值看着还行但实际只撑了 26 小时。差在哪里因为中途有两个批次的输入数据异常膨胀单个批次写进了 3 倍的数据量而且磁盘上还同时住着数据库文件和它的临时文件。26 小时正好是一个工作日加一个晚上。后果是磁盘写满数据库无法写入服务整体不可用。恢复过程本身不难清日志就好但服务停摆的那段时间和连带的数据修复比前面那次查不到证据的代价大得多。改法上有三层限制分别落在容量、速率和单条长度上第一层 日志总量硬上限 日志目录独立挂载配额限定达到 85% 就按天删旧归档第二层 单模块速率限制 每个模块每秒写入上限例如 200 行/秒超限只计数第三层 描述长度上限 单条日志的 detail 字段截断到 2 KB超长打省略标记第二层的实现是令牌桶超限时丢弃并累计一个计数器每隔一分钟把丢弃数汇总成一条pythonclass RateLimitedLogger: def __init__(self, sink, rate200): self.sink sink self.rate rate self.tokens rate self.last time.monotonic() self.dropped 0 def log(self, line): now time.monotonic() self.tokens min(self.rate, self.tokens (now - self.last) * self.rate) self.last now if self.tokens 1: self.tokens - 1 self.sink(line) else: self.dropped 1 # 只加计数不写盘 def report(self): if self.dropped: self.sink(f# log_throttled dropped{self.dropped} rate{self.rate}/s) self.dropped 0这里有个容易忽略的点丢日志这件事本身要留下痕迹。如果只丢不记事后看到的就是一份看起来完整但缺了几行的日志比明显缺失更危险。所以每轮上报一行丢弃计数让缺失变成可观测的。## 复盘可观测性不是有日志回头看那六个小时我的时间分布大致是这样排查方向猜测队列、网络、数据库 3 小时 10 分翻找日志包括反复扩大时间范围 1 小时 40 分怀疑数据本身有问题写脚本验证 50 分确认是日志系统的问题 20 分一百九十分钟花在了错误的猜测上而这些猜测之所以无法被快速证伪是因为每一次验证都缺少可靠的数据。不是没有数据——数据量其实很大一个日志目录有 248 MB。缺的是在需要的时候、对的时间范围里、可信的数据。我后来把这件事的教训压成一句话可观测性不是有日志是关键路径上每一步都能被证明。### 关键路径上每一步都能被证明具体到执行上我现在的检查方式是问三组问题第一组关于时间- 这条记录的时间是 UTC 还是本地时间边界写死了吗- 我查的时间窗口日志真的还在吗回溯窗口是几小时- 日志文件会不会跨天混装我按什么归因第二组关于身份- 这批动作有没有独立标识能否用它把整条链路串起来- 没有标识时我用什么保证不会捞进无关的行第三组关于留存- 如果这条记录丢了我要用什么重建它- 这个磁盘能写多久写满的后果是什么三组问题一共九个没有一个需要新技术全都是改配置和加字段就能覆盖的。但从那以后类似规模的问题我在一小时以内都能给出带证据的结论而不是写没找到相关记录。那三行心虚的说明我到现在还留着。## 相关实现这套做法来自一个本地运行的消息处理工具单机进程、带本地存储、负责把一批批消息按计划投递出去界面就是一个普通的桌面窗口没有服务端集群。它起先只有一份滚动文本日志正是上面这几次事故之后才长出了环形缓冲、UTC 命名规范、独立审计表和限额写入这几块。整套东西的形态很朴素——一个能在你手边把消息按点发出去、并且事后能被自己证明做过什么的小工具。dingdang.asia 日志系统三个盲区复盘：48.2MB 降到 62MB、时区错乱与按时刻筛选捞错行
背景六小时排查卡在没有证据这一环事情发生在一个普通工作日的下午。有人反馈某批推送消息在两点到三点之间集体延迟部分用户到四点多才收到。不算严重故障但用户能感知到所以要给出说明。我从下午三点二十开始查一直查到晚上九点半。四个多小时后我在日志里什么都没找到。注意不是找到的日志说明没问题而是根本没有那个时间段的日志。日志目录里只有从当天十六点开始的文件再往前的都被轮转删掉了。那六个小时的产出是一份三行的说明而且上面这句话我写得非常心虚——因为我没有证据我只有没找到证据。### 我先猜错了方向以为问题在队列我的初始假设是队列积压。理由是延迟是集体的一批用户同时受影响这通常意味着某个共享资源被卡住了。我先看了消费端的处理速率正常。又看了队列的堆积深度那个时间段的曲线确实有一个小凸起但很快就回落了。我甚至写了个脚本去对比消息的入队时间和出队时间做差值分布差值的中位数是 42 毫秒尾部 P99 也就 800 多毫秒。这个数据看起来非常健康健康到让我怀疑反馈本身是不是搞错了。后来我才意识到这份健康的数据本身就是残缺的——我只统计了那段时间里还在日志里的消息。没能进日志的那些恰好就是有问题的那些。用幸存者偏差去证明系统没问题这是我在这件事上犯的第一个方法性错误。### 真正的问题证据在那三个小时里被删掉了晚上八点多我放弃了从应用日志里找线索转而去翻文件系统的修改记录。日志目录下当时的文件列表是这样的app.log 2026-09-24 21:04 48.2 MBapp.log.1 2026-09-24 18:11 50.0 MBapp.log.2 2026-09-24 15:02 50.0 MBapp.log.3 2026-09-24 11:37 50.0 MBapp.log.4 2026-09-24 08:02 50.0 MB问题一眼就看出来了。app.log.2 的时间戳是 15:02也就是说十四点到 fifteen 点这个窗口的内容跨越了 app.log.2 和 app.log.3 的边界——而 app.log.3 是 11:37 到 15:02 的内容。但我用 grep 去搜那批延迟消息的标识一条都没有。再仔细看这五个文件加起来是 248 MB而我当天的写入量按速率反推大约是每小时 62 MB。也就是说这个日志目录能容纳的内容不到四小时。故障发生在十四点我开始查是十五点二十。等到我晚上八点真正去翻文件的时候十四点的日志已经滚了两轮被覆盖掉了。我盯着那五个文件看了很久。感受不是日志不够多而是我们明明配了日志但它在关键的那几小时里是个摆设。这一篇记录的就是从那次事故开始我陆续改掉的三个盲区。图日志系统的三个盲区与对应处置## 盲区一日志轮转把关键证据覆盖了日志轮转是我以前从没认真想过的东西。它太常规了几条配置写上去就再也没人碰。但它的默认行为里藏着一条很硬的规则轮转的存储空间是有限的超出部分必然被丢弃。### 轮转策略是怎么把证据吃掉的当时的配置大致是这样/path/app.log { size 50M rotate 5 missingok notifempty compress delaycompress copytruncate}这里面有三个参数共同决定了证据能活多久-size 50M单个文件到 50 MB 就切-rotate 5保留 5 个历史文件-compressdelaycompress压缩的是从.2开始的文件所以理论上限就是 50 × 6 300 MB实际上因为压缩已归档的部分会小一些但热数据仍然是 50 MB 一个文件。真正致命的是后面两条rotate 5决定了只有 5 份历史而写入速率决定了这 5 份能撑多久。### 按大小轮转的算术题把这件事算清楚只需要三个数写入速率、单文件上限、保留份数。写入速率 R 62 MB/h单文件上限 S 50 MB保留份数 N 6含当前文件可回溯时长 T S × N / R 50 × 6 / 62 ≈ 4.84 小时4.84 小时。这是一个我在配置轮转时从没算过的数。更糟的是这个数字会随着系统负载漂移业务量翻倍或者某天多打了一些调试日志R 涨到 120 MB/hT 就掉到 2.5 小时。我在事故之后做了件很简单的事把这三个数写进配置文件旁边的一行注释并且加了一个定时任务每小时把当前的回溯窗口算出来打到监控指标里。回溯窗口低于 8 小时就告警。这个改动一共没写二十行代码但它把日志能留多久从一个没人知道的隐变量变成了一个被监控的数。### 正确做法环形缓冲 关键事件单独落库改法分两层。一层是把轮转从保留份数改成保留时长。按大小切文件但归档文件按日期命名只删超过 N 天的。这样负载高的时候文件数量自动变多而不是把时间窗口压缩掉。另一层才是关键不再指望主日志承担关键事件的举证责任。我给自己定了一个判据——“如果这条记录丢了我需要用什么去重建它“如果要靠它去证明某个副作用发生过比如这条消息确实发出去了”那它就不该只躺在会被覆盖的文件里。它应该写进一张表。所以现在的结构是热日志文本/JSON滚动保留 7 天 └── 用于排查过程性问题为什么慢了、为什么重试了环形缓冲内存固定 4096 条进程内有界队列 └── 用于崩溃瞬间的快照进程挂掉时把缓冲刷到磁盘审计表数据库不参与轮转 └── 用于证明关键动作发生过发送、状态变更、异常环形缓冲那段代码很短核心是写满就覆盖头部永远不报错、永远不阻塞”pythonfrom collections import dequeclass RingTrace: def __init__(self, cap4096): self._buf deque(maxlencap) self._dropped 0 def push(self, item): if len(self._buf) self._buf.maxlen: self._dropped 1 # 不阻塞 self._buf.append(item) def dump(self, path): # 异常退出时落盘 with open(path, a, encodingutf-8) as f: for rec in self._buf: f.write(rec \n) f.write(f# dropped{self._dropped}\n)这里有个细节值得说deque(maxlenN)在满员时自动丢弃头部而且这个操作是 O(1) 的不会因为日志写入把业务线程拖慢。我一开始自己用 list 加切片实现每次满了做一次self._buf self._buf[1:]在高频写入下这部分的开销吃掉了 3% 左右的 CPU换成 deque 之后这个数字降到了噪声水平。## 盲区二时区错乱让我查了一个空的时间段如果说轮转是证据被删了那时区问题就是我站在错误的地方找证据。它的表现更隐蔽因为查询会正常返回结果——返回零行。零行和没有异常长得一模一样。### 八小时偏差是怎么被发现的还是那次十四点的故障。我在轮转改好之后回头补查历史问题时踩到了这个坑。我按运维同事给的时间下午两点十分左右去查日志查询语句大概是sqlSELECT ts, msg_id, status, latency_ms FROM app_logs WHERE ts 2026-09-24 14:10:00 AND ts 2026-09-24 14:20:00 AND msg_id LIKE MSG20260924%;返回 0 行。我的判断是那段时间没有这个批次的消息。于是在结论里写了两点十到二十之间没有相关记录问题可能发生在更早的环节。这个结论后来被证明是错的。转折来自一个很偶然的动作我不死心直接把时间范围放大到整个下午再按分钟聚合看分布。sqlSELECT substr(ts, 12, 5) AS minute, count(*) FROM app_logs WHERE msg_id LIKE MSG20260924% AND ts 2026-09-24 00:00:00 AND ts 2026-09-25 00:00:00 GROUP BY minute ORDER BY minute;结果里 06:10 到 06:20 这一段有个明显的尖峰计数是其余分钟的四倍多。六点十分。我当时想的是早上六点有另一批消息和这件事无关。直到我把那条记录的完整内容打出来看了一眼发现它的msg_id里嵌着0924而且处理耗时字段是 5 万多毫秒——这和反馈里的延迟了很久对得上。到这里八小时偏差才对上**应用写库时用的是 UTC运维同事报的时间是本地时间UTC8我按本地时间去查 UTC 字段正好查到了八小时前。**我一开始没有怀疑时区理由说出来有点丢人我看了下表结构字段名是ts类型是timestamp没有时区信息我就默认它是本地时间了。数据库里存的值其实一直是 UTC只是从来没人把它写出来过。### 三个时区同时存在的现场把这次排查涉及的环节列一遍就知道为什么会乱环节 1 应用进程 写库用 UTCdatetime.now(timezone.utc)环节 2 数据库 字段类型无时区存进去的值原样保留UTC 数值环节 3 命令行客户端 会话时区为 UTC显示出来还是 UTC环节 4 图形化查询工具 默认按操作系统本地时区渲染显示成 8 小时环节 5 日志文件 用的是本地时间因为 logging 默认用 localtime环节 6 运维同学报障 说的是墙上的钟本地时间六个环节三种时间基准。同一个事件在应用日志里是14:12在数据库里是06:12在图形工具里又显示成14:12。而我去 grep 文本日志的时候搜的是06:12当然搜不到。我当时的错误是把两个地方显示的时间一样当成了它们存的是同一个东西。图形工具显示 14:12 是因为它自己加上了 8 小时和文本日志里的 14:12 完全是两回事。### 统一时区的三条硬规定改完之后我定了三条规矩写进了团队约定1.存储层只存 UTC字段名带_utc后缀。不再是含糊的ts而是created_at_utc。名字本身就是文档。2.日志输出带明确的时区偏移。格式串从%Y-%m-%d %H:%M:%S改成%Y-%m-%dT%H:%M:%S%z输出形如2026-09-24T06:12:310000。多出来的 5 个字符换来的是不需要猜。3.只在展示层做换算而且换算的位置集中在一个函数里。pythonfrom datetime import datetime, timezone, timedeltaCST timezone(timedelta(hours8))def to_local(dt_utc: datetime) - str: 只在展示时调用入库、比对、聚合一律用 UTC if dt_utc.tzinfo is None: raise ValueError(naive datetime is not allowed) return dt_utc.astimezone(CST).strftime(%Y-%m-%d %H:%M:%S%z)# 入库row[created_at_utc] datetime.now(timezone.utc).isoformat()那个raise是故意留的。朴素时间不带时区的时间对象在系统里出现过两次每次都是 bug。与其在比较时静默出错不如在写入时就崩掉。## 盲区三按时刻筛选会捞进前一天同一时刻的行时区改完之后我以为时间相关的问题都解决了。结果第三个坑紧接着就来了而且它比前两个更难发现——因为它返回的数据是看起来正常的。### 一次典型的误捞现场场景是这样的我要统计某天上午十点到十一点之间某个接口的失败次数。日志是滚动文件一天有二十多个文件。我用一个通配把多天的文件一起 grepbash# 统计 09-24 10:00-11:00 的失败grep -h 10:[0-9][0-9]:[0-9][0-9] app.log.2026-09-2[0-9] \ | grep -c statusFAIL输出的数是 312。我拿这个数去做同比感觉那天失败偏多。后来为了写报告我按天拆开统计得到的是这样的09-22 10:00-11:00 FAIL 4709-23 10:00-11:00 FAIL 5309-24 10:00-11:00 FAIL 4909-25 10:00-11:00 FAIL 5109-26 10:00-11:00 FAIL 112五天加起来正好 312。也就是说我那条 grep 根本没有按天筛选——它匹配的是小时:分钟:秒这个形状而通配符把所有天的文件都读进来了。我算的是五天的合计却当成了当天的数。更麻烦的是当天的 112 也不一定干净按大小轮转时一个文件跨越午夜是常态。09-24 03:00 创建的那个文件里既没有 09-24 凌晨的内容也可能混进 09-25 凌晨的行。### 为什么时间戳不足以做归因把这件事抽象一下时间戳是值不是身份。两行日志如果有相同的时分秒它们在按时刻筛选时是不可区分的。而在跨天拼接的场景里这种碰撞是必然发生的不是小概率。我算过这个碰撞的概率有多高。假设一次查询的时间窗口是 1 小时日志跨越 D 天的文件采样精度到秒那窗口内的每一秒在每一天都有一行。窗口有 3600 秒D 5 天那你捞到的行数是单个日期的 5 倍——误捞率是 400%。这就是为什么312这个数看起来像模像样实际上没有意义。### 正确做法行号 / 递增序号 会话标识改法是把归因依据从时间戳换成必然单调的东西。第一个是文件内的行号。大多数文本日志都能拿到行内偏移或者行号如果是自己控制格式就在每行前面加一个进程内单调递增的序号json{seq:1042871,ts_utc:2026-09-24T06:12:31.4020000,lvl:ERROR,mod:dispatcher,msg_id:MSG20260924...,status:FAIL,latency_ms:51204}有了seq跨文件拼接之后我可以按seq排序判断这一行是不是在上一次的断点之后。断点续读、去重、定位都能做而且不依赖时间。第二个是批次标识。跨进程、跨文件、跨机器的场景里seq不够用两个进程的seq会互相穿插。所以每个业务批次带一个独立标识所有相关日志行都打上它sql-- 按批次标识归因而不是按时间SELECT count(*) AS fail_cnt FROM app_logs WHERE batch_id B20260924-1410-A AND status FAIL;-- 需要当天统计时显式带上日期边界SELECT date(created_at_utc) AS d, count(*) FROM app_logs WHERE status FAIL AND created_at_utc 2026-09-24T00:00:00Z AND created_at_utc 2026-09-25T00:00:00Z GROUP BY d;注意第二个查询里日期边界是写死的不是靠LIKE去匹配文本形状。写死边界这件事看起来很笨但它把我要的是哪一天变成了一个显式参数而不是一个隐含在正则里的假设。## 日志分级与采样不是所有日志都值得落盘前面三个盲区都和日志不够用有关。但第四个问题正好相反日志太多了。### 四级分级的具体判据我用的分级不是照搬教科书而是按这条日志在什么场景下会被读来定的ERROR 需要人介入或有副作用失败。任何一条都必须能独立看懂 判据如果不处理会有人受影响WARN 自动恢复但值得计数。不单独告警只看速率 判据出现了但系统还活着且我能忍受到它一直存在INFO 关键路径的状态迁移。是排障时的主要读物 判据能回答走到哪一步了且每个请求不超过 5 条DEBUG 参数细节。默认关闭只在定位到具体模块后临时开 判据单独一行没有意义必须和其他行一起看判据里作用明显的是 INFO 那一条。以前我们把 INFO 当什么都打一个请求打十几行结果真正的状态迁移被淹在参数打印里。改成每个请求不超过 5 条 INFO之后日志总量降了 68%但排障时读起来反而更快——因为跳跃感消失了从上到下能顺着读完一条链路。### 采样比例怎么定高频重复日志的抑制有些日志天然高频且高度重复比如轮询未发现新数据“缓存命中”。这类日志不该按条写该按统计写。我用的方式是按窗口聚合pythonimport timefrom collections import Counterclass Sampler: 同一 key 在一个窗口内只记首条其余计数 def __init__(self, window_sec60): self.window window_sec self._state {} # key - (window_id, cnt) def hit(self, key): wid int(time.time() // self.window) cur self._state.get(key) if cur is None or cur[0] ! wid: self._state[key] (wid, 1) return True # 落盘 self._state[key] (wid, cur[1] 1) return False # 抑制 def flush(self, emit): for key, (wid, cnt) in self._state.items(): if cnt 1: emit(f{key} suppressed{cnt - 1} window{wid})采样比例方面我按类别定了几档调试类参数明细 采样 1/20且在 DEBUG 关闭时全部丢弃轮询类空转探测 每 60 秒保留 1 条 抑制计数重试类单次重试 全部保留重试是异常信号批量类批处理进度 按 10% 进度点保留其余丢弃审计类副作用发生 不采样100% 落表这五档里重试类全部保留是刻意定高的一档。因为重试率很能反映下游健康采样会直接破坏它的可计算性。反过来轮询类占日志量的比例当时是 41%抑制之后降到 2% 以下。## 结构化日志的收益从 grep 到字段查询从文本日志换成 JSON 行之后感受明显的是排查节奏变了。文本时代我需要先想这条日志长什么样再用正则去描述它的形状结构化之后我只需要想我要哪个字段。### 改造前后的对比数据同一类排查任务在两周日志里定位某批消息的处理链路我记录了两组数据文本 grep JSON 字段查询定位到首条相关行 11 分钟 40 秒平均尝试的正则条数 6.3 条 0不需要漏捞事后发现 3 次 / 20 次 0 次 / 20 次准确率 85% 100%同一口径单次查询耗时全量 18-35 秒 2-4 秒跨字段关联 不支持 原生支持准确率那一项的差别主要来自构造正则时的形状假设。文本时代我写了 6.3 条正则里至少有 2 条是因为字段顺序变了或者多了个空格而失效的——它们不报错只是安静地少返回几行。查询耗时从 20 多秒降到 3 秒左右原因不在解析而在可以只扫需要的字段。文本模式必须读全行字段模式下如果底层是按列存的过滤只需要读少数字段。### 字段命名踩过的坑换成 JSON 之后我们踩了几个命名上的坑这些坑不大但会反复咬人坑 1 同一含义用多个名字msg_id / messageId / mid 同时存在 → 约定一律 snake_case全小写下划线写进 lint坑 2 时间字段不带时区后缀见第二部分的那个坑 → 约定时间字段一律 _utc 后缀值为带偏移的 ISO 串坑 3 布尔字段用字符串true / True / 1 都有 → 约定真正的布尔且禁止用字符串表达坑 4 数值字段混入单位latency 有的毫秒有的秒 → 约定字段名带单位latency_ms / size_bytes坑 5 可选字段缺失时整个 key 消失查询要写很多 IS NULL → 约定缺失时写 null保持 schema 稳定字段缺失和字段为 null在查询层面是两回事前者会让按字段存在性过滤的逻辑失效。我们有次统计retry_count 0的行数因为大部分行没有这个字段聚合直接少算了一大截。后来改成所有行的 schema 一致、缺值写 null这类问题就没了。## 关键事件审计表设计这是那六个小时教给我的东西里落成代码的部分。### 哪些事件必须单独存表筛选标准只有一个这个事件发生后我需要能证明它发生过。具体落到四类1. 副作用成功 消息已发出、文件已写、外部调用已返回2. 副作用失败 调用被拒、超时耗尽、状态不允许3. 状态变更 从 A 到 B何时、由谁触发、依据什么4. 异常 未预期分支、断言失败、数据不一致这四类的共同点是不可从其他数据推导出来。比如消息已发出这个事实从消息表的状态字段能推断出结果但推断不出什么时候发的、发了几次、每次的结果。审计表存的是过程。### 字段设计与索引取舍建表语句大致是这样sqlCREATE TABLE event_audit ( id INTEGER PRIMARY KEY AUTOINCREMENT, event_id TEXT NOT NULL, -- 事件自身标识 occurred_at_utc TEXT NOT NULL, -- ISO8601 带偏移 event_type TEXT NOT NULL, -- send_ok / send_fail / state_change ... subject_type TEXT NOT NULL, -- 主体类型 subject_id TEXT NOT NULL, -- 主体标识 from_state TEXT, -- 变更前可空 to_state TEXT, -- 变更后可空 attempt INTEGER NOT NULL DEFAULT 1, detail TEXT, -- JSON 快照只放排查需要的 batch_id TEXT, actor TEXT NOT NULL -- 触发来源);CREATE INDEX idx_ea_subject ON event_audit(subject_type, subject_id, occurred_at_utc);CREATE INDEX idx_ea_batch ON event_audit(batch_id);CREATE INDEX idx_ea_type_t ON event_audit(event_type, occurred_at_utc);三个索引对应三种问法按主体查它的完整历史、按批次查一次作业的全部动作、按类型和时间查总体速率。detail字段存 JSON 是个折中它让我不用为每种事件建一张表代价是查不了里面的字段。判断标准是这个字段只用来给人看还是也要参与查询——只给人看的放 detail。写入时机上我犯过一次错一开始我是在业务事务里同步写审计表。结果外部调用超时的时候事务回滚审计记录也一起没了——恰好丢的是需要的那条。后来改成审计先写、业务后做审计表不参与业务事务pythondef send_with_audit(conn, msg): # 先落意图崩掉也有痕迹 conn.execute( INSERT INTO event_audit(event_id, occurred_at_utc, event_type, subject_type, subject_id, attempt, actor) VALUES(?,?,?,?,?,?,?), (msg.id, now_utc_iso(), send_attempt, message, msg.id, msg.attempt, dispatcher)) conn.commit() try: resp do_send(msg) except Exception as e: write_audit(conn, msg, send_fail, detailstr(e)) raise write_audit(conn, msg, send_ok, detailresp.summary())这里有个取舍要说明审计表不参与业务事务意味着可能出现审计说尝试了但业务其实没开始的记录。对排查来说这是可以接受的——多一条痕迹比少一条痕迹代价小得多。## 排障时段的准备先备份再动手这一节和日志本身没太大关系但它是那次事故里另一件我学到的、收益立竿见影的事。### 一次装包之后原始状态没了的教训那次排查进行到一半我为了加一些临时日志打了个新包替换上去。替换的时候顺手把旧包删了日志目录也没动。问题在于新包启动时会重新初始化本地存储。它的初始化逻辑是如果表不存在就建表如果存在就跳过——听起来很安全。但当时那份存储是旧版本创建的字段少两个新版本检测到表存在就跳过了建表于是启动之后每次写都报字段不存在的错。更麻烦的是新进程在启动阶段把几份陈旧状态做了修复其中一步是把一个计数表清零了。等我发现要回退的时候旧包没了原始数据也被改过了。那次之后我给自己定了条规矩事故现场的处置顺序永远是备份 → 快照 → 再动手。顺序不能换也不能合并。### 备份清单现在我的备份清单是固定的五步1. 进程元信息 ps 输出、启动参数、环境变量脱敏后、当前工作目录 → 这些决定了当时的进程到底是怎么起来的2. 配置快照 应用配置文件、日志轮转配置、数据库连接配置 → 现场改了配置之后你就再也回不到原来的解释3. 数据快照 本地库文件整体复制不是导出是文件级复制 → 导出会丢索引和 WAL也丢当时的状态4. 日志整体归档 整个日志目录打包包含已经轮转的历史文件 → 打包不要 gzip 单文件后再删原文件5. 时间锚点 记录当前 UTC 时间、本地时间、各机器的时钟偏移 → 这一条是给时区坑买的保险执行就是几行命令bashTS$(date -u %Y%m%dT%H%M%SZ)mkdir -p /backup/$TScp -a /srv/app/config /backup/$TS/configcp -a /srv/app/data /backup/$TS/datatar -czf /backup/$TS/logs.tar.gz -C /srv/app logps -ef /backup/$TS/ps.txtdate -u /backup/$TS/clock_utc.txtdate /backup/$TS/clock_utc.txtsha256sum /backup/$TS/data/* /backup/$TS/data.sha256最后一行是校验和。它不是为了安全是为了事后能证明我分析的就是当时那份数据。有一次我基于备份得出的结论被人质疑把校验和拿出来核对之后争议就结束了。## 踩坑日志写得太详细把磁盘写满导致服务不可用前面说日志不够用但过度记录的代价我同样付过而且那次的后果比查不到严重得多。### 日志量与磁盘配额的算术那次是我给一个批量处理模块加了逐条明细日志一条记录约 380 字节单批处理 12 万条单批日志量 380 B × 120000 45.6 MB批次数高峰期 每小时 8 批每小时日志量 45.6 MB × 8 364.8 MB磁盘剩余空间 12 GB理论上限 12288 / 364.8 ≈ 33.7 小时理论值看着还行但实际只撑了 26 小时。差在哪里因为中途有两个批次的输入数据异常膨胀单个批次写进了 3 倍的数据量而且磁盘上还同时住着数据库文件和它的临时文件。26 小时正好是一个工作日加一个晚上。后果是磁盘写满数据库无法写入服务整体不可用。恢复过程本身不难清日志就好但服务停摆的那段时间和连带的数据修复比前面那次查不到证据的代价大得多。改法上有三层限制分别落在容量、速率和单条长度上第一层 日志总量硬上限 日志目录独立挂载配额限定达到 85% 就按天删旧归档第二层 单模块速率限制 每个模块每秒写入上限例如 200 行/秒超限只计数第三层 描述长度上限 单条日志的 detail 字段截断到 2 KB超长打省略标记第二层的实现是令牌桶超限时丢弃并累计一个计数器每隔一分钟把丢弃数汇总成一条pythonclass RateLimitedLogger: def __init__(self, sink, rate200): self.sink sink self.rate rate self.tokens rate self.last time.monotonic() self.dropped 0 def log(self, line): now time.monotonic() self.tokens min(self.rate, self.tokens (now - self.last) * self.rate) self.last now if self.tokens 1: self.tokens - 1 self.sink(line) else: self.dropped 1 # 只加计数不写盘 def report(self): if self.dropped: self.sink(f# log_throttled dropped{self.dropped} rate{self.rate}/s) self.dropped 0这里有个容易忽略的点丢日志这件事本身要留下痕迹。如果只丢不记事后看到的就是一份看起来完整但缺了几行的日志比明显缺失更危险。所以每轮上报一行丢弃计数让缺失变成可观测的。## 复盘可观测性不是有日志回头看那六个小时我的时间分布大致是这样排查方向猜测队列、网络、数据库 3 小时 10 分翻找日志包括反复扩大时间范围 1 小时 40 分怀疑数据本身有问题写脚本验证 50 分确认是日志系统的问题 20 分一百九十分钟花在了错误的猜测上而这些猜测之所以无法被快速证伪是因为每一次验证都缺少可靠的数据。不是没有数据——数据量其实很大一个日志目录有 248 MB。缺的是在需要的时候、对的时间范围里、可信的数据。我后来把这件事的教训压成一句话可观测性不是有日志是关键路径上每一步都能被证明。### 关键路径上每一步都能被证明具体到执行上我现在的检查方式是问三组问题第一组关于时间- 这条记录的时间是 UTC 还是本地时间边界写死了吗- 我查的时间窗口日志真的还在吗回溯窗口是几小时- 日志文件会不会跨天混装我按什么归因第二组关于身份- 这批动作有没有独立标识能否用它把整条链路串起来- 没有标识时我用什么保证不会捞进无关的行第三组关于留存- 如果这条记录丢了我要用什么重建它- 这个磁盘能写多久写满的后果是什么三组问题一共九个没有一个需要新技术全都是改配置和加字段就能覆盖的。但从那以后类似规模的问题我在一小时以内都能给出带证据的结论而不是写没找到相关记录。那三行心虚的说明我到现在还留着。## 相关实现这套做法来自一个本地运行的消息处理工具单机进程、带本地存储、负责把一批批消息按计划投递出去界面就是一个普通的桌面窗口没有服务端集群。它起先只有一份滚动文本日志正是上面这几次事故之后才长出了环形缓冲、UTC 命名规范、独立审计表和限额写入这几块。整套东西的形态很朴素——一个能在你手边把消息按点发出去、并且事后能被自己证明做过什么的小工具。dingdang.asia