Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

76261
1501
219118


[리눅스커널] 시간관리: ftrace 동적 타이머 디버깅 이벤트 소개 8. 커널 타이머 관리

이번 시간에 동적 타이머 실행 흐름을 추적하는 ftrace event를 소개합니다.

ftrace는 커널의 주요 동작을 추적하는데 이를 이벤트로 정의합니다. 동적 타이머도 커널의 중요 기능이니 ftrace에서 다음 이벤트를 제공합니다.
timer_start: 동적 타이머를 등록
timer_cancel: 동적 타이머 등록 해제
timer_expire_entry: 동적 타이머가 만료될 때 해당 타이머 핸들러를 실행하기 직전
timer_expire_exit: 동적 타이머가 만료될 때 해당 타이머 핸들러를 실행한 직후

먼저 ftrace 이벤트를 활성화하는 방법을 알아보고 ftrace에서 각 로그를 분석하는 방법을 소개합니다. 

동적 타이머 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 이벤트 로그 패턴와 실행 코드 확인하기
동적 타이머 ftrace 이벤트 메시지는 다음 형식으로 출력합니다.
rcu_sched-8 [001] .... 211.360650: timer_init: timer=b9e7bed0
rcu_sched-8 [001] d... 211.360652: timer_start: timer=b9e7bed0 function=process_timeout expires=4294958434 [timeout=1] cpu=1 idx=0 flags=
...
Compositor-1170  [001] d.s.   211.380620: timer_cancel: timer=b9e7bed0
Compositor-1170  [001] ..s.   211.380621: timer_expire_entry: timer=b9e7bed0 function=process_timeout now=4294958435
Compositor-1170  [001] .ns.   211.380630: timer_expire_exit: timer=b9e7bed0

각각 메시지의 의미와 메시지를 출력하는 함수 이름은 다음 테이블과 같습니다.
이벤트 종류 역할 실행 함수
timer_init 동적 타이머 초기화 debug_init() 
timer_start 동적 타이머 등록 debug_activate() 
timer_cancel 동적 타이머 해제 debug_deactivate  
timer_expire_entry 동적 타이머 핸들러 실행 시작 call_timer_fn()  
timer_expire_exit 동적 타이머 핸들러 실행 종료 call_timer_fn()  

이번에는 위에서 소개한 이벤트를 출력해주는 커널 코드 위치를 알아보겠습니다.  

다음은 ‘동적 타이머 초기화 시점’을 알려주는 timer_init 이벤트를 출력하는 코드입니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/timer.c]
01 static inline void debug_init(struct timer_list *timer)
02 {
03 debug_timer_init(timer);
04 trace_timer_init(timer);
05 }

04 번째 줄 코드에서 trace_timer_init() 함수를 실행할 때 timer_init 이벤트 메시지를 출력합니다.

이번에는 ‘동적 타이머를 등록’하는 정보를 알려주는timer_start 이벤트를 출력하는 커널 코드입니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/timer.c]
01 debug_activate(struct timer_list *timer, unsigned long expires)
02 {
03 debug_timer_activate(timer);
04 trace_timer_start(timer, expires, timer->flags);
05 }

04 번째 줄 코드에서 trace_timer_start() 함수를 실행할 때 timer_start 이벤트 메시지를 출력합니다.

이어서 ‘동적 타이머 만료’ 시점을 알려주는timer_cancel 이벤트를 출력하는 코드를 보겠습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/timer.c]
01 static inline void debug_deactivate(struct timer_list *timer)
02 {
03 debug_timer_deactivate(timer);
04 trace_timer_cancel(timer);
05 }

04 번째 줄 코드에서 trace_timer_cancel() 함수를 실행할 때 timer_cancel 이벤트 메시지를 출력합니다.

