第3章 Linux内核调试手段之内核打印

开始


640?wx_fmt=png640?wx_fmt=png640?wx_fmt=png640?wx_fmt=png

640?wx_fmt=png640?wx_fmt=png

640?wx_fmt=png

640?wx_fmt=png


前面说的话

在我写代码的生涯里,我看到过很多大神炫耀自己的调试手段,也看到很多大神写过非常厉害的代码,我认为,相比于写代码,调试更加重要,而那些能在写代码的时候就加入了自己的调试信息的,就更加厉害了


printk 调试

打印 Log 调试是一个码农最基本的调试手段了,如果你连打印都不会,那么你基本上已经算是远离码农这个职业了,从我们写的第一行 "HelloWorld" 代码开始,我们就是用打印 Log 开始了自己的职业生涯。


printf 应该是每个写 C 语言都用过,在 Linux 内核,有属于自己的打印函数,就是 printk ,printk 可以往很多个地方输出,可以输出串口,可以输出重定向到某个系统文件。


Linux 发展这么久,prink 的地位一直无法撼动,一个是由于使用方便,还有一个重要的原因是它的健壮性,说出来不怕笑话,大家写内核代码很多,有没有因为 printk 导致问题的?如果有,可以拿出来分享一下。printk 使用范围很广,几乎是内核的任何地方都能调用它。你既可以在中断上下文、进程上下文调用,也可以在任何持有锁时调用它,更可以在SMP系统中调用它,而且调用时连锁都不必使用,根本就不用担心重入性的问题。


这一定要归功于它的设计,我在看 Linux 内核源码的时候,常常感叹是何方上古神兽能想出这样的系统,写出这么优秀的代码,printk 的设计离不开 "ring buff" ,"ring buff" 大家应该都知道一些吧,就是一个环形 buff,系统开机比较初始阶段的时候,日志不能马上输出到终端和串口上,这个日志就缓存在 "ring buff" 里,等系统起来后,就一并输出,从我们的角度看,因为系统启动速度比较快,感觉这个过程是实时的。



640?wx_fmt=png


printk 的源码位置

linux-source-3.2.0/kernel/printk.c


按照上面的框图,里面有一个很重要的函数,do_syslog,日志字符都是从这里进出的,我把代码贴出来,有时候是应该要 read the fucking code.

int do_syslog(int type, char __user *buf, int len, int source)

{

bool clear = false;

static int saved_console_loglevel = LOGLEVEL_DEFAULT;

int error;

error = check_syslog_permissions(type, source);

if (error)

return error;

switch (type) {

case SYSLOG_ACTION_CLOSE: /* Close log */

break;

case SYSLOG_ACTION_OPEN: /* Open log */

break;

case SYSLOG_ACTION_READ: /* Read from log */

if (!buf || len < 0)

return -EINVAL;

if (!len)

return 0;

if (!access_ok(buf, len))

return -EFAULT;

error = wait_event_interruptible(log_wait,

syslog_seq != log_next_seq);

if (error)

return error;

error = syslog_print(buf, len);

break;

/* Read/clear last kernel messages */

case SYSLOG_ACTION_READ_CLEAR:

clear = true;

/* FALL THRU */

/* Read last kernel messages */

case SYSLOG_ACTION_READ_ALL:

if (!buf || len < 0)

return -EINVAL;

if (!len)

return 0;

if (!access_ok(buf, len))

return -EFAULT;

error = syslog_print_all(buf, len, clear);

break;

/* Clear ring buffer */

case SYSLOG_ACTION_CLEAR:

syslog_clear();

break;

/* Disable logging to console */

case SYSLOG_ACTION_CONSOLE_OFF:

if (saved_console_loglevel == LOGLEVEL_DEFAULT)

saved_console_loglevel = console_loglevel;

console_loglevel = minimum_console_loglevel;

break;

/* Enable logging to console */

case SYSLOG_ACTION_CONSOLE_ON:

if (saved_console_loglevel != LOGLEVEL_DEFAULT) {

console_loglevel = saved_console_loglevel;

saved_console_loglevel = LOGLEVEL_DEFAULT;

}

break;

/* Set level of messages printed to console */

case SYSLOG_ACTION_CONSOLE_LEVEL:

if (len < 1 || len > 8)

return -EINVAL;

if (len < minimum_console_loglevel)

len = minimum_console_loglevel;

console_loglevel = len;

/* Implicitly re-enable logging to console */

saved_console_loglevel = LOGLEVEL_DEFAULT;

break;

/* Number of chars in the log buffer */

case SYSLOG_ACTION_SIZE_UNREAD:

logbuf_lock_irq();

if (syslog_seq < log_first_seq) {

/* messages are gone, move to first one */

syslog_seq = log_first_seq;

syslog_idx = log_first_idx;

syslog_partial = 0;

}

if (source == SYSLOG_FROM_PROC) {

/*

* Short-cut for poll(/"proc/kmsg") which simply checks

* for pending data, not the size; return the count of

* records, not the length.

*/

error = log_next_seq - syslog_seq;

} else {

u64 seq = syslog_seq;

u32 idx = syslog_idx;

bool time = syslog_partial ? syslog_time : printk_time;

while (seq < log_next_seq) {

struct printk_log *msg = log_from_idx(idx);

error += msg_print_text(msg, true, time, NULL,

0);

time = printk_time;

idx = log_next(idx);

seq++;

}

error -= syslog_partial;

}

logbuf_unlock_irq();

break;

/* Size of the log buffer */

case SYSLOG_ACTION_SIZE_BUFFER:

error = log_buf_len;

break;

default:

error = -EINVAL;

break;

}

return error;

}


