內(nèi)核日志及printk結(jié)構(gòu)淺析

1、問題的引出：

做DPDK項(xiàng)目時(shí)，調(diào)試rte_kni.ko時(shí)，發(fā)現(xiàn)printk并不會(huì)向我們想想的那樣把log信息顯示在我們的終端上。有人總結(jié)了三個(gè)原因：

原因1：printk()有一個(gè)控制日志級別的字段，如果該字段的日記級別高于console默認(rèn)的日志級別那么才會(huì)打印出來（數(shù)值越小日志級別越高，分為從0-7共計(jì)8個(gè)日志級別）。有一種簡單的改變當(dāng)前終端的日志級別的方法，echo 8 > /sys/kernel/printk。理論上這樣printk就能輸出到終端了。但是我的沒有。

原因2：syslogd守護(hù)進(jìn)程的規(guī)則有問題，/etc/syslog.conf中定義了一些列規(guī)則，其中就包含數(shù)內(nèi)核消息的處理規(guī)則，fedora中的syslogd守護(hù)進(jìn)程叫做rsyslogd，相應(yīng)它的規(guī)則配置文件叫rsyslog.conf，其中有一行”#kern.*????????????????/dev/console“它的意思是把所有日志級別的內(nèi)核log都輸出到/dev/console即我們的終端。我們只需要把該行的'#'去掉，重啟，理論上那么內(nèi)核log (printk()輸出也是內(nèi)核log）就會(huì)輸出到終端了。但是我的還是不能。

原因3：系統(tǒng)中同時(shí)有klogd和syslogd守護(hù)進(jìn)程那么不管日志級別是什么都不能輸出到終端。

如果不能在終端上看到printk的輸出，那么可以通過查看/var/log/messages文件，或運(yùn)行dmesg命令查看，或查看/proc/kmsg文件獲得信息，或是通過ctrl+alt+f2~f6進(jìn)入系統(tǒng)文本模式裝載模塊，這樣也可以看到prink()輸出的信息，當(dāng)然這里就準(zhǔn)確對應(yīng)原因1中所講的規(guī)則。

最后說一下syslogd、直接通過/proc/kmsg、和dmesg讀取printk輸出緩沖區(qū)的區(qū)別：

syslogd：讀取了緩沖區(qū)中的數(shù)據(jù)，不會(huì)刪除緩沖區(qū)中的數(shù)據(jù)。

直接讀取/proc/kmsg：讀取了緩沖區(qū)中的數(shù)據(jù)后，將緩沖區(qū)中的數(shù)據(jù)刪除（klogd默認(rèn)就是采用這種方法）。

dmesg：在不刷新緩沖區(qū)的情況下獲得緩沖區(qū)的內(nèi)容，并將內(nèi)容返回給stdout。

本文里的知識(shí)來至LDD3，和一位網(wǎng)友的博客（http://www.cnitblog.com/textbox/archive/2009/10/13/61785.html）。

1、printk概述:

對于做Linux內(nèi)核開發(fā)的人來說，printk實(shí)在是再熟悉不過了。內(nèi)核啟動(dòng)時(shí)顯示的各種信息大部分都是通過她來實(shí)現(xiàn)的，在做內(nèi)核驅(qū)動(dòng)調(diào)試的時(shí)候大部分 時(shí)候使用她就足矣。她之所以用得如此廣泛，一個(gè)是由于她使用方便，還有一個(gè)重要的原因是她的健壯性。它使用范圍很廣，幾乎是內(nèi)核的任何地方都能調(diào)用它。你既可以在中斷上下文、進(jìn)程上下中調(diào)用她，也可以在任何持有鎖時(shí)調(diào)用她，更可以在SMP系統(tǒng)中調(diào)用她，且調(diào)用時(shí)連鎖都不必使用。這樣好的適應(yīng)性來源于她的設(shè)計(jì)，一個(gè)由三個(gè)指針控制的簡單“ring buffer”。

注意上面說到的是：“幾乎”在內(nèi)核的任何地方都可以使用。那什么地方使用會(huì)有“問題”？那就是在系統(tǒng)啟動(dòng)過程的早期，終端初始化之前的某些地方雖然可以使用，但是在終端和控制臺(tái)被初始化之前所有信息都被緩存在printk的簡單的ring buffer（環(huán)形緩沖區(qū)）中，直到終端和控制臺(tái)被初始化之后，所有緩存信息都被一并輸出。

如果你要調(diào)試的是啟動(dòng)過程最開始的部分（如setup_arch()），可以依靠此時(shí)能夠工作的硬件設(shè)備（如串口）與外界通信，使用printk()的變體early_printk()函數(shù)。她在啟動(dòng)過程初期就具有在終端上打印的能力，功能與prink()類似，區(qū)別在于：

（1）函數(shù)名

（2）能夠更早地工作（輸出信息）

