IT 기술자

"디버깅을 통해 배우는 리눅스 커널의 구조와 원리" 책의 "5.2.2 ftrface와 커널 로그로 인터럽트 컨텍스트 확인하기"에서 소개하는 인터럽트 디버깅을 실습했다.

디렉토리를 만들고 ftrace 로그 작성

usb 인터럽트가 발견되지 않아 이더넷 인터럽트를 추적했다.

root@raspberrypi:/project/linuxSrc # mkdir ch05_02_02 && cd $_
root@raspberrypi:/project/linuxSrc/ch05_02_02 # vi irq_stack_trace.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 dwc_otg_common_irq  > /sys/kernel/debug/tracing/set_ftrace_filter
echo bcmgenet_isr0 bcmgenet_isr1 > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"

echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
echo "event enabled"

echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo "function stack trace enabled"

echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"

스크립트 실행 가능하게 만들기

실행

1. ./irq_stack_trace.sh

2. ../get_trace.sh

네트워크 인터럽트 로그 확인

root@raspberrypi:/project/linuxSrc/ch05_02_02 # vi ftrace_log.c

 349           <idle>-0       [000] d.h1.  3711.974045: irq_handler_entry: irq=28 name=eth0
 350           <idle>-0       [000] d.h1.  3711.974046: bcmgenet_isr0 <-__handle_irq_event_percpu
 351           <idle>-0       [000] d.h1.  3711.974050: <stack trace>
 352  => bcmgenet_isr0
 353  => __handle_irq_event_percpu
 354  => handle_irq_event
 355  => handle_fasteoi_irq
 356  => handle_irq_desc
 357  => generic_handle_domain_irq
 358  => gic_handle_irq
 359  => call_on_irq_stack
 360  => do_interrupt_handler
 361  => el1_interrupt
 362  => el1h_64_irq_handler
 363  => el1h_64_irq
 364  => default_idle_call
 365  => do_idle
 366  => cpu_startup_entry
 367  => rest_init
 368  => arch_call_rest_init
 369  => start_kernel
 370  => __primary_switched
 371           <idle>-0       [000] d.h1.  3711.974052: irq_handler_exit: irq=28 ret=handled
 372           <idle>-0       [003] d.h1.  3711.974053: irq_handler_entry: irq=2 name=IPI
 373           <idle>-0       [003] dNh1.  3711.974055: irq_handler_exit: irq=2 ret=handled

"디버깅을 통해 배우는 리눅스 커널의 구조와 원리" 책의 "4.11 프로세스 디버깅"에서 소개하는 프로세스 디버깅을 실습했다.

디렉터리 만들고 프로그램 작성

root@raspberrypi:/project/linuxSrc # mkdir ch04_11 && cd $_
root@raspberrypi:/project/linuxSrc/ch04_11 # vi raspbian_fork.c

#include <stdio.h>
#include <unistd.h>
#include <sys/types.h>

#define PROC_TIMES 		50
#define SLEEP_DURATION 	2
#define FORK_MAX_TIMES 	3

void raspbian_proc_process(void);

void raspbian_proc_process(void) 
{
	int proc_times = 0;
	
	for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
			printf("raspbian tracing \n");
			sleep(SLEEP_DURATION);
	}
	
}

int main() 
{	
	pid_t pid;
	int fork_times = 0;
	
	printf("About to fork process \n");
	
	pid = fork();
	
	if ( pid == 0 )  {
		printf("start execution of child process\n");
		raspbian_proc_process();
	}
	
	else if ( pid > 0 ) {
		printf("start execution of parent process\n");
		raspbian_proc_process();
	}
	
	return 0;	
}

Makefile 작성과 빌드

root@raspberrypi:/project/linuxSrc/ch04_11 # vi Makefile

raspbian_fork: raspbian_fork.c
	gcc -g -o raspbian_fork raspbian_fork.c

gdb를 이용하여 프로그램 디버그

root@raspberrypi:/project/linuxSrc/ch04_11 # gdb raspbian_fork
GNU gdb (Debian 13.1-3) 13.1
Copyright (C) 2023 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "aarch64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from raspbian_fork...
(gdb) b main
Breakpoint 1 at 0x86c: file raspbian_fork.c, line 25.
(gdb) r
Starting program: /project/linuxSrc/ch04_11/raspbian_fork
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1".

Breakpoint 1, main () at raspbian_fork.c:25
25              int fork_times = 0;
(gdb) list
20      }
21
22      int main()
23      {
24              pid_t pid;
25              int fork_times = 0;
26
27              printf("About to fork process \n");
28
29              pid = fork();
(gdb) n
27              printf("About to fork process \n");
(gdb) n
About to fork process
29              pid = fork();
(gdb) s
0x0000007ff7eb8684 in __libc_fork () at ./posix/fork.c:48
48      ./posix/fork.c: No such file or directory.
(gdb) layout asm

gdb가 어셈블리 모드로 바뀐다.

"4.11.2 리눅스 유틸리티 프로그램을 이용한 실행 추적" 실습

ftrace 로그 작성

root@raspberrypi:/project/linuxSrc/ch04_11 # vi util_process.debug.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 sys_clone do_exit search_binary_handler copy_process.part.5 > /sys/kernel/debug/tracing/set_ftrace_filter
echo  __sched_fork.constprop.0 kernel_clone do_exit do_execveat_common.isra.0 copy_process > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"

echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_free/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exec/enable

sleep 1
echo "event 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"

_do_fork 함수 대신 __sched_fork.constprop.0 함수를 사용해야 한다.

스크립트 실행 가능하게

root@raspberrypi:/project/linuxSrc/ch04_11 # chmod 755 util_process.debug.sh

실행

1.  ./util_process.debug.sh
2.  whoami
3.  cat /proc/interrupts
4.  ../get_trace.sh

whoami 로그 확인

root@raspberrypi:/project/linuxSrc/ch04_11 # vi ftrace_log.c
 
 50             bash-747     [003] .....  6356.424767: <stack trace>
 51  => __sched_fork.constprop.0+0x8/0xf0
 52  => sched_fork+0x24/0x198
 53  => copy_process+0x718/0x15f8
 54  => kernel_clone+0x9c/0x448
 55  => __do_sys_clone+0x70/0xa8
 56  => __arm64_sys_clone+0x28/0x40
 57  => invoke_syscall+0x50/0x128
 58  => el0_svc_common.constprop.0+0x48/0xf0
 59  => do_el0_svc+0x24/0x38
 60  => el0_svc+0x38/0xd0
 61  => el0t_64_sync_handler+0x100/0x130
 62  => el0t_64_sync+0x190/0x198
 63             bash-747     [003] .....  6356.425344: sched_process_fork: comm=bash pid=747 child_comm=bash child_pid=1146
 64           whoami-1146    [000] .....  6356.425958: do_execveat_common.isra.0+0x4/0x248 <-__arm64_sys_execve+0x48/0x68
 65           whoami-1146    [000] .....  6356.425966: <stack trace>
 66  => do_execveat_common.isra.0+0x8/0x248
 67  => __arm64_sys_execve+0x48/0x68
 68  => invoke_syscall+0x50/0x128
 69  => el0_svc_common.constprop.0+0x48/0xf0
 70  => do_el0_svc+0x24/0x38
 71  => el0_svc+0x38/0xd0
 72  => el0t_64_sync_handler+0x100/0x130
 73  => el0t_64_sync+0x190/0x198
 74           whoami-1146    [000] .....  6356.427142: sched_process_exec: filename=/usr/bin/whoami pid=1146 old_pid=1146
 75           whoami-1146    [000] .....  6356.429438: do_exit+0x4/0x990 <-do_group_exit+0x3c/0xa0
 76           whoami-1146    [000] .....  6356.429446: <stack trace>
 77  => do_exit+0x8/0x990
 78  => do_group_exit+0x3c/0xa0
 79  => __arm64_sys_exit_group+0x20/0x28
 80  => invoke_syscall+0x50/0x128
 81  => el0_svc_common.constprop.0+0x48/0xf0
 82  => do_el0_svc+0x24/0x38
 83  => el0_svc+0x38/0xd0
 84  => el0t_64_sync_handler+0x100/0x130
 85  => el0t_64_sync+0x190/0x198
 86           whoami-1146    [000] .....  6356.429802: sched_process_exit: comm=whoami pid=1146 prio=120
 87           <idle>-0       [003] ..s1.  6356.462812: sched_process_free: comm=whoami pid=1146 prio=120

bash 프로세스에서 sched_process_fork를 실행 한 이후에 /usr/bin/whoami 프로세스에서 sched_process_exec 를 실행 한 후에 sched_process_exit를 실행한다.

cat 로그 확인

root@raspberrypi:/project/linuxSrc/ch04_11 # vi ftrace_log.c

213             bash-747     [003] .....  6362.371626: __sched_fork.constprop.0+0x4/0xf0 <-sched_fork+0x24/0x198
214             bash-747     [003] .....  6362.371629: <stack trace>
215  => __sched_fork.constprop.0+0x8/0xf0
216  => sched_fork+0x24/0x198
217  => copy_process+0x718/0x15f8
218  => kernel_clone+0x9c/0x448
219  => __do_sys_clone+0x70/0xa8
220  => __arm64_sys_clone+0x28/0x40
221  => invoke_syscall+0x50/0x128
222  => el0_svc_common.constprop.0+0x48/0xf0
223  => do_el0_svc+0x24/0x38
224  => el0_svc+0x38/0xd0
225  => el0t_64_sync_handler+0x100/0x130
226  => el0t_64_sync+0x190/0x198
227             bash-747     [003] .....  6362.372192: sched_process_fork: comm=bash pid=747 child_comm=bash child_pid=1149
228              cat-1149    [001] .....  6362.372806: do_execveat_common.isra.0+0x4/0x248 <-__arm64_sys_execve+0x48/0x68
229              cat-1149    [001] .....  6362.372813: <stack trace>
230  => do_execveat_common.isra.0+0x8/0x248
231  => __arm64_sys_execve+0x48/0x68
232  => invoke_syscall+0x50/0x128
233  => el0_svc_common.constprop.0+0x48/0xf0
234  => do_el0_svc+0x24/0x38
235  => el0_svc+0x38/0xd0
236  => el0t_64_sync_handler+0x100/0x130
237  => el0t_64_sync+0x190/0x198
238              cat-1149    [001] .....  6362.373864: sched_process_exec: filename=/usr/bin/cat pid=1149 old_pid=1149
239              cat-1149    [001] .....  6362.376400: do_exit+0x4/0x990 <-do_group_exit+0x3c/0xa0
240              cat-1149    [001] .....  6362.376408: <stack trace>
241  => do_exit+0x8/0x990
242  => do_group_exit+0x3c/0xa0
243  => __arm64_sys_exit_group+0x20/0x28
244  => invoke_syscall+0x50/0x128
245  => el0_svc_common.constprop.0+0x48/0xf0
246  => do_el0_svc+0x24/0x38
247  => el0_svc+0x38/0xd0
248  => el0t_64_sync_handler+0x100/0x130
249  => el0t_64_sync+0x190/0x198
250              cat-1149    [001] .....  6362.376735: sched_process_exit: comm=cat pid=1149 prio=120
251           <idle>-0       [003] ..s1.  6362.394903: sched_process_free: comm=cat pid=1149 prio=120

"디버깅을 통해 배우는 리눅스 커널의 구조와 원리" 책의 "4.4 유저 레벨 프로세스 실행 실습"에서 소개하는 프로세스 생성과 종료를 실습했다.

디렉터리 만들기

root@raspberrypi:/project/linuxSrc # mkdir ch04_04 && cd $_
root@raspberrypi:/project/linuxSrc/ch04_04 #

ftrace 디버그 시작 스크립트 파일 생성

sys_clone, _do_fork 함수가 없어서 kernel_clone, __arm64_sys_fork 함수로 대체했다.

(수정 : _do_fork 함수 __sched_fork.constprop.0 함수로 대체해야 한다.)

root@raspberrypi:/project/linuxSrc/ch04_04 # vi clone_process_debug.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/sched/sched_wakeup/enable

echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable

echo 1 > /sys/kernel/debug/tracing/events/signal/enable

#echo sys_clone do_exit > /sys/kernel/debug/tracing/set_ftrace_filter
echo kernel_clone do_exit > /sys/kernel/debug/tracing/set_ftrace_filter
#echo _do_fork copy_process* >> /sys/kernel/debug/tracing/set_ftrace_filter
echo __arm64_sys_fork copy_process* >> /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "event enabled"

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"

테스트 소스 파일 작성

root@raspberrypi:/project/linuxSrc/ch04_04 # vi raspbian_proc.c

#include <stdio.h>
#include <unistd.h>

#define PROC_TIMES 500
#define SLEEP_DURATION 3  // second unit

int main() 
{
	int proc_times = 0;

	for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
		printf("raspbian tracing \n");
		sleep(SLEEP_DURATION);
	}

	return 0;	
}

 Makefile 생성

