fuzidage
专注嵌入式、linux驱动 、arm裸机研究

导航

 

1 dump_stack函数

打印内核调用堆栈。举个例子:

我们定义四个函数aaabbbcccddd,然后bbb中调用aaaccc中调用bbbddd函数谁都不调用。在入口函数中,我们调用cccddd函数,看看堆栈打印效果如何:

#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>
#include <linux/delay.h>
void aaa(void) {
    printk(KERN_EMERG "aaa\n");
    dump_stack();
    msleep(100);
}
void bbb(void) {
    printk(KERN_EMERG "bbb\n");
    aaa();
    msleep(100);
}
void ccc(void) {
    printk(KERN_EMERG "ccc\n");
    bbb();
    msleep(100);
}

void ddd(void) {
    printk(KERN_EMERG "ddd\n");
    msleep(100);
}
static int __init chrdevTest_init(void) {
    printk(KERN_EMERG "INIT func\r\n");
    ccc();
    ddd();

    return 0;
}
static void __exit chrdevTest_exit(void) {
    printk(KERN_EMERG "EXIT func\r\n");
}
module_init(chrdevTest_init);
module_exit(chrdevTest_exit);
MODULE_LICENSE("GPL");

可以看到当打印完aaa后开始dump_stack, 打印出函数调用栈。

image

2 内核态异常call trace等级

内核态call trace 有三种出错情况,分别是bug, oopspanic

1、 bug- bug只是提示警告
BUG: sleeping function called from invalid context at …, 比如在原子上下文中休眠,总断服务函数休眠,spin_lock中进行might_sleep等。

我在某个设备驱动的中断处理函数 XXX_ISR() 里加了 msleep(10) 之后:
image

可以看到跑出了BUG打印,为什么是BUG: scheduling while atomic呢?而不是BUG: sleeping function called from invalid context at …

那是因为在原子上文中发生了调度,我们调用might_sleep是会时间片到了啊,让出CPU自然就进行了schedule。

BUG: spinlock bad magic on CPU错误表示自旋锁使用时没有初始化。

2、 Oops- oops会终止进程,但是不会系统崩溃
程序在内核态进入一种异常情况,比如引用非法指针导致的数据异常,数组越界导致的取指异常,此时异常处理机制能够捕获此异常,并将系统关键信息打印到串口上,正常情况下Oops消息会被记录到系统日志中去。

3、 Panic -panic系统崩溃
当Oops发生在中断上下文中或者在进程0和1中,系统将彻底挂起,因为中断服务程序异常后,将无法恢复,这种情况即称为内核panic。

2.1 WARN_ON函数

我们把上面的实验aaa函数中dump_stack改成WARN_ON(1)函数。可以看到WARN_ON(1)就是调用了dump_stack,多了绿色打印部分而已:

image
image

注意只有当condition=1时才会真正调用__warn:
image

2.2 BUG_ON函数

BUG_ON这句,一旦执行就会抛出oops,导致栈的回溯和错误信息的打印,大部分体系结构把BUG()BUG_ON()定义成某种非法操作,这样自然会产生需要的oops。类似一种断言,让进程终止。我们把上面的实验aaa函数中dump_stack改成BUG_ON(1)函数:
image

2.3 panic函数

当Oops发生在中断上下文中或者在进程0和1中,系统将彻底挂起,因为中断服务程序异常后,将无法恢复,这种情况即称为内核panic

3 Ftrace工具集

FtraceFunction Trace的简写。它是一个内核函数追踪工具,旨在帮助内核设计和开发人员去追踪系统内部的函数调用流程。

还可以用来调试和分析系统的延迟和性能问题,并发展成为一个追踪类调试工具的框架:
image

可以看到还包括了用户态的ltraceftrace

3.1 Ftrace是如何记录信息的

Ftrace采用了静态插桩和动态插桩两种方式来实现。

3.1.1 静态插桩

Kernel中打开了CONFIG_FUNCTION_TRACER功能后,会增加一个-pg的一个编译选项,这样每个函数入口处,都会插入bl mcount跳转指令,使得每个函数运行时都会进入mcount函数。