（3）她有自己的小緩存（一般為512B）

（4）一次性輸出到硬件設(shè)備，不再以ring buffer的形式保留信息。

但該函數(shù)在一些構(gòu)架上無法實(shí)現(xiàn)，所以這種辦法缺少可移植性。（大多數(shù)構(gòu)架都可以，包括x86和arm）。

所以，除非要在啟動(dòng)初期在終端上輸出，否則我們認(rèn)為printk()在任何情況下都能工作。這點(diǎn)從內(nèi)核的啟動(dòng)代碼中就可以看出，在已進(jìn)入start_kernel不久就通過printk打印內(nèi)核版本信息了。

2、printk的使用:

printk()和C庫中的printf()在使用上最主要的區(qū)別就是?printk()指定了日志級別。

2.1：日志等級

內(nèi)核根據(jù)日志級別來判斷是否在終端（console）上打印消息：內(nèi)核把級別比某個(gè)特定值低的所有消息顯示在終端（console）上。但是所有信息都會(huì)記錄在printk的“ring buffer”中。

printk有8個(gè)loglevel,定義在中：

#define KERN_EMERG?"<0>"?/* 系統(tǒng)不可使用?*/

#define KERN_ALERT?"<1>"?/* 需要立即采取行動(dòng)?*/

#define KERN_CRIT?"<2>"?/* 嚴(yán)重情況?*/

#define KERN_ERR?"<3>"?/* 錯(cuò)誤情況?*/

#define KERN_WARNING?"<4>"?/* 警告情況?*/

#define KERN_NOTICE?"<5>"?/* 正常情況, 但是值得注意?*/

#define KERN_INFO?"<6>"?/* 信息型消息?*/

#define KERN_DEBUG?"<7>"?/* 調(diào)試級別的信息?*/

/* 使用默認(rèn)內(nèi)核日志級別?*/

#define KERN_DEFAULT?""

/*

* 標(biāo)注為一個(gè)“連續(xù)”的日志打印輸出行(只能用于一個(gè)

* 沒有用? 封閉的行之后). 只能用于啟動(dòng)初期的 core/arch 代碼

*?(否則續(xù)行是非SMP的安全).

*/

#define KERN_CONT?""

如果使用時(shí)沒有指定日志等級，內(nèi)核會(huì)選用DEFAULT_MESSAGE_LOGLEVEL，這個(gè)定義位于kernel/printk.c：

/* printk's without a loglevel use this..?*/

#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL

可以看出，這個(gè)等級是可以在內(nèi)核配置時(shí)指定,這種機(jī)制是從2.6.39開始有的，如果你不去特別配置，那么默認(rèn)為<4>,也就是KERN_WARNING。

內(nèi)核將最重要的記錄等級?KERN_EMERG定為“”，將無關(guān)緊要的調(diào)試記錄等級“KERN_DEBUG”定為“<7>”。

內(nèi)核用這些宏指定日志等級和當(dāng)前終端的記錄等級console_loglevel來決定是不是向終端上打印，使用示例如下：

printk(KERN_EMERG?"log_level:%s ", KERN_EMERG);

當(dāng)編譯預(yù)處理完成之后，前例中的代碼實(shí)際被編譯成成如下格式：

printk(?"<0>"?"log_level:%s ", KERN_EMERG);

給一個(gè)printk()什么日志等級完全取決于你。那些正式、且需要保持的消息應(yīng)該根據(jù)信息的性質(zhì)給出相應(yīng)的日志等級。但那些為了解決一個(gè)問題臨時(shí)加得到處都是的調(diào)試信息可以有兩種做法：

一種選擇是保持終端的默認(rèn)記錄等級不變，給所有調(diào)試信息KERN CRIT或更低的等級以保證信息一定會(huì)被輸出。

另一種方法則相反，給所有調(diào)試信息KERN DEBUG等級，而調(diào)整終端的默認(rèn)記錄等級為7，也可以輸出所有調(diào)試信息。

兩種方法各有利弊。

這里說到了調(diào)整內(nèi)核的默認(rèn)的日志級別，在我3年半前的學(xué)習(xí)筆記《 Linux設(shè)備驅(qū)動(dòng)程序?qū)W習(xí)（2）-調(diào)試技術(shù) 》中有介紹，可以通過 /proc/sys/kernel/printk來改變，或者C程序調(diào)用syslog系統(tǒng)調(diào)用來實(shí)現(xiàn)。但是現(xiàn)在的glibc的函數(shù)接口改了，由于?syslog?這個(gè)詞使用過于廣泛，這個(gè)函數(shù)的名稱被修改成?klogctl，所以原來博文中的代碼無法使用了，以下是新版的 console_loglevel代碼：

#include?

#include?

#include?

#include?

//#define __LIBRARY__?/* _syscall3?and friends are only available through this?*/

