Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

71261
1501
219113


[리눅스커널][ftrace] 커널 타이머: jiffies와 Soft IRQ 타이머 서비스 처리 횟수 확인 8. 커널 타이머 관리

Overview

ftrace는 리눅스 커널의 마법과 같은 도구입니다. 그래픽 효과가 없는 텍스트 포멧의 리눅스의 단점을 대체하기 충분하다고 봅니다. 이번에는 동적 타이머와 Soft IRQ 타이머 서비스를 동시에 ftrace 로그를 통해 분석해 보겠습니다. 

이 디버깅은 라즈베리 파이에서 수행했다는 사실을 참고합시다.

결론

먼저, 요점부터 말하겠습니다. 이 ftrace 메시지를 분석한 후 알게 될 내용은 다음과 같습니다.

 ■ 1초 동안에 지피스는 100번 업데이트된다.(라즈베리 파이 기준) 
 ■ 1초에 Soft IRQ 타이머 서비스를 요청하는 횟수는 13번(100번 미만)이다.  
 ■ 1초에 Soft IRQ 동적 타이머를 실행하는 횟수는 13번이다.  

먼저 커널 코드를 수정하는 방법을 알아보겠습니다.

커널 코드 수정하기

간단히 커널 코드를 수정해 봅시다. 패치 코드의 목적은 jiffies_64 변수를 확인하려는 의도입니다.

다음은 패치 코드입니다.

diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -2194,11 +2194,17 @@ struct timespec64 get_monotonic_coarse64(void)
}
EXPORT_SYMBOL(get_monotonic_coarse64);
/*
* Must hold jiffies_lock
*/
01 void do_timer(unsigned long ticks)
02 {
03 +  trace_printk("[+]jiffies_64: %llu, caller:%pS \n",
04 +  jiffies_64, (void *)__builtin_return_address(0));
05 +
06  jiffies_64 += ticks;
07  calc_global_load(ticks);
08 }

위 코드를 반영한 후 라즈베리 파이나 리눅스 타겟 디바이스에 빌드한 후 설치합시다. 
(리눅스 커널 코드를 라즈베리 파이에서 빌드하고 설치하는 방법은 아래 링크를 참고합시다.)
http://rousalome.egloos.com/10011640

이어서 ftrace 로그를 설정하는 방법을 알아봅시다.

ftrace 로그 설정하기

다음은 ftrace 로그를 설정하는 셸 스크립트 코드입니다.

1 #!/bin/bash
3 echo 0 > /sys/kernel/debug/tracing/tracing_on
4 sleep 1
5 echo "tracing_off" 
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/irq/irq_handler_entry/enable
20 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
21 echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_raise/enable
22 echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_entry/enable
23 echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_exit/enable
24 echo 1 > /sys/kernel/debug/tracing/events/timer/timer_expire_entry/enable
25 echo 1 > /sys/kernel/debug/tracing/events/timer/timer_expire_exit/enable
26 sleep 1
27 echo "event enabled"
28
29 echo secondary_start_kernel > /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"

위 명령어 중 핵심은 다음 코드 조각입니다. 

19 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
20 echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
21 echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_raise/enable
22 echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_entry/enable
23 echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_exit/enable
24 echo 1 > /sys/kernel/debug/tracing/events/timer/timer_expire_entry/enable
25 echo 1 > /sys/kernel/debug/tracing/events/timer/timer_expire_exit/enable

각 ftrace 이벤트는 다음과 같은 동작을 트레이싱합니다. 

 ■ 19~20번째 줄: 인터럽트 핸들러를 실행하는 동작과 완료 시점을 트레이싱
 ■ 21~23번째 줄: Soft IRQ 서비스를 요청하고 실행하는 동작을 트레이싱
 ■ 24~25번째 줄: 동적 타이머를 실행하고 완료하는 시점을 트레이싱

ftrace 를 설정하고 10초 후에 ftrace 로그를 추출합시다.

