Skip to main content
 首页 » 操作系统

Linux printk()相关函数学习笔记

2022年07月19日316arxive

参考：

https://www.cnblogs.com/sky-heaven/p/6742062.html
韦东山老师的printk讲解：https://blog.csdn.net/W1107101310/article/details/80526039

1.平台内核启动参数：
bootargs = "console=ttySC0,115200n8 rw root=/dev/mmcblk0p3 rootwait ignore_loglevel vt.global_cursor_default=0"

ignore_loglevel：printk.c中即作为启动参数也作为模块参数，指定了它：ignore loglevel setting (prints all kernel messages to the console)"
只有suppress_message_printing()使用了它，拿它做判断

2. 4.14.35内核printk()的调用路径：

printk 
    vprintk_fun 
        vprintk_emit    调用local_irq_save(flags)并获取spin_lock! 
            console_unlock() 关闭本地中断调用call_console_drivers 
                call_console_drivers() 
                    sc-shi.c中注册的console_write()

suppress_message_printing()  里面检测了printk()的打印等级，决定哪些等级打印，哪些等级不打印，到那时配置了一个命令行参数使其恒为假

TODO：确认一下cmdline中的ignore_loglevel生效了没有！

平台上配置的是128K的log_buf
#define CONFIG_LOG_BUF_SHIFT 17 /*1<<17=128K*/
static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN); /*128k,以struct printk_log大小对其*/

3.Kernel代码查看

#define KERN_EMERG      KERN_SOH "0"    /* system is unusable */ 
#define KERN_ALERT      KERN_SOH "1"    /* action must be taken immediately */ 
#define KERN_CRIT       KERN_SOH "2"    /* critical conditions */ 
#define KERN_ERR        KERN_SOH "3"    /* error conditions */ 
#define KERN_WARNING    KERN_SOH "4"    /* warning conditions */ 
#define KERN_NOTICE     KERN_SOH "5"    /* normal but significant condition */ 
#define KERN_INFO       KERN_SOH "6"    /* informational */ 
#define KERN_DEBUG      KERN_SOH "7"    /* debug-level messages */ 
 
//在menuconfig中或下面将第一个参数改为8，也能都打印出来。 
int console_printk[4] = { 
    CONSOLE_LOGLEVEL_DEFAULT,    /*7: console_loglevel  将其改为8，KERN_DEBUG等级的也可以打印出来！ */  
    MESSAGE_LOGLEVEL_DEFAULT,    /*4: default_message_loglevel */ 
    CONSOLE_LOGLEVEL_MIN,        /*1: minimum_console_loglevel */ 
    CONSOLE_LOGLEVEL_DEFAULT,    /*7: default_console_loglevel */ 
};

4.实验

目前能打印的级别：7    4    1    7 (7打印不出来，高于7才能打印出来)

printk(KERN_ERR"kernel: %s: kernel error printed!\n", __func__);    //能打印出来 
printk(KERN_INFO"kernel: %s: kernel info printed!\n", __func__);    //能打印出来 
printk(KERN_DEBUG"kernel: %s: kernel debug printed!\n", __func__);  //不能打印出来

但是此时使用dmesg都可以打印的出来:

[    5.171903] kernel: request_exclusive: kernel error printed! 
[    5.217513] kernel: request_exclusive: kernel debug printed! 
[    5.217517] kernel: request_exclusive: kernel info printed!

测试dmesg和dmesg -n 8是一样的！也就是#dmesg -n 8 只对打印到串口上的有影响，8会KERNEL_DEBUG也打印出来。但是它与dmesg dump出来的log无关。

//目前默认状态： 
# cat /proc/sys/kernel/printk 
    7    4    1    7 
//dmesg -n 8后： 
# cat /proc/sys/kernel/printk 
    8    4    1    7

此时程序再打印KERN_DEBUG的信息也能打印出来了！

5. 修改Linux内核的printk缓冲区（log缓冲区）大小

//printk.c 
#define LOG_ALIGN __alignof__(struct printk_log)   
#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)   
static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);   
static char *log_buf = __log_buf;   
static u32 log_buf_len = __LOG_BUF_LEN;

CONFIG_LOG_BUF_SHIFT这个配置项又是在init/Kconfig里定义，默认是128KB，有个range，若是大于1M时，需要同时将range改大。

config LOG_BUF_SHIFT   
        int "Kernel log buffer size (16 => 64KB, 17 => 128KB)"   
        range 12 21   
        default 17   
        depends on PRINTK

6. 高频的长log打印往往导致死机，此时可以关闭watch dog，Qcom平台关闭命令：echo 1 > /sys/bus/platform/drivers/msm_watchdog/xxxx/disable，如果还是不行的话，可以使用trace_printk，把内容打印到trace中，会自动带入函数名，支持高频打印，抓trace才能看

void set_user_nice(struct task_struct *p, long nice) 
{ 
    ... 
+   trace_printk("DEBUG: set_user_nice: pid=%d, nice_set=%d\n", p->pid, nice); 
    ... 
}

抓trace中显示为：set_user_nice: DEBUG: set_user_nice: pid=7567, nice_set=-10

