日交易额百亿级交易系统的超轻量日志实现

首先来聊聊往事吧~~两年前就职于一家传统金融软件公司，为某交易所开发一套大型交易系统，交易标的的价格为流式数据，采用价格触发成交方式，T+0交易制度（类似炒股，只是炒的不是股票而是其他标的物，但可以随时开平仓）。鉴于系统需要记录大量价格数据、交易信息及订单流水，且系统对性能要求极高（敏感度达毫秒级），因此需要避免日志服务成为系统性能瓶颈。通过对几个通用型日志（如log4j、logback）的性能压测，以及考虑到它们作为通用型日志相对比较臃肿，就决定自个儿写个日志工具以支撑系统功能和性能所需。当时的做法只是简单的将日志的实现作为一个 util 类写在项目中，只有几百行的代码量。

系统上线两个月后日均成交额200亿RMB，最高达440亿RMB，峰值成交4000笔/秒。系统非常庞大，但几百行的代码却完美支撑住了重要的日志服务！

鉴于其优秀的表现，就花了一点点时间把它抽取出来作为一个独立的日志组件，取名叫 FLogger，代码几乎没有改动，现已托管到GitHub（FLogger），有兴趣的童鞋可以clone下来了解并改进，目前它的实现是非常简（纯）单（粹）的。

以上就是 FLogger 的诞生背景。好吧，下面进入正题。

特性

虽然 FLogger 只有几百行的代码，但是麻雀虽小五脏俱全，它可是拥有非常丰富的特性呢：

• 双缓冲队列
• 多种刷盘机制，支持时间触发、缓存大小触发、服务关闭强制触发等刷盘方式
• 多种 RollingFile 机制，支持文件大小触发、按天触发等 Rolling 方式
• 多日志级别，支持 debug、info、warn、error和 fatal 等日志级别
• 热加载，由日志事件触发热加载
• 超轻量，不依赖任何第三方库
• 性能保证，成功用于日交易额百亿级交易系统

使用

既然是个超轻量级日志，使用肯定要很简单。为最大程度保持用户的使用习惯，Flogger 提供了与 log4j 几乎一样的日志 API。你只需要先获取一个实例，接下来的使用方式就非常简单了：

Flogger 使用的配置文件名称为 flogger.properties，内部实现了灵活的配置文件加载机制。配置文件加载顺序为：

• 项目根路径
• src/main/resources
• 默认配置

配置项如下：

当然，为了提供最大程度的便捷性，日志内部针对所有配置项都提供了默认值，你大可不必担心缺少配置文件会抛出异常。

至此，你可能很好奇使用 FLogger 打印出来的日志格式到底是怎样的，会不会杂乱无章无法理解，还是信息不全根本无法判断上下文呢？好吧，你多虑了，FLogger 提供了非常规范且实用的日志格式，能使让你很容易理解且找到相关上下文。

先来看看上面的 demo 代码打印出来的结果：

info.log

warn.log

error.log

从上面可以看到，你可以很清楚的分辨出日志的级别、时间和内容等信息。到这其实很明了了，日志由以下几个元素组成：

当然，处于便捷性的考虑，FLogger 目前并不支持用户定义日志格式，毕竟它的目的也不是要做成一个通用性或者可定制性非常高的日志来使用。

源码解析

上面这么多都是围绕如何使用进行说明，下面就针对 FLogger 的特性进行实现逻辑的源码解析。

双缓冲队列

FLogger 在内部采用双缓冲队列，那何为双缓冲队列呢？它的作用又是什么呢？

FLogger 为每个日志文件维护了一个内部对象 LogFileItem ，定义如下：

在每次写日志时，日志内容作为一个 StringBuffer 添加到当前正在使用的 ArrayList<StringBuffer> 中，另一个则空闲。当内存中的日志输出到磁盘文件时，会将当前使用的 ArrayList<StringBuffer> 与空闲的 ArrayList<StringBuffer> 进行角色交换，交换后之前空闲的 ArrayList<StringBuffer> 将接收日志内容，而之前拥有日志内容的 ArrayList<StringBuffer> 则用来输出日志到磁盘文件。这样就可以避免每次刷盘时影响日志内容的接收（即所谓的 stop-the-world 效应）及多线程问题。流程如下：

关键代码如下：

日志接收代码

日志刷盘代码：

多刷盘机制

FLogger 支持多种刷盘机制：

• 刷盘时间间隔触发
• 内存缓冲大小触发
• 退出强制触发

下面就来一一分析。

刷盘时间间隔触发

配置项如下：

当距上次刷盘时间超过间隔时间，将执行内存日志刷盘。

内存缓冲大小触发

配置项如下：

当内存缓冲队列的大小超过配置大小时，将执行内存日志刷盘。

退出强制触发

FLogger 内部注册了 JVM 关闭钩子 ShutdownHook ，当 JVM 正常关闭时，由钩子触发强制刷盘，避免内存日志丢失。相关代码如下：

当 JVM 异常退出时无法保证内存中的日志全部落盘，但可以通过一种妥协的方式来提高日志刷盘的实时度：设置 SINGLE_LOG_CACHE_SIZE = 0 或者 WRITE_LOG_INV_TIME = 0 。

刷盘代码如下：

多 RollingFile 机制

同 log4j/logback，FLogger 也支持多种 RollingFile 机制：

• 按文件大小 Rolling
• 按天 Rolling

其中按文件大小 Rolling，配置项为：

即当文件大小超过配置大小时，将创建新的文件记录日志，同时重命名旧文件为”日志文件名_日期_时间.log”（如 info_20161208_011105.log）。

按天 Rolling 即每天产生不同的文件。

产生的日志文件列表可参考如下：

当前正在写入的日志文件为 info.log。

关键代码如下：

多日志级别

FLogger 支持多种日志级别：

• DEBUG
• INFO
• WARN
• ERROR
• FATAL

FLogger 为每个日志级别都提供了简易 API，在此就不再赘述了。

打印 error 和 fatal 级别日志时，FLogger 默认会将日志内容输出到控制台。

热加载

FLogger 支持热加载，FLogger 内部并没有采用事件驱动方式（即新增、修改和删除配置文件时产生相关事件通知 FLogger 实时热加载），而是以固定频率的方式进行热加载，具体实现就是每执行完100次刷盘后才进行热加载（频率可调），关键代码如下：

这么做完全是为了保持代码的精简和功能的纯粹性。事件驱动热加载无疑是更好的热加载方式，但需要新建额外的线程并启动对配置文件的事件监听，有兴趣的童鞋可自行实现。

性能保证

FLogger 成功支撑了日交易额百亿级交易系统的日志服务，它的性能是经历过考验的。下面我们就来拿 FLogger 跟 log4j 做个简单的性能对比。

测试环境：Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz  3.20 GHz   4.00 GB Memory   64位操作系统

测试场景：单条记录72byte   共1000000条   写单个日志文件

FLogger 配置如下：

以上配置保证所有日志写入到单个文件，且尽量保证每一条记录不在内存中缓存，减少测试误差。

测试代码：

日志内容：