ftrace 로그 확인하기

이제 ftrace 로그를 분석할 차례입니다. ftrace 로그에서 946~945초 구간의 로그만 복사해서 1_part 폴더에 1_part_log.log로 저장하겠습니다. 1초 동안 커널 내부에서 어떤 동작을 하는지 점검하기 위해서입니다.

jiffies_64 변수가 증가되는 횟수 확인하기

'egrep -nr jiffies_64 *' 명령어를 입력해 1초 동안 jiffies_64 변수, 즉 지피스가 +1만큼 증가되는 횟수를 확인해 보겠습니다.

다음은  'egrep -nr jiffies_64 *' 명령어를 입력한 후 출력 결과입니다. (참고로 이 출력 결과는 라즈베리 파이에서 확인했습니다.)

root@raspberrypi:/home/pi/last_practice/0418_20_timer/1_part# egrep -nr jiffies_64 *
1:          <idle>-0     [000] d...   945.997917: do_timer+0x3c/0x84: [+]jiffies_64: 4295031895, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
63:          <idle>-0     [002] d.h.   946.007832: do_timer+0x3c/0x84: [+]jiffies_64: 4295031896, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
124:          <idle>-0     [000] d...   946.017917: do_timer+0x3c/0x84: [+]jiffies_64: 4295031897, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
...
5491:          <idle>-0     [003] d...   946.967824: do_timer+0x3c/0x84: [+]jiffies_64: 4295031992, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
5553:          <idle>-0     [000] d...   946.977917: do_timer+0x3c/0x84: [+]jiffies_64: 4295031993, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
5602:          <idle>-0     [000] d...   946.987917: do_timer+0x3c/0x84: [+]jiffies_64: 4295031994, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
5651:          <idle>-0     [000] d...   946.997917: do_timer+0x3c/0x84: [+]jiffies_64: 4295031995, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 

출력 결과가 많아 복잡해 보이니 리눅스에서 제공하는 'wc -l' 명령어를 활용해 출력 횟수를 확인해 봅시다.

다음은 'egrep -nr jiffies_64 * | wc -l' 명령어를 입력한 후 출력 결과입니다.

root@raspberrypi:/home/pi/last_practice/0418_20_timer/1_part# egrep -nr jiffies_64 * | wc -l
100

1초에 100번 jiffies_64 변수는 업데이트된다는 사실을 알 수 있습니다. 이로써 라즈비안 커널의 HZ는 100이란 사실을 유추할 수 있습니다.

Soft IRQ의 타이머 서비스를 요청하는 횟수

이번에는 1초 동안에 Soft IRQ의 타이머 서비스를 요청하는 횟수를 확인합시다.

아래 메시지는 'egrep -nr "softirq_raise: vec=1" *' 명령어를 입력한 후 출력 결과입니다.

root@raspberrypi:/home/pi/last_practice/0418_20_timer/1_part# egrep -nr "softirq_raise: vec=1" *
64:          <idle>-0     [002] d.h.   946.007839: softirq_raise: vec=1 [action=TIMER]
456:          <idle>-0     [002] d.h.   946.077837: softirq_raise: vec=1 [action=TIMER]
1329:          <idle>-0     [002] d.h.   946.237837: softirq_raise: vec=1 [action=TIMER]
1536:          <idle>-0     [002] d.h.   946.257837: softirq_raise: vec=1 [action=TIMER]
2896:          <idle>-0     [002] d.h.   946.507837: softirq_raise: vec=1 [action=TIMER]
4254:          <idle>-0     [002] d.h.   946.757836: softirq_raise: vec=1 [action=TIMER]
4487:          <idle>-0     [002] d.h.   946.797835: softirq_raise: vec=1 [action=TIMER]
5214:          <idle>-0     [002] d.h.   946.927870: softirq_raise: vec=1 [action=TIMER]
5286:          <idle>-0     [002] d.h.   946.937837: softirq_raise: vec=1 [action=TIMER]
5334:          <idle>-0     [002] d.h.   946.947828: softirq_raise: vec=1 [action=TIMER]
5338:          <idle>-0     [003] d.h.   946.947837: softirq_raise: vec=1 [action=TIMER]
5419:          <idle>-0     [002] d.h.   946.957834: softirq_raise: vec=1 [action=TIMER]
5493:          <idle>-0     [003] d.h.   946.967834: softirq_raise: vec=1 [action=TIMER]

