日交易额百亿级交易系统的超轻量日志实现
首先来聊聊往事吧~~两年前就职于一家传统金融软件公司，为某交易所开发一套大型交易系统，交易标的的价格为流式数据，采用价格触发成交方式，T+0交易制度（类似炒股，只是炒的不是股票而是其他标的物，但可以随时开平仓）。鉴于系统需要记录大量价格数据、交易信息及订单流水，且系统对性能要求极高（敏感度达毫秒级），因此需要避免日志服务成为系统性能瓶颈。通过对几个通用型日志（如log4j、logback）的性能压测，以及考虑到它们作为通用型日志相对比较臃肿，就决定自个儿写个日志工具以支撑系统功能和性能所需。当时的做法只是简单的将日志的实现作为一个 util 类写在项目中，只有几百行的代码量。
系统上线两个月后日均成交额200亿RMB，最高达440亿RMB，峰值成交4000笔/秒。系统非常庞大，但几百行的代码却完美支撑住了重要的日志服务！
鉴于其优秀的表现，就花了一点点时间把它抽取出来作为一个独立的日志组件，取名叫 FLogger，代码几乎没有改动，现已托管到GitHub（FLogger），有兴趣的童鞋可以clone下来了解并改进，目前它的实现是非常简（纯）单（粹）的。
以上就是 FLogger 的诞生背景。好吧，下面进入正题。
特性
虽然 FLogger 只有几百行的代码，但是麻雀虽小五脏俱全，它可是拥有非常丰富的特性呢：
- 双缓冲队列
- 多种刷盘机制，支持时间触发、缓存大小触发、服务关闭强制触发等刷盘方式
- 多种 RollingFile 机制，支持文件大小触发、按天触发等 Rolling 方式
- 多日志级别，支持 debug、info、warn、error和 fatal 等日志级别
- 热加载，由日志事件触发热加载
- 超轻量，不依赖任何第三方库
- 性能保证，成功用于日交易额百亿级交易系统
使用
FLogger 已经发布到 maven 公共仓库（版本更新信息请点此查看），请添加以下依赖（或直接在项目中引用 jar 包）：
<dependency>
<groupId>com.github.cyfonly</groupId>
<artifactId>flogger</artifactId>
<version>1.0.2</version>
</dependency>
既然是个超轻量级日志，使用肯定要很简单。为最大程度保持用户的使用习惯，Flogger 提供了与 log4j 几乎一样的日志 API。你只需要先获取一个实例，接下来的使用方式就非常简单了：
//获取单例
FLogger logger = FLogger.getInstance();
//简便api,只需指定内容
logger.info("Here is your message...");
//指定日志级别和内容，文件名自动映射
logger.writeLog(Constant.INFO, "Here is your customized level message...");
//指定日志输出文件名、日志级别和内容
logger.writeLog("error", Constant.ERROR, "Here is your customized log file and level message...");
Flogger 使用的配置文件名称为 flogger.properties，内部实现了灵活的配置文件加载机制。配置文件加载顺序为：
- 项目根路径
- src/main/resources
- 默认配置
配置项如下：
########## 公共环境配置 ########## # 字符集 CHARSET_NAME = UTF-8 ########## 日志信息配置 ########## # 日志级别 0:调试信息 1:普通信息 2:警告信息 3:错误信息 4:严重错误信息 LOG_LEVEL = 0,1,2,3,4 # 日志文件存放路径 LOG_PATH =./log # 日志写入文件的间隔时间(默认为1000毫秒) WRITE_LOG_INV_TIME = 1000 # 单个日志文件的大小(默认为10M) SINGLE_LOG_FILE_SIZE = 10485760 # 单个日志文件缓存的大小(默认为10KB) SINGLE_LOG_CACHE_SIZE = 10240
当然，为了提供最大程度的便捷性，日志内部针对所有配置项都提供了默认值，你大可不必担心缺少配置文件会抛出异常。
至此，你可能很好奇使用 FLogger 打印出来的日志格式到底是怎样的，会不会杂乱无章无法理解，还是信息不全根本无法判断上下文呢？好吧，你多虑了，FLogger 提供了非常规范且实用的日志格式，能使让你很容易理解且找到相关上下文。
先来看看上面的 demo 代码打印出来的结果：
info.log
[INFO] 2016-12-06 21:07:32:840 [main] Here is your message...
warn.log
[WARN] 2016-12-06 21:07:32:842 [main] Here is your customized level message...
error.log
[ERROR] 2016-12-06 21:07:32:842 [main] Here is your customized log file and level message...
从上面可以看到，你可以很清楚的分辨出日志的级别、时间和内容等信息。到这其实很明了了，日志由以下几个元素组成：
[日志级别] 精确到毫秒的时间 [当前线程名] 日志内容
当然，处于便捷性的考虑，FLogger 目前并不支持用户定义日志格式，毕竟它的目的也不是要做成一个通用性或者可定制性非常高的日志来使用。
源码解析
上面这么多都是围绕如何使用进行说明，下面就针对 FLogger 的特性进行实现逻辑的源码解析。
双缓冲队列
FLogger 在内部采用双缓冲队列，那何为双缓冲队列呢？它的作用又是什么呢？
FLogger 为每个日志文件维护了一个内部对象 LogFileItem ，定义如下：
public class LogFileItem {
/** 不包括路径，不带扩展名的日志文件名称 如：MsgInner */
public String logFileName = "";
/** 包括路径的完整日志名称 */
public String fullLogFileName = "";
/** 当前日志文件大小 */
public long currLogSize = 0;
/** 当前正在使用的日志缓存 */
public char currLogBuff = 'A';
/** 日志缓冲列表A */
public ArrayList<StringBuffer> alLogBufA = new ArrayList<StringBuffer>();
/** 日志缓冲列表B */
public ArrayList<StringBuffer> alLogBufB = new ArrayList<StringBuffer>();
/** 下次日志输出到文件时间 */
public long nextWriteTime = 0 ;
/** 上次写入时的日期 */
public String lastPCDate = "";
/** 当前已缓存大小 */
public long currCacheSize = 0;
}
在每次写日志时，日志内容作为一个 StringBuffer 添加到当前正在使用的 ArrayList<StringBuffer> 中，另一个则空闲。当内存中的日志输出到磁盘文件时，会将当前使用的 ArrayList<StringBuffer> 与空闲的 ArrayList<StringBuffer> 进行角色交换，交换后之前空闲的 ArrayList<StringBuffer> 将接收日志内容，而之前拥有日志内容的 ArrayList<StringBuffer> 则用来输出日志到磁盘文件。这样就可以避免每次刷盘时影响日志内容的接收（即所谓的 stop-the-world 效应）及多线程问题。流程如下：
关键代码如下：
日志接收代码
//同步单个文件的日志
synchronized(lfi){
if(lfi.currLogBuff == 'A'){
lfi.alLogBufA.add(logMsg);
}else{
lfi.alLogBufB.add(logMsg);
}
lfi.currCacheSize += CommUtil.StringToBytes(logMsg.toString()).length;
}
日志刷盘代码：
//获得需要进行输出的缓存列表
ArrayList<StringBuffer> alWrtLog = null;
synchronized(lfi){
if(lfi.currLogBuff == 'A'){
alWrtLog = lfi.alLogBufA;
lfi.currLogBuff = 'B';
}else{
alWrtLog = lfi.alLogBufB;
lfi.currLogBuff = 'A';
}
lfi.currCacheSize = 0;
}
//创建日志文件
createLogFile(lfi);
//输出日志
int iWriteSize = writeToFile(lfi.fullLogFileName,alWrtLog);
lfi.currLogSize += iWriteSize;
多刷盘机制
FLogger 支持多种刷盘机制：
- 刷盘时间间隔触发
- 内存缓冲大小触发
- 退出强制触发
下面就来一一分析。
刷盘时间间隔触发
配置项如下：
# 日志写入文件的间隔时间(默认为1000毫秒) WRITE_LOG_INV_TIME = 1000
当距上次刷盘时间超过间隔时间，将执行内存日志刷盘。
内存缓冲大小触发
配置项如下：
# 单个日志文件缓存的大小(默认为10KB) SINGLE_LOG_CACHE_SIZE = 10240
当内存缓冲队列的大小超过配置大小时，将执行内存日志刷盘。
退出强制触发
FLogger 内部注册了 JVM 关闭钩子 ShutdownHook ，当 JVM 正常关闭时，由钩子触发强制刷盘，避免内存日志丢失。相关代码如下：
public FLogger(){
Runtime.getRuntime().addShutdownHook(new Thread(new Runnable() {
@Override
public void run() {
close();
}
}));
}
当 JVM 异常退出时无法保证内存中的日志全部落盘，但可以通过一种妥协的方式来提高日志刷盘的实时度：设置 SINGLE_LOG_CACHE_SIZE = 0 或者 WRITE_LOG_INV_TIME = 0 。
刷盘代码如下：
/** 线程方法 */
public void run(){
int i = 0 ;
while(bIsRun){
try{
//输出到文件
flush(false);
//重新获取日志级别
if(i++ % 100 == 0){
Constant.CFG_LOG_LEVEL = CommUtil.getConfigByString("LOG_LEVEL","0,1,2,3,4");
i = 1;
}
}catch(Exception e){
System.out.println("开启日志服务错误...");
e.printStackTrace();
}
}
}
/** 关闭方法 */
public void close(){
bIsRun = false;
try{
flush(true);
}catch(Exception e){
System.out.println("关闭日志服务错误...");
e.printStackTrace();
}
}
/**
* 输出缓存的日志到文件
* @param bIsForce 是否强制将缓存中的日志输出到文件
*/
private void flush(boolean bIsForce) throws IOException{
long currTime = System.currentTimeMillis();
Iterator<String> iter = logFileMap.keySet().iterator();
while(iter.hasNext()){
LogFileItem lfi = logFileMap.get(iter.next());
if(currTime >= lfi.nextWriteTime || SINGLE_LOG_CACHE_SIZE <= lfi.currCacheSize || bIsForce == true){
//获得需要进行输出的缓存列表
ArrayList<StringBuffer> alWrtLog = null;
synchronized(lfi){
if(lfi.currLogBuff == 'A'){
alWrtLog = lfi.alLogBufA;
lfi.currLogBuff = 'B';
}else{
alWrtLog = lfi.alLogBufB;
lfi.currLogBuff = 'A';
}
lfi.currCacheSize = 0;
}
//创建日志文件
createLogFile(lfi);
//输出日志
int iWriteSize = writeToFile(lfi.fullLogFileName,alWrtLog);
lfi.currLogSize += iWriteSize;
}
}
}
多 RollingFile 机制
同 log4j/logback，FLogger 也支持多种 RollingFile 机制：
- 按文件大小 Rolling
- 按天 Rolling
其中按文件大小 Rolling，配置项为：
# 单个日志文件的大小(默认为10M) SINGLE_LOG_FILE_SIZE = 10485760
即当文件大小超过配置大小时，将创建新的文件记录日志，同时重命名旧文件为"日志文件名_日期_时间.log"（如 info_20161208_011105.log）。
按天 Rolling 即每天产生不同的文件。
产生的日志文件列表可参考如下：
info_20161207_101105.log info_20161207_122010.log info_20161208_011110.log info_20161208_015010.log info.log
当前正在写入的日志文件为 info.log。
关键代码如下：
/**
* 创建日志文件
* @param lfi
*/
private void createLogFile(LogFileItem lfi){
//当前系统日期
String currPCDate = TimeUtil.getPCDate('-');
//如果超过单个文件大小，则拆分文件
if(lfi.fullLogFileName != null && lfi.fullLogFileName.length() > 0 && lfi.currLogSize >= LogManager.SINGLE_LOG_FILE_SIZE ){
File oldFile = new File(lfi.fullLogFileName);
if(oldFile.exists()){
String newFileName = Constant.CFG_LOG_PATH + "/" + lfi.lastPCDate + "/" + lfi.logFileName + "_" + TimeUtil.getPCDate() + "_"+ TimeUtil.getCurrTime() + ".log";
File newFile = new File(newFileName);
boolean flag = oldFile.renameTo(newFile);
System.out.println("日志已自动备份为 " + newFile.getName() + ( flag ? "成功!" : "失败!" ) );
lfi.fullLogFileName = "";
lfi.currLogSize = 0;
}
}
//创建文件
if ( lfi.fullLogFileName == null || lfi.fullLogFileName.length() <= 0 || lfi.lastPCDate.equals(currPCDate) == false ){
String sDir = Constant.CFG_LOG_PATH + "/" + currPCDate ;
File file = new File(sDir);
if(file.exists() == false){
file.mkdir();
}
lfi.fullLogFileName = sDir + "/" + lfi.logFileName + ".log";
lfi.lastPCDate = currPCDate;
file = new File(lfi.fullLogFileName);
if(file.exists()){
lfi.currLogSize = file.length();
}else{
lfi.currLogSize = 0;
}
}
}
多日志级别
FLogger 支持多种日志级别：
- DEBUG
- INFO
- WARN
- ERROR
- FATAL
FLogger 为每个日志级别都提供了简易 API，在此就不再赘述了。
打印 error 和 fatal 级别日志时，FLogger 默认会将日志内容输出到控制台。
热加载
FLogger 支持热加载，FLogger 内部并没有采用事件驱动方式（即新增、修改和删除配置文件时产生相关事件通知 FLogger 实时热加载），而是以固定频率的方式进行热加载，具体实现就是每执行完100次刷盘后才进行热加载（频率可调），关键代码如下：
int i = 0;
while(bIsRun){
try{
//输出到文件
flush(false);
//重新获取日志级别
if(i++ % 100 == 0){
Constant.CFG_LOG_LEVEL = CommUtil.getConfigByString("LOG_LEVEL","0,1,2,3,4");
//其他配置项热加载......
i = 1;
}
}catch(Exception e){
System.out.println("开启日志服务错误...");
e.printStackTrace();
}
}
这么做完全是为了保持代码的精简和功能的纯粹性。事件驱动热加载无疑是更好的热加载方式，但需要新建额外的线程并启动对配置文件的事件监听，有兴趣的童鞋可自行实现。
性能保证
FLogger 成功支撑了日交易额百亿级交易系统的日志服务，它的性能和稳定性是经历过考验的。为更加直观地展示 FLogger 的性能，此处对其吞吐量进行测试。
首先确定测试场景：
线程数：1,2,4,8,16,32 日志内容主体大小：100bytes, 200bytes, 400bytes
接着配置参数（未列出配置项使用默认值）：
# 日志写入文件的间隔时间(1000毫秒) WRITE_LOG_INV_TIME = 1000 # 单个日志文件的大小(100M) SINGLE_LOG_FILE_SIZE = 104857600 # 单个日志文件缓存的大小(100KB) SINGLE_LOG_CACHE_SIZE = 102400
然后编写测试代码（查看源码），如下：
private static FLogger flogger = FLogger.getInstance();
private static String record_100_byte = "Performance Testing.Performance Testing.Performance Testing.Performance Testing.Performance Testing."; //100字节
private static String record_200_byte = "..."; //200字节，为方便展示此处以"..."代替
private static String record_400_byte = "..."; //400字节，为方便展示此处以"..."代替
private static AtomicInteger messageCount = new AtomicInteger(0);
private static int count = 1000000; //基准数值，以messageCount为准
private static int threadNum = 1; //1,2,4,8,16,32
public static void main(String[] args) throws InterruptedException{
final CountDownLatch latch = new CountDownLatch(threadNum);
long st = System.currentTimeMillis();
for(int i=0; i<threadNum; i++){
new Thread(new Runnable() {
@Override
public void run() {
while(messageCount.get() < count){
flogger.info(record_400_byte);
messageCount.incrementAndGet();
}
latch.countDown();
}
}).start();
}
latch.await();
long et = System.currentTimeMillis();
System.out.println("messageCount=" + messageCount.get() + ", threadNum=" + threadNum + ", costTime=" + (et-st) +"ms, throughput=" + (1*1000*messageCount.get()/(et-st)));
System.exit(0);
}
每个测试场景在保证相同测试环境（不可控因素除外）的情况下，均进行10次测试并采用平均值作为最终结果，如下：
如对测试方法及结果有疑问、建议或异议，欢迎通过评论或私下交流，本人QQ：869827095。
