kernel module編程（六）：printk-printf的debug

　　本文包含《Linux Device Drivers》，即LDD3的第四章：Debugging Techniques的讀書筆記之一，但我們不限於此內容。我在網上看到了LDD3的中文版：http://www.deansys.com/doc/ldd3/

，我看了一下，最好和原文版一起閱讀。

　　在我們的程式的調測中，無論是JAVA，C（kernel module或者是使用者應用），print都是非常重要的手段。在我以往的項目中，我會有一個log檔案，將log根據項目需要分為幾個層級log，通過setlogLevel可以設定開啟或者關閉哪些些層級的debug，每一行log有[時間] [log-level] [log內容]三部分組成。可以決定是否將log寫入檔案，還是只是在terminal上顯示。在一個JAVA的project中，可以將log輸出到控制台用戶端上，他們之間走TCP連結，如果TCP出現阻塞，將丟棄輸出，直至TCP恢複。在C中，我們可以簡單地在編譯參數中加上-DMY_DEBUG_LEVEL來處理。從某種意義來講DEBUG也是一門學問。

　　對於寫檔案，我有一個慘痛的教訓。寫CDR計費未經處理資料單，每個業務有三條詳細記錄，兩個callleg，有一個業務記錄。我們的大話務量測試，至少48小時，通常我會壓更長的時間。業務超過1千萬次。所以需要寫的資料非常多。在平時的測試中沒有問題，但是在一次正式測試中出現磁碟滿禁止寫入的暈菜現象。這個雖然可以推給整合人員，但是很多時候也是我們自己考慮不周到。如果我們寫檔案，包括log檔案，對於長期啟動並執行系統，我們必須考慮磁碟空間的問題。在這次教訓後，我寫了一個根據時間、容量、檔案數的判斷進行壓縮或者刪除檔案最初檔案的後台小程式，明天定期執行。之後在另外一個下面也是壓測效能，合作方的出現測試用戶端log爆滿磁碟的現象。這是一個在開發中容易被忽略的問題，但是在實際運行中可能產生嚴重問題。

【編程思想1：注意磁碟溢出情況】

　　其實debug對開發很重要，他不僅可以跟蹤我們的程式對他進行診斷，也可以跟蹤我們的商務邏輯，尋找效能瓶頸（對於效能瓶頸gdb是無法勝任的，因為斷點使得系統效能上不去）。在核心模組編程也一樣。我們開發的程式不應該分調測版本和正式版本，他們的source code是一致的，但是正式版本中沒有調測資訊的出現。我們下面將介紹printk的一些使用方法。

一些重要的宏

　　printk和printf非常相似，但是不等同。下面是一個例子：

printk(KERN_DEBUG "wei mark here : %s : %d at %s()/n",__FILE__

,__LINE__

,__FUNCTION__

);

　　其中__FILE__

表示原始碼檔案，以絕對路徑的方式出現，__LINE__

，表示這行printk允許在這個原始碼檔案中的第幾行，這是一個很好的給出調測點位置的資訊。這個同樣可以用在使用者程式。__DATE__

和__TIME__

是非常常用的兩個。不過有時我們需要使用msec，這種情況下只好自己寫了。這4個宏，在debug中會經常使用。此外還有__STDC__

，通常為1，表示為標準的ANSI C。還有一個常用的是__FUNCTION__

表示在那個函數之中，也是比較好的定位方式。這些宏均可以在使用者程式中使用，對debug非常有協助。

　　KERN_DEBUG是一個字串，即"<7>"，這是核心定義的8個debug等級中，最低等級的一個。從0-7，分別是KERN_EMERG，KERN_ALERT，KERN_CRIT，KERN_ERR, KERN_WARING, KERN_NOTICE, KERN_INFO, KERN_DEBUG。對應<0>, <1>, <2> ... ...。由於他是一個字元，所有他後面是沒有逗號的。

　　在fc10中，我查看的dmesg，以及/var/log/messages，發現KERN_DEBUG所代表的"<7>"並沒有顯示，而使用KVM啟動並執行moblin中，這個"<7>"是顯示的。我做了一個實驗，直接用"<7>"來代替KERN_DEBUG，例如上面的例子，我寫為"<7> wei ..."，在fc10中，同樣是不顯示<7>，這和OSV整合的系統有關。

使用printk|printf

　　一個好的編程習慣，在每個printk中都加上DEBUG等級，這樣使得程式更容易瞭解。在scull的例子上，增加一個scull_debug.c檔案，我們的目的是保證原始碼的一致性，而是否顯示debug資訊，可以由編譯來決定。

#ifndef WEI_SCULL_DEBUG_H

#undef PDEBUG

#ifdef SCULL_DEBUG

#  ifdef __KERNEL__

#    define PDEBUG(fmt,args...) printk(KERN_DEBUG "scull:" fmt , ## args)

#  else

#    define PDEBUG(fmt,args...) printf(fmt, ## args)

#  endif

#else

#  define PDEBUG(fmt,args...)

#endif

#undef PDEBUGG

#define PDEBUGG(fmt, args...)

#endif

　　在上面的例子中，定義了PDEBUG的宏，如果需要我們也可以定義PDEBUGG的實際內容。如果我們定義了SCULL_DEBUG，進入DEBUG模式，PDEBUG根據是否核心編程，決定使用printk還是printf。也就是說這個標頭檔也可以在使用者程式中使用 。下面是對Makefile的修改，簡單的處理，就是在gcc那行，如果需要debug，加上參數 -DSCULL_DEBUG，就可以，不需要刪除這個定義。下面是寫得更好看，但是我個人認為不那麼簡潔易懂的方式。我會在EXTRA_CFLAGS的設定中直接加上-DSCULL_DEBUG，在他上面作一行注釋說明參數的含義，不會去搞一堆指令碼。下面是LDD3的例子，其中將CFLAGS改為EXTRA_CFLAGS。另一個注意的地方就是ifeq後面一定要加一個空格，否則報錯。

