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

프로세스 강제 종료

 

ftrace_log.c
2.55MB

 

프로그램 수정 후 빌드

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 호출 확인

 

ftrace_log.c
0.59MB

+ Recent posts