[리눅스커널][디버깅] ftrace 설정과 로그 분석하기

ftrace 란

ftrace 리눅스 커널에서 제공하는 가장 강력한 트레이서입니다. ftrace는 커널 개발자에게 축복입니다. ftrace는 커널 세부 동작을 알기 쉽게 출력하기 때문입니다.

ftrace의 특징은 다음과 같습니다.
1. 인터럽트, 스케줄링, 커널 타이머 커널 동작을 상세히 추적해줍니다.
2. 함수 필터를 지정하면 자신을 호출한 함수와 전체 콜스택까지 출력합니다. 물론 코드를 수정할 필요가 없습니다.
3. 함수를 어느 프로세스가 실행하는지 알 수 있습니다.
4. 함수 실행 시각을 알 수 있습니다.
5. ftrace 로그를 키면 시스템 동작에 부하를 주지 않습니다.

다음에 이어 ftrace를 설정하는 방법을 알아보겠습니다.

ftrace는 어떻게 설정할까?

ftrace에서 제공하는 nop, function 그리고 graph_function 트레이서를 쓰려면 ftrace 관련 코드가 커널 이미지에 포함돼야 합니다. 즉, ftrace 코드 빌드를 해야 합니다.

이를 위해 다음 컨피그를 켜야 합니다.

 
CONFIG_FTRACE=y
CONFIG_DYNAMIC_FTRACE=y 
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_GRAPH_TRACER=y
CONFIG_IRQSOFF_TRACER=y
CONFIG_SCHED_TRACER=y
CONFIG_FUNCTION_PROFILER=y
CONFIG_STACK_TRACER=y
CONFIG_TRACER_SNAPSHOT=y

라즈비안에서는 기본으로 ftrace 에 필요한 세부 컨피그가 모두 켜져 있습니다. 따라서 라즈비안을 라즈베리파이에 설치만 하면 ftrace 메시지를 볼 수 있습니다.

ftrace는 리눅스 커널 공통 기능입니다. 라즈비안 다른 리눅스 시스템에서도 ftrace를 지원합니다.

다음과 같은 패치 코드를 입력하면 라즈베리파이 이외 다른 리눅스 시스템에서도 ftrace 메시지를 볼 수 있습니다.

 
--- a/arch/arm/configs/your_device_defconfig
+++ b/arch/arm/configs/your_device_defconfig
@@ -778,6 +777,14 @@ CONFIG_DEBUG_SET_MODULE_RONX=y
01  CONFIG_SECURITY_PERF_EVENTS_RESTRICT=y
02  CONFIG_SECURITY=y
03  CONFIG_SECURITY_NETWORK=y
04 +CONFIG_FTRACE=y
05 +CONFIG_DYNAMIC_FTRACE=y 
06 +CONFIG_FUNCTION_TRACER=y
07 +CONFIG_FUNCTION_GRAPH_TRACER=y
08 +CONFIG_IRQSOFF_TRACER=y
09 +CONFIG_SCHED_TRACER=y
10 +CONFIG_FUNCTION_PROFILER=y
11 +CONFIG_STACK_TRACER=y
12 +CONFIG_TRACER_SNAPSHOT=y
13 CONFIG_LSM_MMAP_MIN_ADDR=4096
14 CONFIG_HARDENED_USERCOPY=y
15 CONFIG_SECURITY_SELINUX=y

“arch/arm/configs/your_device_defconfig” 은 예시 파일입니다. 현재 리눅스 시스템을 빌드할 때 적용하는 컨피그 파일에 04~12 번째 줄 코드를 입력하면 됩니다. 물론 커널을 빌드해야 합니다.

이번 소절에 소개한 ftrace 컨피그를 킨 후 커널 빌드를 하면 ftrace 관련 코드가 커널 이미지에 포함됩니다. 이 방식으로 커널 이미지를 시스템에 설치하고 난 후 재부팅합시다.

다시 반복하지만 라즈비안은 ftrace 기본 기능이 다 켜져 있습니다. 따라서 ftrace 컨피그를 새롭게 설정해 커널 빌드를 할 필요가 없습니다.

