当日志按业务 Key 拆分后,我们到底会遇到什么问题?

45 阅读8分钟

关于根据业务的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 TouchedFlushes/secWrites/secRejected/secIO MB/sec
20008814,036028.36
2101,3271,3788,5959,97616.11
2202,0342,0344,68711,4537.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 分离日志,看似只是改变日志输出位置,实际上改变的是整个日志系统面对业务过程的方式。

但是我始终认为这种改变,还是有必要的,肯定还有很多需要用到的场景。而且先不说未来硬件的限制突破,哪怕是现在也可以有限的资源内,尽可能提高吞吐,降低延迟的方法。

下一篇继续聊这些约束下的一种设计思路,以及为什么最终选择怎么样的执行模型。