若想在trace解析后显示出来，5.10内核以后还可以使用如下方式：

//kernel/power/qos.c 
 
static noinline int tracing_mark_write(const char *buf) 
{ 
    trace_printk(buf); 
    return 0; 
} 
 
void freq_systrace_c(unsigned long freq, char *msg) 
{ 
    char buf[256]; 
 
    snprintf(buf, sizeof(buf), "C|9999|%s|%lu\n", msg, freq); //9999可以是任意pid 
    tracing_mark_write(buf); 
} 
 
int freq_qos_update_request(struct freq_qos_request *req, s32 new_value) 
{ 
    if (!req) 
        return -EINVAL; 
 
    trace_printk("C|9999|TEST_%s_%d|%lu\n", current->comm, current->pid, new_value); //fail，trace解析后不会显示出来 
    trace_printk("C|9999|%s|%lu\n", current->comm, new_value); //fail，trace解析后不会显示出来 
    freq_systrace_c(new_value, current->comm); //success，trace解析可以显示出来 
    ... 
}

解析后在systrace上检索 9999 。格式要严格对应上才能在解析后的trace上显示出来！

7. 若是想通过trace解析界面看，还可以使用 event_trace_printk 函数，见 https://www.cnblogs.com/hellokitty2/p/14165517.html

8. printk_deferred() 函数使用说明

printk_deferred:
当持有 rq 锁时，我们在调度程序代码中使用 printk_deferred，因为调用 printk 会导致死锁。 这是一个不错的解决方案，但是当我们想要标记 printk_deferred 危险区域时，使用起来有点困难。目前，在调度程序中使用 WARN_ON 或 WARN_ON_ONCE 并持有 rq 锁会在满足警告条件时会导致死锁。 如果我们可以使用 pintk_deferred_{enter, exit} 标记持有 rq 锁的 printk_deferred 区域，则该区域中的所有控制台输出都将被延迟。

参考： https://lkml.org/lkml/2020/9/27/281

9. 带有控制的打印

#define TAG "core_ctl" 
 
#define core_ctl_debug(x...)        \ 
    do {                \ 
        if (debug_enable)    \ 
            pr_info(x);    \ 
    } while (0) 
 
module_param_named(debug_enable, debug_enable, bool, 0600); 
 
core_ctl_debug("%s: Trying to adjust cluster %u from %u to %u\n", TAG, cluster->cluster_id, cluster->active_cpus, need);

printk:

#define chg_err(fmt, ...) \ 
    if (debug_enable) {        \ 
        printk(KERN_ERR "[%s]"fmt, __func__, ##__VA_ARGS__) \ 
    }

10. 打印设备树节点

使用 %pOF 格式 struct device_node *np 得到节点的设备树路径名，eg: /soc/board_temp

11. 打印函数指针

在4.19内核上 %pf 由函数指针打印出函数名，在5.10内核上 %pf 失效了，需要改为使用 %pS 来打印函数名。各种打印格式与打印的内容：

%pS：cpuset_hotplug_workfn.cfi_jt+0x0/0x8 
%p：0000000040c1bf1d 
%ps：cpuset_hotplug_workfn.cfi_jt 
%px：ffffffd65ae48588 //这个可以看 /proc/kallsyms 
%pX：0000000040c1bf1d

cat /proc/kallsyms 有时显示全为0，需要 echo 0 > /proc/sys/kernel/kptr_restrict 后才能正常显示。

举个异步queue work在workfunc中绑核进行trace的例子：

//在想trace的由异步调用的函数中设置标志位 
DEFINE_PER_CPU(int, my_trig_flag); 
set_cpus_allowed_common 
    __this_cpu_write(my_trig_flag, 1); 
 
 
//在workqueue执行work时打印worker->func函数名 
DECLARE_PER_CPU(int, my_trig_flag); 
process_one_work 
    __this_cpu_write(my_trig_flag, 0); 
    worker->current_func(work); 
    if (__this_cpu_read(my_trig_flag)) { 
        printk("worker_func = %pS\n", worker->current_func); 
    }

12. 内核中打印UTC时间

static void debug_print_utc_time(char *annotation) 
{ 
    struct timespec ts; 
    struct rtc_time tm; 
 
    getnstimeofday(&ts); 
    rtc_time_to_tm(ts.tv_sec, &tm); 
    pr_info("%s: %d-%02d-%02d %02d:%02d:%02d.%09lu UTC\n", annotation, tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, 
           tm.tm_hour, tm.tm_min, tm.tm_sec, ts.tv_nsec); 
} 
 
debug_print_utc_time("TAG: enter"); 
debug_print_utc_time("TAG: exit");

13. 内核中打印代码段执行时间

#include <linux/sched/clock.h> 
 
unsigned long t1, t2, delta_t; 
 
t1 = local_clock(); 
//your code 
t2 = local_clock(); 
 
delta_t = t2 - t1;

单位: ns


本文参考链接：https://www.cnblogs.com/hellokitty2/p/9867168.html
  文章来源：
  https://www.itguest.com/post/ghg1a7.html
阅读延展