printk 的使用

相比 printf ,printk 的一个亮点就是指定了日志等级,如果你是一个单片机开发人员,还没有进行过嵌入式系统的设计,我这里跟你说日志等级,估计也会慌得一笔,等你以后写的代码越来越多,就会发现通过宏控制日志等级打印简直就是调试手段里面的万剑归宗。


printk 在内核中的定义如下

/**

* printk - print a kernel message

* @fmt: format string

*

* This is printk().  It can be called from any context.  We want it to work.

*

* We try to grab the console_lock.  If we succeed, it's easy - we log the output and

* call the console drivers.  If we fail to get the semaphore we place the output

* into the log buffer and return.  The current holder of the console_sem will

* notice the new output in console_unlock(); and will send it to the

* consoles before releasing the lock.

*

* One effect of this deferred printing is that code which calls printk() and

* then changes console_loglevel may break. This is because console_loglevel

* is inspected when the actual printing occurs.

*

* See also:

* printf(3)

*

* See the vsnprintf() documentation for format string extensions over C99.

*/


asmlinkage int printk(const char *fmt, ...)

{

va_list args;

int r;


#ifdef CONFIG_KGDB_KDB

if (unlikely(kdb_trap_printk)) {

va_start(args, fmt);

r = vkdb_printf(fmt, args);

va_end(args);

return r;

}

#endif

va_start(args, fmt);

r = vprintk(fmt, args);

va_end(args);


return r;

}


printk日志等级,日志等级定义在头文件 (include/linux/printk.h),定义如下

#define KERN_EMERG     "<0>"  /* system is unusable 系统不可用*/

#define KERN_ALERT     "<1>"  /* action must be taken immediately 需要立即采取行动*/

#define KERN_CRIT     "<2>"  /* critical conditions 严重情况*/

#define KERN_ERR     "<3>"  /* error conditions 错误情况*/

#define KERN_WARNING   "<4>"  /* warning conditions 警告情况*/

#define KERN_NOTICE     "<5>"  /* normal but significant condition 正常情况,但要注意*/

#define KERN_INFO     "<6>"  /* informational 信息型消息*/

#define KERN_DEBUG     "<7>"  /* debug-level messages 调试级别信息*/


/* Use the default kernel loglevel  默认内核日志级别*/

#define KERN_DEFAULT    "<d>"

/*

* Annotation(标注) for a "continued" line of log printout (only done after a

* line that had no enclosing(封闭) \n). Only to be used by core/arch code

* during early bootup (a continued line is not SMP-safe otherwise).

*/

#define KERN_CONT     "<c>"


所以一个正常的内核打印日志应该是这样的

printk(KERN_ALERT "DBG: passed %s %d\n", __FUNCTION__, __LINE__)

通过预编译之后,会变成这样

printk("<1>" "DBG: passed %s %d\n", __FUNCTION__, __LINE__)


但是如果没有指定内核日志等级呢?在 printk.c 里面是这样定义的

/* printk's without a loglevel use this.. */

#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL


640?wx_fmt=png


