Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

11206
629
98793


[라즈베리파이] 커널 타이머 - jiffies란 값은 누가 언제 증가하나 7장. 타이머관리

지금까지 jiffies는 1초에 진동수인 HZ 만큼 증감한다고 배웠습니다. HZ가 100이면 1초에 100번 jiffies는 증가할 것입니다. 여기서 한 가지 의문이 생깁니다.

    그러면 jiffies는 누가 언제 +1만큼 증감시킬까? 

이번 소절에서는 jiffies를 어느 함수에서 증감하는지 살펴보겠습니다. 분석할 함수 목록은 다음과 같습니다.
do_timer()
tick_do_update_jiffies64()

jiffies를 언제 +1만큼 증감하는지 확인하려면 do_timer() 함수를 분석할 필요가 있습니다. 
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/timekeeping.c]
1 void do_timer(unsigned long ticks)
2 {
3 jiffies_64 += ticks;
4 calc_global_load(ticks);
5}

3번째 줄 코드를 보면 ticks이란 인자를 jiffies_64가 저장한 값과 더해 jiffies_64에
 저장합니다.


3번째 줄 코드를 이해하기 쉽게 표현하면 다음과 같습니다.
jiffies_64 = jiffies_64 + ticks;

    그러면 do_timer() 함수는 어디서 호출할까요?

