kernel module编程（六）：printk-…

2009-09-1309:58:26|  分类： 专业砖家 |字号 订阅

　　本文包含《Linux DeviceDrivers》，即LDD3的第四章：DebuggingTechniques的读书笔记之一，但我们不限于此内容。我在网上看到了LDD3的中文版：http://www.deansys.com/doc/ldd3/，我看了一下，最好和原文版一起阅读。

　　在我们的程序的调测中，无论是JAVA，C（kernelmodule或者是用户应用），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是无法胜任的，因为断点使得系统性能上不去）。在内核模块编程也一样。我们开发的程序不应该分调测版本和正式版本，他们的sourcecode是一致的，但是正式版本中没有调测信息的出现。我们下面将介绍printk的一些使用方法。

一些重要的宏

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

printk(KERN_DEBUG "weimark here : %s : %d at%s()\n",__FILE__,__LINE__,__FUNCTION__);

　　其中__FILE__表示源代码文件，以绝对路径的方式出现，__LINE__，表示这行printk允许在这个源代码文件中的第几行，这是一个很好的给出调测点位置的信息。这个同样可以用在用户程序。__DATE__和__TIME__是非常常用的两个。不过有时我们需要使用msec，这种情况下只好自己写了。这4个宏，在debug中会经常使用。此外还有__STDC__，通常为1，表示为标准的ANSIC。还有一个常用的是__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信息，可以由编译来决定。

#ifndefWEI_SCULL_DEBUG_H

#undef PDEBUG
#ifdef SCULL_DEBUG
#  ifdef __KERNEL__
#    definePDEBUG(fmt,args...) printk(KERN_DEBUG "scull:" fmt , ## args)
#  else
#    definePDEBUG(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__
#defineWEI_KERN_ERMER         0
#defineWEI_KERN_ALERT          1
#defineWEI_KERN_CRIT            2
#defineWEI_KERN_ERR             3
#defineWEI_KERN_WARNING    4
#defineWEI_KERN_NOTICE       5
#defineWEI_KERN_INFO           6
#defineWEI_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)
#    ifdefWEI_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
#    definePDEBUG(fmt,args...) printf(fmt, ## args)
#    defineWDEBUG(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  92009 14:18:14 scull [KERN_NOTICE] : Scull module init enter
Sep  9 2009 14:18:18 scull [KERN_NOTICE] : Scullmodule 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：控制输入/输出、控制业务量】