在开发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的流程大致可以分为两步:


  1. 将所有Log输出到内核的Log buffer,该Log Buffer是一个循环缓冲区,其地址可以在内核中用log_buf变量访问。
  2. 根据设定的Log级别决定是否将Log输出到Console。


所以我们打印的log会走向两个位置:


  1. Log Buffer,该Buffer的内容可以在user space通过/proc/kmsg来访问。
  2. 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个数字的含义分别是:

  1. 第一个参数表示console log level,即只有优先级大于这个级别的Log才可以打印到Console。
  2. 第二个参数表示默认Log级别,即打印Log未明确指定Log level的时候默认采用的Log级别。
  3. 第三个参数表示最小可用的Log Level,用于do_syslog()系统调用。
  4. 第四个参数表示默认的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。