既然每个函数都静态插桩,这带来的性能开销是惊人的,有可能导致人们弃用Ftrace功能。为了解决这个问题,开发者推出了Dynamic ftrace,以此来优化整体的性能。

3.1.2 动态插桩

既然静态插桩记录这些可追踪的函数,为了减少性能消耗,将跳转函数替换为nop指令,动态将被调试函数的nop指令,替换为跳转指令,以实现追踪。

3.2 使能Ftrace

CONFIG_FTRACE=y                             # 启用了 Ftrace
CONFIG_FUNCTION_TRACER=y                    # 启用函数级别的追踪器
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y         # 表示内核支持图形显示
CONFIG_FUNCTION_GRAPH_TRACER=y              # 以图形的方式显示函数追踪过程
CONFIG_STACK_TRACER=y                       # 启用堆栈追踪器,用于跟踪内核函数调用的堆栈信息。
CONFIG_DYNAMIC_FTRACE=y                     # 启用动态 Ftrace,允许在运行时启用和禁用 Ftrace 功能。
CONFIG_HAVE_FTRACE_NMI_ENTER=y              # 表示内核支持非屏蔽中断(NMI)时进入 Ftrace 的功能
CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y          # 表示内核支持通过 mcount 记录函数调用关系。
CONFIG_FTRACE_NMI_ENTER=y                   # 表示内核支持通过 mcount 记录函数调用关系。   
CONFIG_FTRACE_SYSCALLS=y                    # 系统调用的追踪
CONFIG_FTRACE_MCOUNT_RECORD=y               # 启用 mcount 记录函数调用关系。
CONFIG_SCHED_TRACER=y                       # 支持调度追踪
CONFIG_CONTEXT_SWITCH_TRACER                #使能上下文切换追踪功能,可以用来跟踪进程之间的切换。
CONFIG_NOP_TRACER                           #使能空操作追踪功能,可以用来在不需要追踪的情况下占位。
CONFIG_FUNCTION_PROFILER=y                  # 启用函数分析器,主要用于记录函数的执行时间和调用次数
CONFIG_DEBUG_FS=y                           # 启用 Debug 文件系统支持

上述配置不一定全部打开,勾选自己需要的即可,通常我们选择CONFIG_FUNCTION_TRACERCONFIG_HAVE_FUNCTION_GRAPH_TRACER即可,然后编译烧录到开发板。

通过make menuconfig的方式写入:

 Kernel hacking  --->
        Tracers ─>
            [*]   Kernel Function Tracer
            [*]     Kernel Function Graph Tracer (NEW)
            // (下面还有几个追踪器的选项,可以根据自己的需要选择)

Ftrace 通过 debugfs 向用户态提供了访问接口,所以还需要将 debugfs 编译进内核:

Kernel hacking  --->
        -*- Debug Filesystem

3.2.1 挂载debugfs

#用户态需要挂载debugfs,or通过配置修改etc/fstab文件
mount -t debugfs none /sys/kernel/debug
或者 mount -t tracefs nodev /sys/kernel/tracing

image

我们能够在/sys/kernel/debug下看到内核支持的所有的调试信息:

# cd /sys/kernel/debug/
# ls
 asoc                gpio                regmap
 bdi                 ieee80211           sched_debug
 block               memblock            sched_features
 clk                 mmc0                sleep_time
 device_component    mmc1                suspend_stats
 devices_deferred    mtd                 tracing
 dma_buf             opp                 ubi
 extfrag             pinctrl             ubifs
 fault_around_bytes  pm_qos              wakeup_sources

3.3 Ftrace 使用

3.3.1 /sys/kernel/tracing介绍

image

3.3.2 trace和trace_pipe使用

cat trace_pipe是堵塞读取,有数据就读,没数据就等待。

打开关闭追踪:

