Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

80258
1323
114582


[리눅스커널] 스케줄링/디버깅: ftrace: 스케줄링 실행 시 콜스택 파악하기 - p 10. Process Scheduling

sched_switch와 sched_wakeup 이벤트는 각각 프로세스 스케줄링과 프로세스를 깨우는 동작을 트레이싱합니다. 이번에는 스케줄링이 실행할 때 콜스택을 점검해 보겠습니다.

커널에선 2가지 타입 스케줄링을 지원합니다.
 
[그림 10.48] 2가지 스케줄링 종류과 동작 방식

스케줄링 종류 별로 어떤 콜스택인지 점검합시다. 먼저 ftrace 설정을 위한 다음 코드를 소개합니다.
1 #!/bin/bash
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"

다음은 sched_switch와 sched_wakeup 이벤트를 설정하는 명령어입니다.
19 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
20 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable

이번에는 함수에 필터를 거는 명령어입니다.
29 echo  schedule ttwu_do_wakeup > /sys/kernel/debug/tracing/set_ftrace_filter

위 명령어로 schedule()와 ttwu_do_wakeup() 함수의 콜스택을 볼 수 있습니다.

다음 22~25번째 줄은 irq_handler_entry, irq_handler_exit 이벤트와 시스템 콜 이벤트를 키는 코드입니다.
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

위와 같이 인터럽트 동작 관련 이벤트와 시스템 콜 이벤트를 설정한 이유는, 인터럽트 핸들링과 시스템 콜 처리가 끝난 다음에 선점 스케줄링이 실행하기 때문입니다.

위 셸 스크립트를 sched_irq_syscall.sh 파일로 저장한 다음에 실행합시다.

셸 스크립트를 실행한 다음 20초 정도 방치합시다. 이후 get_ftrace.sh란 셸 스크립트 파일을 실행해서 ftrace 로그를 추출합시다.

명시적 스케줄링 시 콜스택 분석

이번에는 명시적 스케줄링을 실행할 때 콜스택을 보겠습니다.  

    명시적 스케줄링이란 무엇일까?

프로세스가 스스로 schedule() 함수를 호출해 스케줄링 하는 동작입니다. 비선점 스케줄링을 실행하는 함수 목록은 다음과 같습니다.
schedule_hrtimeout_range_clock()
schedule_timeout()
worker_thread()
__mutex_lock_common()

schedule_hrtimeout_range_clock() 함수 콜스택 분석하기

schedule_hrtimeout_range_clock() 함수 콜스택을 보면서 명시적 스케줄링 실행 시 함수 흐름을 살펴보겠습니다.

먼저 분석할 ftrace 로그는 다음과 같습니다.
1 lxterminal-840   [001] ....  8632.128798: schedule+0x10/0xa8 <-schedule_hrtimeout_range_clock+0xd8/0x14c
2 lxterminal-840   [001] ....  8632.128816: <stack trace>
3 => poll_schedule_timeout+0x54/0x84
4 => do_sys_poll+0x3d8/0x500
5 => sys_poll+0x74/0x114
6 => __sys_trace_return+0x0/0x10
7 lxterminal-840   [001] d...  8632.128827: sched_switch: prev_comm=lxterminal prev_pid=840 prev_prio=120 prev_state=D ==> next_comm=sched_basic.sh next_pid=1153 next_prio=120

위 로그에서 먼저 1번째 줄을 보면 다음 정보를 확인할 수 있습니다. 

    schedule_hrtimeout_range_clock() 함수에서 schedule() 함수를 호출한다.

콜스택으로 프로세스 스스로 schedule() 함수를 호출한다는 사실을 확인했습니다. 이 정보로 다음 사실을 알 수 있습니다.  

    프로세스 스스로 schedule() 함수를 호출해 명시적 스케줄링을 실행한다.

여기서 6~3번째 줄 로그가 함수 호출 방향입니다.

콜스택 다음에 바로 7 번째 줄과 같이 sched_switch 이벤트 메시지를 볼 수 있습니다. 이 메세지로 다음 사실을 알 수 있습니다. 

    "lxterminal" 프로세스에서 "sched_basic.sh" 프로세스로 스케줄링된다.