do_timer() 함수는 tick_do_update_jiffies64() 함수가 호출합니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/tick-sched.c]
1 static void tick_do_update_jiffies64(ktime_t now)
2 {
...
3 if (delta >= tick_period) {
4
5 delta = ktime_sub(delta, tick_period);
6 last_jiffies_update = ktime_add(last_jiffies_update,
...
7 do_timer(++ticks);

7번째 줄 코드와 같이 tick_do_update_jiffies64() 함수에서 +1만큼 증감한 ticks 인자로 do_timer() 함수를 호출합니다.

이론으로 라즈베리파이에서 HZ가 100이니 jiffies는 1초에 100번 증감합니다.

jiffies란 값이 실제 1초 안에 얼마나 증감하는지 실습하기
우리는 jiffise는 1초에 진동수인 HZ 만큼 증감한다고 배웠습니다. 라즈베리파이는 HZ가 100이니 1초에 100번 jiffies는 증감할 것입니다. 이번에는 라즈베리파이에서 jiffies가 1초에 100번 증감하는지 실습으로 확인해보는 시간을 갖겠습니다.

패치 코드를 소개합니다.  
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 }

먼저 패치 코드를 작성하는 방법을 소개하겠습니다.
위 코드에서 + 기호는 새롭게 추가하는 코드를 표현합니다. 그러니 do_timer() 함수 앞단에 코드 다음 2줄 코드만 입력하면 됩니다.
03 + trace_printk("[+]jiffies_64: %llu, caller:%pS \n", 
04 + jiffies_64, (void *)__builtin_return_address(0)); 

패치 코드 내용은 다음과 같습니다.
trace_printk() 함수로 do_timer() 함수가 호출될 때 ftrace 로그를 출력 
jiffies_64 변수를 출력하고 __builtin_return_address(0) 빌트인 매크로 함수를 써서 자신을 호출한 함수 정보 출력

위 코드를 컴파일해서 라즈베리파이에 설치 후 리부팅을 시켜봅시다. 기존에 했던 방식으로 ftrace 로그를 받아 봅시다. 

다음은 분석한 ftrace 로그입니다.
1 <idle>-0     [000] d...   228.989960: do_timer: [+]jiffies_64: 4294960195, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
2 <idle>-0     [000] d...   229.000074: do_timer: [+]jiffies_64: 4294960196, caller:tick_do_update_jiffies64.part.0+0xa0/0x180
...
3 ibus-x11-706   [003] d.h.   229.989991: do_timer: [+]jiffies_64: 4294960295, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 
4 <idle>-0     [003] d.h.   230.000012: do_timer: [+]jiffies_64: 4294960296, caller:tick_do_update_jiffies64.part.0+0xa0/0x180 

사실 위 ftrace 로그는 104줄인데 초가 바뀌는 부분만 복사한 것입니다. 

2번째 줄 로그를 보면 229.000074이라는 숫자가 보입니다. 이는 228초에서 229초로 처음 바뀌는 첫 타임스탬프입니다. HZ단위의 jiffies는 4294960196입니다.

이번에는 4번째 줄 로그를 봅시다. 230.000012 타임스탬프입니다. 229초에서 230초로 처음 바뀐 시각입니다. 오른쪽 로그를 보면 jiffies는 4294960296입니다. 정확히 100만큼 증가했음을 알 수 있습니다.

HZ가 100이면 1초 안에 jiffies가 100번 증감된다는 사실을 확인했습니다. 여러분도 라즈베리파이로 실습해보길 바랍니다.

do_timer() 함수 콜스택 확인해보기 
라즈베리파이에서 jiffies는 do_timer() 함수에서 1초에 100번 증감한다는 사실을 실습으로 확인했습니다. 이번에 do_timer() 함수는 누가 호출하는지 알아볼까요?

이를 위해 다음과 같이 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 do_timer  > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"

echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handle_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handle_exit/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"

위에서 보이는 코드를 입력한 후 do_timer_debug.sh 이름으로 저장합니다. 라즈베리파이 터미널에서 “./do_timer_debug.sh” 명령어로 이 스크립트를 실행하면 효율적으로 ftrace를 설정할 수 있습니다. 

설정 코드 중 중요한 부분만 살펴보겠습니다.  

다음은 do_timer() 함수 콜스택을 보기 위해 set_ftrace_filter 파일에 필터를 거는 명령어입니다.
echo do_timer  > /sys/kernel/debug/tracing/set_ftrace_filter

아래 명령어는 ftrace에서 타이머 인터럽트 발생을 확인하기 위해 다음 irq_handle_entry과 irq_handle_exit 이벤트를 키는 설정입니다. 
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handle_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handle_exit/enable
 
이번 실습에서는 커널 코드를 수정할 필요없이 위에서 소개한 방식으로 ftrace 설정 후 ftrace 로그만 받으면 됩니다. do_timer_debug.sh 셸 스크립트를 실행해 ftrace를 설정한 다음 10초 후에 ftrace를 받아볼까요?

분석할 ftrace 로그는 다음과 같습니다. 
01 <idle>-0     [001] d.h.   230.859933: irq_handler_entry: irq=162 name=arch_timer
02 <idle>-0     [000] d.h.   230.859943: do_timer <-tick_do_update_jiffies64.part.0
03 <idle>-0     [000] d.h.   230.859993: <stack trace>
04 => tick_sched_timer
05 => __hrtimer_run_queues
06 => hrtimer_interrupt
07 => arch_timer_handler_phys
08 => handle_percpu_devid_irq
09 => generic_handle_irq
10 => __handle_domain_irq
11 => bcm2836_arm_irqchip_handle_irq
12 => __irq_svc
13 => arch_cpu_idle
14 => arch_cpu_idle
15 => default_idle_call
16 => do_idle
17 => cpu_startup_entry
18 => rest_init
19 => start_kernel

먼저 01번째 줄 로그를 보겠습니다.
01 <idle>-0     [001] d.h.   230.859933: irq_handler_entry: irq=162 name=arch_timer

17번 arch_timer란 인터럽트가 발생했습니다.

02~19번째 줄 로그를 보면 함수들이 일렬로 늘어서 있습니다. 
이 중에 02~04번째 줄 로그를 보면 다음 순서로 함수 호출이 이루어지는 것을 볼 수 있습니다.
tick_sched_timer()
tick_do_update_jiffies64()
do_timer()

tick_sched_timer() 함수는 1초당 HZ 개수만큼 jiffies를 증감하는 역할을 하는 틱 디바이스 함수입니다. 틱 디바이스는 이 책의 범위를 벗어나므로 다루지는 않습니다. 

이번 소절에서는 jiffies가 1초에 얼만큼 증감하는지 알아봤습니다. 코드 상으로 HZ가 100인데 실제 1초에 100번 증감한다는 사실을 확인했습니다.

다음 절에서는 밀리초를 HZ 단위로 바꿔주는 msecs_to_jiffies() 함수를 소개합니다.

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

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



BR,
Guillermo Austin Kim, 07/30/2018

핑백

덧글

댓글 입력 영역