echo 1 > tracing_on             // 打开跟踪
do_someting
echo 0 > tracing_on             // 关闭跟踪
cat trace  > /tmp/log //一次性导出log
cat trace_pipe > /tmp/log &//后台导出log
cat current_tracer                    // 查看当前追踪器
cat available_tracers                 // 查看当前内核中可用跟踪器
cat available_events                  // 查看当前内核中可用事件
cat available_filter_functions
// 查看当前内核中可用函数,可以被追踪的函数列表,
// 即可以写到 set_ftrace_filter,set_ftrace_notrace,set_graph_function,
// set_graph_notrace 文件的函数列表

echo function > current_tracer        // 选用 function 追踪器,
echo function_graph > current_tracer  // 选用 function_graph 追踪器,
echo [func] > set_ftrace_filter       // 选择追踪指定 [func] 函数的调用栈
echo [pid] > set_ftrace_pid           // 选择追踪指定 [pid] 进程的调用栈

3.3.2.1 选用函数追踪

image

3.3.2.2 选用图像化函数追踪

image

3.3.2.3 选用动态过滤追踪

image

3.3.2.4 追踪特定进程

 echo 0 > tracing_on                                 # 关闭追踪器
 echo function > current_tracer                      # 设置当前追踪类别

echo > trace; echo $$ > set_ftrace_pid; echo 1 > tracing_on; your_command; echo 0 > tracing_on

$$表示当前bash的pid,这样可以追踪任意命令。

如果我们要抓执行a.out的trace信息,那么先要获取到a.out程序的pid。

为什么要写成一条语句?

因为ftrace当打开时,在没有过滤的情况下,瞬间会抓取到内核所有的函数调用,为了更准确的抓取我们执行的命令,所以需要打开trace,执行完命令后,马上关闭。

3.3.2.5 追踪特定函数

echo 1 > options/func_stack_trace
echo 0 > tracing_on									# 关闭追踪器
cat available_filter_functions | grep "xxxxxx"		# 搜索函数是否存在
echo xxxxxx > set_ftrace_filter						# 设定追踪的函数
echo function > current_tracer						# 设置当前追踪类别
echo 1 > options/func_stack_trace					# 记录堆栈信息
echo > trace										# 清空缓存
echo 1 > tracing_on

查看结果:

# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 2/2   #P:3
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/1:1-59    [001] ....   168.954199: mmc_rescan <-process_one_work
     kworker/1:1-59    [001] ....   168.954248: <stack trace>
 => mmc_rescan
 => process_one_work
 => worker_thread
 => kthread
 => ret_from_fork
 => 0

3.3.2.6 追踪特定ko模块

编译ko需要加上编译参数-pg。否则你在available_filter_functions列表中,查找不到你想要的函数。

# 示例
Format: :mod:<module-name>
example: echo :mod:ext3 > set_ftrace_filter

追踪ext3模块内的所有函数。

3.3.2.7 重置追踪

echo 0 > tracing_on         # 关闭trace
echo > trace                # 清空当前trace记录

3.3.2.8 事件追踪

查看事件:

root@100ask:/sys/kernel/debug/tracing/events# ls
alarmtimer    exceptions    i2c          migrate         power         signal
block         ext4          initcall     mmc             printk        skb   
enable        hyperv        mdio         percpu

root@100ask:/sys/kernel/debug/tracing/events/sched# ls
enable                  sched_move_numa     sched_process_free  sched_stat_runtime  sched_switch
filter                  sched_pi_setprio    sched_process_hang  sched_stat_sleep
sched_kthread_stop      sched_process_exec  sched_process_wait  sched_stat_wait

追踪一个/若干事件:


# echo 1 > events/sched/sched_wakeup/enable
 ...(省略追踪过程)

# cat trace | head -10
# tracer: nop
#TASK-PID  CPU#  TIMESTAMP    FUNCTION
# || | |
bash-2613 [001] 425.078164: sched_wakeup: task bash:2613 [120] success=0 [001]
bash-2613 [001] 425.078184: sched_wakeup: task bash:2613 [120] success=0 [001]

追踪所有事件:

# echo 1 > events/enable
...

