CPU 사용률이 100%가 아닌데도 응답이 느린 서버가 있다. 태스크가 실행 가능(runnable) 상태로 런큐에서 기다린 시간, 즉 런큐 지연(run queue latency)이 원인인 경우가 많은데 top이나 vmstat에는 이 값이 나오지 않는다. /proc/PID/schedstat에 누적 합계가 있긴 하지만 분포를 볼 수 없어서, 평균은 멀쩡한데 가끔 수십 ms씩 밀리는 상황을 잡아내지 못한다.
이 글에서는 스케줄러 tracepoint에 BPF를 붙여 런큐 지연 히스토그램을 만들고, 우선순위와 스케줄링 정책을 바꿔가며 그 분포가 어떻게 달라지는지 측정한다. 이어서 컨텍스트 스위치를 자발/비자발로 나눠 세고, 태스크가 CPU 사이를 옮겨다니는 것까지 관측한다. 측정 결과는 모두 커널 6.8.0-139-generic, 6코어 VM에서 실행한 값이다.
이 시리즈의 다른 글
- eBPF 실전 (1) — libbpf와 CO-RE로 첫 커널 프로그램 작성하기
- eBPF 실전 (2) — BPF 맵과 링 버퍼: per-CPU, LRU, 유실, 맵 고정
- eBPF 실전 (3) — kprobe·fentry·tracepoint·uprobe 훅 오버헤드 비교
- eBPF 실전 (5) — sched_ext로 커널 스케줄러 직접 구현하기
- eBPF 실전 (6) — 페이지 폴트·slab·메모리 누수·OOM 관측하기
스케줄러 tracepoint
스케줄러는 필요한 지점마다 tracepoint를 제공한다. 이 글에서 쓰는 것만 정리하면 다음과 같다.
| tracepoint | 인자 | 언제 발생하는가 |
|---|---|---|
sched_wakeup | task_struct *p | 잠든 태스크가 깨어나 런큐에 들어갈 때 |
sched_wakeup_new | task_struct *p | 새로 만들어진 태스크가 처음 런큐에 들어갈 때 |
sched_switch | preempt, *prev, *next | CPU가 다른 태스크로 넘어갈 때 |
sched_migrate_task | *p, dest_cpu | 태스크가 다른 CPU의 런큐로 옮겨갈 때 |
SEC("tp_btf/...")로 붙이면 인자를 task_struct * 포인터 그대로 받아 필드에 직접 접근할 수 있다. BTF가 없는 커널에서는 SEC("tracepoint/sched/...")로 붙이고 트레이스 레코드 구조체에서 값을 꺼내야 한다.
런큐 지연 히스토그램
sched_wakeup에서 시각을 기록하고 sched_switch에서 그 태스크가 CPU를 잡은 순간 차이를 히스토그램에 넣는다. 선점당한 태스크는 sched_switch 시점에도 여전히 TASK_RUNNING이므로, 그 자리에서 다시 대기 시작 시각을 찍어줘야 빠짐없이 센다.
#include "vmlinux.h"
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_tracing.h>
char LICENSE[] SEC("license") = "GPL";
#define TASK_RUNNING 0
#define MAX_SLOTS 26
const volatile __u32 target_tgid = 0; /* 0이면 전체 */
struct {
__uint(type, BPF_MAP_TYPE_HASH);
__uint(max_entries, 65536);
__type(key, u32);
__type(value, u64);
} enq_ts SEC(".maps");
__u64 hist[MAX_SLOTS];
__u64 total_ns;
__u64 samples;
static __always_inline bool wanted(struct task_struct *p)
{
return !target_tgid || p->tgid == target_tgid;
}
static __always_inline void mark_enqueue(struct task_struct *p)
{
u32 pid = p->pid;
u64 ts;
if (!pid || !wanted(p))
return;
ts = bpf_ktime_get_ns();
bpf_map_update_elem(&enq_ts, &pid, &ts, BPF_ANY);
}
SEC("tp_btf/sched_wakeup")
int BPF_PROG(on_wakeup, struct task_struct *p)
{
mark_enqueue(p);
return 0;
}
SEC("tp_btf/sched_wakeup_new")
int BPF_PROG(on_wakeup_new, struct task_struct *p)
{
mark_enqueue(p);
return 0;
}
SEC("tp_btf/sched_switch")
int BPF_PROG(on_switch, bool preempt, struct task_struct *prev, struct task_struct *next)
{
u32 pid = next->pid;
u64 *tsp, delta, us, slot = 0;
/* 선점당한 태스크는 여전히 runnable: 다시 런큐 대기 시작 */
if (prev->__state == TASK_RUNNING)
mark_enqueue(prev);
tsp = bpf_map_lookup_elem(&enq_ts, &pid);
if (!tsp)
return 0;
delta = bpf_ktime_get_ns() - *tsp;
bpf_map_delete_elem(&enq_ts, &pid);
if ((s64)delta < 0) /* 다른 CPU가 방금 갱신한 타임스탬프 */
return 0;
us = delta / 1000;
while (us > 1 && slot < MAX_SLOTS - 1) {
us >>= 1;
slot++;
}
__sync_fetch_and_add(&hist[slot], 1);
__sync_fetch_and_add(&total_ns, delta);
__sync_fetch_and_add(&samples, 1);
return 0;
}유저 공간 로더는 전역 배열을 그대로 읽어 출력한다. target_tgid를 rodata로 두면 로드 전에 값을 정해 verifier가 필터 분기를 정리할 수 있다.
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <bpf/libbpf.h>
#include "runqlat.skel.h"
int main(int argc, char **argv)
{
int sec = argc > 1 ? atoi(argv[1]) : 5;
struct runqlat_bpf *skel = runqlat_bpf__open();
if (argc > 2)
skel->rodata->target_tgid = atoi(argv[2]);
if (runqlat_bpf__load(skel) || runqlat_bpf__attach(skel))
return 1;
sleep(sec);
unsigned long long max = 0;
for (int i = 0; i < 26; i++)
if (skel->bss->hist[i] > max)
max = skel->bss->hist[i];
printf("%-20s %-10s\n", "usecs", "count");
for (int i = 0; i < 26; i++) {
unsigned long long c = skel->bss->hist[i];
if (!c)
continue;
printf("%8llu -> %-8llu : %-8llu |", i ? 1ULL << i : 0, (1ULL << (i + 1)) - 1, c);
for (unsigned long long j = 0; j < c * 40 / max; j++)
putchar('*');
printf("\n");
}
printf("samples=%llu total_wait=%.3f ms avg=%.1f us\n", skel->bss->samples,
skel->bss->total_ns / 1e6,
skel->bss->samples ? skel->bss->total_ns / 1e3 / skel->bss->samples : 0);
runqlat_bpf__destroy(skel);
return 0;
}한가한 상태와, CPU 0-1에 묶은 스피너 4개가 도는 상태를 각각 5초씩 측정했다.
$ sudo ./runqlat 5 # A1 한가한 상태, 시스템 전체
usecs count
0 -> 1 : 31 |****************
2 -> 3 : 55 |****************************
4 -> 7 : 24 |************
8 -> 15 : 14 |*******
16 -> 31 : 63 |********************************
32 -> 63 : 78 |****************************************
64 -> 127 : 25 |************
128 -> 255 : 10 |*****
256 -> 511 : 3 |*
512 -> 1023 : 1 |
1024 -> 2047 : 1 |
samples=305 total_wait=13.054 ms avg=42.8 us
$ for i in $(seq 4); do taskset -c 0,1 ./spin 8 & done # A2 CPU 0-1에 스피너 4개
$ sudo ./runqlat 5
usecs count
0 -> 1 : 9 |
2 -> 3 : 38 |**
4 -> 7 : 35 |**
8 -> 15 : 5 |
16 -> 31 : 22 |*
32 -> 63 : 48 |**
64 -> 127 : 15 |
128 -> 255 : 9 |
256 -> 511 : 1 |
1024 -> 2047 : 1 |
2048 -> 4095 : 285 |*****************
4096 -> 8191 : 273 |*****************
8192 -> 16383 : 641 |****************************************
16384 -> 32767 : 79 |****
32768 -> 65535 : 12 |
samples=1474 total_wait=11356.530 ms avg=7704.6 us평균은 42.8us에서 7704.6us로 올라갔지만, 더 중요한 것은 분포가 둘로 갈라졌다는 점이다. 수 us대 봉우리(경쟁이 없는 CPU 2-5의 태스크들)는 그대로 있고, 스피너와 CPU를 나눠 쓰는 태스크만 8~16ms 구간에 새 봉우리를 만들었다 — 평균만 봤다면 시스템 전체가 느려졌다고 오판했을 상황이다.
우선순위와 정책이 런큐 지연에 미치는 영향
1ms마다 깨어나 짧게 일하는 지연 민감 태스크(ticker)를 만들고, CPU 0-1을 스피너 4개와 나눠 쓰게 했다. runqlat에 PID를 넘겨 이 태스크만 측정한다.
/* ticker: 1ms마다 깨어나 짧은 일을 하는 지연 민감 태스크 */
#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <unistd.h>
#include <sys/resource.h>
static void schedstat(unsigned long long *run, unsigned long long *wait)
{
FILE *f = fopen("/proc/self/schedstat", "r");
if (fscanf(f, "%llu %llu", run, wait) != 2)
*run = *wait = 0;
fclose(f);
}
int main(int argc, char **argv)
{
int n = argc > 1 ? atoi(argv[1]) : 3000;
unsigned long long r0, w0, r1, w1;
struct timespec ts = { 0, 1000000 };
sleep(1); /* 측정기가 붙을 시간 */
schedstat(&r0, &w0);
for (int i = 0; i < n; i++) {
for (volatile int j = 0; j < 20000; j++)
;
nanosleep(&ts, NULL);
}
schedstat(&r1, &w1);
struct rusage ru;
getrusage(RUSAGE_SELF, &ru);
printf("ticker pid=%d schedstat run_delay=%.3f ms rusage nvcsw=%ld nivcsw=%ld\n",
getpid(), (w1 - w0) / 1e6, ru.ru_nvcsw, ru.ru_nivcsw);
return 0;
}run() { # $1=라벨 $2=ticker 실행 래퍼 $3=스피너 수 $4=스피너 nice
for i in $(seq $3); do taskset -c 0,1 nice -n $4 ./spin 14 >/dev/null 2>&1 & done
sleep 0.5
taskset -c 0,1 $2 ./ticker 2000 > /tmp/tk.txt &
TP=$!; sleep 0.3
./runqlat 12 $TP | tail -1 | sed "s/^/$1 /"
wait $TP; sed "s/^/$1 /" /tmp/tk.txt
wait 2>/dev/null
}
run "B1 단독 " "" 0 0
run "B2 nice 0 경쟁 " "" 4 0
run "B3 SCHED_FIFO " "chrt -f 50" 4 0
run "B4 경쟁자 nice 19" "" 4 19--- run 1
B1 단독 samples=1712 total_wait=79.698 ms avg=46.6 us
B1 단독 ticker pid=2297 schedstat run_delay=44.326 ms rusage nvcsw=2001 nivcsw=0
B2 nice 0 경쟁 samples=1899 total_wait=805.199 ms avg=424.0 us
B2 nice 0 경쟁 ticker pid=2309 schedstat run_delay=776.542 ms rusage nvcsw=2001 nivcsw=2
B3 SCHED_FIFO samples=1675 total_wait=73.278 ms avg=43.7 us
B3 SCHED_FIFO ticker pid=2323 schedstat run_delay=22.019 ms rusage nvcsw=2003 nivcsw=3
B4 경쟁자 nice 19 samples=1381 total_wait=168.049 ms avg=121.7 us
B4 경쟁자 nice 19 ticker pid=2335 schedstat run_delay=135.958 ms rusage nvcsw=2001 nivcsw=2
--- run 2
B1 단독 samples=1736 total_wait=69.924 ms avg=40.3 us
B2 nice 0 경쟁 samples=1745 total_wait=1310.968 ms avg=751.3 us
B3 SCHED_FIFO samples=1830 total_wait=85.666 ms avg=46.8 us
B4 경쟁자 nice 19 samples=2002 total_wait=127.699 ms avg=63.8 us
--- run 3
B1 단독 samples=664 total_wait=33.571 ms avg=50.6 us
B2 nice 0 경쟁 samples=1863 total_wait=633.541 ms avg=340.1 us
B3 SCHED_FIFO samples=1836 total_wait=78.453 ms avg=42.7 us
B4 경쟁자 nice 19 samples=1931 total_wait=47.755 ms avg=24.7 us| 설정 | BPF 평균 (3회) | schedstat run_delay (run 1) | 해석 |
|---|---|---|---|
| B1 단독 | 46.6 / 40.3 / 50.6 us | 44.3 ms | 경쟁이 없으면 깨어나자마자 실행 |
| B2 nice 0 경쟁 | 424.0 / 751.3 / 340.1 us | 776.5 ms | 같은 가중치라 CFS가 순서대로 배분 |
| B3 SCHED_FIFO | 43.7 / 46.8 / 42.7 us | 22.0 ms | 실시간 정책이 CFS 태스크를 즉시 선점 |
| B4 경쟁자 nice 19 | 121.7 / 63.8 / 24.7 us | 136.0 ms | 경쟁자 가중치를 낮추면 지연도 내려감 |
chrt -f 50으로 정책만 바꾼 B3는 경쟁자가 4개 그대로인데도 단독 실행(B1)과 같은 수준으로 돌아왔다. 반대로 nice 값만 조정한 B4는 실행마다 24.7~121.7us로 흔들리는데, CFS의 가중치는 지연 상한을 보장하지 않기 때문이다.
BPF 측정값과 커널이 직접 세는 schedstat의 대기 시간을 비교하면 계측이 맞는지 확인할 수 있다. 두 값은 경쟁이 심할수록 가까워지고(B2: 805.2 vs 776.5ms), 지연이 짧을 때는 BPF 쪽이 더 크게 나온다(B3: 73.3 vs 22.0ms).
- BPF는
sched_wakeup이 찍히는 순간부터 잰다 — 깨우는 CPU가 대상 CPU에 IPI를 보내고 런큐에 넣기까지의 시간이 포함된다. schedstat의run_delay는 런큐에 실제로 들어간 뒤부터 센다.- 따라서 두 값의 차이는 웨이크업 경로 자체의 비용이고, 런큐 대기가 길어질수록 상대적으로 묻힌다.
자발/비자발 컨텍스트 스위치 구분하기
sched_switch 시점에 prev가 아직 TASK_RUNNING이면 더 돌 수 있는데 뺏긴 것(비자발), 아니면 스스로 잠든 것(자발)이다.
#include "vmlinux.h"
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_tracing.h>
char LICENSE[] SEC("license") = "GPL";
#define TASK_RUNNING 0
struct cs {
char comm[16];
u64 voluntary;
u64 involuntary;
};
struct {
__uint(type, BPF_MAP_TYPE_HASH);
__uint(max_entries, 16384);
__type(key, u32); /* pid */
__type(value, struct cs);
} counts SEC(".maps");
SEC("tp_btf/sched_switch")
int BPF_PROG(on_switch, bool preempt, struct task_struct *prev, struct task_struct *next)
{
u32 pid = prev->pid;
struct cs *c, zero = {};
if (!pid)
return 0;
c = bpf_map_lookup_elem(&counts, &pid);
if (!c) {
bpf_probe_read_kernel_str(zero.comm, sizeof(zero.comm), prev->comm);
bpf_map_update_elem(&counts, &pid, &zero, BPF_NOEXIST);
c = bpf_map_lookup_elem(&counts, &pid);
if (!c)
return 0;
}
/* 스위치 시점에 여전히 RUNNING이면 선점(비자발), 아니면 스스로 잠든 것(자발) */
if (prev->__state == TASK_RUNNING)
__sync_fetch_and_add(&c->involuntary, 1);
else
__sync_fetch_and_add(&c->voluntary, 1);
return 0;
}### BPF tp_btf/sched_switch 집계 (8초)
PID COMM VOLUNTARY INVOLUNT
2547 spin 0 1275
2545 spin 0 390
2544 spin 0 384
2546 spin 0 380
2548 ticker 1274 0
### /proc/<pid>/status 교차 확인 (프로세스 시작~현재 누적)
PID COMM VOLUNTARY INVOLUNT
2548 ticker 1401 1
2544 spin 0 459
2545 spin 0 471nanosleep()으로 스스로 자는 ticker는 자발 스위치만, CPU를 놓지 않는 스피너는 비자발 스위치만 기록됐다. 측정 창(8초)과 프로세스 수명이 달라 절대값은 다르지만 비율은 /proc/PID/status와 일치한다.
웨이크업과 CPU 마이그레이션
같은 맵에 sched_migrate_task와 sched_wakeup을 함께 집계하면, 태스크가 CPU를 옮겨다니는 빈도를 깨어난 횟수와 나란히 볼 수 있다.
#include "vmlinux.h"
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_tracing.h>
char LICENSE[] SEC("license") = "GPL";
struct mig {
char comm[16];
__u64 migrations;
__u64 wakeups;
};
struct {
__uint(type, BPF_MAP_TYPE_HASH);
__uint(max_entries, 16384);
__type(key, __u32); /* pid */
__type(value, struct mig);
} stats SEC(".maps");
static struct mig *slot(__u32 pid, const char *comm)
{
struct mig *m, zero = {};
m = bpf_map_lookup_elem(&stats, &pid);
if (m)
return m;
bpf_probe_read_kernel_str(zero.comm, sizeof(zero.comm), comm);
bpf_map_update_elem(&stats, &pid, &zero, BPF_NOEXIST);
return bpf_map_lookup_elem(&stats, &pid);
}
SEC("tp_btf/sched_migrate_task")
int BPF_PROG(on_migrate, struct task_struct *p, int dest_cpu)
{
__u32 pid = p->pid;
struct mig *m;
if (!pid)
return 0;
m = slot(pid, p->comm);
if (m)
__sync_fetch_and_add(&m->migrations, 1);
return 0;
}
SEC("tp_btf/sched_wakeup")
int BPF_PROG(on_wakeup, struct task_struct *p)
{
__u32 pid = p->pid;
struct mig *m;
if (!pid)
return 0;
m = slot(pid, p->comm);
if (m)
__sync_fetch_and_add(&m->wakeups, 1);
return 0;
}### C1 스피너 8개, CPU 제한 없음 (6 CPU)
PID COMM MIGRATIONS WAKEUPS
2774 spin 2 0
2773 spin 1 0
2770 spin 5 0
2775 spin 1 0
2772 spin 4 0
### C2 같은 스피너 8개를 CPU 0-1에 묶었을 때
PID COMM MIGRATIONS WAKEUPS
### C3 ticker: 깨어난 횟수 대비 마이그레이션
PID COMM MIGRATIONS WAKEUPS
2792 ticker 2 1022C2가 빈 표인 것은 이벤트가 하나도 없어서다 — 8개를 CPU 2개에 균등하게 묶어두면 로드 밸런서가 옮길 이유가 없다. C3의 ticker는 6초 동안 1022번 깨어나면서 CPU를 2번만 바꿨는데, 웨이크업 시 캐시가 따뜻한 CPU를 먼저 고르기 때문이다.
주의사항
tp_btf/프로그램은 커널 BTF(/sys/kernel/btf/vmlinux)를 요구한다. 없는 커널에서는tracepoint/sched/sched_switch로 붙이고 트레이스 레코드에서prev_state같은 필드를 읽어야 한다.task_struct의 상태 필드는 커널 5.14에서state에서__state로 바뀌었다. CO-RE가 오프셋은 맞춰주지만 이름이 다르면 컴파일 단계에서 실패하므로, 여러 커널을 대상으로 한다면bpf_core_field_exists()로 분기해야 한다.- 히스토그램 도구는 측정 창과 워크로드가 어긋나면 표본이 몇 건만 잡힌다. 위 B1의 run 3(samples=664)이 그런 경우다 — 측정기를 먼저 띄우고 워크로드를 시작할 것.
bpf_ktime_get_ns()차이가 음수로 나올 수 있다. 다른 CPU가 같은 PID의 타임스탬프를 방금 갱신한 경우이므로 버려야 히스토그램이 오염되지 않는다.enq_ts같은 상태 맵은 태스크가 종료되면 항목이 남는다. 장시간 돌릴 도구라면sched_process_exit에서 키를 지우거나 LRU 해시를 쓸 것.SCHED_FIFO는 런큐 지연을 확실히 줄이지만, 우선순위가 낮은 태스크를 무한정 굶길 수 있다./proc/sys/kernel/sched_rt_runtime_us가 최후의 안전장치다.
마무리
스케줄러 tracepoint 3개만으로 런큐 지연 분포, 컨텍스트 스위치 성격, CPU 마이그레이션까지 태스크 단위로 볼 수 있었다. 평균값 하나로는 보이지 않던 이중 봉우리가 히스토그램에서 바로 드러났고, schedstat과 /proc/PID/status로 교차 검증까지 마쳤다.
다음 편에서는 관측을 넘어 sched_ext로 스케줄링 정책 자체를 BPF 프로그램으로 구현한다.