1초에 13번 Soft IRQ의 타이머 서비스를 요청했음을 알 수 있습니다.
ftrace 메시지에서 보이는 'd.h.'로 보아 다음과 같은 사실을 유추할 수 있습니다.

 ■ IRQ를 비활성화했다. 
 ■ 인터럽트 컨텍스트이다. 

이어서 동적 타이머를 처리하는 횟수를 확인해 봅시다. 
밥을 먹으면 반찬을 먹듯이 Soft IRQ의 타이머 서비스를 요청한 동작을 점검했으면 당연히
동적 타이머를 처리하는 결과를 확인할 필요가 있습니다.

Soft IRQ 내에서 동적 타이머를 처리하는 횟수

이어서 Soft IRQ 서비스를 통해 동적 타이머가 호출되는 횟수를 점검하겠습니다.

아래 출력 결과는 'egrep -nr timer_expire_entry *' 명령어를 입력한 후 출력되는 결과입니다.

root@raspberrypi:/home/pi/last_practice/0418_20_timer/1_part# egrep -nr timer_expire_entry *
69:          <idle>-0     [002] ..s.   946.007856: timer_expire_entry: timer=5990d55c function=rh_timer_func now=64601
461:          <idle>-0     [002] d.s.   946.077854: timer_expire_entry: timer=e48e8a8b function=delayed_work_timer_fn now=64608
1334:          <idle>-0     [002] d.s.   946.237853: timer_expire_entry: timer=716f13cf function=delayed_work_timer_fn now=64624
1541:          <idle>-0     [002] ..s.   946.257852: timer_expire_entry: timer=5990d55c function=rh_timer_func now=64626
2901:          <idle>-0     [002] ..s.   946.507853: timer_expire_entry: timer=5990d55c function=rh_timer_func now=64651
4259:          <idle>-0     [002] ..s.   946.757855: timer_expire_entry: timer=5990d55c function=rh_timer_func now=64676
4492:          <idle>-0     [002] d.s.   946.797851: timer_expire_entry: timer=89cc0e1b function=delayed_work_timer_fn now=64680
5347:          <idle>-0     [003] ..s.   946.947855: timer_expire_entry: timer=4e2e6888 function=process_timeout now=64695
5424:          <idle>-0     [002] ..s.   946.957850: timer_expire_entry: timer=c29ab9c3 function=pm_suspend_timer_fn now=64696
5498:          <idle>-0     [003] ..s.   946.967850: timer_expire_entry: timer=4e2e6888 function=process_timeout now=64697

ftrace 메시지에서 보이는 '..s.'와 'd.s.'는 다음과 같이 해석할 수 있습니다.

 ■ Soft IRQ 컨텍스트이다.

Soft IRQ의 타이머 서비스를 요청했으니 이제 해당하는 동적 타이머가 실행됐음을 알 수 있습니다. 

ftrace 로그에서 각 이벤트 별 콜 스택을 확인하기

이번에는 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 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
#echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable

#echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
#echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_raise/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_entry/enable
#echo 1 > /sys/kernel/debug/tracing/events/irq/softirq_exit/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/raw_syscalls/enable
sleep 1
echo "event enabled"

echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter

sleep 1
echo "set_ftrace_filter enabled"

echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo 1 > /sys/kernel/debug/tracing/options/stacktrace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"

echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"