# cat trace | head -10
# tracer: nop
#TASK-PID     CPU#     TIMESTAMP    FUNCTION
#   |                    |                    |                   |
cpid-1470       [001]   794.947181:         kfree: call_site=ffffffff810c996d ptr=(null)
acpid-1470     [001] 794.947182:      sys_read -> 0x1

3.3.2.n trace_printk函数使用

内核头文件 include/linux/kernel.h 中描述了 ftrace 提供的工具函数的原型,这些函数包括 trace_printktracing_on/tracing_off 等。

3.4 引入用户态ltrace和strace

3.4.1 ltrace

跟踪进程调用C库函数的情况。
常用的参数:

-a : 对齐具体某个列的返回值。
-c : 计算时间和调用,并在程序退出时打印摘要。
-d : 打印调试信息。
-h : 打印帮助信息。
-i : 打印指令指针,当库调用时。
-l : 只打印某个库中的调用。
-o, --output=file : 把输出定向到文件。
-p : PID 附着在值为PID的进程号上进行ltrace。
-r : 打印相对时间戳。
-S : 显示系统调用。
-t, -tt, -ttt : 打印绝对时间戳。
-T : 输出每个调用过程的时间开销。
-V, --version : 打印版本信息,然后退出。
#include <stdio.h>
#include <string.h>
#include <stdlib.h>
int main(void) {
	int n = 10;
	int *arr = (int *)malloc(n * sizeof(int));
	if (arr == NULL) {
		printf("failed!\r\n");
		return 1;
	}
	memset(arr, 2, n*sizeof(int));
	for (int i = 0; i < n; i++) {
		printf("%d\t", arr[i]);
	}
	return 0;
}

1.查看c库调用:
image

2.查看c库调用次数:
image

3.查看c库执行时间:
image

4.查看系统调用情况:
image

3.4.2 strace

跟踪进程系统调用System Call使用情况。

常用的参数如下:

-c 统计每一系统调用的所执行的时间,次数和出错的次数等.
-d 输出strace关于标准错误的调试信息.
-f 跟踪由fork调用所产生的子进程.
-ff 如果提供-o filename,则所有进程的跟踪结果输出到相应的filename.pid中,pid是各进程的进程号.
-F 尝试跟踪vfork调用.在-f时,vfork不被跟踪.
-h 输出简要的帮助信息.
-i 输出系统调用的入口指针.
-q 禁止输出关于脱离的消息.
-r 打印出相对时间关于,,每一个系统调用.
-t 在输出中的每一行前加上时间信息.
-tt 在输出中的每一行前加上时间信息,微秒级.
-ttt 微秒级输出,以秒了表示时间.
-T 显示每一调用所耗的时间.
-v 输出所有的系统调用.一些调用关于环境变量,状态,输入输出等调用由于使用频繁,默认不输出.
-V 输出strace的版本信息.
-x 以十六进制形式输出非标准字符串
-xx 所有字符串以十六进制形式输出.
-a column 设置返回值的输出位置.默认 为40.
-e expr 指定一个表达式,用来控制如何跟踪.格式:[qualifier=][!]value1[,value2]...
qualifier只能是 trace,abbrev,verbose,raw,signal,read,write其中之一.value是用来限定的符号或数字.默认的 qualifier是 trace.感叹号是否定符号.例如:-eopen等价于 -e trace=open,表示只跟踪open调用.而-etrace!=open 表示跟踪除了open以外的其他调用.有两个特殊的符号 all 和 none. 注意有些shell使用!来执行历史记录里的命令,所以要使用\\.
-e trace=set 只跟踪指定的系统 调用.例如:-e trace=open,close,rean,write表示只跟踪这四个系统调用.默认的为set=all.
-e signal=set 指定跟踪的系统信号.默认为all.如 signal=!SIGIO(或者signal=!io),表示不跟踪SIGIO信号.
-e read=set 输出从指定文件中读出 的数据.例如: -e read=3,5
-e write=set 输出写入到指定文件中的数据.
-o filename 将strace的输出写入文件filename
-p pid 跟踪指定的进程pid.

查看系统调用的时间:
image

posted on 2024-07-28 16:39  fuzidage  阅读(376)  评论(0编辑  收藏  举报