Blog

CPU 사용률은 낮은데 응답이 느린 서비스를 만나면 perf top이 별 도움이 안 된다. 화면에 뜨는 건 지금 CPU를 쓰고 있는 함수뿐이라, 정작 시간을 잡아먹는 대기 구간은 아무 데도 나오지 않고 그 함수에 어떤 경로로 도달했는지도 알 수 없다. eBPF는 커널 안에서 스택을 통째로 집계해 내보내므로, CPU를 쓴 시간(온-CPU)과 CPU를 놓고 기다린 시간(오프-CPU)을 같은 방식으로 뽑아 비교할 수 있다. 이 글에서는 bpftrace로 두 프로파일을 뜨고, folded 스택으로 변환해 플레임그래프를 만들고, 샘플링 주파수별 오버헤드까지 실측한다.

온-CPU와 오프-CPU

실험 워크로드

두 프로파일의 차이가 드러나도록 CPU만 쓰는 스레드, 블로킹하는 스레드, 뮤텍스를 두고 경합하는 스레드를 섞었다.

static void *cpu_worker(void *arg) {          // 순수 CPU 연산
    unsigned long s = 1;
    while (running) s = compute_chunk(s);
    return (void *)s;
}

static void *io_worker(void *arg) {           // 파일 읽기 + 짧은 sleep
    char buf[65536];
    while (running) {
        int fd = open((const char *)arg, O_RDONLY);
        if (fd < 0) { usleep(1000); continue; }
        while (read(fd, buf, sizeof buf) > 0) ;
        close(fd);
        usleep(5000);
    }
    return NULL;
}

static void *lock_worker(void *arg) {         // 뮤텍스 경합
    long id = (long)arg;
    struct timespec ts = { 0, 2 * 1000 * 1000 };
    while (running) {
        pthread_mutex_lock(&big_lock);
        if (id == 0) nanosleep(&ts, NULL);    // 락을 오래 쥐고 있는 쪽
        pthread_mutex_unlock(&big_lock);
        usleep(200);
    }
    return NULL;
}

gcc -O2 -g -fno-omit-frame-pointer workload.c -o workload -lpthread

온-CPU 프로파일

profile:hz:99는 CPU마다 초당 99번 인터럽트를 걸어 그 순간의 스택을 남긴다. 99라는 어정쩡한 수는 주기적인 워크로드와 박자가 맞아 특정 지점만 반복해서 잡히는 것을 피하기 위한 관행이다.

sudo bpftrace -e 'profile:hz:99 /pid == 44937/ { @[ustack] = count(); }
                 interval:s:10 { exit(); }' > oncpu.txt

@[
    hash_round+67
    compute_chunk+9
    cpu_worker+37
    start_thread+900
    __clone3+44
]: 210

같은 논리적 스택이라도 리프의 오프셋이 달라 항목이 잘게 쪼개지므로, 심볼 단위로 접어서 봐야 비율이 보인다.

$ awk -f fold.awk oncpu.txt | sort -k2 -nr | head -5
__clone3;start_thread;cpu_worker;compute_chunk;hash_round 1979
__clone3;start_thread;lock_worker;__lll_lock_wake 31
__clone3;start_thread;io_worker;__libc_read 28
__clone3;start_thread;lock_worker;usleep;nanosleep;__GI___clock_nanosleep 4
__clone3;start_thread;lock_worker;nanosleep 1

워커별 집계
lock_worker        37    1.8%
io_worker          30    1.5%
cpu_worker       1980   96.7%
합계             2047

CPU 시간의 96.7%가 cpu_worker에 몰려 있고 lock_worker는 1.8%다. 이 프로파일만 보면 락은 문제가 아닌 것처럼 보인다.

오프-CPU 프로파일

오프-CPU는 스레드가 CPU에서 내려간 시점의 스택을 기록해두고, 다시 올라올 때 그동안 흐른 시간을 그 스택에 합산하는 방식으로 잰다. bpftrace 배포판에 해당 도구가 없어 직접 작성했다.

#!/usr/bin/env bpftrace
tracepoint:sched:sched_switch
{
    // CPU에서 내려가는 쪽 — 이 시점의 스택이 "무엇을 기다리는지"를 말해준다
    if (args.prev_comm == str($1)) {
        @start[args.prev_pid] = nsecs;
        @kst[args.prev_pid] = kstack;
        @ust[args.prev_pid] = ustack;
    }

    // 다시 올라오는 쪽 — 기다린 시간을 내려갈 때의 스택에 합산
    if (args.next_comm == str($1) && @start[args.next_pid] != 0) {
        @offcpu_us[@kst[args.next_pid], @ust[args.next_pid]] =
            sum((nsecs - @start[args.next_pid]) / 1000);
        delete(@start[args.next_pid]);
        delete(@kst[args.next_pid]);
        delete(@ust[args.next_pid]);
    }
}

END { clear(@start); clear(@kst); clear(@ust); }