root@raspberrypi:/project/linuxSrc/ch04_04 # vi Makefile

raspbian_proc: raspbian_proc.c
    gcc -o raspbian_proc raspbian_proc.c

빌드

root@raspberrypi:/project/linuxSrc/ch04_04 # make
gcc -o raspbian_proc raspbian_proc.c

1. ftrace On

root@raspberrypi:/project/linuxSrc/ch04_04 # ./clone_process_debug.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/ch04_04 # ./raspbian_proc
raspbian tracing
raspbian tracing
raspbian tracing

3. 터미널을 새로 만들고 접속한 후 로그인

4. 프로세스 상태 조회

root@raspberrypi:/project/linuxSrc/ch04_04 # ps -ely
S   UID     PID    PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S     0       1       0  0  80   0 11308 42107 do_epo ?        00:00:01 systemd
S     0       2       0  0  80   0     0     0 kthrea ?        00:00:00 kthreadd
S     0       3       2  0  80   0     0     0 kthrea ?        00:00:00 pool_workqueue_release
I     0       4       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-rcu_g
I     0       5       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-rcu_p
I     0       6       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-slub_
I     0       7       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-netns
I     0      11       2  0  80   0     0     0 worker ?        00:00:00 kworker/u8:0-ext4-rsv-conversion
I     0      12       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mm_pe
I     0      13       2  0  80   0     0     0 rcu_ta ?        00:00:00 rcu_tasks_kthread
I     0      14       2  0  80   0     0     0 rcu_ta ?        00:00:00 rcu_tasks_rude_kthread
I     0      15       2  0  80   0     0     0 rcu_ta ?        00:00:00 rcu_tasks_trace_kthread
S     0      16       2  0  80   0     0     0 smpboo ?        00:00:00 ksoftirqd/0
I     0      17       2  0  80   0     0     0 rcu_gp ?        00:00:00 rcu_preempt
S     0      18       2  0 -40   -     0     0 smpboo ?        00:00:00 migration/0
S     0      19       2  0  80   0     0     0 smpboo ?        00:00:00 cpuhp/0
S     0      20       2  0  80   0     0     0 smpboo ?        00:00:00 cpuhp/1
S     0      21       2  0 -40   -     0     0 smpboo ?        00:00:00 migration/1
S     0      22       2  0  80   0     0     0 smpboo ?        00:00:00 ksoftirqd/1
S     0      25       2  0  80   0     0     0 smpboo ?        00:00:00 cpuhp/2
S     0      26       2  0 -40   -     0     0 smpboo ?        00:00:00 migration/2
S     0      27       2  0  80   0     0     0 smpboo ?        00:00:00 ksoftirqd/2
I     0      29       2  0  60 -20     0     0 worker ?        00:00:00 kworker/2:0H-kblockd
S     0      30       2  0  80   0     0     0 smpboo ?        00:00:00 cpuhp/3
S     0      31       2  0 -40   -     0     0 smpboo ?        00:00:00 migration/3
S     0      32       2  0  80   0     0     0 smpboo ?        00:00:00 ksoftirqd/3
I     0      35       2  0  80   0     0     0 worker ?        00:00:00 kworker/u9:0-flush-179:0
I     0      36       2  0  80   0     0     0 worker ?        00:00:00 kworker/u10:0-events_unbound
I     0      37       2  0  80   0     0     0 worker ?        00:00:00 kworker/u11:0-events_unbound
I     0      38       2  0  80   0     0     0 worker ?        00:00:00 kworker/u12:0-events_unbound
S     0      39       2  0  80   0     0     0 devtmp ?        00:00:00 kdevtmpfs
I     0      40       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-inet_
S     0      42       2  0  80   0     0     0 kaudit ?        00:00:00 kauditd
S     0      44       2  0  80   0     0     0 watchd ?        00:00:00 khungtaskd
S     0      45       2  0  80   0     0     0 oom_re ?        00:00:00 oom_reaper
I     0      46       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-write
S     0      47       2  0  80   0     0     0 kcompa ?        00:00:00 kcompactd0
I     0      49       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-kinte
I     0      50       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-kbloc
I     0      51       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-blkcg
I     0      52       2  0  80   0     0     0 worker ?        00:00:00 kworker/u10:1-flush-179:0
S     0      53       2  0   9   -     0     0 kthrea ?        00:00:00 watchdogd
I     0      54       2  0  60 -20     0     0 worker ?        00:00:00 kworker/1:1H-kblockd
I     0      55       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-rpcio
I     0      56       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-xprti
S     0      58       2  0  80   0     0     0 kswapd ?        00:00:00 kswapd0
I     0      59       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-nfsio
I     0      60       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-kthro
I     0      61       2  0  80   0     0     0 worker ?        00:00:02 kworker/1:2-mm_percpu_wq
S     0      62       2  0   9   -     0     0 irq_th ?        00:00:00 irq/27-aerdrv
S     0      63       2  0  80   0     0     0 add_hw ?        00:00:00 hwrng
I     0      64       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-iscsi
I     0      65       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-nvme-
I     0      66       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-nvme-
I     0      67       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-nvme-
I     0      69       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-DWC N
I     0      70       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-uas
S     0      72       2  0  61 -19     0     0 slot_h ?        00:00:00 vchiq-slot/0
S     0      73       2  0  61 -19     0     0 recycl ?        00:00:00 vchiq-recy/0
S     0      74       2  0  60 -20     0     0 sync_f ?        00:00:00 vchiq-sync/0
I     0      75       2  0  60 -20     0     0 worker ?        00:00:00 kworker/0:1H-kblockd
I     0      76       2  0  60 -20     0     0 worker ?        00:00:00 kworker/u13:0-hci0
I     0      77       2  0  60 -20     0     0 worker ?        00:00:00 kworker/u14:0
I     0      78       2  0  60 -20     0     0 worker ?        00:00:00 kworker/u15:0
I     0      79       2  0  60 -20     0     0 worker ?        00:00:00 kworker/u16:0
I     0      80       2  0  60 -20     0     0 worker ?        00:00:00 kworker/u17:0
I     0      85       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-sdhci
S     0      86       2  0   9   -     0     0 irq_th ?        00:00:00 irq/37-mmc0
I     0     115       2  0  60 -20     0     0 worker ?        00:00:00 kworker/3:1H-kblockd
I     0     121       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mmc_c
I     0     133       2  0  60 -20     0     0 worker ?        00:00:00 kworker/2:1H-events_highpri
I     0     163       2  0  60 -20     0     0 worker ?        00:00:00 kworker/0:2H
I     0     173       2  0  80   0     0     0 worker ?        00:00:00 kworker/u12:2-events_unbound
S     0     185       2  0  80   0     0     0 kjourn ?        00:00:00 jbd2/mmcblk0p2-8
I     0     186       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-ext4-
I     0     202       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mld
I     0     203       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-ipv6_
I     0     210       2  0  60 -20     0     0 worker ?        00:00:00 kworker/3:2H
S     0     240       1  0  80   0 14592 12505 do_epo ?        00:00:00 systemd-journal
I     0     252       2  0  80   0     0     0 worker ?        00:00:00 kworker/u12:3-events_unbound
I     0     268       2  0  80   0     0     0 worker ?        00:00:00 kworker/u8:1
S     0     269       1  0  80   0  6144  6595 do_epo ?        00:00:00 systemd-udevd
S     0     304       2  0  80   0     0     0 vchiq_ ?        00:00:00 vchiq-keep/0
S     0     305       2  0  70 -10     0     0 vc_sm_ ?        00:00:00 SMIO
I     0     346       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mmal-
S     0     348       2  0  58   -     0     0 drm_sc ?        00:00:00 v3d_bin
I     0     349       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mmal-
S     0     350       2  0  58   -     0     0 drm_sc ?        00:00:00 v3d_render
S     0     351       2  0  58   -     0     0 drm_sc ?        00:00:00 v3d_tfu
S     0     352       2  0  58   -     0     0 drm_sc ?        00:00:00 v3d_csd
S     0     353       2  0  58   -     0     0 drm_sc ?        00:00:00 v3d_cache_clean
I     0     355       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mmal-
I     0     356       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mmal-
I     0     357       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mmal-
I     0     358       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mmal-
I     0     360       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-mmal-
S     0     362       2  0   9   -     0     0 irq_th ?        00:00:00 irq/39-feb10000.codec
S     0     377       2  0   9   -     0     0 irq_th ?        00:00:00 irq/41-vc4 hdmi hpd connected
S     0     378       2  0   9   -     0     0 irq_th ?        00:00:00 irq/42-vc4 hdmi hpd disconnected
S     0     380       2  0  80   0     0     0 cec_th ?        00:00:00 cec-vc4-hdmi-0
S     0     381       2  0   9   -     0     0 irq_th ?        00:00:00 irq/43-vc4 hdmi cec rx
S     0     382       2  0   9   -     0     0 irq_th ?        00:00:00 irq/44-vc4 hdmi cec tx
I     0     392       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-cfg80
S     0     395       2  0   9   -     0     0 irq_th ?        00:00:00 irq/45-vc4 hdmi hpd connected
S     0     400       2  0   9   -     0     0 irq_th ?        00:00:00 irq/46-vc4 hdmi hpd disconnected
S     0     403       2  0  80   0     0     0 cec_th ?        00:00:00 cec-vc4-hdmi-1
S     0     404       2  0   9   -     0     0 irq_th ?        00:00:00 irq/47-vc4 hdmi cec rx
S     0     405       2  0   9   -     0     0 irq_th ?        00:00:00 irq/48-vc4 hdmi cec tx
I     0     406       2  0  60 -20     0     0 rescue ?        00:00:00 kworker/R-brcmf
S     0     409       2  0  80   0     0     0 brcmf_ ?        00:00:02 brcmf_wdog/mmc1:0001:1
S     0     411       2  0   9   -     0     0 kthrea ?        00:00:00 card1-crtc0
S     0     414       2  0   9   -     0     0 kthrea ?        00:00:00 card1-crtc1
S     0     415       2  0   9   -     0     0 kthrea ?        00:00:00 card1-crtc2
S     0     416       2  0   9   -     0     0 kthrea ?        00:00:00 card1-crtc3
S     0     418       2  0   9   -     0     0 kthrea ?        00:00:00 card1-crtc4
S     0     419       2  0   9   -     0     0 kthrea ?        00:00:00 card1-crtc5
S   997     420       1  0  80   0  6784 22677 do_epo ?        00:00:00 systemd-timesyn
I     0     439       2  0  60 -20     0     0 worker ?        00:00:13 kworker/u13:1-brcmf_wq/mmc1:0001:1
S   104     446       1  0  80   0  2816  1840 do_sys ?        00:00:00 avahi-daemon
S     0     447       1  0  80   0  5248  3331 do_sys ?        00:00:00 bluetoothd
S     0     448       1  0  80   0  2432  1673 hrtime ?        00:00:00 cron
S   100     449       1  0  80   0  3712  2170 do_epo ?        00:00:00 dbus-daemon
S   996     458       1  0  80   0  6912 58803 do_sys ?        00:00:00 polkitd
S     0     464       1  0  80   0  7168  8446 do_epo ?        00:00:00 systemd-logind
S 65534     465       1  0  80   0  2304  1457 do_sel ?        00:00:00 thd
S   104     466     446  0  80   0  1300  1795 unix_s ?        00:00:00 avahi-daemon
S   106     487       1  0  80   0  1684   720 do_sys ?        00:00:00 dhcpcd
S     0     488     487  0  80   0  2068   779 do_sys ?        00:00:00 dhcpcd
S   106     489     487  0  80   0  1044   638 do_sys ?        00:00:00 dhcpcd
S   106     490     487  0  80   0  1044   637 do_sys ?        00:00:00 dhcpcd
S     0     529       1  0  80   0 18944 65674 do_sys ?        00:00:05 NetworkManager
S     0     536       1  0  80   0 10496  4323 do_sel ?        00:00:00 wpa_supplicant
S     0     556       1  0  80   0 11136 62413 do_sys ?        00:00:00 ModemManager
S     0     595       1  0  80   0  1920  1405 do_sel tty1     00:00:00 agetty
S     0     601       1  0  80   0  8448  4115 do_sys ?        00:00:00 sshd
S   106     619     488  0  80   0  1456   779 do_sys ?        00:00:00 dhcpcd
I     0     684       2  0  80   0     0     0 worker ?        00:00:00 kworker/3:1-mm_percpu_wq
S     0     686     601  0  80   0  9712  4899 do_sys ?        00:00:00 sshd
S  1000     689       1  0  80   0 10112  4898 do_epo ?        00:00:00 systemd
S  1000     690     689  0  80   0  4976 42547 do_sig ?        00:00:00 (sd-pam)
I     0     705       2  0  60 -20     0     0 worker ?        00:00:00 kworker/1:0H
S  1000     710     686  0  80   0  6540  4964 do_sys ?        00:00:03 sshd
S  1000     711     710  0  80   0  4608  2025 do_wai pts/0    00:00:00 bash
I     0     732       2  0  80   0     0     0 worker ?        00:00:00 kworker/u9:1-events_unbound
I     0     750       2  0  80   0     0     0 worker ?        00:00:00 kworker/2:0-cgwb_release
I     0     761       2  0  80   0     0     0 worker ?        00:00:00 kworker/u10:3-events_unbound
I     0     799       2  0  80   0     0     0 worker ?        00:00:00 kworker/u11:3-events_unbound
I     0     801       2  0  80   0     0     0 worker ?        00:00:00 kworker/1:3-events_power_efficient
I     0     831       2  0  80   0     0     0 worker ?        00:00:01 kworker/3:2-events
I     0     832       2  0  80   0     0     0 worker ?        00:00:00 kworker/2:1-mm_percpu_wq
I     0     845       2  0  80   0     0     0 worker ?        00:00:00 kworker/0:2-events
I     0     846       2  0  80   0     0     0 worker ?        00:00:00 kworker/1:1-events_freezable
I     0     847       2  0  80   0     0     0 worker ?        00:00:00 kworker/3:0-events
I     0     864       2  0  80   0     0     0 worker ?        00:00:00 kworker/u11:1-events_unbound
I     0     870       2  0  80   0     0     0 worker ?        00:00:00 kworker/0:0-events
I     0     902       2  0  80   0     0     0 worker ?        00:00:00 kworker/u9:2-events_unbound
I     0     910       2  0  80   0     0     0 worker ?        00:00:00 kworker/3:3-events
S     0     924     711  0  80   0  3636  2401 do_wai pts/0    00:00:00 su
S     0     925     924  0  80   0  4864  2060 do_wai pts/0    00:00:00 bash
I     0     937       2  0  80   0     0     0 worker ?        00:00:00 kworker/2:2-cgroup_destroy
I     0     938       2  0  80   0     0     0 worker ?        00:00:00 kworker/2:3
I     0     939       2  0  60 -20     0     0 worker ?        00:00:00 kworker/2:2H
S     0     947     925  0  80   0  1024   548 hrtime pts/0    00:00:00 raspbian_proc
S     0     948     601  1  80   0  9868  4898 do_sys ?        00:00:00 sshd
S  1000     954     948  0  80   0  6536  4963 do_sys ?        00:00:00 sshd
S  1000     955     954  0  80   0  4736  2025 do_wai pts/1    00:00:00 bash
S     0     966     955  1  80   0  3636  2401 do_wai pts/1    00:00:00 su
S     0     967     966  0  80   0  4864  2060 do_wai pts/1    00:00:00 bash
I     0     970       2  0  60 -20     0     0 worker ?        00:00:00 kworker/0:0H
I     0     971       2  0  80   0     0     0 worker ?        00:00:00 kworker/0:1-events
R     0     979     967 99  80   0  4224  2784 -      pts/1    00:00:00 ps

