内核打印调试printk学习笔记

Printk打印格式与打印等级

打印数据

• 打印数据格式(跟printf类似、不支持浮点型)
• 打印指针
• • %p:打印指针地址
• • %pF:打印函数指针的函数名和偏移地址
• • %pf:只打印函数指针的函数名&＃xff0c;不打印偏移地址
• • …
• • 打印文件名、函数名、行号

打印等级

日志级别(loglevel)

• 定义&＃xff1a;include/linux/kern_levels.h
• 日志等级&＃xff1a;/proc/sys/kernel/printk
• 日志等级与控制台打印等级

修改控制台打印等级

• echo 8 > /proc/sys/kernel/printk
• dmesg –n 8
• 7 4 1 7

控制台、终端和串口之间的关系

终端(terminal)与控制台(console)

• 能显示系统消息的称为控制台&＃xff0c;其它称为终端
• 硬件终端&＃xff1a;多个键盘、显示器连接一个电脑&＃xff0c;多人共用电脑&＃xff0c;每个显示器键盘称为一个 终端设备&＃xff0c;提供命令行用户界面功能。电脑本身也有显示器键盘&＃xff0c;能看到系统信息&＃xff0c;开关机控制等&＃xff0c;称为控制台。而各个进程绑定的终端只能显示该进程的信息&＃xff0c;不会显示系统信息。
• 虚拟终端&＃xff1a;用软件模拟的终端。使用Ctrl&＃43;Alt&＃43;F1~F6切换到6个不同虚拟终端(tty1~tty6)。Linux下默认所有虚拟终端都是控制台。都可以显示系统消息。
• 控制终端&＃xff1a;当前环境所处的终端&＃xff1a;/dev/tty&＃xff0c;使用tty命令查看当前终端/dev/tty与哪个实际终端进行连接。
• 伪终端&＃xff1a;用户登录(本地/SSH/telnet等)后动态创建的控制台设备文件&＃xff0c;在/dev/pts/目录下&＃xff0c;使用tty查看当前控制终端/dev/tty连接。在图形界面下&＃xff0c;console映射到/dev/pts&＃xff1b;在命令行模式下&＃xff0c;映射到tty0.

控制台与串口

• 控制台可以映射到不同的终端上&＃xff0c;tty0 表示当前所使用终端。设备文件/dev/console即tty0&＃xff0c;指向映射的那个终端tty。系统信息会显示输出到console映射的终端上。
• 对于Linux下的虚拟终端&＃xff0c;Stdin是输入子系统&＃xff0c;stdout是console映射的终端tty。
• 串口终端(dev/ttySn、ttySACn)&＃xff1a;对应DOS系统下的COM1、COM2

嵌入式平台下的console

• Console与终端建立映射可以通过bootargs进行设置console&＃61;tty0
• 建立关联后&＃xff0c;console的打印输出(write函数)由终端设备串口的write回调函数注册完成。

查看和重映射伪终端

每一个伪终端都会在/dev/pts下创建一个节点,可以将内容重映射到该节点即可从节点对应的伪终端看到信息.
使用tty查看当前伪终端节点号

Printk实现

Printk实现流程

• test[]&＃xff1a;打印到控制台的字符串缓存区:根据控制台等级先存放于cont.buf&＃xff0c;调用console_unlock将cont.buf拷贝到test[]&＃xff0c;最后调用底层终端设备write函数打印
• __log_buf&＃xff1a;内核日志缓冲区&＃xff0c;包括等级低无法打印到控制台的日志

控制台console与串口的绑定

• 默认tty0&＃xff1a;当前控制台使用的虚拟终端&＃xff0c;Linux下一般为显示器、LCD显示屏
• 在嵌入式下&＃xff0c;一般重定向console到串口终端
• 控制台的初始化

通过其它方式查看log信息

通过dmesg命令

• 清除信息 dmesg –c
• 通过cat /proc/kmsg

syslogd日志服务

