Blog

스레드를 늘렸는데 처리량이 그대로이거나 오히려 떨어질 때, top은 sys 시간이 높다는 것까지만 알려준다. perf top으로 어느 함수가 CPU를 쓰는지 좁혀도 “락을 기다리느라 잠들어 있던 시간”은 CPU 프로파일에 잡히지 않는다. perf lock은 커널이 락 경합을 만났을 때 쏘는 트레이스포인트를 받아 대기 횟수와 대기 시간을 직접 집계한다. 이 글에서는 Ubuntu 24.04의 기본 커널(lockdep 없음)에서 perf lock을 쓰는 방법과, 경합을 재현하는 워크로드로 스레드 수에 따라 대기 시간이 어떻게 폭증하는지 측정한 결과를 정리한다.

커널과 perf 준비

예전의 perf lock record는 lockdep이 제공하는 lock:lock_acquire 계열 트레이스포인트를 썼지만, 지금은 lock:contention_begin/contention_end 두 개만 있으면 된다. 이 둘은 lockdep과 무관하게 항상 들어 있다.

$ ls /sys/kernel/tracing/events/lock/
contention_begin  contention_end  enable  filter

$ perf list | grep 'lock:'
  lock:contention_begin                              [Tracepoint event]
  lock:contention_end                                [Tracepoint event]

$ grep -E 'CONFIG_LOCK_STAT|CONFIG_PROVE_LOCKING' /boot/config-$(uname -r)
# CONFIG_PROVE_LOCKING is not set
# CONFIG_LOCK_STAT is not set

lockdep(CONFIG_PROVE_LOCKING)도 CONFIG_LOCK_STAT도 꺼져 있는 배포판 기본 커널이지만 측정에는 문제가 없다. perf는 linux-tools-$(uname -r) 패키지로 설치한다.

경합을 재현하는 워크로드

여러 스레드가 같은 파일에 pwrite()를 날리면 커널이 inode의 i_rwsem을 쓰기 잠금으로 잡는다. 전체 쓰기 횟수를 고정하고 스레드 수만 바꾸면 경합의 영향만 분리해서 볼 수 있다.

#define _GNU_SOURCE
#include <pthread.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <fcntl.h>
#include <time.h>

static int fd;
static int per_thread;
static char buf[4096];

static void *worker(void *arg)
{
    (void)arg;
    for (int i = 0; i < per_thread; i++) {
        if (pwrite(fd, buf, sizeof(buf), 0) < 0) {
            perror("pwrite");
            break;
        }
    }
    return NULL;
}

int main(int argc, char **argv)
{
    int nthreads = argc > 1 ? atoi(argv[1]) : 4;
    int total    = argc > 2 ? atoi(argv[2]) : 1200000;   /* 전체 쓰기 횟수 고정 */
    pthread_t th[64];
    struct timespec t0, t1;

    per_thread = total / nthreads;
    memset(buf, 'x', sizeof(buf));

    fd = open("/tmp/lockdemo.dat", O_RDWR | O_CREAT | O_TRUNC, 0644);
    if (fd < 0) {
        perror("open");
        return 1;
    }

    clock_gettime(CLOCK_MONOTONIC, &t0);
    for (int i = 0; i < nthreads; i++)
        pthread_create(&th[i], NULL, worker, NULL);
    for (int i = 0; i < nthreads; i++)
        pthread_join(th[i], NULL);
    clock_gettime(CLOCK_MONOTONIC, &t1);

    double sec = (t1.tv_sec - t0.tv_sec) + (t1.tv_nsec - t0.tv_nsec) / 1e9;
    printf("threads=%2d total=%d elapsed=%.3fs\n", nthreads, total, sec);
    close(fd);
    return 0;
}

gcc -O2 -o lockdemo lockdemo.c -lpthread

첫 측정

perf lock record로 기록하고 perf lock contention -i로 읽는다. 기록에는 루트 권한이 필요하다.

sudo perf lock record -o w24.data -- ./lockdemo 24 1200000
sudo perf lock contention -i w24.data -E 5