$ sudo bpftrace ./offcpu.bt workload
@offcpu_us[
    __schedule+1167
    schedule+39
    futex_do_wait+58
    __futex_wait+153
    futex_wait+114
    do_futex+261
    __x64_sys_futex+297
    do_syscall_64+217
    entry_SYSCALL_64_after_hwframe+118
,
    __lll_lock_wait+48
    lock_worker+116
    start_thread+900
    __clone3+44
]: 9160152

커널 스택과 유저 스택이 함께 찍히므로 “유저 코드의 어느 지점이” “커널의 어떤 대기 지점에서” 멈췄는지가 한 항목에 들어온다. 약 12초 구간의 전체 집계는 다음과 같다.

온-CPU에서 1.8%로 묻혀 있던 lock_worker가 오프-CPU에서는 합계 22.4초로 가장 큰 대기 요인이고, 그중 9.2초가 futex_do_wait — 즉 뮤텍스 경합이다. CPU 프로파일만 봤다면 절대 보이지 않았을 값이다.

folded 스택과 플레임그래프

bpftrace의 스택 출력은 flamegraph.pl이 먹는 folded 형식(root;...;leaf 개수)으로 한 줄 변환하면 그대로 플레임그래프가 된다.

/^@\[/          { n = 0; next }
/^\]: [0-9]+$/  {
                  cnt = $2
                  s = ""
                  for (i = n; i >= 1; i--) s = s (s == "" ? "" : ";") f[i]
                  if (s != "") tot[s] += cnt
                  next
                }
/^ +[^ ]/       { sym = $1; sub(/\+.*$/, "", sym); f[++n] = sym; next }
END             { for (s in tot) print s, tot[s] }

curl -sSL -o flamegraph.pl \
  https://raw.githubusercontent.com/brendangregg/FlameGraph/master/flamegraph.pl
awk -f fold.awk oncpu.txt | perl flamegraph.pl --title "on-CPU" > oncpu.svg

오프-CPU 출력도 같은 방식으로 접되, 합산 단위가 샘플 개수가 아니라 마이크로초이므로 --countname us를 붙여야 축 이름이 맞는다.

샘플링 오버헤드

고정 반복 CPU 연산을 5회 돌린 평균을, 프로파일링을 붙인 채로 다시 측정했다.

샘플마다 유저 스택을 걷는 비용이라, 호출 깊이가 얕은 코드에서는 이보다 낮게 나온다. 운영 중인 시스템에 붙일 때 99Hz를 기본값처럼 쓰는 이유가 이 곡선이다.

주의사항

• BCC 도구(profile-bpfcc, offcputime-bpfcc)는 실행할 때 커널 헤더로 BPF 프로그램을 컴파일하므로 커널이 앞서 나가면 깨진다. 이 환경(커널 7.0)에서는 include/linux/ns_common.h:26:13: error: no member named 'ns_id' in 'struct ns_common'으로 실패했다. BTF를 읽는 bpftrace는 같은 커널에서 그대로 동작한다.
• 컴파일러 최적화로 스택이 사라진다. -O2만 준 첫 빌드에서는 인라이닝으로 hash_round가 cpu_worker에 흡수됐고, return f(x); 형태는 꼬리 호출로 바뀌어 중간 프레임이 통째로 빠졌다. 프로파일 대상 바이너리는 최소한 -fno-omit-frame-pointer로 빌드하고, 스택이 이상하면 인라이닝·꼬리 호출을 먼저 의심할 것.
• 오프-CPU에는 자발적 대기뿐 아니라 비자발적 선점도 섞인다. 위 결과의 irqentry_exit 항목이 타이머 인터럽트에 밀린 cpu_worker인데, 0.3ms로 작아 무시할 수 있는 수준이었지만 CPU가 포화된 시스템에서는 이 쪽이 지배적일 수 있다.
• 오프-CPU 합계는 벽시계 시간을 넘는다. 위 표의 합은 33.5초인데 측정 구간은 약 12초다. 스레드 5개가 각자 기다린 시간을 더한 값이므로 “전체 시간의 몇 %”로 읽으면 안 된다.
• sched_switch는 초당 수만 번 발생할 수 있다. 필터 없이 붙이면 대상 시스템이 느려지므로 comm이나 PID로 반드시 좁힐 것.
• 커널 심볼이 0x…로만 보이면 kernel.kptr_restrict와 kernel.perf_event_paranoid를 확인한다. 측정 환경은 각각 1과 4였고 root로 실행해 문제가 없었다.

마무리

온-CPU 프로파일은 “무엇이 CPU를 태우는가”에만 답한다. 같은 워크로드에서 CPU 기준 1.8%였던 스레드가 대기 기준으로는 22.4초를 차지했고, 그 원인이 뮤텍스 경합이라는 건 오프-CPU 스택을 봐야 드러났다. 지연 문제를 볼 때는 두 프로파일을 항상 같이 뜨고, 둘 중 어느 쪽에서도 설명되지 않는 시간이 남는다면 그때 런큐 대기(runqlat)까지 내려가면 된다.

참고

• bpftrace 매뉴얼
• Brendan Gregg, Off-CPU Analysis
• FlameGraph
• BPF Type Format (BTF) – The Linux Kernel documentation