5. 프로그램 강제 종료

root@raspberrypi:/project/linuxSrc/ch04_04 # kill -9 947
root@raspberrypi:/project/linuxSrc/ch04_04 #

6. ftrace Off

root@raspberrypi:/project/linuxSrc/ch04_04 # ../get_trace.sh
ftrace off

프로세스 종료됨

root@raspberrypi:/project/linuxSrc/ch04_04 # ./raspbian_proc
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
raspbian tracing
Terminated

로그 분석

root@raspberrypi:/project/linuxSrc/ch04_04 # vi ftrace_log.c

 1309             bash-925     [001] d..4.  2638.047819: sched_wakeup: comm=kworker/u10:3 pid=761 prio=120 target_cpu=001
 1310             bash-925     [001] .....  2638.048117: kernel_clone+0x4/0x448 <-__do_sys_clone+0x70/0xa8                   
 1311             bash-925     [001] .....  2638.048123: <stack trace>                                                      
 1312  => kernel_clone+0x8/0x448                                                                                            
 1313  => __do_sys_clone+0x70/0xa8                                                                                          
 1314  => __arm64_sys_clone+0x28/0x40                                                                                       
 1315  => invoke_syscall+0x50/0x128                                                                                         
 1316  => el0_svc_common.constprop.0+0x48/0xf0                                                                              
 1317  => do_el0_svc+0x24/0x38                                                                                              
 1318  => el0_svc+0x38/0xd0                                                                                                 
 1319  => el0t_64_sync_handler+0x100/0x130                                                                                  
 1320  => el0t_64_sync+0x190/0x198                                                                                          
 1321             bash-925     [001] .....  2638.048126: copy_process+0x4/0x15f8 <-kernel_clone+0x9c/0x448                  
 1322             bash-925     [001] .....  2638.048128: <stack trace>
 1323  => copy_process+0x8/0x15f8                                                                                           
 1324  => kernel_clone+0x9c/0x448                                                                                           
 1325  => __do_sys_clone+0x70/0xa8                                                                                          
 1326  => __arm64_sys_clone+0x28/0x40                                                                                       
 1327  => invoke_syscall+0x50/0x128
 1328  => el0_svc_common.constprop.0+0x48/0xf0                                                                              
 1329  => do_el0_svc+0x24/0x38                                                                                              
 1330  => el0_svc+0x38/0xd0                                                                                                 
 1331  => el0t_64_sync_handler+0x100/0x130                                                                                  
 1332  => el0t_64_sync+0x190/0x198
 1333             bash-925     [001] .....  2638.048761: sched_process_fork: comm=bash pid=925 child_comm=bash child_pid=947
 1334           <idle>-0       [002] d..2.  2638.048811: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_sta      te=R ==> next_comm=bash next_pid=947 next_prio=120

