printf的歸宿-資料列印到哪兒了

近日在一次測試Linux核心路由查找算法的過程中，發現一個printf語句竟然能将性能降低2/3。當然，使用“竟然”一詞并不意味着這個問題是第一次發現，我的想法是，把它記錄下來，讓沒有經驗的同學對printf知其是以然，同時導出我對“性能攸關”的這類算法中記錄日志的一個觀點。

我不會把大段的源代碼貼在文章中，而隻是希望能通過闡述原理把我的意思表達清楚。誠然，作為程式員沒有代碼好像一切都會很虛，不過同樣的，也是因為代碼，總是會把人逼進死胡同，代碼隻是一種實作，了解了原理，作為一個懂程式設計的程式員，任何人都可以寫出一個自己的實作。

      我會給出原理圖，但是這圖決不是我憑空想象的，來源在哪？當然是UNIX的相關标準以及Linux的具體實作代碼。既然原理來自于Linux的代碼，為何不貼出來分析一下呢？要知道，代碼随着Linux的核心版本，C庫的版本以及應用程式的版本變化而變化，不變的是思想！UNIX曆經幾十年，其思想不還在指導着千千萬萬的程式員嗎？另外，有誰會去通讀Linux核心代碼呢？對于大多數的人而言，如果想知道printf或者任何其它的接口的原理，肯定不會去擺開架勢做出一副要先了解Linux核心架構，C庫架構作為前置知識，然後去跟蹤調試其實作。在以上這個過程中，你會把大量的精力消耗在了解不相關的内容上，比如函數調用關系，層層嵌套的條件語句，或者調試器怎麼使用，諸如此類。

printf是一個接口，跟UNIX标準IO的write系統調用類似，但是更像C庫的fwrite，因為同系列的函數中還有一個fprintf(至于同系列其它的函數，請自行man)。printf和fwrite的差別在于兩點：

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

2.它免除了你的fopen-fwrite-fclose這個序列的調用，因為它直接将格式化的内容寫入UNIX程序自然打開的1号檔案描述符，即标準輸出。

既然printf寫入了标準輸出，那麼接下來就要定義什麼是标準輸出。在早期UNIX年代，人們在終端或者僞終端操作機器，那時的輸入基本都是鍵盤，錄音帶更古老的東西，而輸出就是一個計算結果，需要展示出來給人看的那種，一般為終端螢幕，也可以是一條紙帶，那麼程式怎麼知道輸入和輸出到底是什麼呢？這就需要程式明确指定。UNIX的“一切皆檔案”思想以及“分離抽象”思想徹底改變了這一切。

      UNIX定義了抽象檔案描述符0，1，2分别為标準輸入，标準輸出，标準錯誤輸出。至于它們到底對應什麼裝置，你可以在程式初始化的時候顯式重定向到任意裝置，也可以在外部shell做類似的重定向，這樣就把指明裝置這件事從程式分離了出來。 

      我為什麼不統一說一下fwrite調用對程式性能的影響呢？因為該調用之前你必須執行fopen，而fopen的一個參數明确表示了你希望寫入的對象是什麼，這就不會帶來異議，畢竟如果你非要在性能測試的時候寫CF卡，那也是你願意。printf就不同了，它對效率的影響取決于标準輸出是什麼以及你是如何重定向标準輸出的，所謂的标準輸出并不是真實的裝置，它隻是一個抽象層，具體如何解釋标準輸出，還要依靠外部。

我以下面這個超級小的程式來說明printf的時候，資料都去哪了：

我先給出結果：

1.在/dev/tty1上直接執行time ./test 1000 

...

#########  995

#########  996

#########  997

#########  998

#########  999

real    0m0.414s

user    0m0.003s

sys     0m0.411s

2.在/dev/tty1上執行time ./test 1000 >/dev/tty2

real    0m0.007s

sys     0m0.007s

3.在SecureCRT上執行time ./test 1000

real    0m0.010s