ftrace 로그를 봤으니 커널 코드를 보면서 실제 위와 같이 함수 호출이 이루어지는지 확인해볼까요?
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/time/hrtimer.c]
1 int __sched
2 schedule_hrtimeout_range_clock(ktime_t *expires, u64 delta,
3        const enum hrtimer_mode mode, int clock)
4 {
...
5 if (!expires) {
6 schedule();
7 return -EINTR;
8 }

위 schedule_hrtimeout_range_clock() 함수를 스케줄링 관점으로 해석하면 
지정한 시각이 지나면 타임아웃으로 명시적 스케줄링을 실행하는 동작입니다. 6번째 줄을 보면 schedule() 함수를 호출합니다.

schedule_timeout() 함수 콜스택 분석하기

이어서 schedule_timeout() 함수 콜스택을 분석하겠습니다. 
01 VCHIQ completio-1630  [002] ....  9447.646780: schedule+0x10/0xa8 <-schedule_timeout+0x1e0/0x418
02 VCHIQ completio-1630  [002] ....  9447.646829: <stack trace>
03 => down_interruptible+0x5c/0x68
04 => vchiq_ioctl+0x9d4/0x1950
05 => do_vfs_ioctl+0xb0/0x7d0
06 => sys_ioctl+0x44/0x6c
07 => __sys_trace_return+0x0/0x10
08 VCHIQ completio-1630  [002] d...  9447.646934: sched_switch: prev_comm=VCHIQ completio prev_pid=1630 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

위 로그에서 먼저 1번째 줄을 보면 다음 정보를 확인할 수 있습니다. 

    schedule_timeout() 함수에서 schedule() 함수를 호출한다.

이번에도 프로세스 스스로 schedule() 함수를 호출하는 정보를 확인했습니다. 이 정보를 토대로 우리는 사실을 알 수 있습니다.  

    프로세스 스스로 schedule() 함수를 호출해 명시적 스케줄링을 실행한다.

여기서 07~03번째 줄 로그가 함수 호출 방향입니다.

콜스택 다음에 바로 08 번째 줄과 같이 sched_switch 이벤트 메시지를 볼 수 있습니다. 이 메세지를 해석하면 다음과 같습니다.  

    "VCHIQ completio" 프로세스에서 "swapper/2" 프로세스로 스케줄링된다.

이번에는 ftrace에서 본 콜스택을 커널 함수에서 확인해보겠습니다. ftrace 로그 분석에서 그치지 말고 커널 코드를 열어 보면 더 많은 것을 얻을 수 있습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/locking/semaphore.c]
01 static inline int __sched __down_common(struct semaphore *sem, long state,
02 long timeout)
03 {
...
04
05 for (;;) {
...
06 __set_current_state(state);
07 raw_spin_unlock_irq(&sem->lock);
08 timeout = schedule_timeout(timeout);

08번째 줄 코드와 같이 세마포어를 획득하는  __down_common() 함수에서 schedule_timeout() 함수를 호출하는 합니다. 이후 schedule_timeout() 함수를 호출하면 schedule() 함수를 호출하게 됩니다.

__mutex_lock_slowpath() 함수 콜스택 분석하기

이번에는 뮤텍스를 할당하는 과정에서 비선점 스케줄링을 수행하는 콜스택을 보겠습니다.
1  kworker/u16:19-23715 [003] ...1 21857.480423: schedule+0x10/0x9c <-schedule_preempt_disabled+0x18/0x2c
2  kworker/u16:19-23715 [003] ...1 21857.480427: <stack trace>
3  => __mutex_lock_slowpath+0x15c/0x39c
4  => mutex_lock+0x34/0x48
5  => clk_prepare_lock+0x48/0xd4
6  => clk_get_rate+0x24/0x90
7  => dev_get_cur_freq+0x28/0x70
8  => update_devfreq+0xa0/0x1d4
9  => devfreq_monitor+0x34/0x94
10 => process_one_work+0x184/0x480
11 => worker_thread+0x140/0x4b4
12 => kthread+0xf4/0x108
13 => ret_from_fork+0x10/0x50
14 <...>-23715 [003] d..2 21857.480468: sched_switch: prev_comm=kworker/u16:19 prev_pid=23715 prev_prio=120 prev_state=D ==> next_comm=swapper/3 next_pid=0 next_prio=120 

먼저 1~3번째 줄 로그를 보겠습니다.
1  kworker/u16:19-23715 [003] ...1 21857.480423: schedule+0x10/0x9c <-schedule_preempt_disabled+0x18/0x2c
2  kworker/u16:19-23715 [003] ...1 21857.480427: <stack trace>
3  => __mutex_lock_slowpath+0x15c/0x39c

1~3번째 줄에 보이는 함수는 다음과 같이 호출됩니다.
__mutex_lock_slowpath()
schedule_preempt_disabled()
schedule()

__mutex_lock_slowpath() 함수에서 schedule_preempt_disabled() 함수를 호출해 명시적 스케줄링을 실행하는 것입니다. 결국 schedule_preempt_disabled() 함수에서 schedule() 함수를 호출하기 때문입니다. 이번에도 프로세스 스스로 schedule() 함수를 호출해 명시적 스케줄링을 수행합니다.

다음 14번째 줄 메시지를 볼까요?
14 <...>-23715 [003] d..2 21857.480468: sched_switch: prev_comm=kworker/u16:19 prev_pid=23715 prev_prio=120 prev_state=D ==> next_comm=swapper/3 next_pid=0 next_prio=120 

kworker/u16:19 프로세스에서 swapper/3 프로세스로 스케줄링되는 동작입니다.

이렇게 뮤텍스를 획득하지 못한 프로세스는 자신을 TASK_UNINTERRUPTIBLE 상태로 바꾼 후 휴면에 진입합니다.

커널 스레드에서 schedule() 함수를 호출하는 패턴을 확인합시다.
1 kworker/u8:0-1128 [001] 8632.128947: schedule+0x10/0xa8 <-worker_thread+0x104/0x5f0
2 kworker/u8:0-1128 [001] 8632.128961: <stack trace>
3 => ret_from_fork+0x14/0x28
4 kworker/u8:0-1128  [001] d...  8632.128968: sched_switch: prev_comm=kworker/u8:0 prev_pid=1128 prev_prio=120 prev_state=R+ ==> next_comm=lxterminal next_pid=840 next_prio=120

ftrace 1 번째 메시지를 보면 worker_thread() 함수에서 schedule() 함수를 호출하는 콜스택을 확인할 수 있습니다.

워크를 처리하는 워커 스레드 핸들인 worker_thread() 함수 어느 코드에서 schedule() 함수를 호출할까요? 
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/workqueue.c]
1 static int worker_thread(void *__worker)
2 {
...
3 process_one_work(worker, work);
...
4 sleep:
5 worker_enter_idle(worker);
6 __set_current_state(TASK_IDLE);
7 spin_unlock_irq(&pool->lock);
8 schedule();
9 goto woke_up;
10 }

워크를 모두 처리한 다음에 8번째 줄 코드와 같이 워커 스레드는 schedule() 함수를 호출해 휴면에 진입합니다.

선점 스케줄링 시 콜스택 분석

프로세스가 자신의 의지에 상관없이 스케줄러에 의해 CPU를 비우는 스케줄링 방식을 선점 스케줄링이라고 합니다. 이번에는 선점 스케줄링 동작 시 콜스택을 ftrace로 확인하겠습니다.

분석할 ftrace 로그는 다음과 같습니다.
1  chromium-browse-1436  [000] d.h.  9448.149965: irq_handler_entry: irq=92 name=mmc1
2  chromium-browse-1436  [000] d.h.  9448.149972: irq_handler_exit: irq=92 ret=handled
3  chromium-browse-1436  [000] d.h.  9448.149982: ttwu_do_wakeup+0x10/0x1a4 <-ttwu_do_activate+0x80/0x84
4  chromium-browse-1436  [000] d.h.  9448.150003: <stack trace>
5  => wake_up_process+0x20/0x24
6  => __irq_wake_thread+0x70/0x74
7  => __handle_irq_event_percpu+0x84/0x224
8  => handle_irq_event_percpu+0x2c/0x68
9  => handle_irq_event+0x54/0x78
10 => handle_level_irq+0xb4/0x160
11 => generic_handle_irq+0x34/0x44
12 => bcm2836_chained_handle_irq+0x38/0x50
13 => generic_handle_irq+0x34/0x44
14 => __handle_domain_irq+0x6c/0xc4
15 => bcm2836_arm_irqchip_handle_irq+0xac/0xb0
16 => __irq_usr+0x4c/0x60
17 => 0x4228e4c
18 chromium-browse-1436  [000] dnh.  9448.150005: sched_wakeup: comm=irq/92-mmc1 pid=65 prio=49 target_cpu=000
19 chromium-browse-1436  [000] dn..  9448.150010: schedule+0x10/0xa8 <-do_work_pending+0x38/0xcc
20 chromium-browse-1436  [000] dn..  9448.150016: <stack trace>
21 chromium-browse-1436  [000] d...  9448.150028: sched_switch: prev_comm=chromium-browse prev_pid=1436 prev_prio=120 prev_state=S ==> next_comm=irq/92-mmc1 next_pid=65 next_prio=49

조금 복잡해 보이는 로그의 실행 흐름은 다음과 같이 분류할 수 있습니다. 

1단계: 인터럽트 발생(01~02번째 줄)
92번 mmc1 인터럽트가 발생한 후 인터럽트 핸들러가 실행됐습니다.

2단계: IRQ 스레드를 깨움(03~18번째 줄)
인터럽트 핸들러에서 IRQ_WAKE_THREAD 을 반환해 등록한 IRQ 스레드를 깨웁니다.

3 단계 선점 스케줄링 실행(19~21번째 줄)
인터럽트 핸들링을 마무리 한 다음에 선점 스케줄링을 실행합니다.

4단계 IRQ 스레드 실행(19~21번째 줄)
바로 IRQ 스레드가 실행을 시작합니다.

1단계 인터럽트 발생 로그를 보겠습니다.
1  chromium-browse-1436  [000] d.h.  9448.149965: irq_handler_entry: irq=92 name=mmc1
2  chromium-browse-1436  [000] d.h.  9448.149972: irq_handler_exit: irq=92 ret=handled

1~2 번째 줄 로그를 보면 92번 mmc1 인터럽트가 발생한 동작을 확인할 수 있습니다. 

다음 2단계로 IRQ 스레드를 깨우는 로그를 보겠습니다.
3  chromium-browse-1436  [000] d.h.  9448.149982: ttwu_do_wakeup+0x10/0x1a4 <-ttwu_do_activate+0x80/0x84
4  chromium-browse-1436  [000] d.h.  9448.150003: <stack trace>
5  => wake_up_process+0x20/0x24
6  => __irq_wake_thread+0x70/0x74
7  => __handle_irq_event_percpu+0x84/0x224
8  => handle_irq_event_percpu+0x2c/0x68
9  => handle_irq_event+0x54/0x78
10 => handle_level_irq+0xb4/0x160
11 => generic_handle_irq+0x34/0x44
12 => bcm2836_chained_handle_irq+0x38/0x50
13 => generic_handle_irq+0x34/0x44
14 => __handle_domain_irq+0x6c/0xc4
15 => bcm2836_arm_irqchip_handle_irq+0xac/0xb0
16 => __irq_usr+0x4c/0x60
17 => 0x4228e4c

7 번째 줄 로그를 보면 __handle_irq_event_percpu() 함수에서 __irq_wake_thread() 함수를 호출해서 IRQ 스레드를 깨웁니다. 

함수 호출 흐름 다음에 보이는 sched_wakeup 이벤트 로그로 irq/92-mmc1 IRQ 스레드를 깨우는 동작을 확인할 수 있습니다.
18 chromium-browse-1436  [000] dnh.  9448.150005: sched_wakeup: comm=irq/92-mmc1 pid=65 prio=49 target_cpu=000

18 번째 줄 로그에서 놓치지 말아야 할 메시지는 ‘9448.150005’ 타임 스탬프 왼쪽에 있는 "dnh" 텍스트입니다. 이는 다음 사실을 알려줍니다. 

    이 중 h란 텍스트는 인터럽트 컨텍스트를 의미합니다.


필자가 92번 mmc1 인터럽트 핸들러가 IRQ_WAKE_THREAD 매크로를 반환해서 IRQ 스레드를 깨웠다고 해석했습니다. 

그 근거는 무엇일까요? 이해를 돕기 위해 소스 코드를 보겠습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/irq/handle.c]
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);
9
...
10 switch (res) {
11 case IRQ_WAKE_THREAD:
...
12 __irq_wake_thread(desc, action);

7 번째 줄 코드를 보겠습니다.
인터럽트 핸들러를 실행한 후 반환값을 res에 저장합니다.

다음 10 번째 줄 코드를 보면 switch/case 문을 실행하는데 res가 IRQ_WAKE_THREAD를 저장하기 때문에 __irq_wake_thread() 함수를 호출하는 것입니다.

물론 ftrace 로그에서 92번 인터럽트 핸들러가 실행했고 IRQ_WAKE_THREAD를 반환했다는 직접적인 메시지를 확인할 수는 없습니다. 하지만 ftrace 로그를 출력하는 코드 흐름을 이해하면 로그에서 출력하지 않는 동작도 머리로 떠올릴 수 있습니다.


다음 분석할 ftrace 로그는 3 단계인 선점 스케줄링 동작입니다. 
19 chromium-browse-1436  [000] dn..  9448.150010: schedule+0x10/0xa8 <-do_work_pending+0x38/0xcc
20 chromium-browse-1436  [000] dn..  9448.150016: <stack trace>
21 chromium-browse-1436  [000] d...  9448.150028: sched_switch: prev_comm=chromium-browse prev_pid=1436 prev_prio=120 prev_state=S ==> next_comm=irq/92-mmc1 next_pid=65 next_prio=49

19~20 번째 줄 로그를 보면 난데 없이 do_work_pending 함수에서 schedule() 함수를 호출했습니다. 조금 더 세밀하게 레이블 동작 흐름을 나열하면 다음과 같습니다.
__irq_usr()
ret_to_user_from_irq()
slow_work_pending()
do_work_pending()
schedule()

__irq_usr 이란 인터럽트 벡터에서 인터럽트 핸들링을 마무리한 다음 선점 스케줄링 조건을 점검합니다. 이전 소절에 다룬 내용을 떠올려 이 로그를 해석해볼까요? 

    현재 실행 중인 chromium-browse(pid:1436) 프로세스 struct thread_info 구조체 
    flags 값을 보고 선점 스케줄링할 조건인지 확인한다. 

프로세스 struct thread_info 구조체 preempt_count필드가 0이고 flags가 TIF_NEED_RESCHED(2) 이면 slow_work_pending(), do_work_pendig() 함수 그리고 schedule() 함수를 실행해서 선점 스케줄링을 실행 하는 것입니다.

다음 21 번째 줄 로그를 보면 바로 선점 스케줄링 동작을 확인할 수 있습니다.
21 chromium-browse-1436  [000] d...  9448.150028: sched_switch: prev_comm=chromium-browse prev_pid=1436 prev_prio=120 prev_state=S ==> next_comm=irq/92-mmc1 next_pid=65 next_prio=49

chromium-browse(pid:1436) 프로세스에서 irq/92-mmc1 프로세스로 컨텍스트 스위칭되는 것입니다.

21 번째 줄 로그를 유심히 보면 irq/92-mmc1 프로세스의 우선순위는 49임을 알 수 있습니다. 0~99 사이 우선순위 프로세스는 RT 클래스 스케줄러에서 실행한다고 유추할 수 있습니다.


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

Thanks,
Austin Kim(austindh.kim@gmail.com)

Reference(프로세스 스케줄링)

스케줄링 소개
프로세스 상태 관리
   어떤 함수가 프로세스 상태를 바꿀까?
스케줄러 클래스
런큐
CFS 스케줄러
   CFS 관련 세부 함수 분석  
선점 스케줄링(Preemptive Scheduling)   
프로세스는 어떻게 깨울까?
스케줄링 핵심 schedule() 함수 분석
컨택스트 스위칭
스케줄링 디버깅
   스케줄링 프로파일링
     CPU에 부하를 주는 테스트   
     CPU에 부하를 주지 않는 테스트




핑백

덧글

댓글 입력 영역