• 在Linux系统中会启动两个守护进程klogd&syslogd
• 守护进程klogd会根据syslog()系统调用或/proc文件系统从__log_buf读取printk的打印信息
• 根据配置文件/etc/*.conf将不同的服务产生的log记录到/var/log不同目录中

rsyslogd

• 增强版的syslogd&＃xff0c;在syslogd基础上增加数据库支持、日志内容筛选、定义日志格式模板。
• 使用TCP传输rsyslog可以将日志从远程服务器传送到本地服务器上。

Printk打印配置

打印时间戳

• 内核配置
• make menuconfig
• Kernel hacking
• Show timing information on printks
• make uImage

设置缓冲区大小

Printk打印内核缓存区

• 环形buffer
• 缓冲区满时&＃xff0c;可能会覆盖掉以前的打印信息

修改缓冲区大小

• 内核缓冲区&＃xff1a;__log_buf
• 修改 __LOG_BUG_LEN
• 大小最高可以达到2^25&＃61;32M&＃xff0c;不同体系结构可能不一样
• 内核配置
• make menuconfig
• General setup
• Kernel log buffer size(16 &＃61;> 64KB, 17 &＃61;> 128KB)

限速打印

printk对系统性能的影响

• 函数效率低&＃xff1a;字符单字节拷贝效率低
• 大量打印(串口)会拖慢系统、影响系统性能
• 对时序要求严格的场合有影响(协议交互、同步传输、流媒体)

printk打印限速

• printk_timed_ratelimit(unsigned long *caller_jiffies, unsigned int interval_msecs)

unsigned long time;if (printk_timed_ratelimit(&time, 1*HZ))printk(<2\>, “warning info\n");


printk限速

• printk_ratelimit()
• /proc/sys/kernel/printk_ratelimit 5 控制打印间隔
• /proc/sys/kernel/printk_ratelimit_burst 10 控制打印消息条数

打印函数调用栈

OOPS

什么是Oops&＃xff1f;从语言学的角度说&＃xff0c;Oops应该是一个拟声词。当出了点小事故&＃xff0c;或者做了比较尴尬的事之后&＃xff0c;你可以说"Oops"&＃xff0c;翻译成中国话就叫做“哎呦”。“哎呦&＃xff0c;对不起&＃xff0c;对不起&＃xff0c;我真不是故意打碎您的杯子的”。看&＃xff0c;Oops就是这个意思。

在Linux内核开发中的Oops是什么呢&＃xff1f;其实&＃xff0c;它和上面的解释也没什么本质的差别&＃xff0c;只不过说话的主角变成了Linux。当某些比较致命的问题出现时&＃xff0c;我们的Linux内核也会抱歉的对我们说&＃xff1a;“哎呦&＃xff08;Oops&＃xff09;&＃xff0c;对不起&＃xff0c;我把事情搞砸了”。Linux内核在发生kernel panic时会打印出Oops信息&＃xff0c;把目前的寄存器状态、堆栈内容、以及完整的Call trace都show给我们看&＃xff0c;这样就可以帮助我们定位错误。
参考.

只打印堆栈&＃xff0c;不发生OOPS

• dump_stack()
• WARN_ON()

打印堆栈并引发OOPS

• BUG()和BUG_ON()
• 引发OOPS&＃xff0c;进而导致栈回溯和错误信息打印

打印堆栈并引发内核panic

• panic()

内核OOPS和panic的区别

• 内核panic
  内核完全无法使用
• 硬panic和软panic
• • 硬panic&＃xff1a;一般可能由驱动模块的中断处理导致&＃xff0c;系统会崩溃或定屏(类似于Windows下的蓝屏)、系统被锁定&＃xff0c;不能使用
• • 软panic&＃xff1a;非中断处理引起的内核模块崩溃&＃xff0c;系统还能用&＃xff0c;但崩溃的模块已经不能用。通常会导致段错误、可以看到一个OOPS&＃xff0c;一般收集好信息后&＃xff0c;还得重启&＃xff0c;使系统正常工作。

动态调试

动态调试优点

• 打印开关在运行状态下就可以动态关闭
• 打印范围可控&＃xff1a;模块级、文件级、某一行、某个函数、某个关
  键字符串

内核配置

• 内核配置&＃xff1a; CONFIG_DYNAMIC_DEBUG&＃xff0c;支持开启动态打印
• • make menuconfig
• • General setup
• 驱动模块中使用pr_debug打印

pr_debug输出等级、打印格式类似printk

运行时动态打印开关控制

• echo “file hello.c &＃43;p” > /sys/kernel/debug/dynamic_debug/control
• echo “file hello.c -p” > /sys/kernel/debug/dynamic_debug/control

Dynamic debug

Line number

• echo -n ‘file hello.c line 16 &＃43;p’ > dynamic_debug/control

Func

• echo -n ‘func svc_process &＃43;p’ > dynamic_debug/control

Module

• echo -n &＃39;module hello &＃43;p‘ > dynamic_debug/control
• echo “file drivers/usb/* &＃43;p” > /dynamic_debug/control

Files of which include format“usb:”

• echo -n ‘format “usb: " &＃43;p’ > dynamic_debug/control

Enable all messages

• echo -n ‘&＃43;p’ > dynamic_debug/control

strace

用来追踪进程的系统调用和所接收的信号

• 应用程序不能直接访问硬件(读取磁盘文件、网卡、打印机)
• 访问硬件时需要通过系统调用&＃xff0c;用户态转为内核态
• 用于定位软件问题、性能分析

输出参数的含义

• 等号左边是系统调用的函数及其参数
• 右边是该系统调用的返回值

strace参数

常用参数

• -c 统计每一系统调用执行时间、执行次数和出错次数
• -i 输出系统调用的入口指针
• -T 显示每一个系统调用所耗的时间
• -t 在输出每一行前加上时间信息
• -tt 在输出每一行前加上时间信息&＃xff1a;微秒级
• -ttt 使用秒输出&＃xff0c;微妙级
• -f 输出由fork调用所产生的子进程
• -o 输出重定向到某一个file文件
• -x 以16进制输出非标准字符串
• -a 40 设置返回值的输出位置&＃xff0c;默认是40
• -p pid 跟踪指定的进程pid

追踪选项

• -e trace&＃61;set 跟踪指定的系统调用.默认的为set&＃61;all.
• -e trace&＃61;open,close,read,write表示只跟踪这四个系统调用.
• -e trace&＃61;file 只跟踪有关文件操作的系统调用.
• -e trace&＃61;process 只跟踪有关进程控制的系统调用.
• -e trace&＃61;network 跟踪与网络有关的所有系统调用.
• -e trace&＃61;signal 跟踪所有与系统信号有关的系统调用.
• -e trace&＃61;ipc 跟踪所有与进程通讯有关的系统调用.
• -e raw&＃61;set 将指定的系统调用的参数以十六进制显示.
• -e signal&＃61;SIGIO 指定跟踪的系统信号.默认为all.
• -e read&＃61;set 输出从指定文件中读出的数据.
• -e write&＃61;set 输出写入到指定文件中的数据.

strace应用举例

程序性能优化定位&＃xff1a;app启动慢

• strace -f -D -T -tt -o app.strace ./app
• 记录每个系统调用所消耗的时间

跟踪一个进程

• strace –o output.txt -T -tt -e trace&＃61;network -p pid
• 跟踪进程ID为pid进程的系统调用
• 记录每个系统调用消耗的时间&＃xff0c;时间显示格式为微秒级
• 只记录跟网络相关的系统调用,结果保存到output.txt文件中

移植strace到ARM平台

下载源代码

• https://sourceforge.net/projects/strace/

配置

• ./configure –host&＃61;arm-linux CC&＃61;arm-linux-gnueabi-gcc LD&＃61;arm-linux-gnueabi-ld

编译

• make CFLAGS &＃43;&＃61;“-static”

优化程序体积

• arm-linux-gnueabi-strip strace

内核转储

core dump

• 应用程序由于各种异常或者bug&＃xff0c;会导致运行过程中异常退出或中止
• 系统会将该程序运行时的内存、寄存器状态、堆栈指针、内存管理信息、各种函数的堆栈调用信息dump在一个core文件中
• 在嵌入式系统中&＃xff0c;core dump有时候会通过串口打印出来

造成core dump的原因

• 内存访问越界
• 数组越界访问
• 多线程读写的数据未加锁保护
• 非法指针
• 空指针、野指针
• 堆栈溢出
• 函数内不要使用大的数组、大的局部变量

core dump设置

查看

• ulimit -c
  

开启core dump

• /etc/profile&＃xff1a;ulimit –c unlimited //文件大小设置为unlimited,即不做限制
• 生成文件名格式core.pid&＃xff1a;echo 1 > /proc/sys/kernel/core_uses_pid

core dump文件格式设置

• 查看文件格式&＃xff1a;cat /proc/sys/kernel/core_pattern
• 设置文件格式&＃xff1a;echo ./core.%e.%p> /proc/sys/kernel/core_pattern
• 系统自启动生效&＃xff1a;/etc/rc.local

core dump文件格式

• %p 所dump进程的进程ID
• %u 所dump进程的实际用户ID
• %g 所dump进程的实际组ID
• %s 导致本次core dump的信号
• %t core dump的时间 (由1970年1月1日计起的秒数)
• %h 主机名
• %e 程序文件名

使用gdb查看core文件

步骤

• 编译程序时&＃xff0c;加上调试信息&＃xff1a;-g
• 使用方式&＃xff1a;gdb 程序文件 coredump文件
• 使用bt命令在源文件中定位程序出错在哪里
  

使用proc与内核进行交互

proc文件系统

• 虚拟文件系统&＃xff0c;在内核和用户空间进行通信
• proc内容动态创建&＃xff0c;断电后消失
• 一开始用来查看进程的信息
• 后来很多模块都可以通过节点与用户空间进行通信、交互

• 每个文件夹都代表一个进程的信息

通过proc查看内核进程信息

• /proc/pid/cmdline 包含了用于开始进程的命令 &＃xff1b;
• /proc/pid/cwd 包含了当前进程工作目录的一个链接 &＃xff1b;
• /proc/pid/environ 包含了可用进程环境变量的列表 &＃xff1b;
• /proc/pid/exe 包含了正在进程中运行的程序链接&＃xff1b;
• /proc/pid/fd/ 该目录包含进程打开的文件的链接&＃xff1b;
• /proc/pid/mem 包含了进程在内存中的内容&＃xff1b;
• /proc/pid/stat 包含了进程的状态信息&＃xff1b;
• /proc/pid/statm 包含了进程的内存使用信息&＃xff1b;

通过proc查看内核信息

打印等级

cat /proc/sys/kernel/printk


控制台

cat /proc/consoles


内存管理

文件系统

设备驱动程序

系统总线

电源管理

终端

系统控制参数

网络

proc接口

proc接口结构体

struct proc_dir_entry {umode_t mode;const struct inode_operations *proc_iops;//inode操作const struct file_operations *proc_fops;//文件操作struct proc_dir_entry *next, *parent, *subdir;read_proc_t *read_proc;write_proc_t *write_proc;atomic_t count;int pde_users;struct completion *pde_unload_completion;struct list_head pde_openers;spinlock_t pde_unload_lock;u8 namelen;char name[];
};


proc接口函数 API

• struct proc_dir_entry *proc_mkdir(const char *, struct proc_dir_entry *);
  在proc文件系统下创建一个目录
• void remove_proc_entry(const char *, struct proc_dir_entry *);
  在proc文件系统下删除一个目录
• struct proc_dir_entry *proc_create_data(const char *,umode_t,struct proc_dir_entry *,const struct file_operations *,void *);
  在proc文件系统下创建一个节点