Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

98258
1323
114600


[리눅스커널] 스케줄링: 스케줄링/디버깅: ftrace: sched_switch와 sched_wakeup 이벤트 소개 - p 10. Process Scheduling

리눅스 커널 ftrace 에서 sched_switch와 sched_wakeup 이벤트를 지원합니다. 각각 이벤트에 대해 소개하고 메시지를 분석하는 방법을 살펴보겠습니다.


리눅스 커널의 프로세스 동작을 처음 접하는 분들이 겪는 어려움이 있습니다. 실제 리눅스 시스템에서 얼마나 자주 프로세스가 스케줄링 되는지 확인할 수 없다는 것입니다. 그 이유는 간단합니다. 

    코드를 분석한 내용을 실제 리눅스 시스템에서 확인하지 않기 때문입니다. 

그래서 임베디드 리눅스를 개발할 때 모듈이나 드라이버 코드가 실행할 때 어떤 프로세스가 어떻게 스케줄링 되는지 확인하기도 어렵습니다.

리눅스 커널에서는 이런 의문을 해소시킬 수 있는 디버깅 기능을 지원합니다. 바로 ftrace입니다. ftrace 에는 프로세스 스케줄링 관련 동작을 트레이싱 할 수 있는 이벤트들이 준비돼 있습니다.
sched_switch
sched_wakeup


sched_switch, sched_wakeup 이벤트를 중심으로 리눅스 시스템에서 얼마나 자주 프로세스를 깨우고 스케줄링 하는지 점검합시다.
 
[그림 10.44] ftrace: sched_switch와 sched_wakeup 이벤트 소개 

위 그림에서 보이듯 sched_switch와 sched_wakeup 이벤트는 커널의 다음 동작을 트레이싱합니다.
sched_switch: 프로세스 스케줄링
sched_wakeup: 프로세스를 깨우기 동작

sched_switch와 sched_wakeup 이벤트를 키는 방법 알아보기

ftrace 메시지를 분석하는 방법을 소개하기 전에 ftrace sched_switch와 sched_wakeup 이벤트를 키는 방법부터 소개하겠습니다.

먼저 다음 명령어를 같이 볼까요? 
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 nop > /sys/kernel/debug/tracing/current_tracer
12 sleep 1
13 echo "nop tracer enabled"
14
15 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
16 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
17 sleep 1
18 echo "event enabled"
19
20 echo 1 > /sys/kernel/debug/tracing/tracing_on
21 echo "tracing_on"

위 명령어 중 sched_switch와 sched_wakeup 이벤트를 키는 부분은 다음과 같습니다.
15 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
16 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable

위 셸 스크립트 코드를 sched_basic.sh 이란 이름으로 저장합니다. 이 후 다음 명령어를 입력해서 sched_basic.sh 스크립트를 실행하면 효율적으로 ftrace를 설정할 수 있습니다. 
root@raspberrypi:/home/pi# ./sched_basic.sh

셸 스크립트를 실행한 다음 10초 동안 기다립니다. 이때 라즈베리파이에서 특별히 브라우저나 다른 프로그램을 실행할 필요는 없습니다. 

10초가 지난 후 ftrace 로그를 추출합시다.
이를 위해 다음과 같은 스크립트를 작성한 후 get_ftrace.sh 이름으로 저장합시다.
#!/bin/bash

echo 0 > /sys/kernel/debug/tracing/tracing_on
echo "ftrace off"

sleep 3

cp /sys/kernel/debug/tracing/trace . 
mv trace ftrace_log.c

위 셸 스크립트를 실행하면 ftrace_log.c 파일이 생성됩니다. 이 파일이 ftrace 로그를 저장하고 있는 것입니다.

sched_switch와 sched_wakeup 이벤트 메시지 분석하기

먼저 ftrace 로그에서 sched_switch 이벤트 메시지를 소개합니다.
kworker/2:1-1106  [002] d...  7831.602384: sched_switch: prev_comm=kworker/2:1 prev_pid=1106 prev_prio=120 prev_state=T ==> next_comm=ksoftirqd/2 next_pid=19 next_prio=120

sched_switch 이벤트 로그는 대부분 위와 같은 패턴으로 프로세스 스케줄링 동작을 표현합니다.

