ftrace는 리눅스 커널에 내장된 강력한 추적 도구로, 함수 호출, 스케줄 및 이벤트 추적을 가능하게 하는 강력한 디버깅 및 프로파일링 도구이다. 이 블로그 글에서는 ftrace를 사용하여 리눅스 커널 함수를 추적하는 방법에 대해 알아본다.
ftrace 란?
리눅스 커널 개발자들은 printk나 dump_stack 을 활용해 디버깅을 해 왔으나 여러가지 불편함들이 있었다. 특히 소스코드 수정 없이도 가능하며, 여러번 호출되더라도 성능에 부담을 주지 않는 도구들이 필요했고, 이러한 요구사항들이 반영된 커널 디버깅 기능이 ftrace이다. printk와 dump_stack에 대한 설명은 다음 글들을 확인한다.
ftrace 특징
- 인터럽트, 스케줄링, 커널 타이머 등의 커널 동작을 상세히 추적한다.
- 함수 필터를 적용하면 지정한 함수를 호출하는 함수와 콜 스택을 출력한다.
- 어떤 프로세스가 함수를 호출했고, 언제 실행되었는지 시각 정보도 알 수 있다.
frace를 활성화 해도 시스템에 부하가 거의 없다.
ftrace 핵심 구성 요소
- Function Tracer (function) : 함수 호출 및 반환 정보를 추적하는데 사용
- Tracepoints (tracepoint) : 커널 내부 이벤트를 추적하기 위한 추적 지점을 나타냄
- Event Tracer (event) : 이벤트를 추적하기 위한 인터페이스 제공
- Ring Buffer (trace_pipe) : 이벤트 및 추적 정보를 수집하고 저장함
ftrace 사용법
ftrace 활성화
우선 frace 를 사용하려면, ftrace가 추가된 커널 소스를 빌드해야 한다. 관련 kconfig는 다음과 같다.
CONFIG_FTRACE=y
CONFIG_DYNAMIC_FTRACE=y
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_GRAPH_TRACER=y
CONFIG_IRQSOFF_TRACE=y
CONFIG_SCHED_TRACER=y
CONFIG_FUNCTION_PROFILER=y
CONFIG_STACK_TRACER=y
CONFIG_TRACER_SNAPSHOT=ytrace를 하기 원하는 config를 활성화하여 커널을 빌드 해야 한다.
ftrace 설정 디렉토리
frace 기능이 추가된 커널에서, frace설정은 다음 위치에서 확인할 수 있다.
$ ls /sys/kernel/debug/tracing/
available_events options stack_trace
available_filter_functions osnoise stack_trace_filter
available_tracers per_cpu synthetic_events
buffer_percent printk_formats timestamp_mode
buffer_size_kb README trace
buffer_total_size_kb saved_cmdlines trace_clock
current_tracer saved_cmdlines_size trace_marker
dynamic_events saved_tgids trace_marker_raw
dyn_ftrace_total_info set_event trace_options
enabled_functions set_event_notrace_pid trace_pipe
error_log set_event_pid trace_stat
events set_ftrace_filter tracing_cpumask
free_buffer set_ftrace_notrace tracing_max_latency
function_profile_enabled set_ftrace_notrace_pid tracing_on
hwlat_detector set_ftrace_pid tracing_thresh
instances set_graph_function uprobe_events
kprobe_events set_graph_notrace uprobe_profile
kprobe_profile snapshot
max_graph_depth stack_max_size
만약 /sys/kernel/debug 디렉토리가 비어 있다면 debugfs가 마운트 되어 있지 않기 때문이다. 다음과 같이 debugfs를 마운트 한다.
$ mount -t debugfs none /sys/kernel/debugftrace 설정 방법
tracing_on: tracer 활성화/비활성화
ftrace를 활성화 하려면 tracing_on파일을 설정해줘야 한다. 부팅 후에는 기본적으로 0이 설정되어 있다. tracer를 활성화 하려면 tracing_on 파일에 1을, 비활성화 하려면 0을 입력한다.
$ echo 1 > /sys/kernel/debug/tracing/tracing_on
or
$ echo 0 > /sys/kernel/debug/tracing/tracing_ontracer 설정
ftrace는 nop, function, function_graph 와 같은 다양한 tracer들을 제공한다. 주요 tracer만 추리면 다음과 같다.
nop: 기본 tracer, ftrace 이벤트만 출력한다.function: 함수 tracer, set_ftrace_filter로 지정한 함수를 누가 호출하는지 출력한다.function_graph: 함수 실행 시간과 세부 호출 정보를 그래프 포맷으로 출력한다.
특정 tracer를 설정하려면 다음과 같이 current_tracer 파일에 tracer명을 추가한다.
$ echo function > /sys/kernel/debug/tracing/current_tracerftrace 이벤트 설정(events/enable)
커널에는 여러 서브시스템 및 이벤트 등 기능별 세부 동작들을 출력하는 기능을 지원한다. 따라서 이벤트 trace를 활성화/비활성화 를 하려면 다음과 같이 /sys/kernel/debug/tracing/events/enable 파일에 1/0 값을 입력하면 된다.
$ echo 1 > /sys/kernel/debug/tracing/events/enable
or
$ echo 0 > /sys/kernel/debug/tracing/events/enable만약 sched_wakeup, sched_switch 이벤트를 추적하려면 다음과 같이 해당 기능의 enable 파일에 1을 입력한다.
$ echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
$ echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable함수 필터 설정 (set_ftrace_filter)
추적하고자 하는 함수가 있으면 /sys/kernel/debug/tracing/set_ftrace_filter 파일에 추적하고자 하는 함수명을 입력한다. 물론 커널 내 모든 함수를 추적할 수 있는 것은 아니다. 추적 가능한 함수는 available_filter_functions 파일에서 확인할 수 있다.
$ cat available_filter_functions | grep schedule
...
io_schedule_timeout
schedule
io_schedule
schedule_idle
...만약 available_filter_functions 파일에 없는 함수를 set_ftrace_filter 파일에 지정하면 시스템이 락업되기 때문에 주의해야 한다.
다음은 schedule, schedule_idle 함수를 추적하도록 set_ftrace_filter 에 지정하는 예제이다.
$ echo schedule schedule_idle > /sys/kernel/debug/tracing/set_ftrace_filter
$ cat current_tracer
function
설정한 function 을 trace 하는 결과를 확인하려면 trace_pipe 파일로 확인한다.
$ cat trace_pipe
...
cat-2127 [002] ..... 4698.878715: schedule <-ring_buffer_wait
kworker/u8:1-2128 [003] ..... 4698.878830: schedule <-worker_thread
<idle>-0 [002] .N... 4698.878837: schedule_idle <-do_idle
cat-2127 [002] ..... 4698.878847: schedule <-ring_buffer_wait
<idle>-0 [000] .N... 4698.878856: schedule_idle <-do_idle
sudo-2125 [000] ..... 4698.878868: schedule <-schedule_hrtimeout_range_clock
<idle>-0 [003] .N... 4698.878888: schedule_idle <-do_idle
...만약 set_ftrace_filter 로 지정한 함수를 trace 하면서 콜 스택을 함께 보고 싶다면 options/func_stack_trace 에 1을 지정하여 활성화 시킨다.
$ echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
결과를 확인해 보면 다음과 같이 콜스택을 함께 보여주고 있는 것을 확인 할 수 있다.
$ cat trace_pipe
...
kworker/u8:3-2169 [003] ..... 5032.566384: schedule <-worker_thread
kworker/u8:3-2169 [003] ..... 5032.566384: <stack trace>
=> schedule
=> worker_thread
=> kthread
=> ret_from_fork
<idle>-0 [001] .N... 5032.566389: schedule_idle <-do_idle
<idle>-0 [001] .N... 5032.566390: <stack trace>
=> schedule_idle
=> do_idle
=> cpu_startup_entry
=> start_secondary
=> secondary_startup_64_no_verify
...추가 설정 파일
available_events: trace 가능한 event 리스트buffer_size_kb:ftrace로그 버퍼 크기trace_pipe: 로그 버퍼로 trace 결과를 확인할 수 있음
events 추적 방법
/sys/kernel/debug/tracing/events 는 커널이 정해 놓은 이벤트들을 추적하기 위한 인터페이스들이 모여있는 디렉토리 이다. 각 서브디렉토리들은 추적 가능한 이벤트 들이다.
$ ls /sys/kernel/debug/tracing/events
alarmtimer fib irq_vectors page_pool swiotlb
amd_cpu fib6 jbd2 percpu sync_trace
avc filelock kmem power syscalls
block filemap libata printk task
bpf_test_run fs_dax mce pwm tcp
bpf_trace ftrace mdio qdisc thermal
bridge gpio migrate ras thermal_power_allocator
btrfs header_event mmap raw_syscalls timer
cgroup header_page mmap_lock rcu tlb
clk huge_memory mmc regmap tls
compaction hwmon module regulator udp
cpuhp hyperv mptcp resctrl vmscan
cros_ec i2c msr rpm vsyscall
dev initcall napi rseq wbt
devfreq intel_iommu neigh rtc workqueue
devlink interconnect net sched writeback
dma_fence iocost netlink scsi x86_fpu
drm iomap nmi signal xdp
enable iommu oom skb xen
error_report io_uring osnoise smbus xhci-hcd
exceptions irq page_isolation sock
ext4 irq_matrix pagemap spi만약 workqueue 관련 이벤트들을 추적하고 싶다면, workqueue 디렉토리로 들어가서 확인 가능한 이벤트를 확인한다.
$ ls /sys/kernel/debug/tracing/events/workqueue/
enable workqueue_activate_work workqueue_execute_start
filter workqueue_execute_end workqueue_queue_work
enable 파일에 1을 입력하여 활성화 하면 workqueu 관련 모든 이벤트(workqueue_active_work, workqueue_execute_start, workqueue_execute_end, worqueue_queue_work)들의 추적이 활성화 된다.
특정 workqueue에 대해서만 추적하려면 filter 파일을 설정하면 된다.
workqueue 이벤트 추적 예제
workqueue이벤트에 대해 추적을 해보려고 하는데, 가장 먼저 할 일은 이벤트를 추적하도록 current_tracer 에 nop을 설정하는 일이다.
$ echo nop > /sys/kernel/debug/tracing/current_tracer그런다음 workqueue 이벤트 추적을 활성화 하고 로그 버퍼에서 결과를 확인한다.
$ echo 1 > /sys/kernel/debug/tracing/events/workqueue/enable
$ cat /sys/kernel/debug/tracing/trace_pipe
...
cat-2301 [000] d.... 6725.384571: workqueue_queue_work: work struct=000000009e5b5f72 function=flush_to_ldisc workqueue=events_unbound req_cpu=8192 cpu=4294967295
cat-2301 [000] d.... 6725.384602: workqueue_activate_work: work struct 000000009e5b5f72
kworker/u8:2-2302 [001] ..... 6725.384781: workqueue_execute_start: work struct 000000009e5b5f72: function flush_to_ldisc
kworker/u8:2-2302 [001] ..... 6725.384782: workqueue_execute_end: work struct 000000009e5b5f72: function flush_to_ldisc
cat-2301 [000] d.... 6725.384862: workqueue_queue_work: work struct=000000009e5b5f72 function=flush_to_ldisc workqueue=events_unbound req_cpu=8192 cpu=4294967295
cat-2301 [000] d.... 6725.384862: workqueue_activate_work: work struct 000000009e5b5f72
kworker/u8:2-2302 [001] ..... 6725.384934: workqueue_execute_start: work struct 000000009e5b5f72: function flush_to_ldisc
kworker/u8:2-2302 [001] ..... 6725.385373: workqueue_execute_end: work struct 000000009e5b5f72: function flush_to_ldisc
...