그러면 ftrace 설정 파일을 어디서 확인할 수 있을까요?
다음 경로에 ftrace 드라이버 설정 폴더와 파일을 볼 수 있습니다.

 
$ ls /sys/kernel/debug/tracing
README                     options             snapshot
available_events           per_cpu             trace
available_filter_functions printk_formats      trace_clock
available_tracers          saved_cmdlines      trace_marker
buffer_size_kb             saved_cmdlines_size trace_marker_raw
buffer_total_size_kb       saved_tgids         trace_options
current_tracer             set_event           trace_pipe
dyn_ftrace_total_info      set_event_pid       tracing_cpumask
enabled_functions          set_ftrace_filter   tracing_max_latency
events                     set_ftrace_notrace  tracing_on
free_buffer                set_ftrace_pid      tracing_thresh
instances                  set_graph_function  uprobe_events
max_graph_depth            set_graph_notrace   uprobe_profile

ftrace 설정 방법
이어서 ftrace를 설정하는 방법을 설명합니다. 필자는 다음과 같은 셸 스크립트를 실행해 ftrace를 빨리 설정합니다. 셸 스크립트 코드를 보면서 ftrace 세부 설정 방법을 소개합니다.

 
1 #!/bin/sh
2 
3 echo 0 > /sys/kernel/debug/tracing/tracing_on
4 sleep 1
5 echo "tracing_off"
6
7 echo 0 > /sys/kernel/debug/tracing/events/enable
8 sleep 1
9 echo "events disabled"
10
11 echo  secondary_start_kernel  > /sys/kernel/debug/tracing/set_ftrace_filter	
12 sleep 1
13 echo "set_ftrace_filter init"
14
15 echo function > /sys/kernel/debug/tracing/current_tracer
16 sleep 1
17 echo "function tracer enabled"
18
19 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
20 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
21
22 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
23 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
24
25 echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
26 sleep 1
27 echo "event enabled"
28
29 echo  schedule ttwu_do_wakeup > /sys/kernel/debug/tracing/set_ftrace_filter
30
31 sleep 1
32 echo "set_ftrace_filter enabled"
33
34 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
35 echo 1 > /sys/kernel/debug/tracing/options/sym-offset
36 echo "function stack trace enabled"
37
38 echo 1 > /sys/kernel/debug/tracing/tracing_on
39 echo "tracing_on"

각 명령어 다음에 보이는 “sleep 1” 코드는 무엇일까요?
1초 동안 딜레이를 주는 동작입니다. ftrace 설정 명령어를 입력하면 커널 내부에서 ftrace를 설정하는 함수가 실행합니다. 커널 내부에서 한 가지 설정을 완료한 다음 ftrace 설정 명령어를 수행하도록 딜레이를 주는 것입니다.

위 ftrace 설정 스크립트는 필자가 라즈베리파이에서 실행해 정상 동작을 확인한 것입니다. 만약 코드 순서가 바뀌면 시스템이 락업될 수 있으니 주의합시다.

tracing_on: 트레이서 on/off 시키기

ftrace를 끄거나 키려면 tracing_on 파일을 설정해야 합니다. tracing_on은 부팅 후 기본으로 0으로 설정돼 있습니다.

3~38 번째 줄 코드를 보겠습니다.
3 echo 0 > /sys/kernel/debug/tracing/tracing_on
...
38 echo 1 > /sys/kernel/debug/tracing/tracing_on

먼저 3 번째 줄 코드를 분석하겠습니다. "/sys/kernel/debug/tracing/tracing_on" 파일에 0을 저장합니다. ftrace를 끄는 동작입니다.

반대로 38 번째 줄 코드와 같이 "/sys/kernel/debug/tracing/tracing_on" 파일에 1을 저장하면 ftrace를 킬 수 있습니다.

tracing_on은 ftrace를 끄거나 키려면 설정해야 하는 파일입니다.

tracer 설정하기
리눅스 커널에선 nop, function, graph_function 트레이서를 제공합니다.
ftrace에서 다양한 tracer를 제공하는데 중요한 부분만 추려 소개하면 다음과 같습니다.
- nop: 기본 트레이서입니다. ftrace 이벤트만 출력합니다.
- function: 함수 트레이서입니다. set_ftrace_filter로 지정한 함수를 누가 호출하는지 출력합니다.
- graph_function: 함수 실행 시간과 세부 호출 정보를 그래픽 정보를 추가해 출력합니다.

트레이서를 설정하기 위해서는 다음과 같이 current_tracer 파일에 트레이서 이름을 저장해야 합니다.
15 echo function > /sys/kernel/debug/tracing/current_tracer