//#include?

/* define the system?call,?to override the library?function?*/

//_syscall3(int, syslog,?int, type, char?*, bufp,?int,?len);

int main(int argc, char?**argv)

{

int level;

if?(argc?== 2)?{

level?= atoi(argv[1]);?/* the chosen console?*/

}?else?{

fprintf(stderr,?"%s: need a single arg ", argv[0]);

exit(1);

}

if?(klogctl(8,?NULL, level)?< 0)?{

fprintf(stderr,?"%s: syslog(setlevel): %s ",

argv[0], strerror(errno));

exit(1);

}

exit(0);

}

2.2：相關(guān)輔助宏

如果確定printk所需要的日志等級，每次都要在其中添加以上宏，似乎有點(diǎn)麻煩了。所以內(nèi)核黑客們定義了一些宏來方便printk的使用，這些宏在內(nèi)核代碼中也是隨處可見：

#ifndef pr_fmt

#define pr_fmt(fmt) fmt

#endif

#define pr_emerg(fmt,?...)?

printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)

#define pr_alert(fmt,?...)?

printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)

#define pr_crit(fmt,?...)?

printk(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)

#define pr_err(fmt,?...)?

printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)

#define pr_warning(fmt,?...)?

printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)

#define pr_warn pr_warning

#define pr_notice(fmt,?...)?

printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)

#define pr_info(fmt,?...)?

printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)

#define pr_cont(fmt,?...)?