bash 925 프로세스가 raspbian_proc 927 프로세스를 생성

 4522    raspbian_proc-947     [002] dN.4.  2647.052615: sched_wakeup: comm=kworker/u11:1 pid=864 prio=120 target_cpu=002
 4523    raspbian_proc-947     [002] d..2.  2647.052619: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=R+ ==> next_comm=kworker/u11:1 next_pid=864 next_prio=120
 4524           <idle>-0       [000] dNh2.  2647.052630: sched_wakeup: comm=sshd pid=710 prio=120 target_cpu=000
 4525    kworker/u11:1-864     [002] d..2.  2647.052630: sched_switch: prev_comm=kworker/u11:1 prev_pid=864 prev_prio=120 prev_state=I ==> next_comm=raspbian_proc next_pid=947 next_prio=120
 4526    raspbian_proc-947     [002] dN.4.  2647.052633: sched_wakeup: comm=kworker/u11:1 pid=864 prio=120 target_cpu=002
 4527           <idle>-0       [000] d..2.  2647.052634: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=710 next_prio=120
 4528    raspbian_proc-947     [002] d..2.  2647.052635: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=R+ ==> next_comm=kworker/u11:1 next_pid=864 next_prio=120
 4529    kworker/u11:1-864     [002] d..2.  2647.052638: sched_switch: prev_comm=kworker/u11:1 prev_pid=864 prev_prio=120 prev_state=I ==> next_comm=raspbian_proc next_pid=947 next_prio=120
 4530    raspbian_proc-947     [002] d..2.  2647.052652: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120


 6133    raspbian_proc-947     [002] dN.4.  2650.052761: sched_wakeup: comm=kworker/u11:1 pid=864 prio=120 target_cpu=002
 6134    raspbian_proc-947     [002] d..2.  2650.052766: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=R+ ==> next_comm=kworker/u11:1 next_pid=864 next_prio=120
 6135    kworker/u11:1-864     [002] d..2.  2650.052776: sched_switch: prev_comm=kworker/u11:1 prev_pid=864 prev_prio=120 prev_state=I ==> next_comm=raspbian_proc next_pid=947 next_prio=120
 6136           <idle>-0       [000] dNh2.  2650.052777: sched_wakeup: comm=sshd pid=710 prio=120 target_cpu=000
 6137    raspbian_proc-947     [002] dN.4.  2650.052779: sched_wakeup: comm=kworker/u11:1 pid=864 prio=120 target_cpu=002
 6138           <idle>-0       [000] d..2.  2650.052781: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=710 next_prio=120
 6139    raspbian_proc-947     [002] d..2.  2650.052781: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=R+ ==> next_comm=kworker/u11:1 next_pid=864 next_prio=120
 6140    kworker/u11:1-864     [002] d..2.  2650.052784: sched_switch: prev_comm=kworker/u11:1 prev_pid=864 prev_prio=120 prev_state=I ==> next_comm=raspbian_proc next_pid=947 next_prio=120
 6141    raspbian_proc-947     [002] d..2.  2650.052797: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120


 7410    raspbian_proc-947     [002] dN.4.  2653.052953: sched_wakeup: comm=kworker/u11:1 pid=864 prio=120 target_cpu=002
 7411    raspbian_proc-947     [002] d..2.  2653.052964: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=R+ ==> next_comm=kworker/u11:1 next_pid=864 next_prio=120
 7412    kworker/u11:1-864     [002] d..2.  2653.052989: sched_switch: prev_comm=kworker/u11:1 prev_pid=864 prev_prio=120 prev_state=I ==> next_comm=raspbian_proc next_pid=947 next_prio=120
 7413           <idle>-0       [000] dNh2.  2653.052993: sched_wakeup: comm=sshd pid=710 prio=120 target_cpu=000
 7414    raspbian_proc-947     [002] dN.4.  2653.052997: sched_wakeup: comm=kworker/u11:1 pid=864 prio=120 target_cpu=002
 7415           <idle>-0       [000] d..2.  2653.053002: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=710 next_prio=120
 7416    raspbian_proc-947     [002] d..2.  2653.053004: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=R+ ==> next_comm=kworker/u11:1 next_pid=864 next_prio=120
 7417    kworker/u11:1-864     [002] d..2.  2653.053012: sched_switch: prev_comm=kworker/u11:1 prev_pid=864 prev_prio=120 prev_state=I ==> next_comm=raspbian_proc next_pid=947 next_prio=120
 7418    raspbian_proc-947     [002] d..2.  2653.053042: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120

