本文用于记录常用的linux中断子系统的debug方法,例如节点查看中断信息,ftrace获取中断信息等。理论知识可见linux中断子系统详解。
1、所有中断信息"cat /proc/interrupts"
linux中断号 各CPU累计处理中断次数 中断控制器 硬件中断号 中断触发方式 中断名
2、某个中断信息"cat /proc/irq/xxx/xxx"
//timer中断亲和性
cat /proc/irq/0/smp_affinity
//timer中断次数,一共发生了18次
cat /proc/irq/0/spurious
也可以通过脚本自动打印中断的次数(每隔1s打印一次)
while true; echo -e "\n"; do cat /proc/irq/0/spurious; sleep 1; done
3、中断线程
ps -A | grep "irq/"
4、ftrace观察中断
//追踪IRQ 事件
irq:irq_handler_exit
irq:irq_handler_entry
//查看当前注册的IRQ,确认要追踪的IRQ号
cat /proc/interrupts
cd /sys/kernel/debug/tracing/
//追踪IRQ进入
echo irq_handler_exit > set_event
//追踪IRQ退出
echo irq_handler_entry >> set_event
//过滤掉过于频繁的IRQ信号
echo "irq != 17" > events/irq/irq_handler_entry/filter
//过滤掉过于频繁的IRQ信号
echo "irq != 17" > events/irq/irq_handler_exit/filter
//设置buff size,单位为kb,因为irq信息比较多,因此选择较大buff
echo 4096 > buffer_size_kb
//清空buffer
echo "" > trace
//保存log到文件
cat trace > trace_data.log &
//开始追踪
echo 1 > tracing_on
//也可以按照name来过滤
//echo "name != timer" > events/irq/irq_handler_entry/filter
//echo "name != timer" > events/irq/irq_handler_exit/filter
//irq_handler_entry输出的数据格式
root@ubuntu:/sys/kernel/debug/tracing# cat events/irq/irq_handler_entry/format
name: irq_handler_entry
ID: 142
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:int irq; offset:8; size:4; signed:1;
field:__data_loc char[] name; offset:12; size:4; signed:1;
print fmt: "irq=%d name=%s", REC->irq, __get_str(name)
//irq_handler_exit输出的数据格式
root@ubuntu:/sys/kernel/debug/tracing# cat events/irq/irq_handler_exit/format
name: irq_handler_exit
ID: 141
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:int irq; offset:8; size:4; signed:1;
field:int ret; offset:12; size:4; signed:1;
print fmt: "irq=%d ret=%s", REC->irq, REC->ret ? "handled" : "unhandled"
打印输出含义:进程上下文 [cpu] 中断上下文状态 时间戳: events: print fmt
中断上下文状态:
- irqs-off:“d”表示中断已经关闭
- need-resched:“N”表示进程设置了 TIF_NEED_RESCHED 和PREEMPT_NEED_RESCHED标志位;“n”表示进程仅设置了TIF_NEED_RESCHED标志位;“p”表示进程仅设置了PREEMPT_NEED_RESCHED标志位;. 表示不需要调度
- hardirq/softirq:“H”表示在一次软中断中发生了一个硬件中断;“h”表示硬件中断发生;“s”表示软中断;“.”表示没有中断发生
- preempt-depth:抢占关闭的嵌套层级
delay:用一些特殊符号来延迟的时间,方便开发者观察。
- “$”表示大于 1s,
- “#”表示大于1000ms,
- “!”表示大于100ms,
- “+”表示大于10ms。
5、ftrace观察软中断
//追踪softirq 事件
irq:softirq_raise
irq:softirq_entry
irq:softirq_exit
cd /sys/kernel/debug/tracing/
//追踪softirq raise
echo softirq_raise > set_event
//追踪softirq进入
echo softirq_entry >> set_event
//追踪softirq退出
echo softirq_exit >> set_event
//设置buff size,单位为kb,因为irq信息比较多,因此选择较大buff
echo 4096 > buffer_size_kb
//清空buffer
echo "" > trace
//保存log到文件
cat trace > trace_data.log &
//开始追踪
echo 1 > tracing_on
cat trace | grep TIMER:
6、ftrace观察中断最大延迟
当一个核的中断关闭(关中断)后,本CPU就不能响应其他的中断事件。如果这时有一个中断产生,要在下一次开中断时才能响应这个中断,这段延时称为中断延迟。irqsoff 记录系统在哪里关中断的时间最长。
默认ubuntu的ftrace是没有打开这个irqsoff tracer的,需要重新编译内核。需要添加相关的编译选项:
+CONFIG_FTRACE=y
+CONFIG_FUNCTION_TRACER=y
+CONFIG_HAVE_FUNCTION_GRAPH_TRACER
+CONFIG_FUNCTION_GRAPH_TRACER=y
+CONFIG_IRQSOFF_TRACER=y
+CONFIG_PREEMPT_TRACER=y
+CONFIG_SCHED_TRACER=y
+CONFIG_CONTEXT_SWITCH_TRACER=y
+CONFIG_STACK_TRACER=y
+CONFIG_DYNAMIC_FTRACE=y
+CONFIG_HAVE_FTRACE_NMI_ENTER=y
+CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y
+CONFIG_FTRACE_NMI_ENTER=y
+CONFIG_FTRACE_SYSCALLS=y
+CONFIG_FTRACE_MCOUNT_RECORD=y
使用qemu打开相关编译选项,并编译。查看/sys/kernel/debug/tracing/available_tracers是否有irqsoff的tracer。
[root@idle tracing]# cat available_tracers
function_graph wakeup_dl wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function nop
可以向current_tracer文件写入 irqsoff字符串即可打开 irqsoff来跟踪中断区域,并保存最大时延。
cd /sys/kernel/debug/tracing/
//关闭 funct-trace可以减少一些延迟
echo 0 > options/function-trace
echo irqsoff > current_tracer
echo 0 > tracing_max_latency
echo 1 > tracing_on
//停顿一会儿
echo 0 > tracing_on
cat trace
在qemu中抓取结果如下:
[root@idle tracing]# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 5.4.0-ge046d52-dirty
# --------------------------------------------------------------------
//最大时延是79497 us
# latency: 79497 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sh-174 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
//记录禁止中断时间最长的开始和结束函数
# => started at: _raw_spin_unlock_irqrestore
# => ended at: irq_exit
#
#
# _------=> CPU#
# / _-----=> irqs-off:d表示中断被disabled,'.'表示中断没有被关闭。
# | / _----=> need-resched:N-表示need_resched被设置;'.'-表示need_resched没有被设置,中断返回不会进行进程切换。
# || / _---=> hardirq/softirq:H-表示softirq中发生了硬件中断;h-硬件中断;s-softirq;'.'-不在中断上下文中。
# ||| / _--=> preempt-depth:当抢占中断势能后,该域代表preempt_disabled的级别。
//cmd-进程名,pid-进程id,time-表示trace从开始到当前的相对时间,delay-突出显示那些有高延迟的地方以便引起注意。!表示需要引起注意。
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
sh-174 2d..1 4us*: el1_irq <-_raw_spin_unlock_irqrestore
sh-174 2d.s1 79473us+: __do_softirq <-irq_exit
sh-174 2d.s1 79509us!: tracer_hardirqs_on <-irq_exit
sh-174 2d.s1 79768us : <stack trace>
//调用栈
=> irq_exit
=> __handle_domain_irq
=> gic_handle_irq
=> el1_irq
=> _raw_spin_unlock_irqrestore
=> uart_write
=> n_tty_write
=> tty_write
=> redirected_tty_write
=> __vfs_write
=> vfs_write
=> ksys_write
=> __arm64_sys_write
=> el0_svc_common.constprop.2
=> el0_svc_handler
=> el0_svc
如果设置function-trace,将最大中断时延过程中的函数调用关系都打印出来,获得更多信息。
实现原理:
#ifdef CONFIG_TRACE_IRQFLAGS
#define local_irq_enable() \
do { trace_hardirqs_on(); raw_local_irq_enable(); } while (0)
#define local_irq_disable() \
do { raw_local_irq_disable(); trace_hardirqs_off(); } while (0)
#endif
开始计时:trace_hardirqs_off() ----> trace_hardirqs_off() ----> start_critical_timing()
----> data->preempt_timestamp = ftrace_now(cpu);
结束计时:trace_hardirqs_on() ----> tracer_hardirqs_on() ----> stop_critical_timing() ----> check_critical_timing()
----> T0 = data->preempt_timestamp; T1 = ftrace_now(cpu); delta = T1-T0; ----> tr->max_latency = delta;