近日在一次測(cè)試Linux內(nèi)核路由查找算法的過程中，發(fā)現(xiàn)一個(gè)printf語(yǔ)句竟然能將性能降低2/3。當(dāng)然，使用“竟然”一詞并不意味著這個(gè)問題是第一次發(fā)現(xiàn)，我的想法是，把它記錄下來，讓沒有經(jīng)驗(yàn)的同學(xué)對(duì)printf知其所以然，同時(shí)導(dǎo)出我對(duì)“性能攸關(guān)”的這類算法中記錄日志的一個(gè)觀點(diǎn)。

聲明

我不會(huì)把大段的源代碼貼在文章中，而只是希望能通過闡述原理把我的意思表達(dá)清楚。誠(chéng)然，作為程序員沒有代碼好像一切都會(huì)很虛，不過同樣的，也是因?yàn)榇a，總是會(huì)把人逼進(jìn)死胡同，代碼只是一種實(shí)現(xiàn)，理解了原理，作為一個(gè)懂編程的程序員，任何人都可以寫出一個(gè)自己的實(shí)現(xiàn)。
我會(huì)給出原理圖，但是這圖決不是我憑空想象的，來源在哪？當(dāng)然是UNIX的相關(guān)標(biāo)準(zhǔn)以及Linux的具體實(shí)現(xiàn)代碼。既然原理來自于Linux的代碼，為何不貼出來分析一下呢？要知道，代碼隨著Linux的內(nèi)核版本，C庫(kù)的版本以及應(yīng)用程序的版本變化而變化，不變的是思想！UNIX歷經(jīng)幾十年，其思想不還在指導(dǎo)著千千萬萬的程序員嗎？另外，有誰會(huì)去通讀Linux內(nèi)核代碼呢？對(duì)于大多數(shù)的人而言，如果想知道printf或者任何其它的接口的原理，肯定不會(huì)去擺開架勢(shì)做出一副要先了解Linux內(nèi)核架構(gòu)，C庫(kù)架構(gòu)作為前置知識(shí)，然后去跟蹤調(diào)試其實(shí)現(xiàn)。在以上這個(gè)過程中，你會(huì)把大量的精力消耗在理解不相關(guān)的內(nèi)容上，比如函數(shù)調(diào)用關(guān)系，層層嵌套的條件語(yǔ)句，或者調(diào)試器怎么使用，諸如此類。

關(guān)于printf

printf是一個(gè)接口，跟UNIX標(biāo)準(zhǔn)IO的write系統(tǒng)調(diào)用類似，但是更像C庫(kù)的fwrite，因?yàn)橥盗械暮瘮?shù)中還有一個(gè)fprintf(至于同系列其它的函數(shù)，請(qǐng)自行man)。printf和fwrite的區(qū)別在于兩點(diǎn)：

1.它可以格式化輸出，如果用fwrite，它接受的是一個(gè)固定的buffer，你不得不在調(diào)fwrite之前先使用sprintf之類的函數(shù)格式化buffer；

2.它免除了你的fopen-fwrite-fclose這個(gè)序列的調(diào)用，因?yàn)樗苯訉⒏袷交膬?nèi)容寫入U(xiǎn)NIX進(jìn)程自然打開的1號(hào)文件描述符，即標(biāo)準(zhǔn)輸出。

既然printf寫入了標(biāo)準(zhǔn)輸出，那么接下來就要定義什么是標(biāo)準(zhǔn)輸出。在早期UNIX年代，人們?cè)诮K端或者偽終端操作機(jī)器，那時(shí)的輸入基本都是鍵盤，磁帶更古老的東西，而輸出就是一個(gè)計(jì)算結(jié)果，需要展示出來給人看的那種，一般為終端屏幕，也可以是一條紙帶，那么程序怎么知道輸入和輸出到底是什么呢？這就需要程序明確指定。UNIX的“一切皆文件”思想以及“分離抽象”思想徹底改變了這一切。

UNIX定義了抽象文件描述符0，1，2分別為標(biāo)準(zhǔn)輸入，標(biāo)準(zhǔn)輸出，標(biāo)準(zhǔn)錯(cuò)誤輸出。至于它們到底對(duì)應(yīng)什么設(shè)備，你可以在程序初始化的時(shí)候顯式重定向到任意設(shè)備，也可以在外部shell做類似的重定向，這樣就把指明設(shè)備這件事從程序分離了出來。

我為什么不統(tǒng)一說一下fwrite調(diào)用對(duì)程序性能的影響呢？因?yàn)樵撜{(diào)用之前你必須執(zhí)行fopen，而fopen的一個(gè)參數(shù)明確表示了你希望寫入的對(duì)象是什么，這就不會(huì)帶來異議，畢竟如果你非要在性能測(cè)試的時(shí)候?qū)慍F卡，那也是你愿意。printf就不同了，它對(duì)效率的影響取決于標(biāo)準(zhǔn)輸出是什么以及你是如何重定向標(biāo)準(zhǔn)輸出的，所謂的標(biāo)準(zhǔn)輸出并不是真實(shí)的設(shè)備，它只是一個(gè)抽象層，具體如何解釋標(biāo)準(zhǔn)輸出，還要依靠外部。

數(shù)據(jù)都去哪兒了

我以下面這個(gè)超級(jí)小的程序來說明printf的時(shí)候，數(shù)據(jù)都去哪了：