부팅하면 current_tracer 파일은 기본으로 nop 트레이서로 설정돼 있습니다.

ftrace event 설정하기
ftrace에선 커널 서브 시스템과 기능별로 세부 동작을 출력하는 기능을 지원합니다. 이것을 이벤트라고 부릅니다.

셸 스크립트 코드를 보면서 이벤트 설정 방법을 배워봅시다.

다음은 ftrace 이벤트를 모두 끄는 코드입니다.
7 echo 0 > /sys/kernel/debug/tracing/events/enable

다음 코드를 보겠습니다.
19 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
20 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
...
22 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
23 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable

19~20 번째 줄 코드를 실행하면 스케줄링 동작을 기록하는 sched_wakeup, sched_switch 이벤트를 킵니다. 이어서 22~23 번재 줄은 인터럽트 핸들링 시작과 종료 시점을 기록하는 irq_handler_entry, irq_handler_exit 이벤트를 키는 설정입니다.

ftrace event 종류에 대해서는 다음 소절에서 살펴볼 예정입니다.

필터 설정: set_ftrace_filter
set_ftrace_filter 파일에 트레이싱하고 싶은 함수를 지정합니다.

현재 트레이서를 function_graph과 function로 설정할 경우 동작하는 파일입니다. 이 set_ftrace_filter 파일에 디버깅하고 싶은 함수 이름을 지정하면 됩니다. 이를 함수 필터를 지정한다고 말합니다. 리눅스 커널에 존재하는 모든 함수를 필터로 지정할 수는 없고 available_filter_functions 파일에 포함된 함수만 지정할 수 있습니다.

ftrace에서 함수 필터 설정 방법은 다음 코드로 알아 보겠습니다.
11 echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter
...
29 echo schedule ttwu_do_wakeup > /sys/kernel/debug/tracing/set_ftrace_filter

11 번째 줄에서는 secondary_start_kernel() 함수를 필터로 설정합니다. 사실 secondary_start_kernel() 함수는 부팅 도중 한 번 호출됩니다. 더미로 secondary_start_kernel() 함수를 필터로 설정하는 것입니다.

반복하지만 현재 트레이서를 function_graph과 function로 설정할 경우 set_ftrace_filter 지정한 함수를 트레이싱합니다. 그런데 11번 째 줄 코드를 실행하지 않고 set_ftrace_filter 필터를 설정 안 하면 어떻게 동작할까요? set_ftrace_filter 파일에 필터로 함수를 지정하지 않으면 모든 커널 함수를 트레이싱합니다. 시스템이 수 많은 커널 함수를 트레이싱하다가 결국 락업 상태에 빠지게 됩니다. 이런 상황을 방지하려는 코드입니다.

라즈베리파이에서 set_ftrace_filter 파일에 필터로 함수 지정을 안 하면 시스템은 100% 락업됩니다. 이 점 주의합시다.

실제 함수 필터를 거는 부분은 29 번째 줄 코드입니다.
29 번째 줄에서 schedule() 함수와 ttwu_do_wakeup() 함수를 필터로 지정합니다.
29 echo schedule ttwu_do_wakeup > /sys/kernel/debug/tracing/set_ftrace_filter

이 책에서는 set_ftrace_filter 기능을 활용해 커널 함수 콜스택을 분석합니다. 잘 알아둡시다.

ftrace: func_stack_trace/sym-offset
options 하위 폴더에 세부 추가로 ftrace를 설정하는 파일이 있습니다.

34 번째 줄 코드를 봅시다.
34 echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace

"options/func_stack_trace" 파일을 1로 설정하면 ftrace를 콜스택을 출력합니다.
set_ftrace_filter 파일에 필터로 지정된 함수 콜스택을 기록합니다.

"options/func_stack_trace" 설정 이 전에 current_tracer는 function으로 지정돼 있어야 합니다.

34 번째 줄 코드입니다.
35 echo 1 > /sys/kernel/debug/tracing/options/sym-offset

ftrace에서 콜스택을 출력할 때 포멧을 지정합니다. 함수를 호출할 때 주소 오프셋을 출력합니다.

다음은 "options/sym-offset" 옵션을 켰을 때 함수 정보입니다.
1 lxterminal-840 [001] .... 8632.128798: schedule+0x10/0xa8 <-schedule_hrtimeout_range_clock+0xd8/0x14c
2 lxterminal-840 [001] .... 8632.128816:
3 => poll_schedule_timeout+0x54/0x84
4 => do_sys_poll+0x3d8/0x500
5 => SyS_poll+0x74/0x114
6 => __sys_trace_return+0x0/0x10

