ftrace에서 동적 타이머 관련 이벤트를 키고 관련 로그를 해석하는 방법을 배웠습니다.
이번 소절에서는 라즈비안 리눅스 커널 코드를 수정해 동적 타이머 동작을 분석하는 실습을 하겠습니다.
이번에 작성할 패치 코드 기능은 다음과 같습니다.
Soft IRQ 타이머 서비스 실행 요청을 할 때 콜스택 파악
동적 타이머 핸들러인 rh_timer_func() 함수 콜스택 파악
각 함수가 실행할 때 프로세스 컨택스트 파악 Soft IRQ 타이머 서비스 실행 요청을 할 때 콜스택 파악
동적 타이머의 전체 실행 흐름을 파악하는 것이 패치 코드의 목적이므로 코드는 최대한 간결하게 소개합니다.
패치 코드 입력 방법과 패치 코드 내용 알아보기
먼저 패치 코드를 소개합니다.
diff --git a/drivers/usb/core/hcd.c b/drivers/usb/core/hcd.c
index 1c21955..8892d43 100644
--- a/drivers/usb/core/hcd.c
+++ b/drivers/usb/core/hcd.c
@@ -789,11 +789,17 @@ void usb_hcd_poll_rh_status(struct usb_hcd *hcd)
01 }
02 EXPORT_SYMBOL_GPL(usb_hcd_poll_rh_status);
03
04 +extern void raspbian_trace_timer_debug_info(void);
05 +extern uint32_t raspbian_debug_state;
06 +
07 /* timer callback */
08 static void rh_timer_func (struct timer_list *t)
09 {
10 struct usb_hcd *_hcd = from_timer(_hcd, t, rh_timer);
11
12 + if (raspbian_debug_state == 701)
13 + raspbian_trace_timer_debug_info();
14 +
15 usb_hcd_poll_rh_status(_hcd);
16 }
17
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 6f58486..494b159 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -416,6 +416,9 @@ void irq_exit(void)
18 trace_hardirq_exit(); /* must be last! */
19 }
20
21 +extern void raspbian_trace_timer_debug_info(void);
22 +extern uint32_t raspbian_debug_state;
23 +
24 /*
25 * This function must run with irqs disabled!
26 */
@@ -423,6 +426,8 @@ inline void raise_softirq_irqoff(unsigned int nr)
27 {
28 __raise_softirq_irqoff(nr);
29
30 + if ( (nr == TIMER_SOFTIRQ) && (raspbian_debug_state == 701) )
31 + raspbian_trace_timer_debug_info();
32 /*
33 * If we're in an interrupt or softirq, we're done
34 * (this also catches softirq-disabled code). We will
diff --git a/kernel/time/timer.c b/kernel/time/timer.c
--- a/kernel/time/timer.c
+++ b/kernel/time/timer.c
@@ -944,6 +944,23 @@ static struct timer_base *lock_timer_base(struct timer_list *timer,
35 }
36 }
37
38 +extern uint32_t raspbian_debug_state;
39 +
40 +void raspbian_trace_timer_debug_info(void)
41 +{
42 + void *stack = NULL;
43 + struct thread_info *current_thread;
44 +
45 + stack = current->stack;
46 + current_thread = (struct thread_info*)stack;
47 +
48 + trace_printk("[-][%s]jiffies_64: %llu, caller:%pS \n",
49 + current->comm, jiffies_64, (void *)__builtin_return_address(0));
50 +
51 + trace_printk("[-] in_softirq(): 0x%08x,preempt_count = 0x%08x \n",
52 + (unsigned int)in_softirq(), (unsigned int)current_thread->preempt_count);
53 +}
54 +
55 #define MOD_TIMER_PENDING_ONLY 0x01
56 #define MOD_TIMER_REDUCE 0x02
57
@@ -1041,6 +1058,8 @@ __mod_timer(struct timer_list *timer, unsigned long expires, unsigned int option
58 debug_activate(timer, expires);
59
60 timer->expires = expires;
61 + if (raspbian_debug_state == 701)
62 + raspbian_trace_timer_debug_info();
63 /*
64 * If 'idx' was calculated above and the base time did not advance
65 * between calculating 'idx' and possibly switching the base, only
각 패치 코드 조각 입력 방법과 패치 코드 내용을 알아봅시다.
첫 번째 패치 코드 입력 방법을 소개하기 위해 다음 __mod_timer() 함수 오리지널 코드를 소개합니다.
01 static inline int
02 __mod_timer(struct timer_list *timer, unsigned long expires, unsigned int options)
03 {
04 struct timer_base *base, *new_base;
05 unsigned int idx = UINT_MAX;
06 unsigned long clk = 0, flags;
07 int ret = 0;
08
09 BUG_ON(!timer->function);
10
...
11 debug_activate(timer, expires);
12
13 timer->expires = expires;
14 /* 첫 번째 패치 코드 조각을 입력하세요 */
15 if (idx != UINT_MAX && clk == base->clk) {
16 enqueue_timer(base, timer, idx);
17 trigger_dyntick_cpu(base, timer);
18 } else {
19 internal_add_timer(base, timer);
20 }
__mod_timer() 함수 코드에서 /* 첫 번째 패치 코드 조각을 입력하세요 */ 라고 표시된 주석문에 다음 61~62 번째 줄 코드를 입력합니다.
60 timer->expires = expires;
61 + if (raspbian_debug_state == 701)
62 + raspbian_trace_timer_debug_info();
raspbian_debug_state 변수가 701일 때만 raspbian_trace_timer_debug_info() 함수를 호출하는 코드입니다. 그렇다면 이 조건을 추가한 이유는 무엇일까요?
동적 타이머는 커널에서 배경으로 자주 호출됩니다. 그런데 실수로 패치 코드를 잘못 입력하면 라즈베리파이가 부팅을 못할 수 있습니다. 그래서 라즈비안 부팅 후 다음 명령어를 입력해 raspbian_debug_state 를 701로 변경할 때만 디버깅 코드가 작동하도록 조건을 추가한 것입니다.
echo 701 > /sys/kernel/debug/raspbian_debug_iface/val
60번째 줄 “timer->expires = expires;” 코드 다음에 패치 코드를 입력한 이유는 동적 타이머 실제 등록하는 과정을 보기 위해서입니다. 혹시 같은 만료 시각으로 __mod_timer() 함수 호출로 동적 타이머를 재실행하면 __mod_timer() 앞부분 코드에서 “return 1;” 문을 실행해서 함수 실행을 종료하기 때문입니다.
다음 2번째 패치 코드 조각 입력 방법을 소개합니다. 아래 코드는 __mod_timer() 함수 오리지널 상태 소스 코드입니다.
/* 2번째 패치 코드를 입력하세요. */
01 #define MOD_TIMER_PENDING_ONLY 0x01
02 #define MOD_TIMER_REDUCE 0x02
03
04
05 static inline int
06 __mod_timer(struct timer_list *timer, unsigned long expires, unsigned int options)
07 {
08 struct timer_base *base, *new_base;
09 unsigned int idx = UINT_MAX;
10 unsigned long clk = 0, flags;
위 코드에서 /* 2번째 패치 코드를 입력하세요. */ 라고 표시된 부분에 다음 패치 코드를 작성합시다.
38 +extern uint32_t raspbian_debug_state;
39 +
40 +void raspbian_trace_timer_debug_info(void)
41 +{
42 + void *stack = NULL;
43 + struct thread_info *current_thread;
44 +
45 + stack = current->stack;
46 + current_thread = (struct thread_info*)stack;
47 +
48 + trace_printk("[-][%s]jiffies_64: %llu, caller:%pS \n",
49 + current->comm, jiffies_64, (void *)__builtin_return_address(0));
50 +
51 + trace_printk("[-] in_softirq(): 0x%08x,preempt_count = 0x%08x \n",
52 + (unsigned int)in_softirq(), (unsigned int)current_thread->preempt_count);
53 +}
패치 코드에 있는 raspbian_trace_timer_debug_info() 함수는 다음 동작을 수행합니다.
45~46번째 라인: current이란 매크로로 현재 실행 중인 프로세스 스택 주소에 접근합니다. 현재 스택 주소로 스택 최상단 주소를 current_thread 에 저장합니다.
48~49번째 라인: 프로세스 이름, jiffies와 자신을 호출한 함수 주소를 ftrace로 출력합니다.
51~52번째 라인: 프로세스 struct thread_info 구조체 preempt_count 출력합니다. 이 변수는 인터럽트 컨택스트 및 Soft IRQ 컨택스트 정보를 저장하고 있습니다.
이번에는 3~4번째 패치 코드 조각을 입력하는 방법을 소개합니다.
void irq_exit(void)
{
...
tick_irq_exit();
rcu_irq_exit();
trace_hardirq_exit(); /* must be last! */
}
/* 3번째 패치 코드 조각을 입력하세요 */
/*
* This function must run with irqs disabled!
*/
inline void raise_softirq_irqoff(unsigned int nr)
{
__raise_softirq_irqoff(nr);
/* 4번째 패치 코드 조각을 입력하세요 */
...
}
위 코드에서 /* 3번째 패치 코드를 입력하세요. */ 라고 표시된 부분에 다음 패치 코드를 작성합시다.
21 +extern void raspbian_trace_timer_debug_info(void);
22 +extern uint32_t raspbian_debug_state;
이어서 /* 4번째 패치 코드를 입력하세요. */ 라고 표시된 부분에 다음 패치 코드를 입력합시다.
30 + if ( (nr == TIMER_SOFTIRQ) && (raspbian_debug_state == 701) )
31 + raspbian_trace_timer_debug_info();
위 패치 코드는 다음 조건에서 raspbian_trace_timer_debug_info() 함수를 호출합니다.
Soft IRQ 서비스가 TIMER_SOFTIRQ이고 raspbian_debug_state변수가 701일 때
TIMER_SOFTIRQ 아이디로 Soft IRQ 서비스를 요청할 때 디버깅 정보를 출력하기 위한 코드입니다.
참고로, 타이머 인터럽트가 발생하면 인터럽트 핸들러인 arch_timer_handler_phys() 함수 이후 다음 순서로 함수를 호출합니다.
arch_timer_handler_phys()
run_local_timers()
__raise_softirq_irqoff()
이번에는 마지막 5번째 패치 코드 조각 입력 방법을 소개합니다.
[https://github.com/raspberrypi/linux/blob//drivers/usb/core/hcd.c]
void usb_hcd_poll_rh_status(struct usb_hcd *hcd)
{
...
if (hcd->uses_new_polling ? HCD_POLL_RH(hcd) :
(length == 0 && hcd->status_urb != NULL))
mod_timer (&hcd->rh_timer, (jiffies/(HZ/4) + 1) * (HZ/4));
}
EXPORT_SYMBOL_GPL(usb_hcd_poll_rh_status);
/* 5번째 패치 코드 조각을 작성하세요 */
/* timer callback */
static void rh_timer_func (struct timer_list *t)
{
struct usb_hcd *_hcd = from_timer(_hcd, t, rh_timer);
/* 6번째 패치 코드 조각을 작성하세요 */
usb_hcd_poll_rh_status(_hcd);
}
위 소스 코드에서 /* 5번째 패치 코드 조각을 작성하세요 */ 로 표시된 부분에 다음 코드를 입력합니다.
04 +extern void raspbian_trace_timer_debug_info(void);
05 +extern uint32_t raspbian_debug_state;
이어서 /* 6번째 패치 코드 조각을 작성하세요 */ 로 표시된 부분에 다음 코드를 입력합니다.
12 + if (raspbian_debug_state == 701)
13 + raspbian_trace_timer_debug_info();
패치 코드는 동적 타이머 핸들러인 rh_timer_func() 함수가 실행할 때 콜스택과 컨택스트 실행 정보를 확인하는 목적입니다.
6개 패치 조각 내용을 정리하면;
동적 타이머를 등록하거나 동적 타이머 핸들러를 호출할 때 raspbian_trace_timer_debug_info() 함수 호출해 디버깅 정보를 출력하는 동작입니다.
위와 같이 설명해 드린 패치 코드를 입력 후 컴파일을 합니다. 라즈비안에 커널 이미지를 설치하고 라즈베리파이를 재부팅을 합니다.
ftrace 설정을 같이 따라해보기
패치 코드 입력 방법을 알아봤으니 이번에는 ftrace를 설정해봅시다.
#!/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
sleep 1
echo "set_ftrace_filter init"
echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"
echo raspbian_raised_timer_softirq raspbian_trace_debug_info mod_timer > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
echo 1 > /sys/kernel/debug/tracing/events/irq/enable
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/timer/timer_init/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_start/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_expire_exit/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_cancel/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_expire_entry/enable
sleep 1
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"
위 코드를 입력 후 timer_debug_raspbian.sh 이름으로 저장합시다. “./timer_debug_raspbian.sh” 명령어로 이 스크립트를 실행할 수 있습니다.
셸 스크립트 코드는 이전에 소개했던 ftrace 설정 코드와 유사하지만 몇 가지 차이점이 있습니다. 가장 큰 차이는 다음 코드입니다.
echo raspbian_trace_debug_info > /sys/kernel/debug/tracing/set_ftrace_filter
패치 코드에서 구현한 raspbian_trace_debug_info() 함수의 콜스택을 보려는 설정입니다. 특정 함수의 콜스택을 보기 위해서는 set_ftrace_filter 파일로 함수 이름을 지정해야 합니다.
패치 코드에서 구현한 raspbian_trace_debug_info() 함수는 다음 조건에서 호출된다는 사실을 떠올립시다.
TIMER_SOFTIRQ 아이디로 Soft IRQ 서비스 요청
동적 타이머 핸들러인 rh_timer_func() 함수 실행
다음은 ftrace 타이머 관련 이벤트를 키는 명령어입니다.
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_init/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_start/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_expire_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_expire_exit/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/timer_cancel/enable
이전 소절에서 소개했던 동적 타이머 ftrace 이벤트를 키는 설정입니다. 위 이벤트는 다음 메시지를 출력합니다.
동적 타이머 핸들러 함수 이름
타이머 플래그
struct timer_list 주소
동적 타이머 만료 시각(HZ단위)
다음 명령어로 ftrace 를 설정하고 10 초후 ftrace 로그를 받습니다.
./timer_debug_raspbian.sh
ftrace 메시지 분석하기
이어서 ftrace 로그와 함께 타이머 관련 커널 소스 코드를 분석하겠습니다.
전체 ftrace 로그와 전체 흐름도 알아보기
다음은 동적 타이머 동작을 담고 있는 ftrace 전체 메시지입니다. 이제부터 ftrace 로그를 분석해볼까요?
1 <idle>-0 [000] ..s. 105.040232: mod_timer <-usb_hcd_poll_rh_status
2 <idle>-0 [000] ..s. 105.040261: <stack trace>
3 => call_timer_fn
4 => expire_timers
5 => run_timer_softirq
6 => __do_softirq
7 => irq_exit
8 => __handle_domain_irq
9 => bcm2836_arm_irqchip_handle_irq
10 => __irq_svc
11 => arch_cpu_idle
12 => arch_cpu_idle
13 => default_idle_call
14 => do_idle
15 => cpu_startup_entry
16 => rest_init
17 => start_kernel
18 <idle>-0 [000] d.s. 105.040265: timer_start: timer=b9029684 function=rh_timer_func expires=4294947825 [timeout=24] cpu=0 idx=25 flags=
19 <idle>-0 [000] d.s. 105.040268: mod_timer: [-][swapper/0]jiffies_64: 4294947801, timer->expires: 4294947825 caller:usb_hcd_poll_rh_status+0x10c/0x138
20 <idle>-0 [000] d.s. 105.040271: mod_timer: [-] in_softirq(): 0x00000100,preempt_count = 0x00000100
…
21 <idle>-0 [000] d.h. 105.290127: irq_handler_entry: irq=162 name=arch_timer
22 <idle>-0 [000] d.h. 105.290131: softirq_raise: vec=1 [action=TIMER]
23 <idle>-0 [000] d.h. 105.290132: raspbian_trace_debug_info <-__raise_softirq_irqoff
24 <idle>-0 [000] d.h. 105.290168: <stack trace>
25 => run_local_timers
26 => update_process_times
27 => tick_sched_handle
28 => tick_sched_timer
29 => __hrtimer_run_queues
30 => hrtimer_interrupt
31 => arch_timer_handler_phys
32 => handle_percpu_devid_irq
33 => generic_handle_irq
34 => __handle_domain_irq
35 => bcm2836_arm_irqchip_handle_irq
36 => __irq_svc
37 => arch_cpu_idle
38 => arch_cpu_idle
39 => default_idle_call
40 => do_idle
41 => cpu_startup_entry
42 => rest_init
43 => start_kernel
44 <idle>-0 [000] d.h. 105.290172: raspbian_raised_timer_softirq: [+][swapper/0]timer softirq raised, jiffies_64: 4294947826, caller:__raise_softirq_irqoff+0x64/0xe8
45 <idle>-0 [000] d.h.105.290175: raspbian_raised_timer_debug: [+] in_softirq(): 0x00000000,preempt_count = 0x00010000
46 <idle>-0 [000] d.h. 105.290181: softirq_raise: vec=7 [action=SCHED]
47 <idle>-0 [000] d.h. 105.290185: irq_handler_exit: irq=162 ret=handled
48 <idle>-0 [000] ..s. 105.290187: softirq_entry: vec=1 [action=TIMER]
49 <idle>-0 [000] d.s. 105.290189: timer_cancel: timer=b9029684
50<idle>-0 [000] ..s. 105.290191: timer_expire_entry: timer=b9029684 function=rh_timer_func now=4294947826
51<idle>-0 [000] ..s. 105.290192: raspbian_trace_debug_info <-rh_timer_func
52<idle>-0 [000] ..s. 105.290219: <stack trace>
53 => expire_timers
54 => run_timer_softirq
55 => __do_softirq
56 => irq_exit
57 => __handle_domain_irq
58 => bcm2836_arm_irqchip_handle_irq
59 => __irq_svc
60 => arch_cpu_idle
61 => arch_cpu_idle
62 => default_idle_call
63 => do_idle
64 => cpu_startup_entry
65 => rest_init
65 => start_kernel
66 <idle>-0 [000] ..s. 105.290223: raspbian_trace_debug_info: [-][swapper/0]jiffies_64: 4294947826, caller:rh_timer_func+0x44/0x54
67 <idle>-0 [000] ..s. 105.290226: raspbian_trace_debug_info: [-] in_softirq():0x00000100,preempt_count = 0x00000100
<idle>-0 [000] ..s. 105.290289: timer_expire_exit: timer=b9029684
콜스택에 보이는 함수는 이번 장에서 배운 낯익은 이름이니 어렵게 생각하지 않았으면 좋겠습니다. 복잡해 보이는 ftrace 메시지인데 전체 실행 흐름은 다음과 같이 4단계로 분류할 수 있습니다.
[그림 8.9] ftrace 분석: 커널 타이머 전체 실행 흐름도
각 단계별로 동적 타이머 처리 과정은 다음과 같습니다.
[1] 단계: 동적 타이머 등록
mod_timer() 함수를 호출해 동적 타이머를 등록합니다. 24 jiffies 후로 동적 타이머 만료 시간을 설정합니다.
[2] 단계: TIMER_SOFTIRQ 서비스 요청
24 jiffies 후 커널 시스템 타이머가 run_local_timers() 함수에서 TIMER_SOFTIRQ 아이디로 Soft IRQ 서비스를 요청하는 동작입니다.
[3] 단계: Soft IRQ 서비스 실행
타이머 인터럽트에 대한 처리를 끝낸 후 irq_exit() 함수를 호출해 Soft IRQ 서비스를 실행합니다.
[4] 단계: 동적 타이머 만료 후 타이머 핸들러 실행
expire_timers() 함수에서 동적 타이머 핸들러인 rh_timer_func() 함수를 호출합니다.
커널 시스템 타이머는 4단계로 도작한다는 점을 머릿속으로 그리면서 ftrace 로그를 봅시다.
ftrace로 단계별 커널 타이머 전체 흐름을 살펴봤으니 각 단계별 ftrace 메시지 분석을 시작합니다.
1단계: 동적 타이머 등록 동작 분석하기
먼저 [1] 단계 ftrace 로그입니다. 동적 타이머를 실행하는 동작입니다.
1 <idle>-0 [000] ..s. 105.040232: mod_timer <-usb_hcd_poll_rh_status
2 <idle>-0 [000] ..s. 105.040261: <stack trace>
3 => call_timer_fn
4 => expire_timers
5 => run_timer_softirq
6 => __do_softirq
7 => irq_exit
8 => __handle_domain_irq
9 => bcm2836_arm_irqchip_handle_irq
10 => __irq_svc
11 => arch_cpu_idle
12 => arch_cpu_idle
13 => default_idle_call
14 => do_idle
15 => cpu_startup_entry
16 => rest_init
17 => start_kernel
18 <idle>-0 [000] d.s. 105.040265: timer_start: timer=b9029684 function=rh_timer_func expires=4294947825 [timeout=24] cpu=0 idx=25 flags=
19 <idle>-0 [000] d.s. 105.040268: mod_timer: [-][swapper/0]jiffies_64: 4294947801, timer->expires: 4294947825 caller:usb_hcd_poll_rh_status+0x10c/0x138
20 <idle>-0 [000] d.s. 105.040271: mod_timer: [-] in_softirq(): 0x00000100,preempt_count = 0x00000100
먼저 1번째 줄 로그를 보겠습니다.
1 <idle>-0 [000] ..s. 105.040232: mod_timer <-usb_hcd_poll_rh_status
동적 타이머 만료 시간을 바꾼 후 동적 타이머를 등록하는 동작입니다.
그러면 위 로그는 어느 커널 코드에서 출력할까요? 다음 코드를 보면 알 수 있습니다.
1 void usb_hcd_poll_rh_status(struct usb_hcd *hcd)
2 {
...
3 if (hcd->uses_new_polling ? HCD_POLL_RH(hcd) :
4 (length == 0 && hcd->status_urb != NULL))
5 mod_timer (&hcd->rh_timer, (jiffies/(HZ/4) + 1) * (HZ/4));
6 }
1번째 줄 ftrace 로그는 usb_hcd_poll_rh_status() 함수 5번째 줄과 같이 mod_timer() 함수를 호출할 때 출력합니다.
다음 1번째 줄 로그를 포함해서 콜스택을 볼까요?
1 <idle>-0 [000] ..s. 105.040232: mod_timer <-usb_hcd_poll_rh_status
2 <idle>-0 [000] ..s. 105.040261: <stack trace>
3 => call_timer_fn
4 => expire_timers
5 => run_timer_softirq
6 => __do_softirq
7 => irq_exit
8 => __handle_domain_irq
9 => bcm2836_arm_irqchip_handle_irq
10 => __irq_svc
11 => arch_cpu_idle
12 => arch_cpu_idle
13 => default_idle_call
14 => do_idle
15 => cpu_startup_entry
16 => rest_init
17 => start_kernel
3~7번째 줄 로그를 보면 TIMER_SOFTIRQ 아이디인 Soft IRQ 서비스를 실행하는 함수 목록을 볼 수 있습니다. 함수 호출 순서는 다음과 같습니다.
irq_exit()
__do_softirq()
run_timer_softirq()
expire_timers()
call_timer_fn()
3번째 줄 로그는 중요한 사실을 알려줍니다.
call_timer_fn() 함수는 동적 타이머 핸들러 함수를 호출한다.
1번째 줄 로그를 볼까요?
mod_timer() 함수는 usb_hcd_poll_rh_status() 함수에서 호출합니다. 코드를 검색하면 동적 타이머 핸들러인 rh_timer_func() 함수가 usb_hcd_poll_rh_status() 함수를 호출한다는 사실을 알 수 있습니다.
동적 타이머 핸들러에서 만료 시각을 HZ 단위로 설정하고 다시 동적 타이머를 실행하는
것입니다.
동적 타이머를 주기적으로 등록할 때 쓰는 기법입니다.
다음 18번째 줄 로그를 봅시다. 간단한 로그 같지만 아주 중요한 정보를 담고 있습니다.
18 <idle>-0 [000] d.s. 105.040265: timer_start: timer=b9029684 function=rh_timer_func expires=4294947825 [timeout=24] cpu=0 idx=25 flags=
동적 타이머를 실행할 때 timer_start 이벤트를 키면 ftrace 메시지로 상세한 동적 타이머 속성 정보를 출력합니다.
이제 18번째 줄에서 출력하는 메시지의 의미를 상세히 분석해 볼까요?
timer=b9029684
동적 타이머를 표현하는 자료구조인 struct timer_list 주소입니다.
function=rh_timer_func
동적 타이머 핸들러는 rh_timer_func() 함수입니다.
expires=4294947825
HZ단위로 동적 타이머가 만료할 시각을 표시합니다. 현재 jiffies와 이 값을 비교하면 HZ 단위로 얼마 후 동적 타이머가 만료할지 알 수 있습니다.
[timeout=24]
현재 jiffies 시각 기준으로 24 후(HZ단위)에 동적 타이머가 만료한다는 의미입니다. 24란 값을 어떻게 계산하는지는 19번째 줄 로그 분석에서 이어집니다.
cpu=0
동적 타이머를 per-cpu timer_base 변수의 CPU0 주소 공간에서 처리한다는 의미입니다. 이 정보로 CPU0에서 동적 타이머를 초기화했다는 정보를 확인할 수 있습니다.
idx=25
timer_base 전역 변수에서 관리하는 해시 타이머 벡터 인덱스입니다.
다음 코드에서 calc_wheel_index() 함수를 호출하면 6번째 줄 코드에서 idx 지역 변수로 커널 타이머 해시 벡터 인덱스를 받습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/timer.c]
1 static void
2 __internal_add_timer(struct timer_base *base, struct timer_list *timer)
3 {
4 unsigned int idx;
5
6 idx = calc_wheel_index(timer->expires, base->clk);
7 enqueue_timer(base, timer, idx);
8}
timer_start 이벤트에서 출력하는 각각 메시지는 다음 코드를 분석하면 알 수 있습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/include/trace/events/timer.h]
TRACE_EVENT(timer_start,
...
TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
__entry->timer, __entry->function, __entry->expires,
(long)__entry->expires - __entry->now,
__entry->flags & TIMER_CPUMASK,
__entry->flags >> TIMER_ARRAYSHIFT,
decode_timer_flags(__entry->flags & TIMER_TRACE_FLAGMASK))
);
이 코드 원리에 대해서 더 설명을 드리고 싶으나 이 책의 범위를 넘어선 내용이므로 넘어 갑니다.
이번에 다시 19번째 줄 로그를 볼까요?
19 <idle>-0 [000] d.s. 105.040268: mod_timer: [-][swapper/0]jiffies_64: 4294947801, timer->expires: 4294947825 caller:usb_hcd_poll_rh_status+0x10c/0x138
20 <idle>-0 [000] d.s. 105.040271: mod_timer: [-] in_softirq(): 0x00000100,preempt_count = 0x00000100
이번 소절에 mod_timer() 함수에 적용한 패치 코드가 실행해서 출력하는 메시지입니다.
19번째 줄 로그로 다음 정보를 알 수 있습니다.
현재 시각인 jiffies는 4294947801이고 동적 타이머 만료 시각은 4294947825입니다.
두 변수의 차이는 24(4294947825 – 4294947801)이므로 다음과 같은 정보를 유추해낼 수 있습니다.
HZ 단위로 jiffies가 24만큼 증감한 후 동적 타이머가 만료한다.
다시 18번째 줄 로그 분석으로 되돌아가 보면 timeout=24”이라는 메시지가 보입니다.
18 <idle>-0 [000] d.s. 105.040265: timer_start: timer=b9029684 function=rh_timer_func expires=4294947825 [timeout=24] cpu=0 idx=25 flags=
위 메시지는 다음과 같은 의미입니다.
24만큼 jiffies가 증감하면 동적 타이머가 만료한다.
다음 20번째 줄 로그를 봅시다.
프로세스 스택 최상단 주소에 있는 struct thread_info 구조체 preempt_count 필드가 0x00000100입니다. 이 정보는 다음과 같이 해석할 수 있습니다.
Soft IRQ 컨택스트에서 동적 타이머를 실행했다.
전체 Soft IRQ 시스템 구조를 머릿속으로 그려보면 이 함수는 __do_softirq() 함수에서 호출된다고 유추할 수 있습니다.
여기까지 동적 타이머를 등록하는 로그를 분석했습니다. 동적 타이머가 만료할 때 호출하는 타이머 핸들러에서 다시 동적 타이머를 등록하는 동작입니다.
이번 ftrace 로그를 보면 동적 타이머는 Soft IRQ 컨택스트에서 등록합니다. 그런데 사실 어느 함수에서도 동적 타이머를 등록할 수 있습니다.
mod_timer() 함수에 다음과 같이 필터를 걸고 ftrace 로그를 받으면 다음과 같은 콜스택을 볼 수 있습니다.
다음과 같은 콜스택을 볼 수 있습니다.
kworker/u8:2-101 [001] d... 211.356838: mod_timer <-bcm2835_mmc_send_command
kworker/u8:2-101 [001] d... 211.356854: <stack trace>
=> __mmc_start_request
=> mmc_start_request
=> mmc_wait_for_req
=> mmc_io_rw_extended
=> sdio_io_rw_ext_helper
=> sdio_readsb
=> brcmf_sdiod_buffrw
=> brcmf_sdiod_recv_pkt
=> brcmf_sdiod_recv_buf
=> brcmf_sdio_dataworker
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork
kworker/u8:2-101 [001] d... 211.356856:
timer_start: timer=b9c1a37c function=bcm2835_mmc_timeout_timer expires=4294959432 [timeout=1000] cpu=1 idx=134 flags=
위 로그를 잠깐 분석해 보겠습니다.
프로세스 이름이kworker/u8:2인 워커 스레드가 bcm2835_mmc_timeout_timer() 타이머 핸들러로 등록한 동적 타이머를 실행합니다.
timer_start 메시지를 보면 현재 시각 기준으로 4294959432 jiffies에 동적 타이머는 만료합니다. CPU1 공간에 있는 per-cpu timer_base 변수에 등록하고 타이머 해시 인덱스는 134입니다.
2 단계: TIMER_SOFTIRQ 서비스 요청 동작 분석하기
이어서 다음 그림에서 검은색으로 된 2단계 ftrace 로그를 분석합시다.
[그림 8.10] ftrace 분석: 커널 타이머 실행 흐름도 2단계
이번에는 24 jiffies 후 동적 타이머 만료 시간에 “timer=b9029684” 동적 타이머 핸들러가 실행하는 과정을 점검합니다.
21 <idle>-0 [000] d.h. 105.290127: irq_handler_entry: irq=162 name=arch_timer
22 <idle>-0 [000] d.h. 105.290131: softirq_raise: vec=1 [action=TIMER]
23 <idle>-0 [000] d.h. 105.290132: raspbian_raised_timer_softirq <-__raise_softirq_irqoff
24 <idle>-0 [000] d.h. 105.290168: <stack trace>
25 => run_local_timers
26 => update_process_times
27 => tick_sched_handle
28 => tick_sched_timer
29 => __hrtimer_run_queues
30 => hrtimer_interrupt
31 => arch_timer_handler_phys
32 => handle_percpu_devid_irq
33 => generic_handle_irq
34 => __handle_domain_irq
35 => bcm2836_arm_irqchip_handle_irq
36 => __irq_svc
37 => arch_cpu_idle
38 => arch_cpu_idle
39 => default_idle_call
40 => do_idle
41 => cpu_startup_entry
42 => rest_init
43 => start_kernel
21번째 줄 로그를 보면 17번 타이머 인터럽트가 발생했음을 알 수 있습니다.
21 <idle>-0 [000] d.h. 105.290127: irq_handler_entry: irq=162 name=arch_timer
22 <idle>-0 [000] d.h. 105.290131: softirq_raise: vec=1 [action=TIMER]
22번째 줄 로그는 TIMER_SOFTIRQ 서비스 아이디로 Soft IRQ를 요청했다는 메시지입니다.
이 ftrace 메시지는 다음 3번째 줄 코드에서 trace_softirq_raise() 함수를 실행할 때 출력합니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/softirq.c]
1 void __raise_softirq_irqoff(unsigned int nr)
2 {
3 trace_softirq_raise(nr);
4 or_softirq_pending(1UL << nr);
5 }
23~43번째 줄 로그로 raspbian_raised_timer_softirq() 함수 콜스택을 볼 수 있습니다. 37번째 줄 로그와 같이 arch_cpu_idle() 함수 실행 도중 타이머 인터럽트가 발생해서 run_local_timers() 함수까지 호출합니다.
이번에는 44번째 줄 로그를 봅시다.
44 <idle>-0 [000] d.h. 105.290172: raspbian_raised_timer_softirq: [+][swapper/0]timer softirq raised, jiffies_64: 4294947826, caller:__raise_softirq_irqoff+0x64/0xe8
45 <idle>-0 [000] d.h.105.290175: raspbian_raised_timer_softirq: [+] in_softirq(): 0x00000000,preempt_count = 0x00010000
현재 jiffies가 4294947826 이고 raspbian_raised_timer_softirq() 함수는 __raise_softirq_irqoff() 함수가 호출했다는 정보입니다. 45번째 줄 로그에서 struct thread_info 구조체 preempt_count가 0x00010000 이므로 인터럽트 컨택스트에서 코드가 실행 중임을 알 수 있습니다.
이 동적 타이머를 실행할 때 만료 시각을 HZ 단위로 4294947825로 설정했는데 현재 jiffies가 4294947826입니다.
18 <idle>-0 [000] d.s. 105.040265: timer_start: timer=b9029684 function=rh_timer_func expires=4294947825 [timeout=24] cpu=0 idx=25 flags=
동적 타이머 만료 시각에 맞춰서 TIMER_SOFTIRQ 아이디로 Soft IRQ 서비스를 요청한 것입니다. 여기까지 2단계 단계까지 로그를 분석했습니다.
3 단계: Soft IRQ TIMER_SOFTIRQ 서비스 요청 동작 분석하기
이제 [3][4] 단계 로그를 분석하겠습니다.
[그림 8.11] ftrace 분석: 커널 타이머 실행 흐름도 3/4단계
다음 47번째 줄 로그를 봅시다.
47 <idle>-0 [000] d.h. 105.290185: irq_handler_exit: irq=162 ret=handled
48 <idle>-0 [000] ..s. 105.290187: softirq_entry: vec=1 [action=TIMER]
49 <idle>-0 [000] d.s. 105.290189: timer_cancel: timer=b9029684
47번째 줄 로그는 17번 TIMER 인터럽트 핸들러 실행이 완료됐다는 정보입니다. Soft IRQ TIMER_SOFTIRQ 서비스 핸들러인 run_timer_softirq() 함수를 호출한다는 의미입니다. 이전 절에서 run_timer_softirq() 함수는 __do_softirq() 함수에서 실행한다고 분석한 내용을 떠올립시다.
이어서 49번째 줄 로그를 봅시다.
49 <idle>-0 [000] d.s. 105.290189: timer_cancel: timer=b9029684
동적 타이머를 취소하는 동작을 출력하는 메시지입니다. 이 ftrace 로그는 다음과 같이 debug_deactivate() 함수에서 trace_timer_cancel() 함수를 실행할 때 출력합니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/timer.c]
static inline void debug_deactivate(struct timer_list *timer)
{
debug_timer_deactivate(timer);
trace_timer_cancel(timer);
}
debug_deactivate() 함수는 다음 함수 흐름으로 호출됩니다. 가장 먼저 실행하는 함수는 expire_timers() 입니다.
expire_timers()
detach_timer()
debug_deactivate()
이 로그로 다음 사실을 다시 확인할 수 있습니다.
커널 시스템 타이머는 동적 타이머가 만료할 때 커널 시스템 타이머가 동적 타이머를
해제시킨다.
따라서 동적 타이머를 주기적으로 실행하려면 동적 타이머가 만료할 시점에 다시 등록해야 합니다.
4 단계: 동적 타이머 만료 후 동적 타이머 핸들러 실행 동작 분석하기
이제 동적 타이머 핸들러를 호출하는 50번째 줄 로그를 봅시다.
50<idle>-0 [000] ..s. 105.290191: timer_expire_entry: timer=b9029684 function=rh_timer_func now=4294947826
51<idle>-0 [000] ..s. 105.290192: raspbian_trace_debug_info <-rh_timer_func
52<idle>-0 [000] ..s. 105.290219: <stack trace>
53 => expire_timers
54 => run_timer_softirq
55 => __do_softirq
56 => irq_exit
57 => __handle_domain_irq
58 => bcm2836_arm_irqchip_handle_irq
59 => __irq_svc
60 => arch_cpu_idle
61 => arch_cpu_idle
62 => default_idle_call
63 => do_idle
64 => cpu_startup_entry
65 => rest_init
65 => start_kernel
66 <idle>-0 [000] ..s. 105.290223: raspbian_trace_debug_info: [-][swapper/0]jiffies_64: 4294947826, caller:rh_timer_func+0x44/0x54
67 <idle>-0 [000] ..s. 105.290226: raspbian_trace_debug_info: [-] in_softirq():0x00000100,preempt_count = 0x00000100
68 <idle>-0 [000] ..s. 105.290289: timer_expire_exit: timer=b9029684
50번째 줄 로그는 동적 타이머 핸들러를 호출하고, 68번째 줄 로그는 동적 타이머 핸들러 실행을 마무리했을 때 출력합니다.
50<idle>-0 [000] ..s. 105.290191: timer_expire_entry: timer=b9029684 function=rh_timer_func now=4294947826
…
68 <idle>-0 [000] ..s. 105.290289: timer_expire_exit: timer=b9029684
이 로그는 동적 타이머를 호출하기 직전 아래 call_timer_fn() 함수 5번과 7번째 줄 코드에서 실행합니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/timer.c]
1 static void call_timer_fn(struct timer_list *timer, void (*fn)(unsigned long),
2 unsigned long data)
3 {
4 int count = preempt_count();
...
5 trace_timer_expire_entry(timer);
6 fn(data);
7 trace_timer_expire_exit(timer);
6번째 줄 코드는 동적 타이머 핸들러를 호출합니다. 이 함수 전후로 ftrace timer_expire_entry와 timer_expire_exit 이벤트 로그를 출력합니다.
이 ftrace 로그로 동적 타이머 핸들러가 실행한 시간을 측정할 수 있습니다. 지금 분석 중인 timer=b9029684 동적 타이머 핸들러인 rh_timer_func() 함수 실행 시간은 다음 계산으로 0.000098 초입니다.
0.000098 = 105.290289 - 105.290191
51~65번째 줄 로그로 raspbian_trace_debug_info() 함수가 호출할 때 콜스택을 볼 수 있습니다.
53 => expire_timers
54 => run_timer_softirq
55 => __do_softirq
56 => irq_exit
57 => __handle_domain_irq
58 => bcm2836_arm_irqchip_handle_irq
59 => __irq_svc
위 콜스택에서 irq_exit() 함수를 보입니다. 17번 타이머 인터럽트 처리를 완료한 후 Soft IRQ 서비스를 실행하는 함수 흐름입니다. 이렇게 동적 타이머 핸들러는 expire_timers() 함수에서 호출합니다.
이제 마지막 66번째 줄 로그를 봅시다.
66 <idle>-0 [000] ..s. 105.290223: raspbian_trace_debug_info: [-][swapper/0]jiffies_64: 4294947826, caller:rh_timer_func+0x44/0x54
67 <idle>-0 [000] ..s. 105.290226: raspbian_trace_debug_info: [-] in_softirq():0x00000100,preempt_count = 0x00000100
rh_timer_func() 함수에서 raspbian_trace_debug_info() 함수를 호출한다는 사실을 알 수 있습니다.
동적 타이머를 커널 시스템 타이머가 어떻게 처리하는지 커널 코드와 ftrace 로그 분석으로 알아봤습니다. 코드 분석으로 우리는 한 가지 유용한 정보를 알 수 있습니다.
동적 타이머 핸들러는 될 수 있는 대로 빨리 수행해야 한다.
여기에는 그럴만한 이유가 있습니다.
동적 타이머 핸들러는 타이머 인터럽트가 발생한 후 Soft IRQ 컨택스트에서 실행한다.
인터럽트는 실행 중인 프로세스를 멈추고 인터럽트 벡터부터 인터럽트에 대한 처리를 시작합니다. 그런데 인터럽트에 대한 처리를 마친 후 바로 Soft IRQ 서비스 요청을 실행합니다. Soft IRQ 서비스도 마찬가지로 프로세스가 실행을 멈춘 상태에서 동작합니다. 따라서 동적 타이머 핸들러는 되도록 빨리 실행도록 간결한 코드를 작성할 필요가 있습니다.
여러분이 혹시 동적 타이머를 구현할 때도 동적 타이머 핸들러 실행 시간을 꼭 점검하시길 바랍니다.
* 강의 동영상도 있으니 같이 들으시면 좋습니다.
#커널 시간관리 목차
커널 타이머 관리 주요 개념 소개
jiffies란
커널 타이머 제어
동적 타이머 초기화
동적 타이머 등록하기
동적 타이머는 누가 언제 실행하나?
라즈베리파이 커널 타이머 실습 및 로그 분석
"혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답글 올려드리겠습니다!"
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글