"디버깅을 통해 배우는 리눅스 커널의 구조와 원리" 책의 "3.1.2 디버깅과 코드 학습 능력"에서 소개하는 ftrace를 실습했다 .
책에서는 라즈베리파이 3에 커널 소스도 4.19.y이다.
라즈베리파이 4에 최신 커널 소스 (2025.4월)에 동작하지 않아 chatGpt와 googling의 도움으로 실습을 할 수 있었다.
커널 소스 버전
root@raspberrypi:/project/linuxSrc # uname -a
Linux raspberrypi 6.6.78-v8+ #2 SMP PREEMPT Sat Apr 5 01:36:56 BST 2025 aarch64 GNU/Linux
책에서 작성한 코드에 "noinline __attribute__((__used__))"를 함수 앞에 추가하여 추적이 가능하게 해야 로그에 출력이 된다.
proc.c 파일에 rpi_get_interrupt_info 함수를 추가하고 show_interrupts 함수에서 호출한다.
root@raspberrypi:/project/linuxSrc # vi linux/kernel/irq/proc.c
459 noinline __attribute__((__used__)) void rpi_get_interrupt_info(struct irqaction *action_p)
460 {
461 unsigned int irq_num = action_p->irq;
462 void *irq_handler = NULL;
463
464 if (action_p->handler) {
465 irq_handler = (void*)action_p->handler;
466 }
467
468 if (irq_handler) {
469 trace_printk("[%s] %d: %s, irq_handler: %pS \n",
470 current->comm, irq_num, action_p->name, irq_handler);
471 }
472 }
541 if (action)
542 rpi_get_interrupt_info(action);
수정된 내용 확인
linux 디렉터리에서 확인
root@raspberrypi:/project/linuxSrc/linux # git diff
diff --git a/kernel/irq/proc.c b/kernel/irq/proc.c
index 623b8136e..277d91555 100644
--- a/kernel/irq/proc.c
+++ b/kernel/irq/proc.c
@@ -456,6 +456,20 @@ int __weak arch_show_interrupts(struct seq_file *p, int prec)
#ifndef ACTUAL_NR_IRQS
# define ACTUAL_NR_IRQS nr_irqs
#endif
+noinline __attribute__((__used__)) void rpi_get_interrupt_info(struct irqaction *action_p)
+{
+ unsigned int irq_num = action_p->irq;
+ void *irq_handler = NULL;
+
+ if (action_p->handler) {
+ irq_handler = (void*)action_p->handler;
+ }
+
+ if (irq_handler) {
+ trace_printk("[%s] %d: %s, irq_handler: %pS \n",
+ current->comm, irq_num, action_p->name, irq_handler);
+ }
+}
int show_interrupts(struct seq_file *p, void *v)
{
@@ -523,6 +537,10 @@ int show_interrupts(struct seq_file *p, void *v)
seq_printf(p, "-%-8s", desc->name);
action = desc->action;
+
+ if (action)
+ rpi_get_interrupt_info(action);
+
if (action) {
seq_printf(p, " %s", action->name);
while ((action = action->next) != NULL)
ftrace 시작 스크립트를 작성한다.
secondary_start_kernel은 필터 항목에 없어 에러가 발생한다.
cpu_startup_entry로 수정하였다.
root@raspberrypi:/project/linuxSrc # vi irq_trace_ftrace.sh
#!/bin/bash
echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1
echo "tracing_off"
echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1
echo "events disabled"
#echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter
echo cpu_startup_entry > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter init"
echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
sleep 1
echo "event enabled"
echo rpi_get_interrupt_info bcm2835_mmc_irq > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"
ftrace 종료 스크립트를 작성한다.
root@raspberrypi:/project/linuxSrc # vi get_trace.sh
#!/bin/bash
echo 0 > /sys/kernel/debug/tracing/tracing_on
echo "ftrace off"
sleep 3
cp /sys/kernel/debug/tracing/trace .
mv trace ftrace_log.c
ftrace를 On 하고, 함수를 호출하는 명령을 실행하고, ftrace를 Off 한다.
1. ftrace On
root@raspberrypi:/project/linuxSrc # ./irq_trace_ftrace.sh
tracing_off
events disabled
set_ftrace_filter init
function tracer enabled
event enabled
set_ftrace_filter enabled
function stack trace enabled
tracing_on
2. 함수를 호출하는 명령 실행
root@raspberrypi:/project/linuxSrc # cat /proc/interrupts
CPU0 CPU1 CPU2 CPU3
9: 0 0 0 0 GICv2 25 Level vgic
11: 17695 12517 7618 8832 GICv2 30 Level arch_timer
12: 0 0 0 0 GICv2 27 Level kvm guest vtimer
14: 1856 0 0 0 GICv2 65 Level fe00b880.mailbox
15: 1249 0 0 0 GICv2 114 Level DMA IRQ
21: 0 0 0 0 GICv2 122 Level DMA IRQ
22: 0 0 0 0 GICv2 123 Level DMA IRQ
27: 0 0 0 0 GICv2 175 Level PCIe PME, aerdrv
28: 9902 0 0 0 GICv2 189 Level eth0
29: 0 0 0 0 GICv2 190 Level eth0
30: 38 0 0 0 BRCM STB PCIe MSI 524288 Edge xhci_hcd
31: 71 0 0 0 GICv2 66 Level VCHIQ doorbell
32: 0 0 0 0 GICv2 48 Level arm-pmu
33: 0 0 0 0 GICv2 49 Level arm-pmu
34: 0 0 0 0 GICv2 50 Level arm-pmu
35: 0 0 0 0 GICv2 51 Level arm-pmu
36: 7416 0 0 0 GICv2 153 Level uart-pl011
37: 99183 0 0 0 GICv2 158 Level mmc1, mmc0
38: 0 0 0 0 GICv2 130 Level feb10000.codec
39: 0 0 0 0 GICv2 106 Level v3d
40: 0 0 0 0 GICv2 129 Level vc4 hvs
41: 0 0 0 0 interrupt-controller@7ef00100 4 Level vc4 hdmi hpd connected
42: 0 0 0 0 interrupt-controller@7ef00100 5 Level vc4 hdmi hpd disconnected
43: 0 0 0 0 interrupt-controller@7ef00100 1 Level vc4 hdmi cec rx
44: 0 0 0 0 interrupt-controller@7ef00100 0 Level vc4 hdmi cec tx
45: 0 0 0 0 interrupt-controller@7ef00100 10 Level vc4 hdmi hpd connected
46: 0 0 0 0 interrupt-controller@7ef00100 11 Level vc4 hdmi hpd disconnected
47: 0 0 0 0 interrupt-controller@7ef00100 7 Level vc4 hdmi cec rx
48: 0 0 0 0 interrupt-controller@7ef00100 8 Level vc4 hdmi cec tx
49: 0 0 0 0 GICv2 107 Level fe004000.txp
50: 0 0 0 0 GICv2 141 Level vc4 crtc
51: 0 0 0 0 GICv2 142 Level vc4 crtc, vc4 crtc
52: 0 0 0 0 GICv2 133 Level vc4 crtc
53: 0 0 0 0 GICv2 138 Level vc4 crtc
IPI0: 205 322 367 302 Rescheduling interrupts
IPI1: 7494 12458 27387 19156 Function call interrupts
IPI2: 0 0 0 0 CPU stop interrupts
IPI3: 0 0 0 0 CPU stop (for crash dump) interrupts
IPI4: 0 0 0 0 Timer broadcast interrupts
IPI5: 4716 2968 1101 653 IRQ work interrupts
IPI6: 0 0 0 0 CPU wake-up interrupts
3. ftrace Off
root@raspberrypi:/project/linuxSrc # ./get_trace.sh
ftrace off
ftrace 로그 파일에서 rpi_get_interrupt_info 파일이 호출
root@raspberrypi:/project/linuxSrc # vi ftrace_log.c
28870 sshd-687 [000] d.h1. 2015.457228: irq_handler_exit: irq=37 ret=handled
28871 sshd-687 [000] d.h1. 2015.457229: irq_handler_entry: irq=37 name=mmc0
28872 sshd-687 [000] d.h1. 2015.457231: irq_handler_exit: irq=37 ret=unhandled
28873 sshd-687 [000] d..2. 2015.457249: sched_switch: prev_comm=sshd prev_pid=687 prev_prio=120 prev_state=R+ ==> next_comm=kworker/u13:0 next_pid=78 next_prio=100
28874 kworker/u13:0-78 [000] d..2. 2015.457269: sched_switch: prev_comm=kworker/u13:0 prev_pid=78 prev_prio=100 prev_state=I ==> next_comm=sshd next_pid=687 next_prio=120
28875 <idle>-0 [003] dnh1. 2015.457318: irq_handler_entry: irq=1 name=IPI
28876 <idle>-0 [003] dNh1. 2015.457320: irq_handler_exit: irq=1 ret=handled
28877 <idle>-0 [003] d..2. 2015.457329: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=925 next_prio=120
28878 sshd-687 [000] d..2. 2015.457331: sched_switch: prev_comm=sshd prev_pid=687 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
28879 bash-701 [002] d..2. 2015.457749: sched_switch: prev_comm=bash prev_pid=701 prev_prio=120 prev_state=S ==> next_comm=kworker/2:2 next_pid=815 next_prio=120
28880 kworker/2:2-815 [002] d..2. 2015.457789: sched_switch: prev_comm=kworker/2:2 prev_pid=815 prev_prio=120 prev_state=I ==> next_comm=swapper/2 next_pid=0 next_prio=120
28881 cat-925 [003] d..1. 2015.460734: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x2b0/0x408
28882 cat-925 [003] d..1. 2015.460744: <stack trace>
28883 => rpi_get_interrupt_info+0x8/0x58
28884 => show_interrupts+0x2b0/0x408
28885 => seq_read_iter+0x34c/0x460
28886 => proc_reg_read_iter+0x8c/0xe8
28887 => vfs_read+0x21c/0x2c8
28888 => ksys_read+0x78/0x118
28889 => __arm64_sys_read+0x24/0x38
28890 => invoke_syscall+0x50/0x128
28891 => el0_svc_common.constprop.0+0x48/0xf0
28892 => do_el0_svc+0x24/0x38
28893 => el0_svc+0x38/0xd0
28894 => el0t_64_sync_handler+0x100/0x130
28895 => el0t_64_sync+0x190/0x198
28896 cat-925 [003] d..1. 2015.460752: rpi_get_interrupt_info+0x10/0x58: [cat] 9: vgic, irq_handler: vgic_maintenance_handler+0x0/0x18
28882 : pid가 925인 cat 프로세스가 rpi_get_interrupt_info() 함수 호출
28885 : req_read_iter() 함수에서 show_interrupts() 함수 호출
28889 : __arm64_sys_read 함수가 호출
root@raspberrypi:/project/linuxSrc # egrep -nr irq_handler ftrace_log.c > egrep_log
root@raspberrypi:/project/linuxSrc # vi egrep_log
6438 28896: cat-925 [003] d..1. 2015.460752: rpi_get_interrupt_info+0x10/0x58: [cat] 9: vgic, irq_handler: vgic_maintenance_handler+0x0/0x18
6439 28912: cat-925 [003] d..1. 2015.460774: rpi_get_interrupt_info+0x10/0x58: [cat] 11: arch_timer, irq_handler: arch_timer_handler_phys+0x0/0x58
6440 28928: cat-925 [003] d..1. 2015.460790: rpi_get_interrupt_info+0x10/0x58: [cat] 12: kvm guest vtimer, irq_handler: kvm_arch_timer_handler+0x0/0xf0
6441 28944: cat-925 [003] d..1. 2015.460805: rpi_get_interrupt_info+0x10/0x58: [cat] 14: fe00b880.mailbox, irq_handler: bcm2835_mbox_irq+0x0/0xc0
6442 28945: cat-925 [003] d.h.. 2015.460815: irq_handler_entry: irq=11 name=arch_timer
6443 28946: <idle>-0 [000] d.h1. 2015.460868: irq_handler_entry: irq=2 name=IPI
6444 28947: cat-925 [003] d.h.. 2015.460869: irq_handler_exit: irq=11 ret=handled
6445 28948: <idle>-0 [000] d.h1. 2015.460873: irq_handler_exit: irq=2 ret=handled
6446 28949: <idle>-0 [001] d.h1. 2015.460894: irq_handler_entry: irq=2 name=IPI
6447 28965: <idle>-0 [001] dNh1. 2015.460906: irq_handler_exit: irq=2 ret=handled
6448 28966: cat-925 [003] d..1. 2015.460909: rpi_get_interrupt_info+0x10/0x58: [cat] 15: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x1d0
6449 28983: cat-925 [003] d..1. 2015.460927: rpi_get_interrupt_info+0x10/0x58: [cat] 21: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x1d0
6450 28999: cat-925 [003] d..1. 2015.460939: rpi_get_interrupt_info+0x10/0x58: [cat] 22: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x1d0
6451 29016: cat-925 [003] d..1. 2015.460954: rpi_get_interrupt_info+0x10/0x58: [cat] 27: PCIe PME, irq_handler: pcie_pme_irq+0x0/0xe8
6452 29032: cat-925 [003] d..1. 2015.460968: rpi_get_interrupt_info+0x10/0x58: [cat] 28: eth0, irq_handler: bcmgenet_isr0+0x0/0x190
6453 29048: cat-925 [003] d..1. 2015.460979: rpi_get_interrupt_info+0x10/0x58: [cat] 29: eth0, irq_handler: bcmgenet_isr1+0x0/0x158
6454 29064: cat-925 [003] d..1. 2015.460993: rpi_get_interrupt_info+0x10/0x58: [cat] 30: xhci_hcd, irq_handler: xhci_msi_irq+0x0/0x30
6455 29080: cat-925 [003] d..1. 2015.461005: rpi_get_interrupt_info+0x10/0x58: [cat] 31: VCHIQ doorbell, irq_handler: vchiq_doorbell_irq+0x0/0x60
6456 29096: cat-925 [003] d..1. 2015.461017: rpi_get_interrupt_info+0x10/0x58: [cat] 32: arm-pmu, irq_handler: armpmu_dispatch_irq+0x0/0x80
6457 29112: cat-925 [003] d..1. 2015.461029: rpi_get_interrupt_info+0x10/0x58: [cat] 33: arm-pmu, irq_handler: armpmu_dispatch_irq+0x0/0x80
6458 29128: cat-925 [003] d..1. 2015.461040: rpi_get_interrupt_info+0x10/0x58: [cat] 34: arm-pmu, irq_handler: armpmu_dispatch_irq+0x0/0x80
6438 라인
인터럽트 번호 : 86
인터럽트 이름 : vgic
인터럽트 핸들러 이름 : vgic_maintenance_handler
'운영체제 > 리눅스' 카테고리의 다른 글
| [리눅스 커널 디버깅] 3. rpi_debugfs (rpi4 6.6.x) (0) | 2025.04.25 |
|---|---|
| [리눅스 커널 디버깅] 1. 커널 빌드와 설치 (rpi4 6.6.x) (1) | 2025.04.11 |