1、問題的引出:
做DPDK項(xiàng)目時(shí),調(diào)試rte_kni.ko時(shí),發(fā)現(xiàn)printk并不會(huì)向我們想想的那樣把log信息顯示在我們的終端上。有人總結(jié)了三個(gè)原因:
原因1:printk()有一個(gè)控制日志級(jí)別的字段,如果該字段的日記級(jí)別高于console默認(rèn)的日志級(jí)別那么才會(huì)打印出來(數(shù)值越小日志級(jí)別越高,分為從0-7共計(jì)8個(gè)日志級(jí)別)。有一種簡單的改變當(dāng)前終端的日志級(jí)別的方法,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“它的意思是把所有日志級(jí)別的內(nèi)核log都輸出到/dev/console即我們的終端。我們只需要把該行的'#'去掉,重啟,理論上那么內(nèi)核log (printk()輸出也是內(nèi)核log)就會(huì)輸出到終端了。但是我的還是不能。
原因3:系統(tǒng)中同時(shí)有klogd和syslogd守護(hù)進(jìn)程那么不管日志級(jí)別是什么都不能輸出到終端。
如果不能在終端上看到printk的輸出,那么可以通過查看/var/log/messages文件,或運(yùn)行dmesg命令查看,或查看/proc/kmsg文件獲得信息,或是通過ctrl+alt+f2~f6進(jìn)入系統(tǒng)文本模式裝載模塊,這樣也可以看到prink()輸出的信息,當(dāng)然這里就準(zhǔn)確對(duì)應(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概述:
對(duì)于做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()指定了日志級(jí)別。
2.1:日志等級(jí)
內(nèi)核根據(jù)日志級(jí)別來判斷是否在終端(console)上打印消息:內(nèi)核把級(jí)別比某個(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)試級(jí)別的信息?*/
/* 使用默認(rèn)內(nèi)核日志級(jí)別?*/
#define KERN_DEFAULT?""
/*
* 標(biāo)注為一個(gè)“連續(xù)”的日志打印輸出行(只能用于一個(gè)
* 沒有用? 封閉的行之后). 只能用于啟動(dòng)初期的 core/arch 代碼
*?(否則續(xù)行是非SMP的安全).
*/
#define KERN_CONT?""
如果使用時(shí)沒有指定日志等級(jí),內(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è)等級(jí)是可以在內(nèi)核配置時(shí)指定,這種機(jī)制是從2.6.39開始有的,如果你不去特別配置,那么默認(rèn)為<4>,也就是KERN_WARNING。
內(nèi)核將最重要的記錄等級(jí)?KERN_EMERG定為“”,將無關(guān)緊要的調(diào)試記錄等級(jí)“KERN_DEBUG”定為“<7>”。
內(nèi)核用這些宏指定日志等級(jí)和當(dāng)前終端的記錄等級(jí)console_loglevel來決定是不是向終端上打印,使用示例如下:
printk(KERN_EMERG?"log_level:%s ", KERN_EMERG);
當(dāng)編譯預(yù)處理完成之后,前例中的代碼實(shí)際被編譯成成如下格式:
printk(?"<0>"?"log_level:%s ", KERN_EMERG);
給一個(gè)printk()什么日志等級(jí)完全取決于你。那些正式、且需要保持的消息應(yīng)該根據(jù)信息的性質(zhì)給出相應(yīng)的日志等級(jí)。但那些為了解決一個(gè)問題臨時(shí)加得到處都是的調(diào)試信息可以有兩種做法:
一種選擇是保持終端的默認(rèn)記錄等級(jí)不變,給所有調(diào)試信息KERN CRIT或更低的等級(jí)以保證信息一定會(huì)被輸出。
另一種方法則相反,給所有調(diào)試信息KERN DEBUG等級(jí),而調(diào)整終端的默認(rèn)記錄等級(jí)為7,也可以輸出所有調(diào)試信息。
兩種方法各有利弊。
這里說到了調(diào)整內(nèi)核的默認(rèn)的日志級(jí)別,在我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所需要的日志等級(jí),每次都要在其中添加以上宏,似乎有點(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),請(qǐ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è)信息。而對(duì)于打印速率的控制內(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)測(cè)周期,在這個(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)試完成以后做性能測(cè)試或者發(fā)布的時(shí)候千萬記得盡量減少printk輸出,做到僅在出錯(cuò)時(shí)輸出少量信息。否則往console輸出無用信息影響性能。我剛開始學(xué)驅(qū)動(dòng)的時(shí)候就犯過這樣的白癡錯(cuò)誤,在測(cè)試CAN驅(qū)動(dòng)性能的時(shí)候居然printk出信息來核對(duì),結(jié)果直接宕機(jī)。
2、printk的臨時(shí)緩存printk_buf只有1K,所有一次printk函數(shù)只能記錄<1K的信息到log buffer,并且printk使用的“ring buffer”
3、printk的內(nèi)核實(shí)現(xiàn)
對(duì)于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)對(duì)__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):
?
評(píng)論
查看更多