在开发Linux device Driver或者跟踪调试内核行为的时候经常要通过Log API来trace整个过程,Kernel API printk() 是整个Kernel Log机制的基础API,几乎所有的Log方式都是基于printk来实现的。
利用printk,我们可以像开发C应用中printf接口一样印log,最简单的方式,我们只要把需要打印的内容传给printk函数就可以了,如下:
printk("This is just an example!!");
当然使用printk还有一些需要注意的地方,在详细讲述之前我们先分析一下printk()实现,其流程大致如下图所示:
从上图可以看出,printk的流程大致可以分为两步:
- 将所有Log输出到内核的Log buffer,该Log Buffer是一个循环缓冲区,其地址可以在内核中用log_buf变量访问。
- 根据设定的Log级别决定是否将Log输出到Console。
所以我们打印的log会走向两个位置:
- Log Buffer,该Buffer的内容可以在user space通过/proc/kmsg来访问。
- Console,Console的实现可以有很多,目前我们用到的有UART Console和RAM Console。拿UART Console来说,通向UART Console的log会在对应的UART端口打印出来。而RAM Console也是我们一种重要的Debug手段。
对于console log,不可避免的对系统的性能有损失,尤其是像UART Log这种收到硬件传输效率影响的。所以对于console log设置了两道关卡。第一个是对Log级别进行过滤,只能输出高优先级的log;第二个是为UART Console设置单独的开关,在不必要的时候可以将其关闭以提高系统性能。
在这里我们提到了Log Level的概念,那什么是Log Level呢?
LOG 优先级
Log Level,也叫做Log优先级,为了能够区分各个Log的重要程度,printk机制设计了若干Log级别以作区分。当我们读取log buffer (adb shell cat /proc/kmsg)的时候可以看到如下的log,在每一行Log的前面有一对尖角号,里面包含一个数字,这个数字即为这行Log优先级。
<6>[ 641.908202] (0)[130:healthd]healthd: battery l=26 l2=50 v=3859 t=30.0 h=2
<4>[ 641.908685] (0)[64:bat_thread_kthr][0x4]=0x9b [0x5]=0x4 [0x6]=0x70
<6>[ 641.914564] (0)[130:healthd]healthd: battery l=26 l2=50 v=3859 t=30.0 h=2
<4>[ 643.716514] (0)[0:swapper/0][printk_delayed:start]
<4>[ 643.717113] (0)[0:swapper/0][WDK], local_bit:0x0, cpu:0,RT[643706704575]
<4>[ 643.717120] (0)[0:swapper/0][WDK], local_bit:0x1, cpu:0, check bit0x:1,RT[6
<4>[ 643.717127] (0)[0:swapper/0][WDK]: kick Ex WDT,RT[643706714498]
<4>[ 643.717134] (0)[0:swapper/0][thread:86][RT:643706722652] 2013-01-01 00
<4>[ 643.721143] (0)[0:swapper/0][printk_delayed:done]
<7>[ 644.916496] (0)[0:swapper/0][ccci/ctl] (1)get_txpower(0): 16
<7>[ 644.916520] (0)[0:swapper/0][ccci/ctl] (1)get_txpower(1): 16
<7>[ 644.916540] (0)[0:swapper/0][ccci/ctl] (1)get_txpower(2): 16
<6>[ 644.916663] (0)[96:flush-179:0][BLOCK_TAG] BDI_Flush statistic in timeline
<6>[ 644.916682] (0)[96:flush-179:0][BLOCK_TAG] BDI_Flush [(PID):cnt] -- ( 96
完整的8个级别的定义可以参考下表,值越小级别越高:
宏定义 | 级别 | 描述 |
KERN_EMERG | "<0>" | 紧急信息,此信息会引起系统崩溃 |
KERN_ALERT | "<1>" | 提示要马上采取某些行动 |
KERN_CRIT | "<2>" | 关键信息,通常有严重的软件或者硬件问题发生了 |
KERN_ERR | "<3>" | 通常用来报告错误,例如设备驱动通常会用来报告硬件操作失败等 |
KERN_WARNING | "<4>" | 警告信息,用来警告那些并不会造成严重的系统异常的问题 |
KERN_NOTICE | "<5>" | 用于正常但是值得注意的情况,比如大量安全相关的log |
KERN_INFO | "<6>" | 信息,许多驱动程序都会在硬件启动的时候使用这个级别打印Log |
KERN_DEBUG | "<7>" | 用于调试信息的打印 |
那优先级是怎么应用的呢?
我们可以为将要打印的log指定优先级,举例如下,可以在我们要打印的log前面简单的添加上Log优先级的宏定义即可,这个优先级在printk API里面会去解析处理,以判断是否要打印到console中去。
printk(KERN_ERR"This is an error message!!");
如果不指定优先级会怎样呢?
如果在印Log的时候不指定Log的优先级,printk会为这行Log采用默认的优先级。通常系统默认的优先级是4,即warning级别。
系统默认的优先级可以通过读取/proc文件来得到,如下所示,其中读回来的第2个参数即为未指定Log Level的时候printk默认的Log级别。
D:\>adb shell cat /proc/sys/kernel/printk
6 4 1 6
/proc/sys/kernel/printk里面的参数意义是什么?
前面我们使用cat读取了/proc/sys/kernel/printk里面的内容,读取的这4个数字的含义分别是:
- 第一个参数表示console log level,即只有优先级大于这个级别的Log才可以打印到Console。
- 第二个参数表示默认Log级别,即打印Log未明确指定Log level的时候默认采用的Log级别。
- 第三个参数表示最小可用的Log Level,用于do_syslog()系统调用。
- 第四个参数表示默认的Console Log Level,未找到使用的地方。
Console Log 输出控制
从前面的图例以及讲述都有提到,console_loglevel 决定了哪些级别的log可以输出到console。而console_loglevel的值可以通过 /proc/sys/kernel/printk 来读取出来。
除此之外,我们还可以通过/proc/sys/kernel/printk设置console_loglevel来达到控制 console log 输出的目的,方法如下(修改这个参数需要有root权限):
D:\>adb shell cat /proc/sys/kernel/printk
6 4 1 6
D:\>adb shell "echo 8 > /proc/sys/kernel/printk"
D:\>adb shell cat /proc/sys/kernel/printk
8 4 1 6
上面黄色一行命令将console_loglevel设置8,即所有级别的log(因为定义的最低优先级的Log Level是7)都可以输出到console。当然通过这个命令也可以禁止一些低优先级的log输出到console,只要将console_loglevel的值设置小一些即可。
UART Console 的控制
对于UART Console单独设置了开关主要是因为其对系统性能的影响比较大,因为UART Console是同步的方式通过硬件以固定的传输速率印Log,如果Log量比较大的时候,印Log不可避免会花费系统较多的时间,这样就会引起较多的Performance问题,如UI卡顿等。另外由于往UART Console印Log会关闭中断,严重的时候可能会引起系统无法响应或者重启。
也正因为此,我们在user版本上面默认是关闭UART Console Log的。
那么如何在runtime控制UART Console 的打开和关闭呢?可以使用如下命令(执行该命令需要有root权限):
D:\>adb shell "echo 1 > /sys/module/printk/parameters/disable_uart"
D:\>adb shell "echo 0 > /sys/module/printk/parameters/disable_uart"
通过将disable_uart参数设置为1来关闭UART Console,反之通过将disable_uart参数设置为0来打开UART Console。