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