日交易額百億級(jí)交易系統(tǒng)的超輕量日志實(shí)現(xiàn)
首先來聊聊往事吧~~兩年前就職于一家傳統(tǒng)金融軟件公司，為某交易所開發(fā)一套大型交易系統(tǒng)，交易標(biāo)的的價(jià)格為流式數(shù)據(jù)，采用價(jià)格觸發(fā)成交方式，T+0交易制度（類似炒股，只是炒的不是股票而是其他標(biāo)的物，但可以隨時(shí)開平倉(cāng)）。鑒于系統(tǒng)需要記錄大量?jī)r(jià)格數(shù)據(jù)、交易信息及訂單流水，且系統(tǒng)對(duì)性能要求極高（敏感度達(dá)毫秒級(jí)），因此需要避免日志服務(wù)成為系統(tǒng)性能瓶頸。通過對(duì)幾個(gè)通用型日志（如log4j、logback）的性能壓測(cè)，以及考慮到它們作為通用型日志相對(duì)比較臃腫，就決定自個(gè)兒寫個(gè)日志工具以支撐系統(tǒng)功能和性能所需。當(dāng)時(shí)的做法只是簡(jiǎn)單的將日志的實(shí)現(xiàn)作為一個(gè) util 類寫在項(xiàng)目中，只有幾百行的代碼量。
系統(tǒng)上線兩個(gè)月后日均成交額200億RMB，***達(dá)440億RMB，峰值成交4000筆/秒。系統(tǒng)非常龐大，但幾百行的代碼卻***支撐住了重要的日志服務(wù)！
鑒于其優(yōu)秀的表現(xiàn)，就花了一點(diǎn)點(diǎn)時(shí)間把它抽取出來作為一個(gè)獨(dú)立的日志組件，取名叫 FLogger，代碼幾乎沒有改動(dòng)，現(xiàn)已托管到GitHub（FLogger），有興趣的童鞋可以clone下來了解并改進(jìn)，目前它的實(shí)現(xiàn)是非常簡(jiǎn)（純）單（粹）的。
以上就是 FLogger 的誕生背景。好吧，下面進(jìn)入正題。
特性
雖然 FLogger 只有幾百行的代碼，但是麻雀雖小五臟俱全，它可是擁有非常豐富的特性呢：
- 雙緩沖隊(duì)列
- 多種刷盤機(jī)制，支持時(shí)間觸發(fā)、緩存大小觸發(fā)、服務(wù)關(guān)閉強(qiáng)制觸發(fā)等刷盤方式
- 多種 RollingFile 機(jī)制，支持文件大小觸發(fā)、按天觸發(fā)等 Rolling 方式
- 多日志級(jí)別，支持 debug、info、warn、error和 fatal 等日志級(jí)別
- 熱加載，由日志事件觸發(fā)熱加載
- 超輕量，不依賴任何第三方庫(kù)
- 性能保證，成功用于日交易額百億級(jí)交易系統(tǒng)
使用
既然是個(gè)超輕量級(jí)日志，使用肯定要很簡(jiǎn)單。為***程度保持用戶的使用習(xí)慣，F(xiàn)logger 提供了與 log4j 幾乎一樣的日志 API。你只需要先獲取一個(gè)實(shí)例，接下來的使用方式就非常簡(jiǎn)單了：
|
1
2
3
4
5
6
7
8
|
//獲取單例FLogger logger = FLogger.getInstance();//簡(jiǎn)便api,只需指定內(nèi)容logger.info("Here is your message...");//指定日志級(jí)別和內(nèi)容，文件名自動(dòng)映射logger.writeLog(Constant.INFO, "Here is your customized level message...");//指定日志輸出文件名、日志級(jí)別和內(nèi)容logger.writeLog("error", Constant.ERROR, "Here is your customized log file and level message..."); |
Flogger 使用的配置文件名稱為 flogger.properties，內(nèi)部實(shí)現(xiàn)了靈活的配置文件加載機(jī)制。配置文件加載順序?yàn)椋?/p>
- 項(xiàng)目根路徑
- src/main/resources
- 默認(rèn)配置
配置項(xiàng)如下：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
|
########## 公共環(huán)境配置 ########### 字符集CHARSET_NAME = UTF-8########## 日志信息配置 ########### 日志級(jí)別 0:調(diào)試信息 1:普通信息 2:警告信息 3:錯(cuò)誤信息 4:嚴(yán)重錯(cuò)誤信息LOG_LEVEL = 0,1,2,3,4# 日志文件存放路徑LOG_PATH =./log# 日志寫入文件的間隔時(shí)間(默認(rèn)為1000毫秒)WRITE_LOG_INV_TIME = 1000# 單個(gè)日志文件的大小(默認(rèn)為10M)SINGLE_LOG_FILE_SIZE = 10485760# 單個(gè)日志文件緩存的大小(默認(rèn)為10KB)SINGLE_LOG_CACHE_SIZE = 10240 |
當(dāng)然，為了提供***程度的便捷性，日志內(nèi)部針對(duì)所有配置項(xiàng)都提供了默認(rèn)值，你大可不必?fù)?dān)心缺少配置文件會(huì)拋出異常。
至此，你可能很好奇使用 FLogger 打印出來的日志格式到底是怎樣的，會(huì)不會(huì)雜亂無章無法理解，還是信息不全根本無法判斷上下文呢？好吧，你多慮了，F(xiàn)Logger 提供了非常規(guī)范且實(shí)用的日志格式，能使讓你很容易理解且找到相關(guān)上下文。
先來看看上面的 demo 代碼打印出來的結(jié)果：
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... |
從上面可以看到，你可以很清楚的分辨出日志的級(jí)別、時(shí)間和內(nèi)容等信息。到這其實(shí)很明了了，日志由以下幾個(gè)元素組成：
|
1
|
[日志級(jí)別] 精確到毫秒的時(shí)間 [當(dāng)前線程名] 日志內(nèi)容 |
當(dāng)然，處于便捷性的考慮，F(xiàn)Logger 目前并不支持用戶定義日志格式，畢竟它的目的也不是要做成一個(gè)通用性或者可定制性非常高的日志來使用。
源碼解析
上面這么多都是圍繞如何使用進(jìn)行說明，下面就針對(duì) FLogger 的特性進(jìn)行實(shí)現(xiàn)邏輯的源碼解析。
雙緩沖隊(duì)列
FLogger 在內(nèi)部采用雙緩沖隊(duì)列，那何為雙緩沖隊(duì)列呢？它的作用又是什么呢？
FLogger 為每個(gè)日志文件維護(hù)了一個(gè)內(nèi)部對(duì)象 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 { /** 不包括路徑，不帶擴(kuò)展名的日志文件名稱 如：MsgInner */ public String logFileName = ""; /** 包括路徑的完整日志名稱 */ public String fullLogFileName = ""; /** 當(dāng)前日志文件大小 */ public long currLogSize = 0; /** 當(dāng)前正在使用的日志緩存 */ public char currLogBuff = 'A'; /** 日志緩沖列表A */ public ArrayList<StringBuffer> alLogBufA = new ArrayList<StringBuffer>(); /** 日志緩沖列表B */ public ArrayList<StringBuffer> alLogBufB = new ArrayList<StringBuffer>(); /** 下次日志輸出到文件時(shí)間 */ public long nextWriteTime = 0 ; /** 上次寫入時(shí)的日期 */ public String lastPCDate = ""; /** 當(dāng)前已緩存大小 */ public long currCacheSize = 0;} |
在每次寫日志時(shí)，日志內(nèi)容作為一個(gè) StringBuffer 添加到當(dāng)前正在使用的 ArrayList<StringBuffer> 中，另一個(gè)則空閑。當(dāng)內(nèi)存中的日志輸出到磁盤文件時(shí)，會(huì)將當(dāng)前使用的 ArrayList<StringBuffer> 與空閑的 ArrayList<StringBuffer> 進(jìn)行角色交換，交換后之前空閑的 ArrayList<StringBuffer> 將接收日志內(nèi)容，而之前擁有日志內(nèi)容的 ArrayList<StringBuffer> 則用來輸出日志到磁盤文件。這樣就可以避免每次刷盤時(shí)影響日志內(nèi)容的接收（即所謂的 stop-the-world 效應(yīng)）及多線程問題。流程如下：
關(guān)鍵代碼如下：
日志接收代碼
|
1
2
3
4
5
6
7
8
9
|
//同步單個(gè)文件的日志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
|
//獲得需要進(jìn)行輸出的緩存列表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;}//創(chuàng)建日志文件createLogFile(lfi);//輸出日志int iWriteSize = writeToFile(lfi.fullLogFileName,alWrtLog);lfi.currLogSize += iWriteSize; |
多刷盤機(jī)制
FLogger 支持多種刷盤機(jī)制：
- 刷盤時(shí)間間隔觸發(fā)
- 內(nèi)存緩沖大小觸發(fā)
- 退出強(qiáng)制觸發(fā)
下面就來一一分析。
刷盤時(shí)間間隔觸發(fā)
配置項(xiàng)如下：
|
1
2
|
# 日志寫入文件的間隔時(shí)間(默認(rèn)為1000毫秒)WRITE_LOG_INV_TIME = 1000 |
當(dāng)距上次刷盤時(shí)間超過間隔時(shí)間，將執(zhí)行內(nèi)存日志刷盤。
內(nèi)存緩沖大小觸發(fā)
配置項(xiàng)如下：
|
1
2
|
# 單個(gè)日志文件緩存的大小(默認(rèn)為10KB)SINGLE_LOG_CACHE_SIZE = 10240 |
當(dāng)內(nèi)存緩沖隊(duì)列的大小超過配置大小時(shí)，將執(zhí)行內(nèi)存日志刷盤。
退出強(qiáng)制觸發(fā)
FLogger 內(nèi)部注冊(cè)了 JVM 關(guān)閉鉤子 ShutdownHook ，當(dāng) JVM 正常關(guān)閉時(shí)，由鉤子觸發(fā)強(qiáng)制刷盤，避免內(nèi)存日志丟失。相關(guān)代碼如下：
publicFLogger(){Runtime.getRuntime().addShutdownHook(newThread(newRunnable() {@Overridepublicvoidrun() {close();}}));}當(dāng) JVM 異常退出時(shí)無法保證內(nèi)存中的日志全部落盤，但可以通過一種妥協(xié)的方式來提高日志刷盤的實(shí)時(shí)度：設(shè)置 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); //重新獲取日志級(jí)別 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("開啟日志服務(wù)錯(cuò)誤..."); e.printStackTrace(); } }}/** 關(guān)閉方法 */public void close(){ bIsRun = false; try{ flush(true); }catch(Exception e){ System.out.println("關(guān)閉日志服務(wù)錯(cuò)誤..."); e.printStackTrace(); }}/*** 輸出緩存的日志到文件* @param bIsForce 是否強(qiáng)制將緩存中的日志輸出到文件*/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){ //獲得需要進(jìn)行輸出的緩存列表 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; } //創(chuàng)建日志文件 createLogFile(lfi); //輸出日志 int iWriteSize = writeToFile(lfi.fullLogFileName,alWrtLog); lfi.currLogSize += iWriteSize; } } } |
多 RollingFile 機(jī)制
同 log4j/logback，F(xiàn)Logger 也支持多種 RollingFile 機(jī)制：
- 按文件大小 Rolling
- 按天 Rolling
其中按文件大小 Rolling，配置項(xiàng)為：
|
1
2
|
# 單個(gè)日志文件的大小(默認(rèn)為10M)SINGLE_LOG_FILE_SIZE = 10485760 |
即當(dāng)文件大小超過配置大小時(shí)，將創(chuàng)建新的文件記錄日志，同時(shí)重命名舊文件為”日志文件名_日期_時(shí)間.log”（如 info_20161208_011105.log）。
按天 Rolling 即每天產(chǎn)生不同的文件。
產(chǎn)生的日志文件列表可參考如下：
info_20161207_101105.loginfo_20161207_122010.loginfo_20161208_011110.loginfo_20161208_015010.loginfo.log當(dāng)前正在寫入的日志文件為 info.log。
關(guān)鍵代碼如下：
|
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
|
/*** 創(chuàng)建日志文件* @param lfi*/private void createLogFile(LogFileItem lfi){ //當(dāng)前系統(tǒng)日期 String currPCDate = TimeUtil.getPCDate('-'); //如果超過單個(gè)文件大小，則拆分文件 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("日志已自動(dòng)備份為 " + newFile.getName() + ( flag ? "成功!" : "失敗!" ) ); lfi.fullLogFileName = ""; lfi.currLogSize = 0; } } //創(chuàng)建文件 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; } }} |
多日志級(jí)別
FLogger 支持多種日志級(jí)別：
- DEBUG
- INFO
- WARN
- ERROR
- FATAL
FLogger 為每個(gè)日志級(jí)別都提供了簡(jiǎn)易 API，在此就不再贅述了。
打印 error 和 fatal 級(jí)別日志時(shí)，F(xiàn)Logger 默認(rèn)會(huì)將日志內(nèi)容輸出到控制臺(tái)。
熱加載
FLogger 支持熱加載，F(xiàn)Logger 內(nèi)部并沒有采用事件驅(qū)動(dòng)方式（即新增、修改和刪除配置文件時(shí)產(chǎn)生相關(guān)事件通知 FLogger 實(shí)時(shí)熱加載），而是以固定頻率的方式進(jìn)行熱加載，具體實(shí)現(xiàn)就是每執(zhí)行完100次刷盤后才進(jìn)行熱加載（頻率可調(diào)），關(guān)鍵代碼如下：
inti =0;while(bIsRun){try{//等待一定時(shí)間Thread.sleep(200);//輸出到文件flush(false);//重新獲取日志級(jí)別if(i++ %100==0){Constant.CFG_LOG_LEVEL = CommUtil.getConfigByString("LOG_LEVEL","0,1,2,3,4");//其他配置項(xiàng)熱加載......i =1;}}catch(Exception e){System.out.println("開啟日志服務(wù)錯(cuò)誤...");e.printStackTrace();}}這么做完全是為了保持代碼的精簡(jiǎn)和功能的純粹性。事件驅(qū)動(dòng)熱加載無疑是更好的熱加載方式，但需要新建額外的線程并啟動(dòng)對(duì)配置文件的事件監(jiān)聽，有興趣的童鞋可自行實(shí)現(xiàn)。
性能保證
FLogger 成功支撐了日交易額百億級(jí)交易系統(tǒng)的日志服務(wù)，它的性能是經(jīng)歷過考驗(yàn)的。下面我們就來拿 FLogger 跟 log4j 做個(gè)簡(jiǎn)單的性能對(duì)比。
測(cè)試環(huán)境：Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz 3.20 GHz 4.00 GB Memory 64位操作系統(tǒng)
測(cè)試場(chǎng)景：?jiǎn)螚l記錄72byte 共1000000條 寫單個(gè)日志文件
FLogger 配置如下：
# 日志寫入文件的間隔時(shí)間WRITE_LOG_INV_TIME = 0# 單個(gè)日志文件的大小SINGLE_LOG_FILE_SIZE = 104857600# 單個(gè)日志文件緩存的大小SINGLE_LOG_CACHE_SIZE = 0以上配置保證所有日志寫入到單個(gè)文件，且盡量保證每一條記錄不在內(nèi)存中緩存，減少測(cè)試誤差。
測(cè)試代碼：
|
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字節(jié)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"); |
日志內(nèi)容：
|
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. |
測(cè)試結(jié)果（執(zhí)行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 |
說明：測(cè)試結(jié)果為日志全部刷盤成功的修正時(shí)間，加上各種環(huán)境的影響，有少許誤差，在此僅做簡(jiǎn)單測(cè)試，并不是最嚴(yán)格最公平的測(cè)試對(duì)比。有興趣的童鞋可進(jìn)行精確度更高的測(cè)試。
