[MTK] 深入了解Logging Tools 之 Kernel Log

Kernel Log

　　在开发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个级别的定义可以参考下表，值越小级别越高：

那优先级是怎么应用的呢？

　　我们可以为将要打印的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。