ftrace로 커널 읽기 - #1
Linux Internal
리눅스 커널의 동작 원리를 이해하고 파악하는데 가장 좋은 방법은 역시 소스 코드를 직접 보는 것입니다. 하지만 커널의 소스 코드는 너무나도 크고, 함수도 너무 많죠. 무엇보다 내가 궁금한 영역, 예를 들면 메모리 할당 이라던가 IO가 일어나는 과정에 대해 추적해보고 싶어도 어디서 어떻게 시작해야 할지를 찾기가 어렵습니다.
바로 이럴 때 ftrace를 활용할 수 있습니다. 그래서 이번 글을 시작으로 ftrace를 통한 커널 내부 구조 파악하는 과정을 시리즈로 다뤄 볼까 합니다.
그럼 시작합니다.
ftrace란?
ftrace는 커널 2.6.28 버전부터 포함된 기본 기능입니다. 커널이 호출하는 함수를 추적할 수 있는 기능인데요, 2.6.28 버전부터 가능하기 때문에 CentOS를 기준으로는 6.x 버전부터 가능합니다.
활성화시키는 방법은 아주 간단합니다. 아래 명령으로 debugfs를 마운트 시켜 주면 됩니다.
mount -t debugfs nodev /sys/kernel/debug
그러고 나서 /sys/kernel/debug로 이동하면 아래와 같이 디렉터리와 파일들이 생성되어 있습니다.
drwxr-xr-x 14 root root 0 2016-04-07 02:11.
drwxr-xr-x 5 root root 0 2016-04-07 02:11 ..
drwxr-xr-x 29 root root 0 2016-04-07 02:11 bdi
drwxr-xr-x 3 root root 0 2016-04-07 02:11 boot_params
drwxr-xr-x 2 root root 0 2016-04-07 02:11 dma_buf
drwxr-xr-x 2 root root 0 2016-04-07 02:11 dynamic_debug
drwxr-xr-x 2 root root 0 2016-04-07 02:11 extfrag
-r--r--r-- 1 root root 0 2016-04-07 02:11 gpio
drwxr-xr-x 2 root root 0 2016-04-07 02:11 hid
drwxr-xr-x 2 root root 0 2016-04-07 02:11 kprobes
drwxr-xr-x 2 root root 0 2016-04-07 02:11 mce
-rw-r--r-- 1 root root 0 2016-04-07 02:11 sched_features
drwxr-xr-x 6 root root 0 2016-04-07 02:11 tracing
drwxr-xr-x 3 root root 0 2016-04-07 02:11 usb
-r--r--r-- 1 root root 0 2016-04-06 17:11 vmmemctl
drwxr-xr-x 2 root root 0 2016-04-07 02:11 x86
drwxr-xr-x 4 root root 0 2016-04-07 02:11 xen
여기까지 잘 보인다면 ftrace를 사용할 준비가 완료된 것입니다.
커널 함수 추적하기
이제 본격적으로 커널 함수들이 호출되는 과정을 살펴보겠습니다. 우선 tracing 디렉터리로 이동해서 추적할 수 있는 항목들을 살펴보겠습니다.
[root@server tracing]# cat available_tracers
blk kmemtrace function_graph wakeup_rt wakeup function sysprof sched_switch initcall nop
여러 옵션들이 있습니다만, 이번 글에서는 function과 function_graph를 다뤄 보겠습니다.
[root@server tracing]# echo function > ./current_tracer
그리고 vi로 trace 파일을 열어 보면 아래와 같은 내용을 볼 수 있습니다.
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
sshd-15219 [000] 159421.106063: __math_state_restore <-__switch_to
sshd-15219 [000] 159421.106064: finish_task_switch <-thread_return
sshd-15219 [000] 159421.106065: fget_light <-do_select
sshd-15219 [000] 159421.106065: sock_poll <-do_select
sshd-15219 [000] 159421.106066: tcp_poll <-sock_poll
sshd-15219 [000] 159421.106066: fget_light <-do_select
sshd-15219 [000] 159421.106066: pipe_poll <-do_select
프로세스 별로 호출하고 있는 커널 함수를 직접 살펴볼 수 있습니다.
이번엔 function_graph로 tracer를 바꿔 보겠습니다.
[root@server tracing]# echo function_graph > ./current_tracer
그리고 trace 파일의 내용을 살펴보겠습니다.
0) | do_vfs_ioctl() {
0) | vfs_ioctl() {
0) | tty_ioctl() {
0) 0.349 us | tty_paranoia_check();
0) 0.301 us | pty_unix98_ioctl();
0) | tty_ldisc_ref_wait() {
0) | tty_ldisc_try() {
0) 0.301 us | _spin_lock_irqsave();
함수의 호출 관계를 포함해서 들여쓰기가 되어 있습니다. 이를 통해 어떤 함수가 언제 어떻게 호출되는지를 한 눈에 살펴볼 수 있습니다.
스케쥴링 과정 살펴보기
이번 글에서는 맛보기로 스케쥴링 과정을 살펴보겠습니다.
function_graph로 tracing 한 후 trace 파일을 살펴보면 아래와 같은 내용을 찾을 수 있습니다.
0) | schedule() {
0) 0.301 us | rcu_sched_qs();
0) 0.301 us | _spin_lock_irq();
0) 0.298 us | put_prev_task_idle();
0) | pick_next_task_fair() {
0) 0.299 us | clear_buddies();
0) | set_next_entity() {
0) | update_stats_wait_end() {
0) | /* sched_stat_wait: comm=sshd pid=15219 delay=0 [ns] */
0) 0.587 us | }
0) 0.393 us | __dequeue_entity();
0) 1.932 us | }
0) 0.331 us | hrtick_start_fair();
0) 4.154 us | }
0) 0.434 us | perf_event_task_sched_out();
0) | /* sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=15219 next_prio=120 */
0) 0.404 us | native_load_sp0();
0) 0.304 us | native_load_tls();
------------------------------------------
0) <idle>-0 => sshd-15210
-------------------------------------------
0) 0.483 us | __math_state_restore();
0) 0.399 us | finish_task_switch();
0) ! 160572.7 us | }
0) ! 160573.6 us | }
0) ! 160574.3 us | }
이 과정은 idle 프로세스에서 sshd 프로세스로 context switch 되는 과정을 담고 있습니다.
idle 프로세스는 맨 처음 schedule() 함수를 호출합니다. 해당 함수의 소스 코드를 쭉 보면 ftrace에 잡혀 있는 함수들을 호출하는 걸 코드로도 살펴볼 수 있습니다.
schedule() 함수의 일부5423번 줄에 있는 rcu_sched_qs() 함수가 호출되는 것도 볼 수 있으며, 5452번 줄에 있는 put_prev_task() 함수가 호출되어 실제로는 put_prev_task_idle() 함수가 호출되는 것을 볼 수 있습니다.
kernel/sched_idletask.cput_prev_task는 sched_class 마다 다른 함수를 사용하며 idle_sched_class는 put_prev_task_idle 함수가 포인터로 연결되어 있는 것을 볼 수 있습니다.
그리고 set_next_entity() 함수를 호출해서 다음번에 실행시킬 프로세스를 찾고, 해당 프로세스를 대기 큐에서 빼내는 과정을 볼 수 있습니다. (__dequeue_entity 함수)
그리고 sshd로 context switch를 하고 finish_task_switch() 함수를 호출하는 것까지 볼 수 있습니다.
이렇게 ftrace를 통하면 시스템 운영 중에 호출되는 커널 함수들을 직접 볼 수 있으며 이를 통해 어떻게 동작하는지를 파악할 수 있습니다.
이번 글에서는 ftrace를 설정하는 방법과 간단하게 그 내용을 바탕으로 커널의 동작 과정을 확인해 보는 시간을 가졌습니다. 다음 글에서 부터는 본격적으로 ftrace를 바탕으로 커널의 동작을 이해하고 따라가는 방법에 대해 다뤄보겠습니다.
읽어 주셔서 감사합니다.