DEBUG = y

ifeq ($(DEBUG),y)

        DEBFLAGS = -O -g -DSCULL_DEBUG

else

        DEBFLAGS = -O2

endif

EXTRA_CFLAGS

+= $(DEBFLAGS)

obj-m := scull.o

module-objs :=

PWD := $(shell pwd)

KDIR := /lib/modules/$(shell uname -r)/build

all:

        make -C $(KDIR) M=$(PWD) modules

clean:

        make -C $(KDIR) M=$(PWD) clean

在fc10中，我們還是希望能夠看到debug的等級，另方面，我們對0-7對應的含義不熟悉，只知道數字越高，資訊越為重要。我們將scull_debug.c改寫為下面：

#ifndef WEI_SCULL_DEBUG_H

#ifdef __KERNEL__

#define WEI_KERN_ERMER          0

#define WEI_KERN_ALERT           1

#define WEI_KERN_CRIT             2

#define WEI_KERN_ERR              3

#define WEI_KERN_WARNING     4

#define WEI_KERN_NOTICE        5

#define WEI_KERN_INFO            6

#define WEI_KERN_DEBUG         7

static char * log_level[] = {

  "KERN_EMERG",

  "KERN_ALERT",

  "KERN_CRIT",

  "KERN_ERR",

  "KERN_WARNING",

  "KERN_NOTICE",

  "KERN_INFO",

  "KERN_DEBUG"

};

#endif

#undef PDEBUG

#ifdef SCULL_DEBUG

#ifdef __KERNEL__

#  define PDEBUG(fmt,args...) printk(KERN_DEBUG "scull:" fmt , ## args)

#    ifdef WEI_DEBUG_LEVEL

#      define WDEBUG(level,fmt,args...) /

        if( level <= WEI_DEBUG_LEVEL)  printk("%s %s scull [%s] : " fmt , __DATE__

, __TIME__

, log_level[level], ## args)

#    else

#      define WDEBUG(level,fmt,args...) printk("%s scull [%s] : " fmt ,__TIME__ ,  log_level[level], ## args)

#    endif
#  else

#    define PDEBUG(fmt,args...) printf(fmt, ## args)

#    define WDEBUG(level,fmt,args...)

#  endif

#else

#  define PDEBUG(fmt,args...)

#endif

#undef PDEBUGG

#define PDEBUGG(fmt, args...)

#endif

　　我們可以選擇debug的層級，將debug等級用字串打出來。對於簡單程式可能意義不大，我們也可以設定自己的等級。將Makefile改寫為下面：

DEBUG = y

DEBUGLEVEL = 6

ifeq ($(DEBUG),y)

        DEBFLAGS = -O -g -DSCULL_DEBUG -DWEI_DEBUG_LEVEL=$(DEBUGLEVEL)

else

        DEBFLAGS = -O2

endif

EXTRA_CFLAGS += $(DEBFLAGS)

obj-m := scull.o

module-objs :=

PWD := $(shell pwd)

KDIR := /lib/modules/$(shell uname -r)/build

all:

        make -C $(KDIR) M=$(PWD) modules

clean:

        make -C $(KDIR) M=$(PWD) clean

 

在scull的例子，通過load和unload，我們從dmesg中可以獲得下面的資訊：

Sep  9 2009 14:18:14 scull [KERN_NOTICE] : Scull module init enter

Sep  9 2009 14:18:18 scull [KERN_NOTICE] : Scull module exit

避免printk產生阻塞

　　由於某些原因，頻繁設定迴圈調用某個printk的語句，將會造成CPU的擁堵，如果輸入終端是慢速，就會造成擁堵，我們也不可能從這種狂刷螢幕上讀取到什麼有效資訊，基本上就看不清。核心編程提供了一下保護機制。下面是一個測試的例子：

        for(i = 0 ; i < 1000; i ++){

                if(printk_ratelimit()){

                        printk(KERN_DEBUG "Test for ratelimte i = %d j = %d/n",i ,++j);

                }

        }

        printk(KERN_NOTICE "After Test i = %d j = %d/n",i , j);

　　printk_ratelimit()根據列印的頻繁程度返回的一個值，根據這個值我們決定是否將debug資訊列印出來。這個傳回值取決於兩個因素，分別定義在/proc/sys/kernel/printk_ratelimit和/proc/sys/kernel/printk_ratelimit_burst。前者表示當這個值置為0後隔多少秒後恢複為1，即等待允許再次列印的時間（秒），後者可能和緩衝隊列長度有關，他表示在值為0之前，可以printk的條目數。系統預設值為5和10，也就是在printk_ratelimit()的控制下，每秒可以有兩個輸出。在上面的例子，我們看到輸出了10次。我想象的處理機制是，系統根據printk_ratelimit_burst的值設定一個隊列長度，如果這個隊列滿，則值printk_ratelimit()為0，禁止新的訊息排入佇列，等待printk_ratelimit秒設定的時間，將

printk_ratelimit()設為1，即允許新的訊息排入佇列。這種方式我曾用於處理業務請求，設定允許接納請求的頻率，避免burst的出現。我猜想這裡面的機制也是類似的。不管如何，這是一種看行之有效方法。

【編程思想2：控制輸入/輸出、控制業務量】

相關連結：

我的與kernel module有關的文章

我的與編程思想相關的文章