linux中断子系统debug方法

1,599 阅读4分钟

本文用于记录常用的linux中断子系统的debug方法,例如节点查看中断信息,ftrace获取中断信息等。理论知识可见linux中断子系统详解

1、所有中断信息"cat /proc/interrupts"

linux中断号 各CPU累计处理中断次数 中断控制器 硬件中断号 中断触发方式 中断名 image.png

2、某个中断信息"cat /proc/irq/xxx/xxx"

//timer中断亲和性
cat /proc/irq/0/smp_affinity

image.png

//timer中断次数,一共发生了18次
cat /proc/irq/0/spurious

image.png

也可以通过脚本自动打印中断的次数(每隔1s打印一次)

while true; echo -e "\n"; do cat /proc/irq/0/spurious; sleep 1; done

3、中断线程

ps -A | grep "irq/"

image.png

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。

image.png

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: image.png

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;