3초마다 실행됨

2647.052615 -> 2650.052761 -> 2653.052953

16046             bash-967     [003] d..4.  2681.529574: sched_wakeup: comm=kworker/u12:3 pid=252 prio=120 target_cpu=003
16047             bash-967     [003] d..1.  2681.529861: signal_generate: sig=9 errno=0 code=0 comm=raspbian_proc pid=947 grp=1 res=0
16048           <idle>-0       [002] dNh2.  2681.529872: sched_wakeup: comm=raspbian_proc pid=947 prio=120 target_cpu=002
16049           <idle>-0       [002] d..2.  2681.529882: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=947 next_prio=120
16050    raspbian_proc-947     [002] d..1.  2681.529898: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0
16051    raspbian_proc-947     [002] .....  2681.529903: do_exit+0x4/0x990 <-do_group_exit+0x3c/0xa0
16052    raspbian_proc-947     [002] .....  2681.529909: <stack trace>
16053  => do_exit+0x8/0x990
16054  => do_group_exit+0x3c/0xa0
16055  => get_signal+0x9e4/0x9f0
16056  => do_notify_resume+0x15c/0xfa0
16057  => el0_svc+0xbc/0xd0
16058  => el0t_64_sync_handler+0x100/0x130
16059  => el0t_64_sync+0x190/0x198
16060    raspbian_proc-947     [002] .....  2681.530253: sched_process_exit: comm=raspbian_proc pid=947 prio=120
16061    raspbian_proc-947     [002] d..2.  2681.530310: signal_generate: sig=17 errno=0 code=2 comm=bash pid=925 grp=1 res=0
16062           <idle>-0       [001] dNh2.  2681.530331: sched_wakeup: comm=bash pid=925 prio=120 target_cpu=001
16063           <idle>-0       [001] d..2.  2681.530341: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=925 next_prio=120
16064             bash-967     [003] d..2.  2681.530357: sched_switch: prev_comm=bash prev_pid=967 prev_prio=120 prev_state=S ==> next_comm=kworker/u12:3 next_pid=252 next_prio=120
16065    raspbian_proc-947     [002] d..2.  2681.530358: sched_switch: prev_comm=raspbian_proc prev_pid=947 prev_prio=120 prev_state=X ==> next_comm=swapper/2 next_pid=0 next_prio=120
16066           <idle>-0       [000] dNh2.  2681.530386: sched_wakeup: comm=sshd pid=954 prio=120 target_cpu=000

프로세스 강제 종료

프로그램 수정 후 빌드

root@raspberrypi:/project/linuxSrc/ch04_04 # vi raspbian_proc.c

#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>

#define PROC_TIMES 3
#define SLEEP_DURATION 3  // second unit

int main()
{
    int proc_times = 0;

    for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) {
        printf("raspbian tracing \n");
        sleep(SLEEP_DURATION);
    }

    exit(EXIT_SUCCESS);

    return 0;
}


root@raspberrypi:/project/linuxSrc/ch04_04 # make
gcc -o raspbian_proc raspbian_proc.c

1. ftrace On

2. 프로그램 실행

root@raspberrypi:/project/linuxSrc/ch04_04 # ./raspbian_proc
raspbian tracing
raspbian tracing
raspbian tracing
root@raspberrypi:/project/linuxSrc/ch04_04 #

3. ftrace Off

로그 분석

root@raspberrypi:/project/linuxSrc/ch04_04 # vi ftrace_log.c

2358           <idle>-0       [002] dNh4.  6830.586789: sched_wakeup: comm=raspbian_proc pid=1168 prio=120 target_cpu=002
2359           <idle>-0       [002] dNh5.  6830.586797: sched_wakeup: comm=kworker/2:1 pid=832 prio=120 target_cpu=002
2360           <idle>-0       [002] d..2.  6830.586807: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=raspbian_proc next_pid=1168 next_prio=120
2361    raspbian_proc-1168    [002] .....  6830.586853: do_exit+0x4/0x990 <-do_group_exit+0x3c/0xa0
2362    raspbian_proc-1168    [002] .....  6830.586860: <stack trace>
2363  => do_exit+0x8/0x990
2364  => do_group_exit+0x3c/0xa0
2365  => __arm64_sys_exit_group+0x20/0x28
2366  => invoke_syscall+0x50/0x128
2367  => el0_svc_common.constprop.0+0x48/0xf0
2368  => do_el0_svc+0x24/0x38
2369  => el0_svc+0x38/0xd0
2370  => el0t_64_sync_handler+0x100/0x130
2371  => el0t_64_sync+0x190/0x198
2372    raspbian_proc-1168    [002] .....  6830.587190: sched_process_exit: comm=raspbian_proc pid=1168 prio=120
2373    raspbian_proc-1168    [002] d..2.  6830.587245: signal_generate: sig=17 errno=0 code=1 comm=bash pid=925 grp=1 res=0
2374           <idle>-0       [001] dNh2.  6830.587264: sched_wakeup: comm=bash pid=925 prio=120 target_cpu=001
2375           <idle>-0       [001] d..2.  6830.587272: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=925 next_prio=120
2376    raspbian_proc-1168    [002] d..2.  6830.587276: sched_switch: prev_comm=raspbian_proc prev_pid=1168 prev_prio=120 prev_state=Z ==> next_comm=kworker/2:1 next_pid=832 next_prio=120
2377      kworker/2:1-832     [002] d..2.  6830.587308: sched_switch: prev_comm=kworker/2:1 prev_pid=832 prev_prio=120 prev_state=I ==> next_comm=swapper/2 next_pid=0 next_prio=120
2378             bash-925     [001] d..1.  6830.587439: signal_deliver: sig=17 errno=0 code=1 sa_handler=557a8d50f4 sa_flags=10000000

함수 호출 위치 확인 하기

1. 커널 이미지에서 __arm64_sys_exit_group 함수의 시작 주소를 얻는다.

root@raspberrypi:/project/linuxSrc/ch04_04 # objdump -x ../out/vmlinux | grep __arm64_sys_exit_group
ffffffc080094998 g     F .text  0000000000000020 __arm64_sys_exit_group

2. 커널 이미지에서 __arm64_sys_exit_group 함수의 어셈블리 코드를 확인한다.

root@raspberrypi:/project/linuxSrc/ch04_04 # objdump --start-address=0xffffffc080094998 -d ../out/vmlinux | more

../out/vmlinux:     file format elf64-littleaarch64


Disassembly of section .text:

