日交易額百億級交易系統的超輕量日志實現
首先來聊聊往事吧~~兩年前就職于一家傳統金融軟件公司，為某交易所開發一套大型交易系統，交易標的的價格為流式數據，采用價格觸發成交方式，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。你只需要先獲取一個實例，接下來的使用方式就非常簡單了：
|
1
2
3
4
5
6
7
8
|
//獲取單例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
- 默認配置
配置項如下：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
|
########## 公共環境配置 ########### 字符集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
|
1
|
[INFO] 2016-12-06 21:07:32:840 [main] Here is your message... |
warn.log
|
1
|
[WARN] 2016-12-06 21:07:32:842 [main] Here is your customized level message... |
error.log
|
1
|
[ERROR] 2016-12-06 21:07:32:842 [main] Here is your customized log file and level message... |
從上面可以看到，你可以很清楚的分辨出日志的級別、時間和內容等信息。到這其實很明了了，日志由以下幾個元素組成：
|
1
|
[日志級別] 精確到毫秒的時間 [當前線程名] 日志內容 |
當然，處于便捷性的考慮，FLogger 目前并不支持用戶定義日志格式，畢竟它的目的也不是要做成一個通用性或者可定制性非常高的日志來使用。
源碼解析
上面這么多都是圍繞如何使用進行說明，下面就針對 FLogger 的特性進行實現邏輯的源碼解析。
雙緩沖隊列
FLogger 在內部采用雙緩沖隊列，那何為雙緩沖隊列呢？它的作用又是什么呢？
FLogger 為每個日志文件維護了一個內部對象 LogFileItem ，定義如下：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
|
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 效應）及多線程問題。流程如下：
關鍵代碼如下：
日志接收代碼
|
1
2
3
4
5
6
7
8
9
|
//同步單個文件的日志synchronized(lfi){ if(lfi.currLogBuff == 'A'){ lfi.alLogBufA.add(logMsg); }else{ lfi.alLogBufB.add(logMsg); } lfi.currCacheSize += CommUtil.StringToBytes(logMsg.toString()).length;} |
日志刷盤代碼：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
|
//獲得需要進行輸出的緩存列表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 支持多種刷盤機制：
- 刷盤時間間隔觸發
- 內存緩沖大小觸發
- 退出強制觸發
下面就來一一分析。
刷盤時間間隔觸發
配置項如下：
|
1
2
|
# 日志寫入文件的間隔時間(默認為1000毫秒)WRITE_LOG_INV_TIME = 1000 |
當距上次刷盤時間超過間隔時間，將執行內存日志刷盤。
內存緩沖大小觸發
配置項如下：
|
1
2
|
# 單個日志文件緩存的大小(默認為10KB)SINGLE_LOG_CACHE_SIZE = 10240 |
當內存緩沖隊列的大小超過配置大小時，將執行內存日志刷盤。
退出強制觸發
FLogger 內部注冊了 JVM 關閉鉤子 ShutdownHook ，當 JVM 正常關閉時，由鉤子觸發強制刷盤，避免內存日志丟失。相關代碼如下：
publicFLogger(){Runtime.getRuntime().addShutdownHook(newThread(newRunnable() {@Overridepublicvoidrun() {close();}}));}當 JVM 異常退出時無法保證內存中的日志全部落盤，但可以通過一種妥協的方式來提高日志刷盤的實時度：設置 SINGLE_LOG_CACHE_SIZE = 0 或者 WRITE_LOG_INV_TIME = 0 。
刷盤代碼如下：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
|
/** 線程方法 */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，配置項為：
|
1
2
|
# 單個日志文件的大小(默認為10M)SINGLE_LOG_FILE_SIZE = 10485760 |
即當文件大小超過配置大小時，將創建新的文件記錄日志，同時重命名舊文件為”日志文件名_日期_時間.log”（如 info_20161208_011105.log）。
按天 Rolling 即每天產生不同的文件。
產生的日志文件列表可參考如下：
info_20161207_101105.loginfo_20161207_122010.loginfo_20161208_011110.loginfo_20161208_015010.loginfo.log當前正在寫入的日志文件為 info.log。
關鍵代碼如下：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
|
/*** 創建日志文件* @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次刷盤后才進行熱加載（頻率可調），關鍵代碼如下：
inti =0;while(bIsRun){try{//等待一定時間Thread.sleep(200);//輸出到文件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 跟 log4j 做個簡單的性能對比。
測試環境：Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz 3.20 GHz 4.00 GB Memory 64位操作系統
測試場景：單條記錄72byte 共1000000條 寫單個日志文件
FLogger 配置如下：
# 日志寫入文件的間隔時間WRITE_LOG_INV_TIME = 0# 單個日志文件的大小SINGLE_LOG_FILE_SIZE = 104857600# 單個日志文件緩存的大小SINGLE_LOG_CACHE_SIZE = 0以上配置保證所有日志寫入到單個文件，且盡量保證每一條記錄不在內存中緩存，減少測試誤差。
測試代碼：
|
1
2
3
4
5
6
7
8
9
|
FLogger logger = FLogger.getInstance(); //FLogger//Logger logger = Logger.getLogger(Log4jTest.class); //log4jString record = "Performance Testing about log4j and cyfonly customized java project log."; //72字節long st = System.currentTimeMillis();for(int i=0; i<1000000; i++){ logger.info(record);}long et = System.currentTimeMillis();System.out.println("FLogger/log4j write 1000000 records with each record 72 bytes, cost :" + (et - st) + " millseconds"); |
日志內容：
|
1
2
3
4
5
|
FLogger:[INFO] 2016-12-06 21:40:06:842 [main] Performance Testing about log4j and cyfonly customized java project log.log4j:[INFO ]2016-12-06 21:41:12,852, [main]Log4jTest:12, Performance Testing about log4j and cyfonly customized java project log. |
測試結果（執行10次取平均值）：
|
1
2
|
FLogger write 1000000 records with each record 72 bytes, cost :2144 millsecondslog4j write 1000000 records with each record 72 bytes, cost :cost :12691 millseconds |
說明：測試結果為日志全部刷盤成功的修正時間，加上各種環境的影響，有少許誤差，在此僅做簡單測試，并不是最嚴格最公平的測試對比。有興趣的童鞋可進行精確度更高的測試。