위 로그에서 함수 호출 방향은 6 번째 줄에서 3 번째 줄 방향입니다.

3~6 번째 줄 로그와 같이 함수 이름 오른쪽에 16진수 포멧 숫자가 보입니다.
함수를 호출한 주소를 함수 시작 주소 기준으로 출력합니다.
3 => poll_schedule_timeout+0x54/0x84
4 => do_sys_poll+0x3d8/0x500

4 번째 줄 do_sys_poll() 함수 시작 주소에서 0x3d8 오프셋만큼 떨어진 주소에서 poll_schedule_timeout() 함수를 호출한다는 의미입니다.

나머지 함수도 같은 의미로 해석하면 됩니다.

추가 설정 파일 설명
buffer_size_kb:

ftrace 로그 버퍼 사이즈이며 킬로 바이트 단위입니다. ftrace 로그를 더 많이 저장하고 싶을 때 설정합니다.

available_filter_functions:

트레이싱 할 수 있는 함수 목록을 저장한 파일입니다. 만약 여러분이 리눅스 드라이버나 커널에 새로운 함수를 새로 구현했으면 이 파일에 함수 이름을 볼 수 있습니다.

events:

ftrace에서 제공하는 이벤트 종류를 알 수 있는 폴더 타입 파일입니다. 수 많은 이벤트 중 가장 대표적인 부부만 추려 소개하겠습니다.

sched:

프로세스 스케줄링 동작과 스케줄링 프로파일링을 트레이싱하는 이벤트를 볼 수 있습니다.
 sched_switch: 컨택스트 스위칭 동작
 sched_wakeup: 프로세스를 깨우는 동작

irq:

인터럽트와 소프트웨어 인터럽트를 트레이싱하는 이벤트들이 있습니다.
 irq_handler_entry: 인터럽트 발생한 시각과 인터럽트 번호 및 이름을 출력
 irq_handler_exit: 인터럽트 핸들링이 완료
 softirq_raise: Soft IRQ 서비스 실행 요청
 softirq_entry: Soft IRQ 서비스 실행 시작
 softirq_exit: Soft IRQ 서비스 실행 완료

다음 소절에 이어서 ftrace 메시지를 분석하는 방법을 소개합니다.
 
ftrace 메시지는 어떻게 분석할까?

이번 소절에서는 ftrace 메시지를 읽고 해석하는 방법을 소개합니다.

다시 말하지만 ftrace는 임베디드 리눅스 개발자에게 축복입니다. ftrace는 커널 동작을 세부 로그로 출력하기 때문입니다. 이 강력한 ftrace 를 잘 활용하려면 무엇보다 ftrace 메시지를 해석하는 방법을 알아야 합니다.

여러 ftrace 이벤트 중 공통으로 가장 많이 보는 sched_switch, sched_wakeup, irq_handler_entry, irq_handler_exit 이벤트 중심으로 살펴보겠습니다.

먼저 ftrace 로그를 하나 소개합니다.
chromium-browse-1436 [002] d... 9445.131875: sched_switch: prev_comm=chromium-browse prev_pid=1436 prev_prio=120 prev_state=S ==> next_comm=kworker/2:3 next_pid=1454 next_prio=120

위 ftrace는 sched_switch 이벤트 포멧 로그입니다. sched_switch 이벤트 메시지 분석하기 앞서 ftrace 공통 포멧을 살펴보겠습니다.

ftrace 메세지에서 가장 왼쪽 부분에 ftrace를 출력하는 프로세스 정보를 볼 수 있습니다. 포멧은 “프로세스이름-[pid]” 형식입니다. pid가 1436인 chromium-browse 프로세스가 실행 중입니다.

다음 “[002]”는 CPU 번호입니다. 현재 몇 번째 CPU에서 실행 중인지 출력합니다. 위 ftrace 메시지에서 2번 CPU에서 실행 중입니다.

다음 위 그림에서 “컨택스트 정보”라고 표기된 부분 박스는 “d...” 으로 알파벳입니다.
별 거 아닌 것으로 보이지만 ftrace에서 눈여겨봐야 할 중요 정보이며 다음 내용을 출력합니다.
 인터럽트 비활성화
 선점 스케줄링 설정 여부
 인터럽트 컨택스트나 Soft IRQ 컨택스트 여부
 프로세스 struct thread_info 구조체 preempt_count 값

