Arm Linux Kernel Hacks : [리눅스커널] 스케줄링: 스케줄링/디버깅: ftrace: sched_switch와 sched_wakeup 이벤트 소개

리눅스 커널 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"

7 echo 0 > /sys/kernel/debug/tracing/events/enable

8 sleep 1

9 echo "events disabled"

11 echo nop > /sys/kernel/debug/tracing/current_tracer

12 sleep 1

13 echo "nop tracer enabled"

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"

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,

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,

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",

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;

...

5 if (likely(prev != next)) {

6 rq->nr_switches++;

7 rq->curr = next;

9 ++*switch_count;

11 trace_sched_switch(preempt, prev, next);

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 }

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);