이제 ftrace 로그의 의미를 차근차근 분석해볼까요? 
 
[그림 10.45] ftrace 로그 prev와 next 메시지의 의미

sched_switch 메시지 세부 내용은 다음과 같습니다.
 
[그림 10.46] ftrace: sched_switch 이벤트 메시지 세부 내용
 


여기서 다음과 같은 의문이 생깁니다.

    ftrace sched_switch 이벤트를 메시지 포멧을 어디서 확인할 수 있을까?

sched_switch 이벤트를 출력하는 포멧은 다음 해더 파일에서 확인할 수 있습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/include/trace/events/sched.h]
01 TRACE_EVENT(sched_switch,
02
03 TP_PROTO(bool preempt,
04 struct task_struct *prev,
05 struct task_struct *next),
...
06 TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d",
07 __entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
08
09 (__entry->prev_state & (TASK_REPORT_MAX - 1)) ?
10   __print_flags(__entry->prev_state & (TASK_REPORT_MAX - 1), "|",
11 { 0x01, "S" }, { 0x02, "D" }, { 0x04, "T" },
12 { 0x08, "t" }, { 0x10, "X" }, { 0x20, "Z" },
13 { 0x40, "P" }, { 0x80, "I" }) :
14   "R",
15
16 __entry->prev_state & TASK_REPORT_MAX ? "+" : "",
17 __entry->next_comm, __entry->next_pid, __entry->next_prio)
18 );

prev 프로세스와 next 프로세스의 태스트 디스크립터를 읽어서 각각 필드를 출력하는 것입니다.

이 중에 프로세스 상태를 출력하는 포멧은 다음 코드입니다.
09 (__entry->prev_state & (TASK_REPORT_MAX - 1)) ?
10   __print_flags(__entry->prev_state & (TASK_REPORT_MAX - 1), "|",
11 { 0x01, "S" }, { 0x02, "D" }, { 0x04, "T" },
12 { 0x08, "t" }, { 0x10, "X" }, { 0x20, "Z" },
13 { 0x40, "P" }, { 0x80, "I" }) :

프로세스 태스크 디스크립터 state 필드 값을 읽어서 알파벳으로 출력하는 것입니다.
각 알파벳은 다음 상태 정보에 매핑할 수 있습니다.
 
[그림 10.47] ftrace: 프로세스 상태 메시지와 프로세스 상태 코드 관계


먼저 가장 왼쪽 부분에 있는 "kworker/2:1-1106" 메시지를 보겠습니다.
kworker/2:1-1106  [002] d...  7831.602384

ftrace 로그를 실행하는 프로세스 정보입니다.  

    프로세스 이름은 "kworker/2:1" 이고 PID는 1106입니다. 

프로세스 이름으로 보아 워크를 처리하는 워커 스레드임을 알 수 있습니다. 또한 실행 중인 CPU 번호는 2이고 타임스탬프는 7831.602384입니다.

다음 메시지는 스케줄링 되기 전 실행했던 프로세스 정보를 출력합니다.
prev_comm=kworker/2:1 prev_pid=1106 prev_prio=120 prev_state=T

"prev_state=T" 메시지로 보아 프로세스 상태가 __TASK_STOPPED 임을 알 수 있습니다.

분석 내용을 요약하면 스케줄링으로 CPU를 비울 prev 프로세스 정보는 다음과 같습니다. 

    프로세스 이름은 "kworker/2:1" 이고 PID는 1106입니다. 또한 프로세스 우선순위가 
      120이고 프로세스 상태는 T이다.

다음은 스케줄링 동작으로 다음에 실행될 프로세스 정보입니다.
next_comm=ksoftirqd/2 next_pid=19 next_prio=120

프로세스 이름은 "ksoftirqd/2" 이고 PID는 19입니다. 또한 프로세스 우선순위가 120입니다.

정리하면 "kworker/2:1" 프로세스에서 "ksoftirqd/2" 프로세스로 스케줄링하는 동작을 출력하는 메시지입니다.