세부 컨택스트 정보는 ftrace 메시지에서 항상 출력하며 4개 알파벳으로 세부 컨택스트 정보를 출력합니다.

프로세스 컨택스트 세부 정보를 표현하는 알파벳의 의미는 다음과 같습니다.
d: 인터럽트를 비활성화한 상태입니다.
n: 현재 프로세스가 선점 스케줄링이 요청된 대상입니다.
h/s: h 이면 인터럽트 컨택스트, s이면 Soft IRQ 컨택스트입니다.
0~5: 프로세스 struct thread_info 구조체 preempt_count 필드 정수값입니다.

세부 항목이 활성화돼 있지 않으면 “.”를 출력합니다.

다른 ftrace 메시지를 보면서 세부 컨택스트 정보를 확인합시다.

1~2 번째 ftrace 메시지에서 세부 컨택스트는 “dnh.”입니다.
1 -0 [002] dnh. 9444.893973: sched_wakeup: comm=chromium-browse pid=1170 prio=120 target_cpu=002
2 -0 [002] dnh. 9444.893975: irq_handler_exit: irq=17 ret=handled

“dnh.”을 해석하면 인터럽트 비활성화, 선점 스케줄링 대상, 인터럽트 컨택스트인 상태입니다.

다음 3 번째 줄 메시지를 보겠습니다.
3 -0 [002] d... 9444.893983: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=S

“d...” 이니 인터럽트만 비활성화한 상태입니다.

다음에 소개할 ftrace 공통 포멧은 타임 스탬프입니다.

위 ftrace 메시지에서 타임 스탬프는 9445.131875입니다. 커널 로그에서 출력하는 타임스탬프와 같은 시간 정보입니다.

마지막으로 sched_switch는 이벤트 이름입니다. sched_switch 이벤트입니다.

ftrace 이벤트 분석하기
이어서 ftrace 이벤트를 분석하는 방법을 배워보겠습니다. ftrace 중 가장 많이 쓰는 2가지 이벤트 분석 방법을 소개합니다.
 sched_switch
 irq_handler_entry/irq_handler_exit

먼저 sched_switch 이벤트 분석 방법을 소개합니다. sched_switch 메시지 세부 내용은 다음과 같습니다.

다음 메시지는 스케줄링될 프로세스 정보입니다.
prev_comm=kworker/2:1 prev_pid=1106 prev_prio=120 prev_state=T

prev 프로세스의 PID는 1106이고 이름은 "kworker/2:1" 입니다. 프로세스 우선순위는 120이고 프로세스 상태는 T입니다.

다음 메시지는 스케줄링 동작으로 다음에 실행될 프로세스입니다.
next_comm=ksoftirqd/2 next_pid=19 next_prio=120

프로세스 이름은 "ksoftirqd/2" 이고 PID는 19입니다. 또한 프로세스 우선순위가 120입니다.

정리하면 "kworker/2:1" 프로세스에서 "ksoftirqd/2" 프로세스로 스케줄링하는 동작을 출력합니다.

이어서 irq_handler_entry와 irq_handler_exit 이벤트 메시지를 해석하는 방법을 배워봅시다.
1 kworker/0:1-31 [000] d.h. 592.790968: : irq=23 name=3f00b880.mailbox
2 kworker/0:1-31 [000] d.h. 592.791016: irq_handler_exit: irq=23 ret=handled

먼저 ftrace 공통 실행 정보를 확인합시다.

ftrace 메시지를 볼 때 가장 왼쪽에 보이는 메시지를 실행하는 프로세스를 확인해야 합니다.
pid가 31인 kworker/0:1 프로세스가 실행 중 인터럽트가 발생했습니다.

CPU 번호는 [000]이니 CPU0에서 실행 중이었습니다. 컨택스트 정보인 “d.h.” 알파벳을 보면 d 알파벳이 있으니 CPU0번 인터럽트 라인을 비활성화했으며, h가 보이니 현재 인터럽트 컨택스트입니다.

592.790968 초에 irq_handler_entry 메시지, 592.791016 초에 irq_handler_exit 이벤트 메시지를 각각 출력합니다.