printk(KERN_CONT fmt, ##__VA_ARGS__)

/* 除非定義了DEBUG ，否則pr_devel()不產(chǎn)生任何代碼?*/

#ifdef DEBUG

#define pr_devel(fmt,?...)?

printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#else

#define pr_devel(fmt,?...)?

no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#endif

/* 如果你在寫一個(gè)驅(qū)動(dòng)，請使用dev_dbg?*/

#if defined(DEBUG)

#define pr_debug(fmt,?...)?

printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#elif defined(CONFIG_DYNAMIC_DEBUG)

/* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here?*/

#define pr_debug(fmt,?...)?

dynamic_pr_debug(fmt, ##__VA_ARGS__)

#else

#define pr_debug(fmt,?...)?

no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#endif

從上面的代碼大家應(yīng)該就可以知道這些宏的使用了。值得注意的是：pr_devel和?pr_debug這些宏只有在定義了DEBUG之后才會(huì)產(chǎn)生實(shí)際的 printk代碼，這樣方便了內(nèi)核開發(fā)：在代碼中使用這些宏，當(dāng)調(diào)試結(jié)束，只要簡單地#undef?DEBUG就可以消除這些調(diào)試使用的代碼，無需真正地 去刪除調(diào)試輸出代碼。

2.3：輸出速率控制

在調(diào)試的時(shí)候，有時(shí)某些部分可能printk會(huì)產(chǎn)生大量輸出, 導(dǎo)致系統(tǒng)無法正常工作，并可能使系統(tǒng)日志ring buffer溢出（舊的信息被快速覆蓋）。特別地，當(dāng)使用一個(gè)慢速控制臺(tái)設(shè)備(如串口), 過量輸出也能拖慢系統(tǒng)。這樣反而難于發(fā)現(xiàn)系統(tǒng)出問題的地方。所以你應(yīng)當(dāng)非常注意：正常操作時(shí)不應(yīng)當(dāng)打印任何東西，打印的輸出應(yīng)當(dāng)是指示需要注意的異常，并 小心不要做過頭。

在某些情況下, 最好的做法是設(shè)置一個(gè)標(biāo)志變量表示：已經(jīng)打印過這個(gè)了，以后不再打印任何這個(gè)信息。而對于打印速率的控制內(nèi)核已經(jīng)提供了一個(gè)現(xiàn)成的宏:

#define printk_ratelimit() __printk_ratelimit(__func__)

這個(gè)函數(shù)應(yīng)當(dāng)在你認(rèn)為打印一個(gè)可能會(huì)出現(xiàn)大量重復(fù)的消息之前調(diào)用，如果這個(gè)函數(shù)返回非零值, 繼續(xù)打印你的消息, 否則跳過它。典型的調(diào)用如這樣:

if?(printk_ratelimit())

printk(KERN_NOTICE?"The printer is still on fire ");

printk_ratelimit通過跟蹤發(fā)向控制臺(tái)的消息的數(shù)量和時(shí)間來工作。當(dāng)輸出超過一個(gè)限度, printk_ratelimit 開始返回 0 使消息被丟棄。我們可以通過修改 ：

/proc/sys/kern/printk_ratelimit( 可以看作一個(gè)監(jiān)測周期，在這個(gè)周期內(nèi)只能發(fā)出下面的控制量的信息)?

/proc/sys/kernel/printk_ratelimit_burst(以上周期內(nèi)的最大消息數(shù)，如果超過了printk_ratelimit()返回0)

來控制消息的輸出.

在中還定義了其他的宏，比如printk_ratelimited(fmt, ...)等，有興趣的朋友就去文件中看看便知，很好理解的。

2.4：最后特別提醒：

1、雖然printk很健壯，但是看了源碼你就知道，這個(gè)函數(shù)的效率很低：做字符拷貝時(shí)一次只拷貝一個(gè)字節(jié)，且去調(diào)用console輸出可能還產(chǎn)生中斷。所以如果你的驅(qū)動(dòng)在功能調(diào)試完成以后做性能測試或者發(fā)布的時(shí)候千萬記得盡量減少printk輸出，做到僅在出錯(cuò)時(shí)輸出少量信息。否則往console輸出無用信息影響性能。我剛開始學(xué)驅(qū)動(dòng)的時(shí)候就犯過這樣的白癡錯(cuò)誤，在測試CAN驅(qū)動(dòng)性能的時(shí)候居然printk出信息來核對，結(jié)果直接宕機(jī)。

2、printk的臨時(shí)緩存printk_buf只有1K，所有一次printk函數(shù)只能記錄<1K的信息到log buffer，并且printk使用的“ring buffer”

3、printk的內(nèi)核實(shí)現(xiàn)

對于Linux的printk內(nèi)核日志，常常被稱為kernel ring buffer，這是由于printk的緩存實(shí)現(xiàn)就是使用了一個(gè)簡單的ring buffer（環(huán)形緩沖區(qū)）。但是這里需要注意的是，不要和內(nèi)核trace系統(tǒng)ring buffer混淆，雖然他們都是為了跟蹤調(diào)試，但是trace系統(tǒng)的ring buffer實(shí)現(xiàn)更加完善復(fù)雜，而printk使用的ring buffer則非常簡單，其實(shí)就定義了一個(gè)字符數(shù)組：

static char __log_buf[__LOG_BUF_LEN];

并使用了一套指針來管理：

/*

* 在指向log_buf時(shí)并沒有用log_buf_len做限制?- 所以他們

* 在作為下標(biāo)使用前必須用掩碼處理（去除CONFIG_LOG_BUF_SHIFT以上的高位）

*/

static unsigned log_start;?/* log_buf中的索引: 指向由syslog()讀取的下一個(gè)字符?*/

static unsigned con_start;?/* log_buf中的索引: 指向發(fā)送到console的下一個(gè)字符?*/

static unsigned log_end;?/* log_buf中的索引:最近寫入的字符地址?+ 1?*/

具體的實(shí)現(xiàn)CU中已經(jīng)有一位博友寫過了，我這里就不再啰嗦了，我轉(zhuǎn)載備份了一下：《printk實(shí)現(xiàn)分析》

4、用戶空間訪問內(nèi)核日志

用戶空間訪問和控制內(nèi)核日志有兩個(gè)接口：

（1）通過glibc的klogctl函數(shù)接口調(diào)用內(nèi)核的syslog系統(tǒng)調(diào)用

（2）通過fs/proc/kmsg.c內(nèi)核模塊中導(dǎo)出的procfs接口：/proc/kmsg文件。

他們其實(shí)最終都調(diào)用了/kernel/printk.c中的do_syslog函數(shù)，實(shí)現(xiàn)對__log_buf的訪問及相關(guān)變量的修改。

但值得注意的是：從/proc/kmsg中獲取數(shù)據(jù)，那么__log_buf中被讀取過的數(shù)據(jù)就不再保留（也就是會(huì)修改log_start指針）, 然而 syslog 系統(tǒng)調(diào)用返回日志數(shù)據(jù)并保留數(shù)據(jù)給其他進(jìn)程。讀取/proc文件是 klogd的默認(rèn)做法。dmesg命令可用來查看緩存的內(nèi)容并保留它，其實(shí)它是將__log_buf中的所有內(nèi)容返回給stdout，并不管它是否已經(jīng)被讀取過。

這里我還是推薦大家?RTFSC?– Read The Fucking Source Code，自己看這些代碼比什么都強(qiáng)，我這里就只引個(gè)路。

在用戶空間有專門用于記錄系統(tǒng)日志的程序，統(tǒng)稱為“syslog守護(hù)進(jìn)程”。早期及現(xiàn)在的大部分嵌入式系統(tǒng)使用的是klogd+syslogd組合，現(xiàn)在 大多數(shù)發(fā)行版都使用rsyslogd或者syslogd-ng了。這些用戶空間的程序我這里就不分析了，我不擅長，運(yùn)維的可能比較清楚。我只知道一下他們 大致的調(diào)用關(guān)系就好。

這里我用一張圖來總結(jié)一下內(nèi)核printk和日志系統(tǒng)的總體結(jié)構(gòu)：

?