contended   total wait     max wait     avg wait         type   caller

        64      7.23 s     410.65 ms    112.94 ms      rwsem:W   vfs_write+0x29e
     72251    376.58 ms    985.90 us      5.21 us     spinlock   up_write+0x4f
     42807    239.13 ms    580.61 us      5.59 us     spinlock   wake_up_q+0x4b
        61    252.40 us     13.24 us      4.14 us     spinlock   ext4_buffered_write_iter+0x36
         9     49.11 us      7.72 us      5.46 us     spinlock   exit_to_user_mode_loop+0x6c

맨 윗줄이 범인이다. vfs_write에서 잡는 쓰기 rwsem(rwsem:W)에 64번 걸렸을 뿐인데 누적 대기가 7.23초, 한 번은 410ms를 기다렸다. 아래의 스핀락들은 걸린 횟수는 수만 번이지만 평균 5us라 총합이 훨씬 작다 — 횟수가 아니라 대기 시간으로 봐야 한다.

스레드가 하나면 같은 워크로드에서 경합 자체가 잡히지 않는다.

$ sudo perf lock record -o w1.data -- ./lockdemo 1 1200000
$ sudo perf lock contention -i w1.data
 contended   total wait     max wait     avg wait         type   caller

스레드 수에 따른 변화

전체 작업량을 120만 회로 고정하고 스레드만 늘리면, 경과 시간은 2스레드에서 최소가 되고 그 뒤로는 되레 나빠진다.

4스레드까지는 경합이 아예 기록되지 않는다. rwsem은 잠금을 놓을 때까지 짧게 스핀(optimistic spinning)해 보고, 그 안에 얻으면 트레이스포인트를 쏘지 않기 때문이다. 즉 이 표에 줄이 하나라도 뜬다면 이미 잠들었다 깨어난 경합이다.

총 대기가 경과 시간(0.782초)보다 큰 것도 정상이다. 24개 스레드가 동시에 기다린 시간을 모두 더한 값이라 벽시계 시간을 넘어설 수 있다.

보는 각도 바꾸기

sudo perf lock contention -i w24.data -t -E 3      # 스레드별
sudo perf lock contention -i w24.data -l -E 3      # 락 주소별
sudo perf lock contention -i w24.data -Y rwsem     # rwsem만

contended   total wait     max wait     avg wait          pid   comm

      2127    548.04 ms    410.65 ms    257.66 us        31211   :31211
       991    510.21 ms    410.57 ms    514.84 us        31197   :31197
      1983    509.83 ms    410.48 ms    257.10 us        31207   :31207

 contended   total wait     max wait     avg wait            address   symbol

        64      7.23 s     410.65 ms    112.94 ms   ffff8ef4f38bf8a0    (rwsem)
     72312    376.83 ms    985.90 us      5.21 us   ffff8ef4f38bf8b4    (spinlock)
      8439     50.27 ms     95.97 us      5.96 us   ffff8ef448918e2c    (spinlock)

 contended   total wait     max wait     avg wait         type   caller

        64      7.23 s     410.65 ms    112.94 ms      rwsem:W   vfs_write+0x29e

-l의 첫 줄과 둘째 줄 주소가 20바이트 차이(…f8a0 / …f8b4)로 붙어 있다. 같은 inode 구조체 안의 rwsem과 그 옆 스핀락이라는 뜻으로, 락 하나를 지목해야 할 때 함수 이름보다 확실하다.

결과를 파일로 뽑을 때

perf lock contention의 결과 표는 stdout이 아니라 stderr로 나간다. 파이프로 걸면 아무것도 안 잡히므로 --output을 쓴다.

$ sudo perf lock contention -i w24.data 2>/dev/null | wc -l
0
$ sudo perf lock contention -i w24.data 2>&1 >/dev/null | wc -l
9

$ sudo perf lock contention -i w24.data --output res.txt
$ sudo perf lock contention -i w12.data -x, --output res.csv
$ head -3 res.csv
# output: contended, total wait, max wait, avg wait, type, caller
14, 58319667, 20188677, 4165690, rwsem:W, vfs_write+0x29e
1874, 10302596, 322450, 5497, spinlock, wake_up_q+0x4b