마지막으로 동적 타이머 핸들러를 호출하는 정보를 알려주는 timer_expire_entry와 trace_timer_expire_exit 이벤트를 출력하는 코드를 보겠습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/timer.c]
01 static void call_timer_fn(struct timer_list *timer, void (*fn)(unsigned long),
02   unsigned long data)
03 {
04 int count = preempt_count();
...
05 trace_timer_expire_entry(timer);
06 fn(data);
07 trace_timer_expire_exit(timer);

06 번째 줄에서 동적 타이머 핸들러를 실행합니다. 06 번째 줄 코드 전 후로 timer_expire_entry와 timer_expire_exit 이벤트를 출력합니다.

동적 타이머 ftrace 이벤트 로그 분석하기
이번에는 ftrace에서 동적 타이머 이벤트 로그를 분석하는 방법을 소개합니다.

분석할 로그를 소개합니다.
01 rcu_sched-8 [001] .... 211.360650: timer_init: timer=b9e7bed0
02 rcu_sched-8 [001] d... 211.360652: timer_start: timer=b9e7bed0 function=process_timeout expires=4294958434 [timeout=1] cpu=1 idx=0 flags=
...
03 Compositor-1170  [001] d.s.   211.380620: timer_cancel: timer=b9e7bed0
04 Compositor-1170  [001] ..s.   211.380621: timer_expire_entry: timer=b9e7bed0 function=process_timeout now=4294958435
05 Compositor-1170  [001] .ns.   211.380630: timer_expire_exit: timer=b9e7bed0

01 번째 줄 로그를 보겠습니다.
01 rcu_sched-8 [001] .... 211.360650: timer_init: timer=b9e7bed0

동적 타이머를 초기화하는 동작입니다. 이 로그의 핵심 정보는 다음과 같습니다.

    "timer=b9e7bed0"는 동적 타이머 자료구조인 struct timer_list 주소를 의미한다.

위와 같은 ftrace 메시지가 출력할 때 struct timer_list 구조체 세부 필드는 다음과 같습니다.
01 (struct timer_list *)0xb9e7bed0 = 0xB9E7BED0 -> (
02  (struct hlist_node) entry = (
03    (struct hlist_node *) next = 0x0,
04    (struct hlist_node * *) pprev = 0x0),
05  (long unsigned int) expires = 0x0,
06  (void (*)()) function = 0x0,
07  (u32) flags = 0x1)

timer_init 이벤트 왼쪽 부분에 ‘[001]’ 패턴이 보입니다. 이 정보로 보아  CPU1에서 rcu_sched-8 프로세스 실행하니 07번째 줄 flags 필드가 0x1입니다.

다음 02번째 줄 로그를 보겠습니다.
02 rcu_sched-8 [001] d... 211.360652: timer_start: timer=b9e7bed0 function=process_timeout expires=4294958434 [timeout=1] cpu=1 idx=0 flags=
  
timer_start는 동적 타이머를 등록하는 동작을 출력하는 이벤트로 다음 정보를 담고 있습니다.
struct timer_list 주소: b9e7bed0
동적 타이머 핸들러: process_timeout()
동적 타이머가 만료될 시간: 4294958434
동적 타이머를 초기화한 CPU 번호: CPU1

이 ftrace 메시지가 출력할 때 struct timer_list 구조체 세부 필드는 다음과 같습니다. 
01  (struct timer_list *)0xb9e7bed0 
02    (struct hlist_node) entry = (
03      (struct hlist_node *) next = 0x0 = ,
04      (struct hlist_node * *) pprev = 0x0 = ),
05    (long unsigned int) expires = 4294958434,
06    (void (*)()) function = 0x8018DFFC = process_timeout,
07    (u32) flags = 1)

03~05번째 줄 ftrace 로그를 보겠습니다.
03 Compositor-1170  [001] d.s.   211.380620: timer_cancel: timer=b9e7bed0
04 Compositor-1170  [001] ..s.   211.380621: timer_expire_entry: timer=b9e7bed0 function=process_timeout now=4294958435
05 Compositor-1170  [001] .ns.   211.380630: timer_expire_exit: timer=b9e7bed0

먼저 03번째 줄 로그를 볼까요?
03 Compositor-1170  [001] d.s.   211.380620: timer_cancel: timer=b9e7bed0

동적 타이머를 해제하는 동작입니다. 위 메시지로 다음과 같은 사실을 알 수 있습니다.

    동적 타이머 핸들러를 실행하기 전에 동적 타이머를 해제합니다.

이어서 동적 타이머 핸들러를 호출하는 04~05번째 줄 로그를 분석합니다.
04 Compositor-1170  [001] ..s.   211.380621: timer_expire_entry: timer=b9e7bed0 function=process_timeout now=4294958435
05 Compositor-1170  [001] .ns.   211.380630: timer_expire_exit: timer=b9e7bed0

04번째 줄 로그에서 다음 정보를 알 수 있습니다.
"timer=b9e7bed0" = 동적 타이머 struct timer_list 구조체 주소 
"function=process_timeout" = 동적 타이머 핸들러는 process_timeout() 
"now=4294958435" = 현재 jiffies 
 
이렇게 timer_expire_entry 이벤트는 동적 타이머 세부 정보를 출력합니다. 

이어서 05번째 줄 로그입니다.
05 Compositor-1170  [001] .ns.   211.380630: timer_expire_exit: timer=b9e7bed0

struct timer_list 구조체 주소가 b9e7bed0인 동적 타이머 핸들러 함수 실행이 종료됐다는 정보입니다.

이번 소절에서 분석한 타이머 ftrace 이벤트로 커널에서 동적 타이머 처리할 때 세부 정보를 알 수 있습니다.ftrace 로그와 로그를 출력하는 커널 코드를 함께 분석하면 커널 코드만 읽을 때 보다 훨씬 빨리 동적 타이머 작동 원리를 파악할 수 있습니다. 또한 ftrace 타이머 ftrace 이벤트는 실전 임베디드 리눅스 개발에서 바로 활용할 수 있습니다.

* 강의 동영상도 있으니 같이 들으시면 좋습니다.



#커널 시간관리 목차
커널 타이머 관리 주요 개념 소개
jiffies란
커널 타이머 제어
동적 타이머 초기화
동적 타이머 등록하기
동적 타이머는 누가 언제 실행하나?
라즈베리파이 커널 타이머 실습 및 로그 분석

"혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답글 올려드리겠습니다!"


# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2


 


핑백

덧글

댓글 입력 영역