在 .config 里面我们可以看到这个宏的值,如下

CONFIG_DEFAULT_MESSAGE_LOGLEVEL=4


printk 核心代码,我刚开始看 printk 的时候,一直在怀疑前面的 「<1>」字符为什么没有打印出来,直到自己去修改了源码,看了源码,才了解其中了奥秘,其中文章摘录 call_console_drivers 源码如下,其中实现在 call_console_drivers 函数里面。


对于 printk 的调用流程,大致如下

printk()->vprintk()->release_console_sem()->call_console_drivers()

/*

* Call the console drivers, asking them to write out

* log_buf[start] to log_buf[end - 1].

* The console_lock must be held.

*/

static void call_console_drivers(unsigned start, unsigned end)

{

unsigned cur_index, start_print;

static int msg_level = -1;


BUG_ON(((int)(start - end)) > 0);


cur_index = start;

start_print = start;

while (cur_index != end) {

if (msg_level < 0 && ((end - cur_index) > 2)) {

/*

* prepare buf_prefix, as a contiguous array,

* to be processed by log_prefix function

*/

char buf_prefix[SYSLOG_PRI_MAX_LENGTH+1];

unsigned i;

for (i = 0; i < ((end - cur_index)) && (i < SYSLOG_PRI_MAX_LENGTH); i++) {

buf_prefix[i] = LOG_BUF(cur_index + i);

}

buf_prefix[i] = '\0'; /* force '\0' as last string character */


/* strip log prefix */

                       /*这里说面,把日志等级 <x> 去掉*/

cur_index += log_prefix((const char *)&buf_prefix, &msg_level, NULL);

start_print = cur_index;

}

while (cur_index != end) {

char c = LOG_BUF(cur_index);


cur_index++;

if (c == '\n') {

if (msg_level < 0) {

/*

* printk() has already given us loglevel tags in

* the buffer.  This code is here in case the

* log buffer has wrapped right round and scribbled

* on those tags

*/

msg_level = default_message_loglevel;

}

_call_console_drivers(start_print, cur_index, msg_level);

msg_level = -1;

start_print = cur_index;

break;

}

}

}

_call_console_drivers(start_print, end, msg_level);

printk 输出格式

我们使用 printf 的时候,大部分同学都知道它的输出格式,printk 跟 printf 一样,也有格式输出,只不过我们

控制输出日志等级

在 printk.c 里面定义了几个日志等级,0 表示日志最重要 7 表示日志最不重要,但是我们如何控制它呢?

查看日志等级控制

linux@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0$ cat /proc/sys/kernel/printk

4 4 1 7

linux@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0$


它们的含义分别是

控制台日志级别:优先级高于该值的消息将被打印控制台(console)

默认的消息日志级别:将用该优先级来打印没有优先级的消息,使用 printk 的时候没有指定优先级的时候

最低的控制台日志级别:控制台日志级别可被设置的最小值(最高优先级)

默认的控制台日志级别:控制台日志级别的缺省值


可能很多读者对控制台这个概念不是非常情况,控制台也可以理解为终端,就是用来控制 Linux 系统的一个窗口。

640?wx_fmt=png


怎么控制日志的输出等级呢?

用下面这个命令


root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0# echo 7 > /proc/sys/kernel/printk

root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0# cat /proc/sys/kernel/printk

7 4 1 7

root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0# echo 8 8 1 8 > /proc/sys/kernel/printk

root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0# cat /proc/sys/kernel/printk

8 8 1 8

root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0#

加上上面对这几个值的说明,我相信你是能够理解其中的奥秘了。


内核打印相关辅助宏

#ifndef pr_fmt

#define pr_fmt(fmt) fmt

#endif

#define pr_emerg(fmt, ...) \

    printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)

#define pr_alert(fmt, ...) \

    printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)

#define pr_crit(fmt, ...) \

    printk(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)

#define pr_err(fmt, ...) \

    printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)

#define pr_warning(fmt, ...) \

    printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)

#define pr_warn pr_warning

#define pr_notice(fmt, ...) \

    printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)

#define pr_info(fmt, ...) \

    printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)