정리하면 23번 "3f00b880.mailbox" 인터럽트 핸들러를 592.790968 초에 실행하고 592.791016 초에 마무리한다는 정보입니다.

irq_handler_entry 이벤트 출력 시점은 다음과 같습니다.
 irq_handler_entry: 인터럽트 핸들러를 실행하기 직전에 출력
 irq_handler_exit: 인터럽트 핸들러 실행을 마무리한 직후 출력

ftrace 는 커널 코드 분석의 안내자

ftrace 메시지는 텍스트 포멧입니다. 그래서 많은 분들이 해석하기 어렵다고 불평합니다.
하지만 ftrace 메시지는 바로 커널 코드 분석의 안내자일 수 있습니다. ftrace 이벤트 이름으로 어느 커널 소스 코드에서 이벤트를 출력하는지 알 수 있기 때문입니다.

실제 각 이벤트 별 ftrace를 출력하는 함수 이름은 다음 기준과 같습니다.
trace_ftrace_event_name

각 이벤트 별 출력함수는 다음 테이블에서 볼 수 있습니다.
ftrace 이벤트 출력함수
sched_switch trace_sched_switch
irq_handler_enter trace_irq_handler_enter
irq_handler_exit trace_irq_handler_exit

sched_switch 이벤트는 trace_sched_switch() 함수가 실행할 때 출력하고, irq_handler_enter와 irq_handler_exit이벤트는 각각 trace_irq_handler_enter()와 trace_irq_handler_exit() 함수가 실행할 때 출력합니다.

먼저 sched_switch ftrace 이벤트를 출력하는 코드를 검색하는 방법을 소개합니다.
리눅스 커널 코드에서 다음과 같이 trace_sched_switch 키워드로 검색해봅시다.
root@raspberrypi:/home/pi/src/RPi_kernel/linux# egrep -nr trace_sched_switch *
kernel/sched/core.c:3380: trace_sched_switch(preempt, prev, next);

검색 결과 위와 같이 kernel/sched/core.c 함수 3380 번째 줄이 보입니다.

