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

时间  2019-11-24
标签 交易额 百亿 交易 系统 轻量 日志 实现 繁體版
原文   原文链接

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

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

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

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

特性

虽然 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。你只须要先获取一个实例，接下来的使用方式就很是简单了：maven

//获取单例
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，内部实现了灵活的配置文件加载机制。配置文件加载顺序为：ide

  • 项目根路径
  • 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。

相关文章
相关标签/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公众号
   欢迎关注本站公众号,获取更多信息
联系我们 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程