警惕程序日志對(duì)性能的影響
作者:Solrex Yang
做后臺(tái)系統(tǒng)比做客戶端軟件的辛苦的地方,就是不能讓程序輕易地掛掉。因?yàn)樵谏a(chǎn)環(huán)境中無法容易地復(fù)現(xiàn)或調(diào)試 bug,很多時(shí)候需要程序日志提供足夠的信息,所以一個(gè)后臺(tái)系統(tǒng)的程序員必須要明白該如何打日志(logging)。
做后臺(tái)系統(tǒng)比做客戶端軟件的辛苦的地方,就是不能讓程序輕易地掛掉。因?yàn)樵谏a(chǎn)環(huán)境中無法容易地復(fù)現(xiàn)或調(diào)試 bug,很多時(shí)候需要程序日志提供足夠的信息,所以一個(gè)后臺(tái)系統(tǒng)的程序員必須要明白該如何打日志(logging)。
很多語言都有自己現(xiàn)成的 logging 庫,比如 Python 標(biāo)準(zhǔn)庫中的 logging 模塊,Apache 的 log4cxx(C++), log4j(Java)。如果你愿意找,很容易能找到基本滿足自己需求的日志程序庫。當(dāng)然,自己實(shí)現(xiàn)一個(gè)也不是很困難。難點(diǎn)不在于寫這些庫,而是如何去使用它們。
大部分情況下,我們關(guān)注的都是日志的級(jí)別和內(nèi)容。即哪些情況下,該打哪個(gè)級(jí)別的日志,日志語句中,該怎么寫。
在程序開發(fā)的過程中,我們需要很多的日志協(xié)助分析程序問題;但在生產(chǎn)環(huán)境中,我們沒有那么多的空間存儲(chǔ)豐富的日志,而且日志量太大對(duì)于問題排查反而是累贅。有些人使用預(yù)處理解決這個(gè)問題,在 debug 版本和 release 版本中編譯進(jìn)不同的日志語句。這樣能夠解決一些問題,但卻使得在生產(chǎn)環(huán)境中無法輕易地打印更多的日志。大部分人更接受的做法是,使用配置(參數(shù))控制日志的打印級(jí)別,在需要更多日志的時(shí)候,可以隨時(shí)打開它們。為了實(shí)現(xiàn)日志“少但是足夠”的目標(biāo),開發(fā)人員必須明白日志信息的價(jià)值,即哪些日志應(yīng)該屬于哪個(gè)級(jí)別。
日志的作用是提供信息,但不同的日志語句,提供的信息量卻是不一樣的。有的日志里會(huì)寫“Failed to get sth..”,但卻忘記加上失敗調(diào)用的返回值。同程序一樣,日志語句中有的是變量(某個(gè)變量內(nèi)容),有的是常量(提示信息)。常量你總能從程序源代碼中獲得,但變量不行。所以在一條日志中,信息量***的是變量,是函數(shù)返回值/字符串內(nèi)容/錯(cuò)誤碼,因而變量應(yīng)該盡量放在靠前的位置。常量也不是一點(diǎn)價(jià)值沒有,寫得好的提示語句,會(huì)使問題一目了然,可以免去你到代碼中 grep,然后重讀代碼的麻煩。
上面這兩點(diǎn),幾乎所有知道 logging 重要性的同學(xué)都會(huì)了解。但關(guān)于 logging 對(duì)性能的影響,很多人沒有足夠的警惕心。例如有人會(huì)在一個(gè)按行解析文件的函數(shù)中寫下這樣的日志:
int parseline(...)
{
log_trace("Enter parseline with ...");
DO_SOMETHING;
log_trace("Exit parseline with ...");
return 0;
}
乍一看,由于 log_trace 級(jí)別不高,在生產(chǎn)環(huán)境中肯定會(huì)關(guān)閉,那么這樣做看起來對(duì)性能沒太大影響。但實(shí)際上 log_trace 可能是這樣實(shí)現(xiàn)的:
#define log_trace(fmt, arg...) \\
xx_log(LVL_TRACE, "[%s:%d][time:%uus]" fmt, __FILE__, __LINE__,\\
log_getussecond(), ## arg)
#endif
可以看到 log_trace 宏中自動(dòng)添加了很多信息,值得注意的是時(shí)間參數(shù) log_getussecond()。大家都知道統(tǒng)計(jì)時(shí)間需要系統(tǒng)調(diào)用,那么無論 log_getussecond() 函數(shù)是如何實(shí)現(xiàn)的,它的代價(jià)肯定是高于一般的簡單函數(shù)。
我們本以為 log_trace 在 LVL_TRACE 級(jí)別被關(guān)閉的情況下,消耗的代價(jià)僅僅是一個(gè)函數(shù)調(diào)用和分支判斷,卻沒有發(fā)現(xiàn)宏參數(shù)中還隱藏著一個(gè)需要調(diào)用系統(tǒng)調(diào)用的函數(shù)。當(dāng)文件不大是還算能夠忍受,但當(dāng)這個(gè)文件是一個(gè)數(shù)據(jù)庫,掃描每一行都要執(zhí)行兩次 log_trace() 時(shí),它對(duì)系統(tǒng)性能的影響就絕不可忽視了。
所以,***的做法還是,在性能攸關(guān)的代碼中,使用可被預(yù)處理掉的 logging 語句,僅僅在 debug 發(fā)布中才能見到這些日志,release 版本中不把它們編譯進(jìn)來。
此外,上面這個(gè) log_trace,是一個(gè)糟糕的設(shè)計(jì)。logging 模塊只應(yīng)該干 logging 的事情,開發(fā)人員需要時(shí)間統(tǒng)計(jì)時(shí)會(huì)自己完成。
責(zé)任編輯:趙寧寧