Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

80258
1323
114582


[리눅스커널] CFS: vruntime을 ftrace로 확인하는 실습 따라해보기 10. Process Scheduling

여러분이 이 부분까지 포기하지 않고 읽었다면 다음과 같은 의문이 생길 것입니다. 

    리눅스 시스템에서 vruntime 은 실제 어떤 값일까?

이번 소절에서는 vruntime을 ftrace에서 보는 방법을 소개합니다. 
ftrace에서 sched_stat_runtime 이벤트를 키면 다음과 같은 프로세스의 실행 정보를 출력할 수 있습니다.
vruntime
프로세스 실행 시각

sched_stat_runtime ftrace 이벤트 키는 방법 소개

sched_stat_runtime 이벤트 메시지를 분석하기 앞서 이벤트를 키는 방법을 먼저 알아보겠습니다. 다음 명령어를 입력하면 sched_stat_runtime 이벤트를 킬 수 있습니다.
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_stat_runtime/enable
16 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_waking/enable
17 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
18 sleep 1
19 echo "event enabled"
20
21 echo 1 > /sys/kernel/debug/tracing/tracing_on
22 echo "tracing_on"

sched_stat_runtime 이벤트를 키는 명령어는 다음과 같습니다.
15 echo 1 > /sys/kernel/debug/tracing/events/sched/sched_stat_runtime/enable

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

위에서 소개한 방식으로 ftrace 이벤트를 킨 10초 후에 ftrace를 받습니다. 이번 실습에서는 커널 코드를 수정할 필요가 없습니다. 단지 ftrace만 설정하고 ftrace 로그를 받으면 됩니다.

ftrace 로그로 vruntime 확인하기

분석할 ftrace 로그는 다음과 같습니다.
1 InputThread-620 [000] d... 10213.037017: sched_waking: comm=Xorg pid=552 prio=120 target_cpu=002
2 InputThread-620 [000] d... 10213.037042: sched_stat_runtime: comm=InputThread pid=620 runtime=211355 [ns] vruntime=52059310628 [ns]
3 InputThread-620 [000] d... 10213.037052: sched_switch: prev_comm=InputThread prev_pid=620 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120
4 InputThread-620 [000] d... 10213.052890: sched_waking: comm=Xorg pid=552 prio=120 target_cpu=002
5 InputThread-620 [000] d... 10213.052907: sched_stat_runtime: comm=InputThread pid=620 runtime=142812 [ns] vruntime=52059453440 [ns]

위 ftrace 메시지 중에서 sched_stat_runtime 이벤트 로그는 2 번째와 5 번째 줄입니다.

2 번째와 5 번째 메시지를 보면 vruntime을 확인할 수 있습니다.

우선 sched_stat_runtime 이벤트 메시지를 보겠습니다.
2 InputThread-620 [000] d... 10213.037042: sched_stat_runtime: comm=InputThread pid=620 runtime=211355 [ns] vruntime=52059310628 [ns]

pid가 620인 InputThread 프로세스에 대한 스케줄링 정보입니다.  

    vruntime은 52059310628 이고 실행 시각은 211355입니다. 

여기서 시간 단위는 모두 나노 초입니다.

이번에 vruntime이 얼마나 증감했는지 살펴보겠습니다.
5 번째 줄와 2번째 줄 vruntime을 확인하니 +142812 만큼 증감한 사실을 알 수 있습니다. 
52059453440 – 52059310628 = 142812 

    그렇다면 sched_stat_runtime 이벤트는 어느 코드가 실행할 때 출력할까?

update_curr() 함수에서 sched_stat_runtime 이벤트를 처리합니다.  
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/sched/fair.c]
1 static void update_curr(struct cfs_rq *cfs_rq)
2 {
...
3 if (entity_is_task(curr)) {
4 struct task_struct *curtask = task_of(curr);
5
6 trace_sched_stat_runtime(curtask, delta_exec, curr->vruntime);
...
7 }
8
9 account_cfs_rq_runtime(cfs_rq, delta_exec);
10 }

6 번째 줄 코드를 보면 trace_sched_stat_runtime() 함수를 호출해서 sched_stat_runtime 이벤트 메시지를 출력합니다.

프로세스 세부 동작을 점검할 때 vruntime과 실제 실행 시간을 같이 보면 더 유익한 정보를 얻을 수 있습니다.


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

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

Reference(프로세스 스케줄링)

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



핑백

덧글

댓글 입력 영역