ffffffc080094998 <__arm64_sys_exit_group>:
ffffffc080094998:       d503201f        nop
ffffffc08009499c:       d503201f        nop
ffffffc0800949a0:       d503233f        paciasp
ffffffc0800949a4:       a9bf7bfd        stp     x29, x30, [sp, #-16]!
ffffffc0800949a8:       910003fd        mov     x29, sp
ffffffc0800949ac:       f9400000        ldr     x0, [x0]
ffffffc0800949b0:       53181c00        ubfiz   w0, w0, #8, #8
ffffffc0800949b4:       97ffffd1        bl      ffffffc0800948f8 <do_group_exit>
ffffffc0800949b8:       d503201f        nop
ffffffc0800949bc:       d503201f        nop

ffffffc0800949c0 <__wake_up_parent>:
ffffffc0800949c0:       d503201f        nop
ffffffc0800949c4:       d503201f        nop
ffffffc0800949c8:       aa0103e3        mov     x3, x1
ffffffc0800949cc:       d503233f        paciasp
ffffffc0800949d0:       a9bf7bfd        stp     x29, x30, [sp, #-16]!
ffffffc0800949d4:       aa0003e2        mov     x2, x0
ffffffc0800949d8:       52800021        mov     w1, #0x1                        // #1
ffffffc0800949dc:       910003fd        mov     x29, sp
ffffffc0800949e0:       f943f460        ldr     x0, [x3, #2024]
ffffffc0800949e4:       91008000        add     x0, x0, #0x20
ffffffc0800949e8:       940176fa        bl      ffffffc0800f25d0 <__wake_up_sync_key>
ffffffc0800949ec:       a8c17bfd        ldp     x29, x30, [sp], #16
ffffffc0800949f0:       d50323bf        autiasp
ffffffc0800949f4:       d65f03c0        ret
ffffffc0800949f8:       d503201f        nop
ffffffc0800949fc:       d503201f        nop

ffffffc080094a00 <__arm64_sys_waitid>:
ffffffc080094a00:       d503201f        nop
ffffffc080094a04:       d503201f        nop
ffffffc080094a08:       aa0003e4        mov     x4, x0
ffffffc080094a0c:       d503233f        paciasp
ffffffc080094a10:       a9bf7bfd        stp     x29, x30, [sp, #-16]!
ffffffc080094a14:       910003fd        mov     x29, sp
ffffffc080094a18:       f9400882        ldr     x2, [x4, #16]
ffffffc080094a1c:       b9400881        ldr     w1, [x4, #8]
ffffffc080094a20:       b9401883        ldr     w3, [x4, #24]
ffffffc080094a24:       f9401084        ldr     x4, [x4, #32]
ffffffc080094a28:       b9400000        ldr     w0, [x0]
ffffffc080094a2c:       97fffa8b        bl      ffffffc080093458 <__do_sys_waitid>
ffffffc080094a30:       a8c17bfd        ldp     x29, x30, [sp], #16
ffffffc080094a34:       d50323bf        autiasp
ffffffc080094a38:       d65f03c0        ret
ffffffc080094a3c:       d503201f        nop
ffffffc080094a40:       d503201f        nop
ffffffc080094a44:       d503201f        nop

ffffffc080094a48 <kernel_wait4>:
ffffffc080094a48:       d503201f        nop
ffffffc080094a4c:       d503201f        nop
ffffffc080094a50:       d503233f        paciasp
ffffffc080094a54:       a9b77bfd        stp     x29, x30, [sp, #-144]!
ffffffc080094a58:       d5384104        mrs     x4, sp_el0
ffffffc080094a5c:       910003fd        mov     x29, sp
ffffffc080094a60:       a90153f3        stp     x19, x20, [sp, #16]
ffffffc080094a64:       2a0003f4        mov     w20, w0
ffffffc080094a68:       2a0203f3        mov     w19, w2
ffffffc080094a6c:       a9025bf5        stp     x21, x22, [sp, #32]
ffffffc080094a70:       d2800b02        mov     x2, #0x58                       // #88
ffffffc080094a74:       aa0103f5        mov     x21, x1
--More--

__arm64_sys_exit_group 시작 주소 + 오프셋 - 0x4 계산

0xffffffc080094998 + 0x20 - 0x4 = 0xffffffc0800949b4 

ffffffc0800949b4:       97ffffd1        bl      ffffffc0800948f8 <do_group_exit>

do_group_exit 호출 확인

"디버깅을 통해 배우는 리눅스 커널의 구조와 원리" 책의 "3.1.2 디버깅과 코드 학습 능력"에서 소개하는 rpi_debugfs를 실습했다 .

rpi_debugfs.c 드라이버 파일 작성을 작성하여 디버깅 옵션을 준다.

rpi_debugfs.c 파일을 생성한다.

6.6.x 버전의 커널 소스에서 linux/sub_def.h 파일을 include 하면 빌드 에러가 발생하므로 주석처리한다.

root@raspberrypi:/project/linuxSrc # vi linux/drivers/soc/bcm/rpi_debugfs.c

#include <linux/module.h>
#include <linux/moduleparam.h>
#include <linux/platform_device.h>
//#include <linux/reboot.h>
#include <linux/io.h>
#include <linux/init.h>
#include <linux/memblock.h>
#include <linux/slab.h>
#include <linux/of.h>
#include <linux/of_address.h>
#include <linux/cpu.h>
#include <linux/delay.h>
#include <asm/setup.h>
#include <linux/input.h>
#include <linux/debugfs.h>
#include <linux/timer.h>
#include <linux/workqueue.h>
#include <linux/mutex.h>
//#include <linux/slub_def.h>
#include <linux/uaccess.h>
#include <asm/memory.h>

uint32_t raspbian_debug_state = 0x1000;
static struct dentry *rpi_kernel_debug_debugfs_root;

static int rpi_kernel_debug_stat_get(void *data, u64 *val)
{
    printk("===[%s][L:%d][val:%d]===\n", __func__, __LINE__, raspbian_debug_state);
    *val = raspbian_debug_state;

    return 0;
}

static int rpi_kernel_debug_stat_set(void *data, u64 val)
{
    raspbian_debug_state = (uint32_t)val;

    printk("[raspbian] [%s][L:%d], raspbian_debug_state[%lu],value[%lu]===\n", 
								__func__, __LINE__, (long unsigned int)raspbian_debug_state, (long unsigned int)val);

    return 0;
}


DEFINE_SIMPLE_ATTRIBUTE(rpi_kernel_debug_stat_fops, rpi_kernel_debug_stat_get, rpi_kernel_debug_stat_set, "%llu\n");

static int rpi_kernel_debug_debugfs_driver_probe(struct platform_device *pdev)
{
    printk("===[%s][L:%d]===\n", __func__, __LINE__);
    return 0;
}

static struct platform_driver rpi_kernel_debug_debugfs_driver = {
    .probe      = rpi_kernel_debug_debugfs_driver_probe,
    .driver     = {
        .owner  = THIS_MODULE,
        .name   = "rpi_debug",
    },
};

static int __init rpi_kernel_debug_debugfs_init(void)
{
    printk("===[%s][L:%d]===\n", __func__, __LINE__);

    rpi_kernel_debug_debugfs_root = debugfs_create_dir("rpi_debug", NULL);
    debugfs_create_file("val", S_IRUGO, rpi_kernel_debug_debugfs_root, NULL, &rpi_kernel_debug_stat_fops);

    return platform_driver_register(&rpi_kernel_debug_debugfs_driver);
}

late_initcall(rpi_kernel_debug_debugfs_init);

MODULE_DESCRIPTION("raspberrypi debug interface driver");
MODULE_AUTHOR("Austin Kim <austindh.kim@gmail.com>");
MODULE_LICENSE("GPL");

Makefile 파일 수정

2행 "obj-y += rpi_debugfs.o"를 추가한다.

  root@raspberrypi:/project/linuxSrc # vi linux/drivers/soc/bcm/Makefile
  
  1 # SPDX-License-Identifier: GPL-2.0-only
  2 obj-y += rpi_debugfs.o
  3 obj-$(CONFIG_SOC_BRCMSTB)   += brcmstb/

빌드 -> 인스톨

커널 이미지에 포함되었는지 확인

root@raspberrypi:/project/linuxSrc # ls /sys/kernel/debug/rpi_debug/
val

rpi_debugfs 전역변수 값 확인

root@raspberrypi:/project/linuxSrc # cat /sys/kernel/debug/rpi_debug/val
4096

rpi_debugfs 전역변수 값 수정

root@raspberrypi:/project/linuxSrc # echo 825 > /sys/kernel/debug/rpi_debug/val
root@raspberrypi:/project/linuxSrc # cat /sys/kernel/debug/rpi_debug/val
825

rpi_get_interrupt_info 함수 호출을 raspbian_debug_state 값이 825일 때 실행되게 수정한다.

raspbian_debug_state 외부 변수를 선언하고, 변수가 825일 때 함수 진입

root@raspberrypi:/project/linuxSrc # vi linux/kernel/irq/proc.c

474 extern uint32_t raspbian_debug_state;

543     if (825 == raspbian_debug_state && action)
544         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..8758d3d48 100644
--- a/kernel/irq/proc.c
+++ b/kernel/irq/proc.c
@@ -456,6 +456,22 @@ 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);
+       }
+}
+
+extern uint32_t raspbian_debug_state;

 int show_interrupts(struct seq_file *p, void *v)
 {
@@ -523,6 +539,10 @@ int show_interrupts(struct seq_file *p, void *v)
                seq_printf(p, "-%-8s", desc->name);

        action = desc->action;
+
+       if (825 == raspbian_debug_state && action)
+               rpi_get_interrupt_info(action);
+
        if (action) {
                seq_printf(p, "  %s", action->name);
                while ((action = action->next) != NULL)

빌드 -> 인스톨

rpi_debugfs 전역변수 값 확인

부팅시 4096으로 초기화된다.

root@raspberrypi:/project/linuxSrc # cat /sys/kernel/debug/rpi_debug/val
4096

1. ftrace On

2. 함수를 호출하는 명령 실행

3. ftrace Off

irq_get_interrupt_info 함수 호출 로그 확인

root@raspberrypi:/project/linuxSrc # egrep -nr rpi_get_interrupt_info ftrace_log.c
root@raspberrypi:/project/linuxSrc #

rip_degugfs 전역변수를 825로 설정

root@raspberrypi:/project/linuxSrc # echo 825 > /sys/kernel/debug/rpi_debug/val
root@raspberrypi:/project/linuxSrc # cat /sys/kernel/debug/rpi_debug/val
825

1. ftrace On

2. 함수를 호출하는 명령 실행

3. ftrace Off

irq_get_interrupt_info 함수 호출 로그 확인

root@raspberrypi:/project/linuxSrc # egrep -nr rpi_get_interrupt_info ftrace_log.c
17388:             cat-835     [002] d..1.   718.675230: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17390: => rpi_get_interrupt_info+0x8/0x58
17403:             cat-835     [002] d..1.   718.675246: rpi_get_interrupt_info+0x10/0x58: [cat] 9: vgic, irq_handler: vgic_maintenance_handler+0x0/0x18
17404:             cat-835     [002] d..1.   718.675259: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17406: => rpi_get_interrupt_info+0x8/0x58
17419:             cat-835     [002] d..1.   718.675265: rpi_get_interrupt_info+0x10/0x58: [cat] 11: arch_timer, irq_handler: arch_timer_handler_phys+0x0/0x58
17420:             cat-835     [002] d..1.   718.675274: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17422: => rpi_get_interrupt_info+0x8/0x58
17435:             cat-835     [002] d..1.   718.675280: rpi_get_interrupt_info+0x10/0x58: [cat] 12: kvm guest vtimer, irq_handler: kvm_arch_timer_handler+0x0/0xf0
17436:             cat-835     [002] d..1.   718.675289: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17438: => rpi_get_interrupt_info+0x8/0x58
17451:             cat-835     [002] d..1.   718.675294: rpi_get_interrupt_info+0x10/0x58: [cat] 14: fe00b880.mailbox, irq_handler: bcm2835_mbox_irq+0x0/0xc0
17452:             cat-835     [002] d..1.   718.675303: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17454: => rpi_get_interrupt_info+0x8/0x58
17467:             cat-835     [002] d..1.   718.675308: rpi_get_interrupt_info+0x10/0x58: [cat] 15: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x1d0
17468:             cat-835     [002] d..1.   718.675319: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17470: => rpi_get_interrupt_info+0x8/0x58
17483:             cat-835     [002] d..1.   718.675324: rpi_get_interrupt_info+0x10/0x58: [cat] 21: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x1d0
17484:             cat-835     [002] d..1.   718.675331: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17486: => rpi_get_interrupt_info+0x8/0x58
17499:             cat-835     [002] d..1.   718.675335: rpi_get_interrupt_info+0x10/0x58: [cat] 22: DMA IRQ, irq_handler: bcm2835_dma_callback+0x0/0x1d0
17500:             cat-835     [002] d..1.   718.675346: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17502: => rpi_get_interrupt_info+0x8/0x58
17515:             cat-835     [002] d..1.   718.675351: rpi_get_interrupt_info+0x10/0x58: [cat] 27: PCIe PME, irq_handler: pcie_pme_irq+0x0/0xe8
17516:             cat-835     [002] d..1.   718.675360: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17518: => rpi_get_interrupt_info+0x8/0x58
17531:             cat-835     [002] d..1.   718.675365: rpi_get_interrupt_info+0x10/0x58: [cat] 28: eth0, irq_handler: bcmgenet_isr0+0x0/0x190
17532:             cat-835     [002] d..1.   718.675372: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17534: => rpi_get_interrupt_info+0x8/0x58
17547:             cat-835     [002] d..1.   718.675377: rpi_get_interrupt_info+0x10/0x58: [cat] 29: eth0, irq_handler: bcmgenet_isr1+0x0/0x158
17548:             cat-835     [002] d..1.   718.675386: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17550: => rpi_get_interrupt_info+0x8/0x58
17563:             cat-835     [002] d..1.   718.675394: rpi_get_interrupt_info+0x10/0x58: [cat] 30: xhci_hcd, irq_handler: xhci_msi_irq+0x0/0x30
17564:             cat-835     [002] d..1.   718.675402: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17566: => rpi_get_interrupt_info+0x8/0x58
17579:             cat-835     [002] d..1.   718.675407: rpi_get_interrupt_info+0x10/0x58: [cat] 31: VCHIQ doorbell, irq_handler: vchiq_doorbell_irq+0x0/0x60
17580:             cat-835     [002] d..1.   718.675414: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17582: => rpi_get_interrupt_info+0x8/0x58
17595:             cat-835     [002] d..1.   718.675419: rpi_get_interrupt_info+0x10/0x58: [cat] 32: arm-pmu, irq_handler: armpmu_dispatch_irq+0x0/0x80
17596:             cat-835     [002] d..1.   718.675426: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17598: => rpi_get_interrupt_info+0x8/0x58
17611:             cat-835     [002] d..1.   718.675430: rpi_get_interrupt_info+0x10/0x58: [cat] 33: arm-pmu, irq_handler: armpmu_dispatch_irq+0x0/0x80
17612:             cat-835     [002] d..1.   718.675436: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17614: => rpi_get_interrupt_info+0x8/0x58
17627:             cat-835     [002] d..1.   718.675441: rpi_get_interrupt_info+0x10/0x58: [cat] 34: arm-pmu, irq_handler: armpmu_dispatch_irq+0x0/0x80
17628:             cat-835     [002] d..1.   718.675447: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17630: => rpi_get_interrupt_info+0x8/0x58
17643:             cat-835     [002] d..1.   718.675451: rpi_get_interrupt_info+0x10/0x58: [cat] 35: arm-pmu, irq_handler: armpmu_dispatch_irq+0x0/0x80
17644:             cat-835     [002] d..1.   718.675459: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17646: => rpi_get_interrupt_info+0x8/0x58
17659:             cat-835     [002] d..1.   718.675463: rpi_get_interrupt_info+0x10/0x58: [cat] 36: uart-pl011, irq_handler: pl011_int+0x0/0x448
17660:             cat-835     [002] d..1.   718.675471: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17662: => rpi_get_interrupt_info+0x8/0x58
17675:             cat-835     [002] d..1.   718.675475: rpi_get_interrupt_info+0x10/0x58: [cat] 37: mmc1, irq_handler: bcm2835_mmc_irq+0x0/0x690
17676:             cat-835     [002] d..1.   718.675483: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17678: => rpi_get_interrupt_info+0x8/0x58
17691:             cat-835     [002] d..1.   718.675488: rpi_get_interrupt_info+0x10/0x58: [cat] 38: v3d, irq_handler: v3d_irq+0x0/0x2f8 [v3d]
17692:             cat-835     [002] d..1.   718.675496: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17694: => rpi_get_interrupt_info+0x8/0x58
17707:             cat-835     [002] d..1.   718.675501: rpi_get_interrupt_info+0x10/0x58: [cat] 39: feb10000.codec, irq_handler: rpivid_irq_irq+0x0/0x128 [rpivid_hevc]
17708:             cat-835     [002] d..1.   718.675508: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17710: => rpi_get_interrupt_info+0x8/0x58
17723:             cat-835     [002] d..1.   718.675513: rpi_get_interrupt_info+0x10/0x58: [cat] 40: vc4 hvs, irq_handler: vc4_hvs_irq_handler+0x0/0x180 [vc4]
17724:             cat-835     [002] d..1.   718.675521: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17726: => rpi_get_interrupt_info+0x8/0x58
17739:             cat-835     [002] d..1.   718.675526: rpi_get_interrupt_info+0x10/0x58: [cat] 41: vc4 hdmi hpd connected, irq_handler: irq_default_primary_handler+0x0/0x18
17740:             cat-835     [002] d..1.   718.675533: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17742: => rpi_get_interrupt_info+0x8/0x58
17755:             cat-835     [002] d..1.   718.675537: rpi_get_interrupt_info+0x10/0x58: [cat] 42: vc4 hdmi hpd disconnected, irq_handler: irq_default_primary_handler+0x0/0x18
17756:             cat-835     [002] d..1.   718.675545: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17758: => rpi_get_interrupt_info+0x8/0x58
17771:             cat-835     [002] d..1.   718.675549: rpi_get_interrupt_info+0x10/0x58: [cat] 43: vc4 hdmi cec rx, irq_handler: vc4_cec_irq_handler_rx_bare+0x0/0x58 [vc4]
17772:             cat-835     [002] d..1.   718.675556: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17774: => rpi_get_interrupt_info+0x8/0x58
17787:             cat-835     [002] d..1.   718.675561: rpi_get_interrupt_info+0x10/0x58: [cat] 44: vc4 hdmi cec tx, irq_handler: vc4_cec_irq_handler_tx_bare+0x0/0x180 [vc4]
17788:             cat-835     [002] d..1.   718.675569: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17790: => rpi_get_interrupt_info+0x8/0x58
17803:             cat-835     [002] d..1.   718.675573: rpi_get_interrupt_info+0x10/0x58: [cat] 45: vc4 hdmi hpd connected, irq_handler: irq_default_primary_handler+0x0/0x18
17804:             cat-835     [002] d..1.   718.675580: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17806: => rpi_get_interrupt_info+0x8/0x58
17819:             cat-835     [002] d..1.   718.675585: rpi_get_interrupt_info+0x10/0x58: [cat] 46: vc4 hdmi hpd disconnected, irq_handler: irq_default_primary_handler+0x0/0x18
17820:             cat-835     [002] d..1.   718.675592: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17822: => rpi_get_interrupt_info+0x8/0x58
17835:             cat-835     [002] d..1.   718.675596: rpi_get_interrupt_info+0x10/0x58: [cat] 47: vc4 hdmi cec rx, irq_handler: vc4_cec_irq_handler_rx_bare+0x0/0x58 [vc4]
17836:             cat-835     [002] d..1.   718.675604: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17838: => rpi_get_interrupt_info+0x8/0x58
17851:             cat-835     [002] d..1.   718.675608: rpi_get_interrupt_info+0x10/0x58: [cat] 48: vc4 hdmi cec tx, irq_handler: vc4_cec_irq_handler_tx_bare+0x0/0x180 [vc4]
17852:             cat-835     [002] d..1.   718.675615: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17854: => rpi_get_interrupt_info+0x8/0x58
17867:             cat-835     [002] d..1.   718.675621: rpi_get_interrupt_info+0x10/0x58: [cat] 49: fe004000.txp, irq_handler: vc4_txp_interrupt+0x0/0x80 [vc4]
17868:             cat-835     [002] d..1.   718.675629: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17870: => rpi_get_interrupt_info+0x8/0x58
17883:             cat-835     [002] d..1.   718.675633: rpi_get_interrupt_info+0x10/0x58: [cat] 50: vc4 crtc, irq_handler: vc4_crtc_irq_handler+0x0/0x70 [vc4]
17884:             cat-835     [002] d..1.   718.675640: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17886: => rpi_get_interrupt_info+0x8/0x58
17899:             cat-835     [002] d..1.   718.675645: rpi_get_interrupt_info+0x10/0x58: [cat] 51: vc4 crtc, irq_handler: vc4_crtc_irq_handler+0x0/0x70 [vc4]
17900:             cat-835     [002] d..1.   718.675653: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17902: => rpi_get_interrupt_info+0x8/0x58
17915:             cat-835     [002] d..1.   718.675657: rpi_get_interrupt_info+0x10/0x58: [cat] 52: vc4 crtc, irq_handler: vc4_crtc_irq_handler+0x0/0x70 [vc4]
17916:             cat-835     [002] d..1.   718.675664: rpi_get_interrupt_info+0x4/0x58 <-show_interrupts+0x340/0x420
17918: => rpi_get_interrupt_info+0x8/0x58
17931:             cat-835     [002] d..1.   718.675668: rpi_get_interrupt_info+0x10/0x58: [cat] 53: vc4 crtc, irq_handler: vc4_crtc_irq_handler+0x0/0x70 [vc4]

"디버깅을 통해 배우는 리눅스 커널의 구조와 원리" 책의 "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

"디버깅을 통해 배우는 리눅스 커널의 구조와 원리" 책과 유튜브 [오제이 튜브] 님의 한국에서 제일 쉬운 리눅스 커널 강의"를 참고하였다.

책의 예제 소스

https://github.com/wikibook/linux-kernel

라즈베리파이 4에 "rpaspberry pi os lite (64-bit)"를 설치한다. (2025.4월)

su root 패스워드 설정

pi@raspberrypi:~ $ sudo passwd root
새 암호:
새 암호 재입력:
passwd: password updated successfully

root 로그인

pi@raspberrypi:~ $ su
암호:
root@raspberrypi:/home/pi # cd ~
root@raspberrypi:~ #

패키지 업데이트

root@raspberrypi:~ # apt-get update
root@raspberrypi:~ # apt-get upgrade

vim 설치와 root에 bash 환경 적용

root@raspberrypi:~ # apt-get install vim

root@raspberrypi:~ # cp /home/pi/.bashrc /root/
root@raspberrypi:~ # source .bashrc

Sop 정보를 확인한다.

root@raspberrypi:~ # lscpu
Architecture:                    aarch64
Byte Order:                      Little Endian
CPU(s):                          4
On-line CPU(s) list:             0-3
Thread(s) per core:              1
Core(s) per socket:              4
Socket(s):                       1
Vendor ID:                       ARM
Model:                           3
Model name:                      Cortex-A72
Stepping:                        r0p3
CPU max MHz:                     1800.0000
CPU min MHz:                     600.0000
BogoMIPS:                        108.00
L1d cache:                       128 KiB
L1i cache:                       192 KiB
L2 cache:                        1 MiB
Vulnerability Itlb multihit:     Not affected
Vulnerability L1tf:              Not affected
Vulnerability Mds:               Not affected
Vulnerability Meltdown:          Not affected
Vulnerability Mmio stale data:   Not affected
Vulnerability Retbleed:          Not affected
Vulnerability Spec store bypass: Vulnerable
Vulnerability Spectre v1:        Mitigation; __user pointer sanitization
Vulnerability Spectre v2:        Vulnerable
Vulnerability Srbds:             Not affected
Vulnerability Tsx async abort:   Not affected
Flags:                           fp asimd evtstrm crc32 cpuid

칩셋 정보를 확인한다.

root@raspberrypi:~ # lspci
00:00.0 PCI bridge: Broadcom Inc. and subsidiaries BCM2711 PCIe Bridge (rev 20)
01:00.0 USB controller: VIA Technologies, Inc. VL805 USB 3.0 Host Controller (rev 01)

커널 버전을 확인한다.

root@raspberrypi:~ # uname -a
Linux raspberrypi 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr  3 17:24:16 BST 2023 aarch64 GNU/Linux

패키지 설치

root@raspberrypi:~ # apt-get install git bc bison flex libssl-dev

작업 디렉터리 생성

root@raspberrypi:~ # mkdir -p /project/linuxSrc && cd $_

커널 소스 받기

root@raspberrypi:/project/linuxSrc # git clone --depth=1 https://github.com/raspberrypi/linux

안정된 버전을 받아도 된다.

"git clone -b stable --depth=1 https://github.com/raspberrypi/linux"

빌드 스크립트 생성

root@raspberrypi:/project/linuxSrc # vi build_rpi_kernel.sh

#!/bin/bash

echo "configure build output path"

KERNEL_TOP_PATH="$( cd "$(dirname "$0")" ; pwd -P)"
OUTPUT="$KERNEL_TOP_PATH/out"
echo "$OUTPUT"

KERNEL=kernel8
BUILD_LOG="$KERNEL_TOP_PATH/rpi_build_log.txt"

echo "move kernel source"
cd linux

echo "make defconfig"
make O=$OUTPUT bcm2711_defconfig

echo "kernel build"
make O=$OUTPUT Image modules dtbs -j4 2>&1 | tee $BUILD_LOG

빌드 스크립트에 실행권한 주고 실행하기

root@raspberrypi:/project/linuxSrc # chmod 755 build_rpi_kernel.sh
root@raspberrypi:/project/linuxSrc # ./build_rpi_kernel.sh

몇 시간 걸림 (few hours later....)

설치 스크립트 생성

root@raspberrypi:/project/linuxSrc # vi install_rpi_kernel.sh

#!/bin/bash

cd  /project/linuxSrc/out
make modules_install
make dtbs_install
cp arch/arm64/boot/Image /boot/firmware/kernel8.img
reboot

설치 스크립트에 실행권한 주고 실행하기

root@raspberrypi:/project/linuxSrc # chmod 755 install_rpi_kernel.sh

root@raspberrypi:/project/linuxSrc # ./install_rpi_kernel.sh

설치 후 버전 확인

root@raspberrypi:/project/linuxSrc # cat /proc/version
Linux version 6.6.78-v8+ (root@raspberrypi) (gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP PREEMPT Sat Mar 29 13:25:51 GMT 2025