关于根据业务的Key,对日志进行拆分的必要性,在之前文章 数据库只存结果,日志才是过程 已经说过,这里就不再展开了。
简单来说就是按业务Key,如:(玩家、租户、订单)把日志分发到不同文件,每个业务对象拥有自己的日志。排查时直接打开对应文件,不用 grep,不用拼上下文,直观方便。
最直接的实现:Key 映射文件
// 伪代码,仅说明思路
Writer writer = writers.get(key);
if (writer == null) {
writer = createWriter(key);
writers.put(key, writer);
}
writer.write(event);
一个 Map,Key 对应一个文件,每次写日志时查找或创建。在 Key 数量较少的时候,这种方案确实没有什么问题,但真正放到线上环境后,情况会完全不同。
先不说是否有几十万玩家同时在线时,即使是几万玩家,每个玩家一个 Key,Map的查找与创建效率就会明显降低。
而且这里还忽略了一个重要问题:谁负责写入这个文件,以及如何保证同一个 Key 内的顺序。
日志是有顺序的
日志不是普通文本,很大程度上,它承担着记录一个业务对象的经历,比如状态变化、操作过程、事件轨迹等。这些记录都需要有一个时间顺序。例如:
10:00:01 玩家登录
10:00:02 玩家进入匹配
10:00:03 匹配成功,进入战斗
10:00:05 释放技能
10:00:06 技能结算完成
10:00:08 战斗结束
当需要排查问题时,肯定是需要这条时间线,来定位问题的出处。但如果输出变成这样:
10:00:06 技能结算完成
10:00:03 匹配成功,进入战斗
10:00:05 释放技能
数据在展示时顺序乱了,不直观,还容易排查出错。这种事不能寄望于事后排序,肯定需要在产生时就是有序的。
另外如果日志是不同线程写入的,就有可能出现虽然日志的产生是顺序的,但由于写入时是不同线程,因此导致看到的顺序依然是乱的。
所以我认为在实现上,一个最基本且重要的约束应该是:同一个业务 Key 的日志,必须保持写入顺序。
一个 Key 一个线程看起来简单,但实际无人会这么做
player-1001 → thread-1 → file-1001.log
player-1002 → thread-2 → file-1002.log
player-1003 → thread-3 → file-1003.log
...
Key 之间互不干扰,天然并行,顺序也能保证。但是只要有一定开发经验的人都知道,这个是完全不可行的。因为 key 的数量一定会很多,线程数量无法得到控制。
如果每个 Key 一个线程:
- 线程数量爆炸,线程切换成本远超写入本身
- 如果每个 Key 都维护独立的写入上下文,最终仍然需要管理大量文件句柄、缓冲区等资源
- 内存中维护大量线程栈和缓冲区,GC 压力剧增
这种做法最终只为消耗大量cpu开销,效率反而降低。
那如果所有日志一个线程呢
既然每个 Key 一个线程不行,那反过来:所有 Key 的日志共用一个写入线程。
其实最开始实现时,我也是这么做的,但新问题很快就出现了。举个常用的例子,多数项目都会有 info 级别的全局日志,这个通常都属于热Key。在单线程模型下,这个热Key的日志会占据写入线程的大部分时间。其他玩家的日志虽然在队列里,但必须等热 Key 写完才能被处理。 即使这个热键在写入队列中不是连续的,但反复的文件句柄切换同样降低写入效率。
这里就出现了一个矛盾,全局顺序与Key内顺序的同时满足。单线程模型解决了全局顺序问题,但牺牲了不同业务对象之间的并行能力。
所以我们最终需要的,其实是:同一个Key内部保持顺序,不同Key之间可以并行。
顺着这个思路,我设计了一个初步的方案,使用固定的线程数,然后将不同键值做hash取余处理,这样即可以保证key 的顺序,也保留一定的并行能力。
刚刚提及了一个问题,就是文件切换
是的,同一线程内,热键必然不是连续的,这样就会出现文件句柄切换带来的效率问题。
第一时间想到的就是缓存解决。将已经打开的文件句柄,以对应的Key进行映射保存,等下次再需要请求时,就可以直接写入。但问题是系统能打开的文件数是有限制的,所以这里也需要同时引入类似LRU的淘汰机制。
最终大致的流程大概如下:
新 Key 请求写入
↓
缓存未命中
↓
需要打开新文件
↓
但缓存已满,必须淘汰一个旧文件
↓
flush 旧文件缓冲区
↓
关闭 FileChannel
↓
释放文件描述符
↓
创建新文件,打开新 Channel
↓
写入
当方案实现后,却发现真正重要的问题
为了更接近真正的运行环境,我设置了最大文件打开数是205,并做了第一次基准测试,这里先贴一下测试的数据和数据说明:
Files Touched:文件打开数 Flushes:文件刷盘数(真正写入到系统Page) Writes:写入到文件Buffer Rejected:因为文件打开数达到上限,触发LRU淘汰的次数 IO:每秒写入硬盘的容量(实际是写入到Page)
| Key 数量 | Files Touched | Flushes/sec | Writes/sec | Rejected/sec | IO MB/sec |
|---|---|---|---|---|---|
| 200 | 0 | 88 | 14,036 | 0 | 28.36 |
| 210 | 1,327 | 1,378 | 8,595 | 9,976 | 16.11 |
| 220 | 2,034 | 2,034 | 4,687 | 11,453 | 7.42 |
从以上可以看到,Key 的数量增加后,系统并不是简单地线性下降,而是断岸式的。当Key的数量从 200 增加到 210 时,Files Touched 从 0 跳升到 1,327,同时 Rejected 从 0 一下升到 9,976,说明活跃 Key 开始超过缓存有效覆盖范围,大量日志目标无法持续复用已有写入资源,开始进入淘汰处理。
而随着淘汰次数的增加,文件切换也肯定上升,最终会看到 Flushes 次数从 88 涨到 1,378 ,而 Writes 和 IO 这些体现写入吞吐能力的值,直接下降到 8,595 和 16.11,几乎腰斩。之后当Key的数达到 220 时,情况进一步恶化。
通过这个测试,我们可以看到以下一个问题链:
Key 数量增加
↓
打开的文件无法持续复用,Channel 缓存命中下降
↓
文件切换(打开/关闭)频率上升
↓
flush / close 操作增加
↓
写入路径上的阻塞增多
↓
写入的吞吐下降
↓
队列开始积压
↓
延迟上升
活跃Key数量的增加,对最终的日志处理的吞吐量,以及写入延迟造成的极大的影响。
而且这种影响,哪怕我们用最好的淘汰策略,效果也未必很好。因为在淘汰的过程中,旧文件的flush,重新打开文件,注入缓存,这些都是需要占用cpu与资源的,也需要产生一定的代价。
仍然存在的物理边界
到这里,即使解决了文件句柄问题,最终还是需要面对存储系统本身的限制。
日志最终还是要写到磁盘上。当日志产生速度持续大于存储消费速度,任何缓冲和优化都只能延缓问题,不能消除它。
这不是某个实现方案的问题,而是所有日志系统共同面对的边界。
或者这个就是为什么 logback/log4j2 一直不做按业务 Key 来拆分日志功能的原因之一。
最后
其实到这里才发现,按业务 Key 路由拆分日志,本质上已经不是一个 Appender 或 Writer 的问题。它涉及:
- 顺序并行:在多 Key 并行写入时保证单个 Key 的顺序
- 文件管理:基于缓存管理大量文件的打开和关闭
- 资源控制:如何在有限资源下做淘汰决策
- IO的硬件边界:磁盘的物理限制下最大化写入效率
这些问题每一项单独拿出来都不算特别复杂,但当它们同时出现在一个系统里,而且互相约束、互相影响时,设计难度就完全不同了。
按 Key 分离日志,看似只是改变日志输出位置,实际上改变的是整个日志系统面对业务过程的方式。
但是我始终认为这种改变,还是有必要的,肯定还有很多需要用到的场景。而且先不说未来硬件的限制突破,哪怕是现在也可以有限的资源内,尽可能提高吞吐,降低延迟的方法。