-x로 뽑은 CSV의 시간 값은 나노초 정수다. 여러 번 측정해 표로 비교할 때 이쪽이 파싱하기 쉽다.

구 방식과 라이브 모드의 한계

perf lock report는 같은 데이터를 읽지만 락 이름을 채우지 못한다. 이름은 lockdep이 등록하는 정보라 CONFIG_PROVE_LOCKING이 꺼진 커널에서는 빈칸이 된다.

$ sudo perf lock report -i w24.data
                Name   acquired  contended     avg wait   total wait     max wait     min wait

                          72312      72312      5.21 us    376.83 ms    985.90 us      1.08 us
                           8439       8439      5.96 us     50.27 ms     95.97 us      1.26 us
                           7624       7624      5.88 us     44.82 ms    120.00 us      1.21 us

실시간으로 붙어서 보는 -a/-p 모드는 BPF 수집기가 필요한데, Ubuntu의 perf 패키지는 BUILD_BPF_SKEL=1 없이 빌드돼 있어 쓸 수 없다. 에러 메시지가 원인을 전혀 안 알려주니 기억해 둘 만하다.

$ sudo perf lock contention -a -- sleep 1
incompatible file format (rerun with -v to learn more)
Initializing perf session failed

$ sudo perf lock contention -b
 Error: switch `b' is not available because no BUILD_BPF_SKEL=1

결국 이 커널·이 패키지 조합에서는 record → contention -i 2단계가 유일한 경로다.

기록 오버헤드

트레이스포인트는 경합이 일어날 때만 찍히므로, 경합이 심한 워크로드라도 측정 자체의 비용은 크지 않다.

[perf 없이]                     [perf lock record 하에서]
threads=12 elapsed=0.665s        threads=12 elapsed=0.705s
threads=12 elapsed=0.715s        threads=12 elapsed=0.666s
threads=12 elapsed=0.639s        threads=12 elapsed=0.747s

3회씩 측정한 결과가 서로의 편차 안에 들어온다. 다만 경합 횟수가 초당 수십만 건인 스핀락까지 모두 기록되므로 perf.data 크기와 out-of-order 경고는 늘어난다.

주의사항

• 횟수보다 시간: 스핀락은 수만 번 걸려도 평균 5us라 총합이 작다. 정렬 기본값이 총 대기 시간인 이유이고, -k avg_wait로 바꿔 보면 순위가 달라진다.
• 경합이 안 잡힌다고 없는 것은 아니다: rwsem·mutex는 짧은 경합을 스핀으로 흡수한다. 트레이스포인트에 잡히는 것은 실제로 스케줄 아웃된 경우뿐이다.
• 총 대기 > 실행 시간: 여러 스레드의 대기를 합산한 값이라 벽시계 시간을 넘는다. 스레드 수로 나눠 봐야 체감 지연에 가깝다.
• 결과는 stderr로 나간다: | grep으로 걸러 쓰려다 빈 결과를 받기 쉽다. --output 또는 2>&1을 붙인다.
• 커널 심볼: caller 열이 주소로만 나오면 kptr_restrict나 심볼 접근 권한 문제다. sudo로 실행하고 필요하면 --kallsyms를 지정한다.
• 유저 공간 락은 대상이 아니다: pthread mutex 경합은 futex로 잠들 때만 커널을 거친다. 애플리케이션 락을 보려면 perf trace -e futex나 perf top 쪽이 맞다.

마무리

perf lock은 “어디가 느린가”가 아니라 “어디서 기다렸는가”를 알려주는 도구다. 스레드를 늘려도 처리량이 안 오르는 상황에서 CPU 프로파일만 들여다보면 보이지 않던 원인이, perf lock contention 한 줄로 호출 지점과 누적 대기 시간으로 정리돼 나온다. 배포판 기본 커널에서 별도 설정 없이 쓸 수 있으니, 락 경합이 의심되면 lockdep 커널을 새로 빌드하기 전에 먼저 이걸 돌려볼 만하다.

참고

• perf top으로 실시간 락 함수 프로파일링하는 방법
• LOCKDEP 사용법
• perf-lock(1) man page
• Linux kernel documentation — Lock types and their rules