#define pr_cont(fmt, ...) \

    printk(KERN_CONT fmt, ##__VA_ARGS__)

/* 除非定义了DEBUG ,否则pr_devel()不产生任何代码 */

#ifdef DEBUG

#define pr_devel(fmt, ...) \

    printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#else

#define pr_devel(fmt, ...) \

    no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#endif

/* 如果你在写一个驱动,请使用dev_dbg */

#if defined(DEBUG)

#define pr_debug(fmt, ...) \

    printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#elif defined(CONFIG_DYNAMIC_DEBUG)

/* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */

#define pr_debug(fmt, ...) \

    dynamic_pr_debug(fmt, ##__VA_ARGS__)

#else

#define pr_debug(fmt, ...) \

    no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#endif

从上面的代码大家应该就可以知道这些宏的使用了。值得注意的是:pr_devel 和 pr_debug 这些宏只有在定义了 DEBUG 之后才会产生实际的 printk 代码,这样方便了内核开发,在代码中使用这些宏,当调试结束,只要简单地 #undef DEBUG 就可以消除这些调试使用的代码,无需真正地去删除调试输出代码。


开启 DEBUG 宏看书的时候觉得简单,但是实际写代码的时候,可能会一脸懵逼,不知道在哪里添加 DEBUG ,内核里面给了一个示例,我们只需要在 pr_debug/pr_devel 输出的 .c 文件的最前面写上就好了。


/* init/main.c */

#define DEBUG           /* Enable initcall_debug */


悲剧的是,我们有可能都不知道是哪个文件里面打印了出来的,我们要一个文件一个文件的去找,那会非常浪费时间,这就需要秀一下操作了,使用 Makefile 传递宏参数


KCFLAGS=-DDEBUG


用户空间访问内核日志文件

/proc/kmsg

这个日志文件还是非常有用的,我们可以通过这个文件实时查看你内核 Log ,做驱动开发的同学们,请务必记住这个文件。


查看内核日志命令

dmesg 命令

dmesg 的作用非常明显,一个命令来显示内核日志,还可以加上一些辅助的命令提取自己想要的内核日志,实在是不能再好的了。

root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0# dmesg |tail -1

[   36.406262] init: vmware-tools pre-start process (1789) terminated with status 1

root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0# dmesg |head -1

[    0.000000] Initializing cgroup subsys cpuset

root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0# dmesg --help


Usage:

dmesg [options]


Options:

-C, --clear                 clear the kernel ring buffer

-c, --read-clear            read and clear all messages

-D, --console-off           disable printing messages to console

-d, --show-delta            show time delta between printed messages

-E, --console-on            enable printing messages to console

-f, --facility <list>       restrict output to defined facilities

-h, --help                  display this help and exit

-k, --kernel                display kernel messages

-l, --level <list>          restrict output to defined levels

-n, --console-level <level> set level of messages printed to console

-r, --raw                   print the raw message buffer

-s, --buffer-size <size>    buffer size to query the kernel ring buffer

-T, --ctime                 show human readable timestamp (could be

                            inaccurate if you have used SUSPEND/RESUME)

-t, --notime                don't print messages timestamp

-u, --userspace             display userspace messages

-V, --version               output version information and exit

-x, --decode                decode facility and level to readable string


Supported log facilities:

   kern - kernel messages

   user - random user-level messages

   mail - mail system

 daemon - system daemons

   auth - security/authorization messages

 syslog - messages generated internally by syslogd

    lpr - line printer subsystem

   news - network news subsystem


Supported log levels (priorities):

  emerg - system is unusable

  alert - action must be taken immediately

   crit - critical conditions

    err - error conditions

   warn - warning conditions

 notice - normal but significant condition

   info - informational

  debug - debug-level messages


root@ubuntu:/usr/src/linux-source-3.2.0/linux-source-3.2.0#


动态打印内核日志

我们写代码的时候,有些日志你让它一直输出的话,就会不断的刷屏,把别人的日志给覆盖了,查看日志的时候就会特别麻烦,但是你有想让这个地方打印一些日志,比如,测试人员过来给你说,某某工程师,你的这个模块有 bug 了,你说,把自己给我看看,你拿到机器,你输入一串东东,也没有重新编译烧录内核,你想看的日志就出来了,就是这么炫,看起来还是挺爽的。


所以动态打印内核日志也是非常的爽的,不仅让你的内功加深了很多,也让你做项目更加顺手。

内核配置打开动态打印内核日志功能

CONFIG_DYNAMIC_DEBUG=y

CONFIG_DEBUG_FS=y


举个例子,我们看看这一句打印


pr_debug("%s: %s (%s)\n",

                __func__,

                chan ? "success" : "fail",

                chan ? dma_chan_name(chan) : NULL);


pr_debug 是在 printk.h 里面定义的,定义如下

/* If you are writing a driver, please use dev_dbg instead */

#if defined(DEBUG)

#define pr_debug(fmt, ...) \

printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#elif defined(CONFIG_DYNAMIC_DEBUG)

/* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */

#define pr_debug(fmt, ...) \

dynamic_pr_debug(fmt, ##__VA_ARGS__)

#else

#define pr_debug(fmt, ...) \

no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#endif


有时间去源码里面翻翻还是非常不错的,里面写了一个,如果你写驱动的话,就使用哪个函数,每每看到这样的英文注释,我都感觉自己非常的卑微。


三个宏分别决定了 pr_debug 使用哪个函数来输出 Log

第一种是,如果定义了 DEBUG 就使用 printk 开输出

第二种是,如果定义了 CONFIG_DYNAMIC_DEBUG 就采用动态输出

第三种就不输出了,就是你写的这个代码,没有任何输出了。


打开动态调试示例命令

#echo 'file sprdfb_main.c +p' > /sys/kernel/debug/dynamic_debug/control

#echo 'file lcdc.c +p' > /sys/kernel/debug/dynamic_debug/control

#echo 'file sprdfb_dispc.c +p' > /sys/kernel/debug/dynamic_debug/control

#echo 'file sprd-core.c +p' > /sys/kernel/debug/dynamic_debug/control


关闭动态调试示例命令

#echo 'file sprdfb_main.c -p' > /sys/kernel/debug/dynamic_debug/control

#echo 'file lcdc.c -p' > /sys/kernel/debug/dynamic_debug/control

#echo 'file sprd-corec.c -p' > /sys/kernel/debug/dynamic_debug/control


查看当前动态调试的状态

我就不把输出的日志贴上来了,因为太多了,我怕别人打我

cat /sys/kernel/debug/dynamic_debug/control


关于上面提到的 /sys/kernel/debug/ 这个可能在不同的系统下面还会不一样,主要看挂载点不同,不过不管怎么样,我们都可以用 find 命令搜索 dynamic_debug 来找到它的目录位置。

linux@ubuntu:~$ sudo find / -iname dynamic_debug

/sys/kernel/debug/dynamic_debug


给个例程看看我在 rockchip 的安卓平台上是如何使用 dynamic_debug 来动态调试代码的

代码patch

--- a/kernel/drivers/gosodrv/touchscreen/ft5x06_ts.c

+++ b/kernel/drivers/gosodrv/touchscreen/ft5x06_ts.c

@@ -402,6 +402,7 @@ static void ft5x0x_ts_pen_irq_work(struct work_struct *work)

       struct ft5x06_ts_data *data = container_of(work, struct ft5x06_ts_data,

                                         pen_event_work);

       //printk("ft5x0x_ts_pen_irq_work\n");

      pr_debug("%s: dev_dbg test owen.wei ==============\n", __func__);

       ret = ft5x06_handle_touchdata(data);

       if (ret)

       pr_err("%s: handling touchdata failed\n", __func__);


命令触发打印Log

adb root 获取root权限


255|root@android:/ # mkdir data/debugfs   建立debugfs日志文件

mkdir data/debugfs

root@android:/ # mount -t debugfs none /data/debugfs  挂载到这个日志文件里去

mount -t debugfs none /data/debugfs

root@android:/ # echo -n "file ft5x06_ts.c +p" > /data/debugfs/dynamic_debug/control  打开ft5x06_ts.c下面的pr_debug日志输出

/data/debugfs/dynamic_debug/control                                          <

root@android:/ #

各位大哥大姐,看到没有,我把文件系统挂载的位置决定了 dynamic_debug 文件的位置,这个要特别的注意哈。


命令帮助总结

标志规范包括随后的改变操作

由一个或多个标志字符组成。变更操作是一个

人物:


   -     删除给定的标志

  +     添加给定的标志

  =     将标志设置为给定的标志


标志是:


 p 启用 pr_debug()调用点。

 f  在打印的消息中包含功能名称

 l  在打印的消息中包含行号

 m 在打印的消息中包含模块名称

 t  在非中断上下文生成的消息中包含线程ID

 _没有设置标志。(或者“ 与其他输入D)


示例

Examples ========

// enable the message at line 1603 of file svcsock.c


nullarbor:~ # echo -n 'file svcsock.c line 1603 +p' > <debugfs>/dynamic_debug/control 打开某个文件某一行的日志

// enable all the messages in file svcsock.c  打开某个文件的所有日志


nullarbor:~ # echo -n 'file svcsock.c +p' > <debugfs>/dynamic_debug/control

// enable all the messages in the NFS server module 打开某个模块的所有日志


nullarbor:~ # echo -n 'module nfsd +p' > <debugfs>/dynamic_debug/control

// enable all 12 messages in the function svc_process() 打开某个函数的所有日志


nullarbor:~ # echo -n 'func svc_process +p' > <debugfs>/dynamic_debug/control

// disable all 12 messages in the function svc_process() 关闭某个文件的所有日志


nullarbor:~ # echo -n 'func svc_process -p' > <debugfs>/dynamic_debug/control

// enable messages for NFS calls READ, READLINK, READDIR and READDIR+.


nullarbor:~ # echo -n 'format "nfsd: READ" +p' > <debugfs>/dynamic_debug/control


更改printk输出串口号

上面说的都是一些理论的东西,理论的很多都是可以百度到的,刚好我在看printk部分的时候,有一个朋友问了我一个问题,他问我,发哥,我想把我printk输出的日志重定向串口修改一下,在哪里修改呢?


可能看了上面的文章,心里还是有点思路的,但是看了理论的部分,再实际去写代码的时候,还是会有些不一样,特别是厂商拿到Linux 内核之后,都会自己做一些修改,高通的自己修改高通的变成自己的SDK,MTK的也会自己修改自己的,虽然有些小变化,但是整体框架是不可能变化太多的。


所以,我们需要做的,就是 “fucking the code” 就好了。


下面是整个修改的流程,感谢小贝同学的无私奉献。


实战过程

我最近负责的一个项目,高通平台SDK默认SBL、LK、Kernel log都是从uart5输出的;

然并卵,坑爹的硬件把uart5另做它用,留了个uart2来输出系统log,并甩了一句“软件改一下就可以了……”


我相信很多人都遇到这样悲催的事情了吧,项目开始的时候,不让软件确认,硬件自以为认为可以修改软件就可以完成,完全不考虑项目周期和风险,如果作为软件工程师,我真的也想甩一句,你要不都用模拟电路实现了吧,我们还可以省下一颗主控芯片,后面还可以降低成本,都不用给高通交Lisence的费用了。


V9700项目,高通平台SDK默认SBL、LK、Kernel log都是从uart5输出的,但是产品定义上uart5有其他用途,硬件留了uart2做为log输出口,开始修改默认log输出口

开始做之前,先问下同事有没有改过这三个阶段的log,同事说,SBL有个.xml文件,改一下就可以了。

于是,进去到SBL源码目录中,使用find . -iname "*.xml"查找文件,列出了一大排.xml文件,看了下路径,发现uart/config/下面有好多不同项目的.xml文件

(路径:SBL/core/buses/uart/config/)


640?wx_fmt=png

OK,根据项目,打开对应的配置文件,里面一堆uart的配置,咱也不懂都是干啥,咱也不需要了解是干啥,因为我发现了这个

640?wx_fmt=png

好嘛,SBLlog走uart5输出,这里填的就是UART_PHY_DEVICE_5,果断改为UART_PHY_DEVICE_2试一试

经历了编译、导出镜像、下载,验证后发现,OK,SBL log从uart2开始了。

好了,接下来看下LK阶段如何改uart吧。按原本套路,先问下同事有没有做过,同事说记得LK里有个gpio.c是可以配置uart的GPIO的,老办法,进LK查找下gpio.c结尾的文件,嗯,不错,找到了,打开看下:(路径:lk/platform/mdm***/gpio.c)

640?wx_fmt=png

打开原理图看下下,gpio8、9对应的是uart5 的GPIO,看看代码里注释, blsp uart 2,我艹,原来还是祖传代码……,不管了,先改一改试一试……改成uart2 对应的gpio4、5试一试……试过的结果是没卵用,LK log消失了,uart2没有,uart5也没有,看了这个方法不行……

那就看下是谁调用了gpio_config_uart_dm函数,找到了如下函数:(路径:lk/platform/msm_shared/uart_dm.c)

640?wx_fmt=png

OK,再找下是谁调用了uart_dm_init函数:(路径:lk/target/mdm****/init.c)

640?wx_fmt=png

吆西,我好想发现了什么……,回过头来研究下uart_dm_init函数中的clock_config_uart_dm函数:(路径:lk/platform/mdm****/acpuclock.c)

640?wx_fmt=png

嗯……,看来要找下哪里配置uart5_iface_clk、uart5_core_clk 这两个时钟的地方了;还记得之前追踪到了target_early_init函数吗?target_early_init函数要通过字符串匹配时钟,那就得有个地方配置这个字符串的,这个地方得是在target_early_init被调用前配置才可以,于是,找谁调用了target_early_init:(路径:lk/kernel/main.c)

640?wx_fmt=png

看来这就是LK的入口函数了,看到target_early_init前面有好三个函数,一个个看太麻烦了,我看到了platform……,嗯,就你了:platform_early_init,进入看看:(路径:lk/platform/mdm****/platform.c)

640?wx_fmt=png

嗯,发现有platform_clock_init,先进去看看:(路径:lk/platform/mdm****/acpuclock.c)

640?wx_fmt=png

嗯,找到了uart5时钟配置的地方,再进去一点点看看:

640?wx_fmt=png

嗯,原来是寄存器地址……,好吧,扒下代码,找个相近的平台,寄存器地址排列方式差不多的拿来一用,借来uart5的代码一用,于是,我添加了uart2的clock:

640?wx_fmt=png


640?wx_fmt=png

再回到target_early_init函数,把 uart_dm_init(5, 0, BLSP1_UART5_BASE);这行换成uart_dm_init(2, 0, BLSP1_UART1_BASE)。

(PS:不要问我为啥uart5写BLSP1_UART5_BASE,uart2就写BLSP1_UART1_BASE,这就是俩地址,为啥命名这个样子你去问下高通,我也很头痛)。

然后在gpio_config_uart_dm里,配置GPIO为uart2的gpio4、5。

编译、导出镜像、下载,开机……

OK,uart2输出SBL log正常,LK log正常,kernel无log,嗯这个正常,我还没改kernel呢,但是,纳尼?怎么重启了?

回想一下,LK默认uart5输出log正常,我就改了个uart2上去,就不行了?

uart5输出时把gpio改成uart2的还能正常开机,全部换成uart2就不行了?

恩,好像和uart5的时钟有关?不管了,试一试……

640?wx_fmt=png

我这样改,先初始化uart2,然后初始化uart5,但是,uart5的GPIO还是uart2对应的GPIO,也就是只初始化uart5的时钟,我来试一试………OK,LK log修改成功!

剩下个kernel log,看了下cmdline,发现是ttyHSL0输出的,嗯,也就是我只要把ttyHSL0这个节点换车uart2就可以。嗯,我真佩服我自己

在dts中,修改注册顺序,把uart2第一个注册,这样ttyHSL0就是uart2的节点了

编译,下载,验证,嗯,SBL 正常,LK 正常,kernel……怎么没有?哦,吆西,出来了……

嗯,kernel丢失了前面的1.4秒左右的log,看了下log,应该是TTYHSL0节点没有创建前的早期log……查看正常log,发现前面几行打印的是

[    0.000000] Booting Linux on physical CPU 0x0

[    0.000000] Linux version 3.18.48 (zhangbei@LsBuildSrv-3) (gcc version 4.9.3 (GCC) ) #1 PREEMPT Fri Jul 5 09:47:37 CST 2019

[    0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c53c7d

[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache

[    0.000000] Machine model: Qualcomm Technologies, Inc. MDM 9607 MTP

[    0.000000] Early serial console at I/O port 0x0 (options '')

[    0.000000] bootconsole [uart0] enabled

那就根据第一行log来找代码:

OK,发现了,原来在这里:(路径:kernel/arch/arm/kernel/setup.c)

640?wx_fmt=png

进pr_info里面看看:(路径:kernel/include/linux/printk.h)

640?wx_fmt=png

嗯,原来是printk穿了个花衣裳……进来看一看:(路径:kernel/printk/printk.c)

640?wx_fmt=png

嗯,CONFIG_KGDB_KDB宏没有定义,走vprintk_emit函数,进来看一看,额,太长了,就贴出关键的吧:

640?wx_fmt=png

console_trylock_for_printk就是看下console是否存在,存在就返回1

console_unlock 这个……这个里面代码有点长,我也没看明白,不过我发现了这个:

640?wx_fmt=png

call_console_drivers这看函数名也明白干啥的了吧?!

打电话给console设备,进来看一看

640?wx_fmt=png

嗯,write,写嘛,看来这里就是把log写到uart口的地方了,但是,线索断了……

别着急,让我看下正常log,嗯~,有Early serial console at I/O port这行,根据这个再找一找:(路径:kernel/drivers/tty/serial/earlycon.c)

640?wx_fmt=png

跟踪一下,看谁调用了parse_options函数:

640?wx_fmt=png

OK,这里调用了parse_options,最后调用了register_console来注册一个早期的console。这就对应printk中的console存在就打印log到console,嗯,继续看下谁调用了setup_earlycon函数:(路径:kernel/include/linux/serial_core.h)

640?wx_fmt=png

额,万万没想到,居然是一个宏……,emmmm,结合编译后的驱动.o文件,看下谁调用了这个宏:(路径:kernel/drivers/tty/serial/msm_serial_***.c)

640?wx_fmt=png

原来在这里,这就是printk中最后调用con->write(con, text, len),write实现的地方……

然并卵,还有个问题,这个函数是啥时候执行的呢?setup_earlycon函数中的第一个传参buf是怎么来的的?我查看了下setup_earlycon中代码,发现buf传递过来的数据经过处理后成为了membase,这个是uart的寄存器地址,问题来了:EARLYCON_DECLARE宏什么时候执行的?参数buf又是怎么传递的?继续看EARLYCON_DECLARE:

640?wx_fmt=png

我怎么看怎么感觉这像是一个函数呢?根据

EARLYCON_DECLARE(msm_hsl_uart, msm_hsl_earlycon_setup);

这行代码,推断函数名应该为 msm_hsl_uart__setup_earlycon ;

为了判断函数存在不存在,跑到编译后生成的System.map文件,查找了下:

640?wx_fmt=png

嗯,夸奖一下自己,这个都能找到。还剩一个问题,啥时候执行的?又怎么传参的?

看到EARLYCON_DECLARE宏最后一行

early_param("earlycon", name ## _setup_earlycon);

我认为秘密就在这里,关键是我不知道这行是干啥的,于是,问下度娘:

640?wx_fmt=png

果然,高手在民间,网友都通神。

commandline……我好想发现了什么,赶快adb shell 进去,cat proc/cmdline看下:

640?wx_fmt=png

这里有个eralycon,early_param("earlycon", name ## _setup_earlycon)这行代码也有这个,应该就是用这个字符匹配的,这个字符后面的0x开头的就应该是uart5的地址了,看了下DTS中uart5的地址,果然一模一样!

迫不及待的想要试一试,先把这个cmdlin文件导出,修改后在导入,卧槽!?不能导入……

找到了修改的地方,但是cmdline这个文件push不进机器,没办法找吧,找下这个cmdline这个在哪里。

前面查看LK代码的时候我就发现了,这个平台有点怪,cmdline并不是LK产生的,于是去源码目录里找,终于找到了,修改、编译、验证,SBL log正常、LK log 正常、kernel log…正常!OK啦

整理代码准备提交


总结

printk是内核里面非常重要的调试手段,不知道大家注意了没有printk前面对应的时间戳是和开机时间对应起来的,通过这个时间戳,我们可以知道当前的开机时间,如果我们这个设备放在公司一天回来后查看时间戳如果不对应,那我们也可以知道自己的设备肯定是重启了。


还有一个功能,printk可以用来计算时间,写代码的时候,你有没有想过自己代码的执行时间,我之前做的一个项目,跟一个大神一起调试平板的亮屏和灭屏时间,就用到了printk,通过在不同的阶段打印,就可以看出是哪里消耗了多少时间。


内核调试还有后面的章节,因为篇幅有点长,先写第一个小章节,比如通过gdb调试,dump_stack调试,还有一些proc文件系统调试等等,我觉得还是有必要介绍的。所以就放到后面的章节去讲解了。


还是啰嗦一下,非常感谢大家赏脸看小弟的文章,如果可以,给个转发或者再看,江湖很大,我们后会有期。

===================================

640?wx_fmt=jpeg



评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值