電子發燒友App
1、問題的引出：
做DPDK項目時，調試rte_kni.ko時，發現printk并不會向我們想想的那樣把log信息顯示在我們的終端上。有人總結了三個原因：
原因1：printk()有一個控制日志級別的字段，如果該字段的日記級別高于console默認的日志級別那么才會打印出來（數值越小日志級別越高，分為從0-7共計8個日志級別）。有一種簡單的改變當前終端的日志級別的方法，echo 8 > /sys/kernel/printk。理論上這樣printk就能輸出到終端了。但是我的沒有。
原因2：syslogd守護進程的規則有問題，/etc/syslog.conf中定義了一些列規則，其中就包含數內核消息的處理規則，fedora中的syslogd守護進程叫做rsyslogd，相應它的規則配置文件叫rsyslog.conf，其中有一行”#kern.*????????????????/dev/console“它的意思是把所有日志級別的內核log都輸出到/dev/console即我們的終端。我們只需要把該行的'#'去掉，重啟，理論上那么內核log (printk()輸出也是內核log）就會輸出到終端了。但是我的還是不能。
原因3：系統中同時有klogd和syslogd守護進程那么不管日志級別是什么都不能輸出到終端。
如果不能在終端上看到printk的輸出，那么可以通過查看/var/log/messages文件，或運行dmesg命令查看，或查看/proc/kmsg文件獲得信息，或是通過ctrl+alt+f2~f6進入系統文本模式裝載模塊，這樣也可以看到prink()輸出的信息，當然這里就準確對應原因1中所講的規則。
最后說一下syslogd、直接通過/proc/kmsg、和dmesg讀取printk輸出緩沖區的區別：
syslogd：讀取了緩沖區中的數據，不會刪除緩沖區中的數據。
直接讀取/proc/kmsg：讀取了緩沖區中的數據后，將緩沖區中的數據刪除（klogd默認就是采用這種方法）。
dmesg：在不刷新緩沖區的情況下獲得緩沖區的內容，并將內容返回給stdout。
本文里的知識來至LDD3，和一位網友的博客（http://www.cnitblog.com/textbox/archive/2009/10/13/61785.html）。
1、printk概述:
對于做Linux內核開發的人來說，printk實在是再熟悉不過了。內核啟動時顯示的各種信息大部分都是通過她來實現的，在做內核驅動調試的時候大部分 時候使用她就足矣。她之所以用得如此廣泛，一個是由于她使用方便，還有一個重要的原因是她的健壯性。它使用范圍很廣，幾乎是內核的任何地方都能調用它。你既可以在中斷上下文、進程上下中調用她，也可以在任何持有鎖時調用她，更可以在SMP系統中調用她，且調用時連鎖都不必使用。這樣好的適應性來源于她的設計，一個由三個指針控制的簡單“ring buffer”。
注意上面說到的是：“幾乎”在內核的任何地方都可以使用。那什么地方使用會有“問題”？那就是在系統啟動過程的早期，終端初始化之前的某些地方雖然可以使用，但是在終端和控制臺被初始化之前所有信息都被緩存在printk的簡單的ring buffer（環形緩沖區）中，直到終端和控制臺被初始化之后，所有緩存信息都被一并輸出。
如果你要調試的是啟動過程最開始的部分（如setup_arch()），可以依靠此時能夠工作的硬件設備（如串口）與外界通信，使用printk()的變體early_printk()函數。她在啟動過程初期就具有在終端上打印的能力，功能與prink()類似，區別在于：
（1）函數名
（2）能夠更早地工作（輸出信息）
（3）她有自己的小緩存（一般為512B）
（4）一次性輸出到硬件設備，不再以ring buffer的形式保留信息。
但該函數在一些構架上無法實現，所以這種辦法缺少可移植性。（大多數構架都可以，包括x86和arm）。
所以，除非要在啟動初期在終端上輸出，否則我們認為printk()在任何情況下都能工作。這點從內核的啟動代碼中就可以看出，在已進入start_kernel不久就通過printk打印內核版本信息了。
2、printk的使用:
printk()和C庫中的printf()在使用上最主要的區別就是?printk()指定了日志級別。
2.1：日志等級
內核根據日志級別來判斷是否在終端（console）上打印消息：內核把級別比某個特定值低的所有消息顯示在終端（console）上。但是所有信息都會記錄在printk的“ring buffer”中。
printk有8個loglevel,定義在中：
#define KERN_EMERG?"<0>"?/* 系統不可使用?*/
#define KERN_ALERT?"<1>"?/* 需要立即采取行動?*/
#define KERN_CRIT?"<2>"?/* 嚴重情況?*/
#define KERN_ERR?"<3>"?/* 錯誤情況?*/
#define KERN_WARNING?"<4>"?/* 警告情況?*/
#define KERN_NOTICE?"<5>"?/* 正常情況, 但是值得注意?*/
#define KERN_INFO?"<6>"?/* 信息型消息?*/
#define KERN_DEBUG?"<7>"?/* 調試級別的信息?*/
/* 使用默認內核日志級別?*/
#define KERN_DEFAULT?""
/*
* 標注為一個“連續”的日志打印輸出行(只能用于一個
* 沒有用? 封閉的行之后). 只能用于啟動初期的 core/arch 代碼
*?(否則續行是非SMP的安全).
*/
#define KERN_CONT?""
如果使用時沒有指定日志等級，內核會選用DEFAULT_MESSAGE_LOGLEVEL，這個定義位于kernel/printk.c：
/* printk's without a loglevel use this..?*/
#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL
可以看出，這個等級是可以在內核配置時指定,這種機制是從2.6.39開始有的，如果你不去特別配置，那么默認為<4>,也就是KERN_WARNING。
內核將最重要的記錄等級?KERN_EMERG定為“”，將無關緊要的調試記錄等級“KERN_DEBUG”定為“<7>”。
內核用這些宏指定日志等級和當前終端的記錄等級console_loglevel來決定是不是向終端上打印，使用示例如下：
printk(KERN_EMERG?"log_level:%s ", KERN_EMERG);
當編譯預處理完成之后，前例中的代碼實際被編譯成成如下格式：
printk(?"<0>"?"log_level:%s ", KERN_EMERG);
給一個printk()什么日志等級完全取決于你。那些正式、且需要保持的消息應該根據信息的性質給出相應的日志等級。但那些為了解決一個問題臨時加得到處都是的調試信息可以有兩種做法：
一種選擇是保持終端的默認記錄等級不變，給所有調試信息KERN CRIT或更低的等級以保證信息一定會被輸出。
另一種方法則相反，給所有調試信息KERN DEBUG等級，而調整終端的默認記錄等級為7，也可以輸出所有調試信息。
兩種方法各有利弊。
這里說到了調整內核的默認的日志級別，在我3年半前的學習筆記《 Linux設備驅動程序學習（2）-調試技術 》中有介紹，可以通過 /proc/sys/kernel/printk來改變，或者C程序調用syslog系統調用來實現。但是現在的glibc的函數接口改了，由于?syslog?這個詞使用過于廣泛，這個函數的名稱被修改成?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：相關輔助宏
如果確定printk所需要的日志等級，每次都要在其中添加以上宏，似乎有點麻煩了。所以內核黑客們定義了一些宏來方便printk的使用，這些宏在內核代碼中也是隨處可見：
#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()不產生任何代碼?*/
#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
/* 如果你在寫一個驅動，請使用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
從上面的代碼大家應該就可以知道這些宏的使用了。值得注意的是：pr_devel和?pr_debug這些宏只有在定義了DEBUG之后才會產生實際的 printk代碼，這樣方便了內核開發：在代碼中使用這些宏，當調試結束，只要簡單地#undef?DEBUG就可以消除這些調試使用的代碼，無需真正地 去刪除調試輸出代碼。
2.3：輸出速率控制
在調試的時候，有時某些部分可能printk會產生大量輸出, 導致系統無法正常工作，并可能使系統日志ring buffer溢出（舊的信息被快速覆蓋）。特別地，當使用一個慢速控制臺設備(如串口), 過量輸出也能拖慢系統。這樣反而難于發現系統出問題的地方。所以你應當非常注意：正常操作時不應當打印任何東西，打印的輸出應當是指示需要注意的異常，并 小心不要做過頭。
在某些情況下, 最好的做法是設置一個標志變量表示：已經打印過這個了，以后不再打印任何這個信息。而對于打印速率的控制內核已經提供了一個現成的宏:
#define printk_ratelimit() __printk_ratelimit(__func__)
這個函數應當在你認為打印一個可能會出現大量重復的消息之前調用，如果這個函數返回非零值, 繼續打印你的消息, 否則跳過它。典型的調用如這樣:
if?(printk_ratelimit())
printk(KERN_NOTICE?"The printer is still on fire ");
printk_ratelimit通過跟蹤發向控制臺的消息的數量和時間來工作。當輸出超過一個限度, printk_ratelimit 開始返回 0 使消息被丟棄。我們可以通過修改 ：
/proc/sys/kern/printk_ratelimit( 可以看作一個監測周期，在這個周期內只能發出下面的控制量的信息)?
/proc/sys/kernel/printk_ratelimit_burst(以上周期內的最大消息數，如果超過了printk_ratelimit()返回0)
來控制消息的輸出.
在中還定義了其他的宏，比如printk_ratelimited(fmt, ...)等，有興趣的朋友就去文件中看看便知，很好理解的。
2.4：最后特別提醒：
1、雖然printk很健壯，但是看了源碼你就知道，這個函數的效率很低：做字符拷貝時一次只拷貝一個字節，且去調用console輸出可能還產生中斷。所以如果你的驅動在功能調試完成以后做性能測試或者發布的時候千萬記得盡量減少printk輸出，做到僅在出錯時輸出少量信息。否則往console輸出無用信息影響性能。我剛開始學驅動的時候就犯過這樣的白癡錯誤，在測試CAN驅動性能的時候居然printk出信息來核對，結果直接宕機。
2、printk的臨時緩存printk_buf只有1K，所有一次printk函數只能記錄<1K的信息到log buffer，并且printk使用的“ring buffer”
3、printk的內核實現
對于Linux的printk內核日志，常常被稱為kernel ring buffer，這是由于printk的緩存實現就是使用了一個簡單的ring buffer（環形緩沖區）。但是這里需要注意的是，不要和內核trace系統ring buffer混淆，雖然他們都是為了跟蹤調試，但是trace系統的ring buffer實現更加完善復雜，而printk使用的ring buffer則非常簡單，其實就定義了一個字符數組：
static char __log_buf[__LOG_BUF_LEN];
并使用了一套指針來管理：
/*
* 在指向log_buf時并沒有用log_buf_len做限制?- 所以他們
* 在作為下標使用前必須用掩碼處理（去除CONFIG_LOG_BUF_SHIFT以上的高位）
*/
static unsigned log_start;?/* log_buf中的索引: 指向由syslog()讀取的下一個字符?*/
static unsigned con_start;?/* log_buf中的索引: 指向發送到console的下一個字符?*/
static unsigned log_end;?/* log_buf中的索引:最近寫入的字符地址?+ 1?*/
具體的實現CU中已經有一位博友寫過了，我這里就不再啰嗦了，我轉載備份了一下：《printk實現分析》
4、用戶空間訪問內核日志
用戶空間訪問和控制內核日志有兩個接口：
（1）通過glibc的klogctl函數接口調用內核的syslog系統調用
（2）通過fs/proc/kmsg.c內核模塊中導出的procfs接口：/proc/kmsg文件。
他們其實最終都調用了/kernel/printk.c中的do_syslog函數，實現對__log_buf的訪問及相關變量的修改。
但值得注意的是：從/proc/kmsg中獲取數據，那么__log_buf中被讀取過的數據就不再保留（也就是會修改log_start指針）, 然而 syslog 系統調用返回日志數據并保留數據給其他進程。讀取/proc文件是 klogd的默認做法。dmesg命令可用來查看緩存的內容并保留它，其實它是將__log_buf中的所有內容返回給stdout，并不管它是否已經被讀取過。
這里我還是推薦大家?RTFSC?– Read The Fucking Source Code，自己看這些代碼比什么都強，我這里就只引個路。
在用戶空間有專門用于記錄系統日志的程序，統稱為“syslog守護進程”。早期及現在的大部分嵌入式系統使用的是klogd+syslogd組合，現在 大多數發行版都使用rsyslogd或者syslogd-ng了。這些用戶空間的程序我這里就不分析了，我不擅長，運維的可能比較清楚。我只知道一下他們 大致的調用關系就好。
這里我用一張圖來總結一下內核printk和日志系統的總體結構：
?
工商網監
評論