user    0m0.002s

sys     0m0.003s

4.在SecureCRT上執行time ./test 100000 >/dev/tty1,此時不切換tty

等了幾秒，無結果，于是在鍵盤按下Alt-F2，切換到第二個tty，馬上顯示出了結果：

real    0m4.276s

user    0m0.066s

sys     0m4.204s

5.在tty1上執行time ./test 100000 >/dev/tty2：

real    0m0.499s

user    0m0.081s

sys     0m0.410s

6.在tty1上執行time ./test 100000 >/dev/null

real    0m0.030s

user    0m0.028s

sys     0m0.001s

通過以上的結果資料，我們可以得到以下的結論：

a.對于tty終端而言，如果目前終端不是寫入的終端，那麼開銷主要在核心态，且開銷不是很大；

b.對于tty終端而言，如果目前終端是寫入的終端，那麼開銷主要在核心态，且開銷很大；

c.對于不管是tty還是遠端的pty終端，寫入/dev/null的開銷主要在使用者态，開銷不大；

d.對于pty遠端終端(/dev/pts/X)，不管寫入的是不是目前的pty終端，開銷主要在核心态，且開銷不是很大

e.

對應上面的結果和結論，下面給出一幅圖解，詳細解釋一下printf冰山下面的秘密：

<a href="http://s3.51cto.com/wyfs02/M01/23/B6/wKiom1NAHAShKWYKAAKXrW9OPRo192.jpg" target="_blank"></a>

我想上圖已經很清楚了，如果不懂什麼叫行規程(也叫線路規程)的話，請閱讀《UNIX環境進階程式設計》的終端和僞終端章節，簡單來說，它就是一個中間層，用來适配VFS接口和底層的具體驅動，比如解釋和處理控制字元等。從上面的圖中，我們可以看出，主要的開銷幾乎都集中在底層，而底層卻偏偏是我們不能控制或者很難控制的。之是以上面的測試例子中ssh登入的終端對test性能的測試效果良好，但是那是因為網絡環境好，你在一個64kbps相隔5k公裡的線路上試一下。

      小小的printf下面竟然藏着如此多的内容，并且很可能就是它成了你的程式的性能瓶頸，因為最底層的影響因素往往是不可控的。那麼是不是就是意味着我要建議大家從來不用printf列印呢？或者說幹脆就不要用标準輸出呢？并不是這樣。但是為何不把列印這種事交給本機的另一個程序呢？事實上，幾乎所有的需要記錄日志的系統都是這麼做的，而syslog則迎合了這個思想。這種思想的背後就是“用可控制的一次IPC替換不可控制冰山之下的茫茫深海”

日志記錄一直都是“薛定谔貓”式的東西，因為日志記錄作為一段代碼，它已經是程式的一部分，不可能獨立地觀察程式的行為，如果說用鏡像系統的話，那麼這種行為就是被動的，你不得不鏡像每一條指令，以發現一些關鍵的資訊，要想主動記錄關鍵事件，必須用日志系統。列印日志可以友善資訊擷取和審計，但是代價有時也是高昂的：

1.你要設計一套日志復原系統，防止存儲空間被撐爆；

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

3.你要反複調試代碼，確定日志記錄的緩沖區不會溢出；

4.為了讓日志更短，語言能力不好的人組織的日志就像電報一樣難以了解。

我認為，日志記錄應該遵循以下的原則：

1.除非必須要把事件發生的時間記錄下來，否則就用計數器代替日志記錄，一系列的事件映射成一系列的計數器，由使用者決定什麼時候檢視事件發生了。事實上，Linux的網絡子系統就是用的這種方式，所有的/proc/net/netstat就是這個檢視接口。

2.一定要有一個日志級别控制選項，使用者可以決定是否記錄日志，以及記錄的日志詳細到什麼程度。

 本文轉自 dog250 51CTO部落格，原文連結:http://blog.51cto.com/dog250/1391018