다음 sched_wakeup 이벤트 로그를 소개합니다. 
1 lxpanel-718 [002] d... 7831.739767: sched_wakeup: comm=Xorg pid=552 prio=120 target_cpu=002
2 lxpanel-718   [002] d...  7831.739824: sched_switch: prev_comm=lxpanel prev_pid=718 prev_prio=120 prev_state=D ==> next_comm=Xorg next_pid=552 next_prio=120


1 번째 줄 메시지가 sched_wakeup 이벤트인데 2 번째 줄에 sched_switch 이벤트를 추가했습니다. sched_wakeup 이벤트는 sched_switch 이벤트와 같이 분석하는 경우가 많기 때문입니다.


먼저 1 번째 줄 메시지를 봅시다.
1 lxpanel-718 [002] d... 7831.739767: sched_wakeup: comm=Xorg pid=552 prio=120 target_cpu=002

위 메시지는 다음 사실을 말해줍니다. 

    PID가 552 이고 우선순위가 120인 "Xorg" 프로세스를 깨우는 동작입니다.

여기서 "Xorg" 프로세스를 누가 깨울까요? ftrace 로그에서 가장 왼쪽에 있는 부분이 현재 코드를 실행하는 프로세스 정보입니다.  

    "Xorg" 프로세스는 lxpanel(pid: 718) 프로세스가 깨웁니다.

이 메시지로 프로세스는 자신을 깨울 수 없다는 사실을 파악할 수 있습니다.

ftrace로 sched_switch/sched_wakeup 이벤트 로그에 대해 알아봤으니 이번에 sched_switch/sched_wakeup 이벤트 로그를 출력하는 리눅스 커널 코드를 살펴봅시다.

sched_switch와 sched_wakeup 이벤트 출력 함수 분석하기

ftrace 메시지를 보면 그 내용을 해석하면서 해당 ftrace 이벤트를 메시지를 커널 어느 코드에서 출력하는지 확인하면 더 많은 것을 배울 수 있습니다. sched_switch 이벤트 로그를 출력하는 코드를 확인해볼까요? 
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/sched/core.c]
1 static void __sched notrace __schedule(bool preempt)
2 {
3 struct task_struct *prev, *next;
...
4
5 if (likely(prev != next)) {
6 rq->nr_switches++;
7 rq->curr = next;
8
9 ++*switch_count;
10
11 trace_sched_switch(preempt, prev, next);
12
13 rq = context_switch(rq, prev, next, &rf);
14 } else {
15 rq->clock_update_flags &= ~(RQCF_ACT_SKIP|RQCF_REQ_SKIP);
16 rq_unlock_irq(rq, &rf);
17 }
18
19 balance_callback(rq);
20 }

__schedule() 함수 13 번째 줄을 보면 context_switch() 함수를 호출해서 컨텍스트 스위칭을 실행합니다. 13 번째 줄 바로 위 11 번째 줄에서 trace_sched_switch() 함수를 실행할 때 sched_switch 이벤트 로그를 출력합니다.


여기서 한 가지 의문이 생깁니다. 

    ftrace 이벤트를 출력하는 함수 이름에 어떤 패턴이 있지 않을까?

ftrace 이벤트를 보면 리눅스 커널 소스 코드 어디서 해당 메시지를 출력하는지 파악할 수 있습니다.

ftrace 이벤트를 출력하는 함수 이름은 다음과 같은 형식입니다. 따라서 sched_switch 이벤트를 출력하는 함수는 trace_sched_switch() 함수입니다.
trace_ + ftrace 이벤트 이름

마찬가지로 sched_wakeup 이벤트를 출력하는 함수는 trace_sched_wakeup() 란 사실을 유추할 수 있습니다.


이어서 sched_wakeup 이벤트를 출력하는 코드는 다음과 같습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/sched/core.c]
1 static void ttwu_do_wakeup(struct rq *rq, struct task_struct *p, int wake_flags,
2    struct rq_flags *rf)
3 {
4 check_preempt_curr(rq, p, wake_flags);
5 p->state = TASK_RUNNING;
6 trace_sched_wakeup(p);

ttwu_do_wakeup() 함수 6 번째 줄 코드에서 trace_sched_wakeup() 함수를 호출할 때 sched_wakeup 이벤트를 출력하는 것입니다.

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

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

Reference(프로세스 스케줄링)

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



핑백

덧글

댓글 입력 영역