#include #include 
int main(int argc, char **argv){        int i = 0;        int c = atoi(argv[1]);        for(; i < c; i++) {                printf("############  %d
", i);        }        return 0;}

我先給出結(jié)果：
1.在/dev/tty1上直接執(zhí)行time ./test 1000
...
######### 995
######### 996
######### 997
######### 998
######### 999

real 0m0.414s
user 0m0.003s
sys 0m0.411s

2.在/dev/tty1上執(zhí)行time ./test 1000 >/dev/tty2
real 0m0.007s
user 0m0.003s
sys 0m0.007s

3.在SecureCRT上執(zhí)行time ./test 1000
...
######### 997
######### 998
######### 999

real 0m0.010s
user 0m0.002s
sys 0m0.003s

4.在SecureCRT上執(zhí)行time ./test 100000 >/dev/tty1,此時(shí)不切換tty
...
等了幾秒，無結(jié)果，于是在鍵盤按下Alt-F2，切換到第二個(gè)tty，馬上顯示出了結(jié)果：
real 0m4.276s
user 0m0.066s
sys 0m4.204s

5.在tty1上執(zhí)行time ./test 100000 >/dev/tty2：
real 0m0.499s
user 0m0.081s
sys 0m0.410s

6.在tty1上執(zhí)行time ./test 100000 >/dev/null
real 0m0.030s
user 0m0.028s
sys 0m0.001s

通過以上的結(jié)果數(shù)據(jù)，我們可以得到以下的結(jié)論：

a.對(duì)于tty終端而言，如果當(dāng)前終端不是寫入的終端，那么開銷主要在內(nèi)核態(tài)，且開銷不是很大；

b.對(duì)于tty終端而言，如果當(dāng)前終端是寫入的終端，那么開銷主要在內(nèi)核態(tài)，且開銷很大；

c.對(duì)于不管是tty還是遠(yuǎn)程的pty終端，寫入/dev/null的開銷主要在用戶態(tài)，開銷不大；

d.對(duì)于pty遠(yuǎn)程終端（/dev/pts/X），不管寫入的是不是當(dāng)前的pty終端，開銷主要在內(nèi)核態(tài)，且開銷不是很大

e.對(duì)應(yīng)上面的結(jié)果和結(jié)論，下面給出一幅圖解，詳細(xì)解釋一下printf冰山下面的秘密：

我想上圖已經(jīng)很清楚了，如果不懂什么叫行規(guī)程（也叫線路規(guī)程）的話，請(qǐng)閱讀《UNIX環(huán)境高級(jí)編程》的終端和偽終端章節(jié)，簡(jiǎn)單來說，它就是一個(gè)中間層，用來適配VFS接口和底層的具體驅(qū)動(dòng)，比如解釋和處理控制字符等。從上面的圖中，我們可以看出，主要的開銷幾乎都集中在底層，而底層卻偏偏是我們不能控制或者很難控制的。之所以上面的測(cè)試?yán)又衧sh登錄的終端對(duì)test性能的測(cè)試效果良好，但是那是因?yàn)榫W(wǎng)絡(luò)環(huán)境好，你在一個(gè)64kbps相隔5k公里的線路上試一下。

小小的printf下面竟然藏著如此多的內(nèi)容，并且很可能就是它成了你的程序的性能瓶頸，因?yàn)樽畹讓拥挠绊懸蛩赝遣豢煽氐?。那么是不是就是意味著我要建議大家從來不用printf打印呢？或者說干脆就不要用標(biāo)準(zhǔn)輸出呢？并不是這樣。但是為何不把打印這種事交給本機(jī)的另一個(gè)進(jìn)程呢？事實(shí)上，幾乎所有的需要記錄日志的系統(tǒng)都是這么做的，而syslog則迎合了這個(gè)思想。這種思想的背后就是“用可控制的一次IPC替換不可控制冰山之下的茫茫深?！?/p>

關(guān)于日志記錄

日志記錄一直都是“薛定諤貓”式的東西，因?yàn)槿罩居涗涀鳛橐欢未a，它已經(jīng)是程序的一部分，不可能獨(dú)立地觀察程序的行為，如果說用鏡像系統(tǒng)的話，那么這種行為就是被動(dòng)的，你不得不鏡像每一條指令，以發(fā)現(xiàn)一些關(guān)鍵的信息，要想主動(dòng)記錄關(guān)鍵事件，必須用日志系統(tǒng)。打印日志可以方便信息獲取和審計(jì)，但是代價(jià)有時(shí)也是高昂的：

1.你要設(shè)計(jì)一套日志回滾系統(tǒng)，防止存儲(chǔ)空間被撐爆；

2.你要讓日志記錄盡快完成，不能降低關(guān)鍵路徑的性能；

3.你要反復(fù)調(diào)試代碼，確保日志記錄的緩沖區(qū)不會(huì)溢出；

4.為了讓日志更短，語(yǔ)言能力不好的人組織的日志就像電報(bào)一樣難以理解。

我認(rèn)為，日志記錄應(yīng)該遵循以下的原則：

1.除非必須要把事件發(fā)生的時(shí)間記錄下來，否則就用計(jì)數(shù)器代替日志記錄，一系列的事件映射成一系列的計(jì)數(shù)器，由用戶決定什么時(shí)候查看事件發(fā)生了。事實(shí)上，Linux的網(wǎng)絡(luò)子系統(tǒng)就是用的這種方式，所有的/proc/net/netstat就是這個(gè)查看接口。

2.一定要有一個(gè)日志級(jí)別控制選項(xiàng)，用戶可以決定是否記錄日志，以及記錄的日志詳細(xì)到什么程度。