위 명령어에서 ftrace의 이벤트가 출력될 때 콜 스택을 출력하도록 설정하는 명령어는 다음과 같습니다.

echo 1 > /sys/kernel/debug/tracing/options/stacktrace

softirq_raise 이벤트의 콜 스택 확인하기 

다음은 ftrace의 softirq_raise 이벤트가 출력될 때의 콜 스택입니다.

<idle>-0     [000] d.h.  2391.588912: softirq_raise: vec=1 [action=TIMER]
<idle>-0     [001] d.h.  2391.588913: do_timer+0x3c/0x84: [+]jiffies_64: 4295176453, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
          <idle>-0     [001] d.h.  2391.588981: <stack trace>
 => __hrtimer_run_queues+0x17c/0x344
 => hrtimer_interrupt+0x130/0x2a8
 => arch_timer_handler_phys+0x40/0x48
 => handle_percpu_devid_irq+0x88/0x23c
 => generic_handle_irq+0x34/0x44
 => __handle_domain_irq+0x6c/0xc4
 => bcm2836_arm_irqchip_handle_irq+0x60/0xa8
 => __irq_svc+0x5c/0x7c
 => arch_cpu_idle+0x34/0x4c
 => arch_cpu_idle+0x34/0x4c
 => default_idle_call+0x34/0x48
 => do_idle+0xf0/0x17c
 => cpu_startup_entry+0x28/0x2c
 => secondary_start_kernel+0x164/0x170
 => 0x10264c

위 ftrace 메시지에서 주요 로그 조각을 해석해봅시다. 

 ■ __irq_svc+0x5c/0x7c: 인터럽트 벡터가 호출됐으니 인터럽트가 실행됐다.
 ■ softirq_raise: vec=1 [action=TIMER]: Soft IRQ의 TIMER 서비스를 요청했다.


softirq_entry와 timer_expire_entry 이벤트의 콜 스택 확인하기

다음은 softirq_entry와 timer_expire_entry 이벤트의 콜 스택입니다. 

<idle>-0     [000] ..s.  2391.589105: timer_expire_entry: timer=4e2e6888 function=process_timeout now=209158
<idle>-0     [001] ..s.  2391.589112: softirq_entry: vec=1 [action=TIMER]
<idle>-0     [000] ..s.  2391.589131: <stack trace>
 => call_timer_fn+0x148/0x198
 => expire_timers+0xec/0x14c
 => run_timer_softirq+0xb8/0x1ec
 => __do_softirq+0x184/0x3d0
 => irq_exit+0xf4/0x120
 => __handle_domain_irq+0x70/0xc4
 => bcm2836_arm_irqchip_handle_irq+0x60/0xa8
 => __irq_svc+0x5c/0x7c
 => arch_cpu_idle+0x34/0x4c
 => arch_cpu_idle+0x34/0x4c
 => default_idle_call+0x34/0x48
 => do_idle+0xf0/0x17c
 => cpu_startup_entry+0x28/0x2c
 => rest_init+0xc0/0xc4
 => start_kernel+0x490/0x4b8
          <idle>-0     [001] ..s.  2391.589132: <stack trace>
 => __do_softirq+0x284/0x3d0
 => irq_exit+0xf4/0x120
 => __handle_domain_irq+0x70/0xc4
 => bcm2836_arm_irqchip_handle_irq+0x60/0xa8
 => __irq_svc+0x5c/0x7c
 => arch_cpu_idle+0x34/0x4c
 => arch_cpu_idle+0x34/0x4c
 => default_idle_call+0x34/0x48
 => do_idle+0xf0/0x17c
 => cpu_startup_entry+0x28/0x2c
 => secondary_start_kernel+0x164/0x170
 => 0x10264c

ftrace 메시지에서 '..s.' 부분으로 모두 Soft IRQ 컨텍스트에서 콜 스택이 출력됐음을 알 수 있습니다.

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


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

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

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





덧글

댓글 입력 영역