해당 코드를 열어 보겠습니다.

 
[kernel/sched/core.c]
3295 static void __sched notrace __schedule(bool preempt)
3296 {
3297     struct task_struct *prev, *next;
3298     unsigned long *switch_count;
...
3360     if (likely(prev != next)) {
3361         rq->nr_switches++;
3362         rq->curr = next;
...
3378         ++*switch_count;
3379
3380         trace_sched_switch(preempt, prev, next);
3381
3382         /* Also unlocks the rq: */
3383         rq = context_switch(rq, prev, next, &rf);
3384     } else {
3385         rq->clock_update_flags &= ~(RQCF_ACT_SKIP|RQCF_REQ_SKIP);
3386         rq_unlock_irq(rq, &rf);
3387     }

sched_switch는 __schedule() 함수 3380 번째 줄에서 출력한다는 사실을 알 수 있습니다.

이로 컨택스트 스위칭은 __schedule() 함수에서 context_switch() 코드를 실행할 때 수행된다는 사실을 알 수 있습니다.

이번에는 irq_handler_entry와 irq_handler_exit 이벤트 메시지를 어떤 커널 코드에서 출력하는지 살펴봅시다.

ftrace 이벤트를 출력하는 함수 이름 규칙에 따라 irq_handler_entry 이벤트 이름 앞에 trace_를 붙혀 소스 코드를 검색합시다.

검색 결과 __handle_irq_event_percpu() 함수에서 trace_irq_handler_entry() 함수 와 trace_irq_handler_exit() 함수를 호출합니다.

관련 코드는 다음과 같습니다.

 
[<a href="https://elixir.bootlin.com/linux/v4.14.70/source/kernel/irq/handle.c" rel="nofollow">https://elixir.bootlin.com/linux/v4.14.70/source/kernel/irq/handle.c</a>]
1 irqreturn_t __handle_irq_event_percpu(struct irq_desc *desc, unsigned int *flags)
2 {
...
3	for_each_action_of_desc(desc, action) {
4		irqreturn_t res;
5
6		trace_irq_handler_entry(irq, action);
7		res = action->handler(irq, action->dev_id);
8		trace_irq_handler_exit(irq, action, res);

7 번째 줄 코드는 인터럽트 핸들러를 호출한다는 점을 기억합시다.

6 번째 줄에선 인터럽트 핸들러 호출 직전 trace_irq_handler_entry() 함수를 호출해 irq_handler_entry 이벤트를 출력합니다.

8 번째 줄에서는 인터럽트 핸들러 실행을 종료한 후 바로 trace_irq_handler_exit() 함수를 호출해 irq_handler_exit 이벤트를 출력합니다.

임베디드 리눅스 입문자들이 가장 많이 하는 고민은 ‘리눅스 커널 어느 코드를 봐야 할 지 모르겠다.’입니다. ftrace 이벤트를 출력하는 함수 코드를 코드 분석의 출발점으로 삼으면 좋습니다.

부팅 과정에서 ftrace 로그를 보고 싶을 때
ftrace는 기본으로 부팅 후 ftrace 로그를 저장하지 않습니다. 부팅 후 ftrace는 비활성화되는 것입니다. 따라서 부팅이 끝난 후 다음 같은 echo 명령어로 설정해야 ftrace 로그를 킬 수 있습니다.
echo 1 > /sys/kernel/debug/tracing/tracing_on

그런데 가끔 부팅 도중 ftrace 로그를 보고 싶을 때가 있습니다.
 부팅 과정에서 어떤 프로세스가 실행됐는지 알고 싶을 때
 프로세스 실행과 종료 과정을 보고 싶을 때

다음에 소개하는 패치 코드를 라즈베리파이에 적용하면 라즈비안이 부팅할 때 ftrace 로그를 활성화하면서 ftrace 로그를 저장합니다.

먼저 전체 소스 코드를 소개합니다.

 
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 4ad6f6c..2789562 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -702,6 +702,12 @@ config TRACING_EVENTS_GPIO
        help
          Enable tracing events for gpio subsystem
 
+config ENABLE_FTRACE_BOOT
+     bool "Enable ftrace at boot"
+        depends on TRACING
+        help
+          Enable ftrace at boot
+
 endif # FTRACE
 
 endif # TRACING_SUPPORT
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index d53268a..db17a5a 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -3110,6 +3110,47 @@ static __init int event_trace_enable(void)
        return 0;
 }
 
+#ifdef CONFIG_ENABLE_FTRACE_BOOT
+static void ftrace_events_enable(int enable)
+{
+       if (enable) {
+               trace_set_clr_event(NULL, "printk", 1);
+               trace_set_clr_event(NULL, "console", 1);
+               trace_set_clr_event(NULL, "signal_generate", 1);
+               trace_set_clr_event(NULL, "signal_deliver", 1);
+               trace_set_clr_event(NULL, "sched_switch", 1);
+       } else {
+               tracing_off();
+               trace_set_clr_event(NULL, NULL, 0);
+       }
+}
+
+static __init int rpi_enable_ftrace_boot(void)
+{
+       struct trace_array *tr;
+       int ret = 0;
+
+       tr = top_trace_array();
+       if (!tr) {
+               pr_err("%s: Invalid tr from top_trace_array \n", __func__);
+               return -ENODEV;
+       }
+
+       ret = tracing_update_buffers();
+       if (ret != 0) {
+               pr_err("%s: invalid buffer ret=%d\n", __func__, ret);
+               return -ENODEV;
+       }
+
+       ftrace_events_enable(1);
+       set_tracer_flag(tr, TRACE_ITER_OVERWRITE, 0);
+
+       tracing_on();
+
+       return 0;
+}
+
+late_initcall(rpi_enable_ftrace_boot);
+#endif

위 패치 코드의 핵심은 다음 코드 조각입니다.

 
+static void ftrace_events_enable(int enable)
+{
+       if (enable) {
+               trace_set_clr_event(NULL, "signal_generate", 1);
+               trace_set_clr_event(NULL, "signal_deliver", 1);
+               trace_set_clr_event(NULL, "sched_switch", 1);
+       } else {
+               tracing_off();
+               trace_set_clr_event(NULL, NULL, 0);
+       }
+}

trace_set_clr_event() 함수 2 번째 인자로 ftrace 이벤트를 설정합니다. 위 코드는 다음 이벤트를 설정합니다.
 signal_generate
 signal_deliver
 sched_switch

세부 패치 코드 분석은 아쉽지만 이 책의 범위를 넘어서는 것 같으니, ftrace_events_enable() 함수 내 trace_set_clr_event() 함수를 써서 ftrace 이벤트를 설정한다는 정도로 기억합시다.

(개인블로그)
http://rousalome.egloos.com