시스템 모니터링과 디버깅

프로그램이 이상하게 동작하는데 로그만으로 원인을 알 수 없을 때, 운영체제 수준의 도구가 필요합니다. 프로그램이 커널에 무엇을 요청하는지, 커널이 어떤 사건을 기록했는지, CPU와 메모리, 디스크를 어떻게 쓰고 있는지를 들여다보면 원인을 상당히 좁힐 수 있습니다.

이 글에서는 먼저 문제를 체계적으로 좁히는 방법을 보고, /proc, strace, 커널 로그, 코어 덤프, perf를 차례로 살펴봅니다. 명령의 출력은 시스템마다 다르므로, 각 도구가 무엇을 재고 무엇은 재지 않는지에 집중합니다.

무엇부터 볼까: USE 방법

장애가 나면 눈에 띄는 지표부터 쫓기 쉽지만, 그러다 보면 정작 병목인 자원을 놓칩니다. Brendan Gregg가 제안한 USE 방법은 CPU, 메모리, 디스크, 네트워크 같은 자원마다 세 가지를 빠짐없이 확인하는 점검표입니다. 사용률(utilization)은 자원이 바빴던 시간의 비율, 포화(saturation)는 자원이 감당하지 못해 쌓인 대기, 오류(errors)는 자원에서 난 오류의 수입니다.

사용률이 낮아도 포화가 있을 수 있고, 둘 다 정상이어도 오류가 성능을 떨어뜨릴 수 있으므로 세 가지를 모두 봅니다. 이 점검으로 의심 가는 자원을 찾은 뒤, 아래의 도구로 어느 프로세스와 어느 코드가 원인인지 좁혀 갑니다.

/proc: 커널이 보여 주는 정보

/proc은 디스크에 있는 파일이 아니라, 읽을 때마다 커널이 그 자리에서 내용을 만들어 주는 가상 파일 시스템입니다. 시스템 전체의 정보와 프로세스마다의 정보를 파일의 형태로 보여 줍니다.

cat /proc/loadavg                       # 부하 평균
nproc                                   # 이 프로세스가 쓸 수 있는 CPU 수
cat /proc/PID/status                    # 이름, 상태, 스레드 수, VmRSS 같은 메모리 정보
cat /proc/PID/maps                      # 가상 주소 구간과 권한, 매핑된 파일
ls -l /proc/PID/fd                      # 열린 파일 디스크립터와 그 대상
tr '\0' ' ' < /proc/PID/cmdline; echo   # 실행한 명령줄
cat /proc/PID/io                        # 읽고 쓴 바이트 수

PID에는 확인할 프로세스의 번호를 넣습니다. /proc/PID/maps는 8장과 9장에서 본 주소 공간의 배치를 그대로 보여 주고, /proc/PID/fd는 10장 4편의 fd 테이블을 보여 줍니다. 다른 사용자의 프로세스는 볼 수 없는 파일도 있고, 여러 파일을 차례로 읽는 동안 프로세스가 바뀌거나 끝날 수 있다는 점도 기억해 둡니다.

부하 평균 읽기

proc_loadavg(5)에 따르면 /proc/loadavg의 처음 세 값은 실행 대기 상태(R)이거나 디스크 I/O를 기다리는 상태(D)인 태스크 수의 1분, 5분, 15분 평균입니다. uptime과 top이 보여 주는 값도 이것입니다. 커널은 5초마다 지금의 태스크 수를 지수 이동 평균에 섞어 넣는데, 다음 코드는 그 계산을 흉내 냅니다.

import math

def loadavg(runnable, seconds, window):
    load = 0.0
    decay = math.exp(-5 / window)            # 커널은 5초마다 지수 이동 평균을 갱신한다
    for _ in range(seconds // 5):
        load = load * decay + runnable * (1 - decay)
    return load

# 한가하던 시스템에서 태스크 4개가 계속 실행 대기 상태가 된 지 60초 뒤
for minutes in (1, 5, 15):
    print(f"{minutes:>2}분 평균: {loadavg(4, 60, minutes * 60):.2f}")

 1분 평균: 2.53
 5분 평균: 0.73
15분 평균: 0.26

태스크 넷이 1분 동안 쉬지 않고 실행을 기다렸지만, 1분 평균은 아직 4에 이르지 못했고 15분 평균은 거의 움직이지 않았습니다. 세 값을 함께 보면 부하가 막 오르는 중인지 내려가는 중인지 알 수 있습니다. 부하 평균은 CPU 사용률이 아니라 대기 중인 태스크의 수이므로, CPU 수와 비교해 읽어야 합니다. CPU가 4개인 서버의 부하 4는 꽉 찬 상태이지만 CPU가 32개라면 한가한 상태입니다. D 상태도 세므로, CPU는 한가한데 부하 평균만 높다면 디스크나 네트워크 파일 시스템을 기다리는 태스크를 의심해야 합니다.

더 깊이: 자원별로 멈춘 시간을 보여 주는 PSI

부하 평균은 CPU를 기다리는 태스크와 디스크를 기다리는 태스크를 한 숫자로 세므로, 어느 자원이 모자란지는 따로 알아내야 합니다. Linux의 PSI(pressure stall information)는 이 질문에 자원별로 답합니다. PSI 문서에 따르면 /proc/pressure/ 아래의 cpu, memory, io 파일은 각각 some과 full 두 줄로, 최근 10초, 60초, 300초 동안 그 자원을 기다리느라 멈춘 시간의 비율과 마이크로초 단위의 누적 시간을 보여 줍니다.

두 줄의 차이가 중요합니다. some은 적어도 일부 태스크가 그 자원을 기다리며 멈춘 시간의 비율이고, full은 쉬고 있지 않은 모든 태스크가 동시에 멈춘 시간의 비율입니다. full 상태에서는 CPU 시간이 쓸모 있는 일에 쓰이지 못하고 버려지므로, 문서는 이 상태에 오래 머무는 작업을 스래싱 중이라고 봅니다. 시스템 전체의 CPU에는 full이 정의되지 않지만, Linux 5.13부터는 호환성을 위해 그 줄을 0으로 보여 줍니다.

감시 프로그램은 파일을 주기적으로 읽는 대신 기준을 정해 두고 기다릴 수도 있습니다. 예를 들어 /proc/pressure/memory를 열어 some 150000 1000000을 쓰면 1초 동안 일부 태스크가 메모리 때문에 멈춘 시간이 150ms를 넘을 때 깨워 달라는 기준이 등록되고, 프로그램은 그 fd를 poll()이나 epoll로 기다립니다. cgroup v2를 쓰는 시스템에서는 cgroup마다 같은 형식의 cpu.pressure, memory.pressure, io.pressure 파일이 있어, 컨테이너 하나가 받는 압박만 따로 볼 수 있습니다.

strace: 시스템 콜 엿보기

strace는 프로세스가 부르는 시스템 콜과 받는 신호를 하나하나 보여 줍니다. 프로그램의 소스가 없어도, 그 프로그램이 어떤 파일을 열려다 실패하는지, 어디에 연결하려다 기다리는지 알 수 있습니다.

strace ./myprogram                         # 처음부터 추적
strace -p 1234                             # 실행 중인 프로세스에 붙기
strace -f ./myprogram                      # 자식 프로세스와 스레드까지
strace -e trace=file ./myprogram           # 파일 경로를 다루는 시스템 콜만
strace -e trace=network -p 1234            # 네트워크 시스템 콜만
strace -tt -T -p 1234                      # 각 호출의 시각과 걸린 시간
strace -c ./myprogram                      # 시스템 콜별 횟수, 오류, 시간 요약

strace(1)에 따르면 출력의 한 줄은 시스템 콜 이름, 괄호 안의 인자, 등호 뒤의 반환값으로 이루어집니다. 매뉴얼은 cat /dev/null을 추적한 예로 open("/dev/null", O_RDONLY) = 3을 들고, 실패한 호출은 open("/foo/bar", O_RDONLY) = -1 ENOENT (No such file or directory)처럼 반환값 -1 뒤에 오류 이름과 설명이 붙는다고 설명합니다. 다만 glibc 2.26부터는 open() 함수가 openat() 시스템 콜을 쓰므로, 요즘 시스템에서 직접 추적하면 openat(AT_FDCWD, "/dev/null", O_RDONLY) = 3처럼 보입니다. 설정 파일을 찾지 못해 실패하는 프로그램이라면, -e trace=file로 어떤 경로들을 찾아보다 ENOENT를 받는지 보면 됩니다.

strace -c가 보여 주는 시간 비율의 분모는 추적한 시스템 콜에 쓴 커널의 CPU 시간 합계입니다. 프로그램 전체의 실행 시간이 아니므로, 여기서 read가 65%라고 해서 프로그램이 시간의 65%를 읽기에 썼다는 뜻은 아닙니다. 또 strace는 ptrace로 시스템 콜마다 프로그램을 멈추고 값을 읽어 오므로, 시스템 콜이 많은 프로그램은 몇 배씩 느려질 수 있습니다. 운영 중인 서버에 붙일 때는 이 영향을 각오하고 짧게 쓰거나, 아래의 perf trace나 eBPF 도구처럼 부담이 적은 도구를 고릅니다.

커널 로그와 서비스 로그

커널은 하드웨어 오류, 드라이버의 경고, OOM 킬러의 동작처럼 커널 수준에서 일어난 일을 커널 로그에 남깁니다. 커널 로그는 dmesg로 읽고, systemd를 쓰는 시스템에서는 저널에도 함께 모이므로 journalctl -k로도 볼 수 있습니다. 아래 앞의 두 줄은 dmesg로 커널 로그만 보고, 나머지는 journalctl로 커널과 서비스의 로그를 부팅, 시간, 우선순위로 골라 봅니다. -T는 부팅 뒤 지난 초로 적힌 시각을 사람이 읽는 시각으로 바꾸어 주지만, 절전 모드를 거친 시스템에서는 시각이 어긋날 수 있습니다.

sudo dmesg -T --level=err,warn | tail -20   # 사람이 읽을 수 있는 시각과 함께, 오류와 경고만
sudo dmesg -T | grep -i 'out of memory'      # OOM 킬러가 동작했는지
journalctl -k -b                             # 이번 부팅의 커널 로그(systemd 저널)
journalctl -u myapp --since '2 hours ago'    # 특정 서비스의 로그
journalctl -p err -b                         # 이번 부팅에서 오류 이상의 메시지
journalctl --disk-usage                      # 저널이 차지하는 디스크 공간

OOM 킬러가 프로세스를 종료하면 커널 로그에 "Out of memory"로 시작하는 줄과 함께 종료된 프로세스의 PID와 이름, 그때의 메모리 사용량이 남습니다. 애플리케이션이 아무 오류 없이 갑자기 사라졌다면 가장 먼저 확인할 곳입니다. 컨테이너 안이라면 13장에서 본 cgroup의 메모리 한도에 걸린 것일 수 있습니다.

systemd를 쓰지 않는 로그는 /var/log 아래의 파일에 남습니다. Debian 계열은 /var/log/syslog와 인증 기록인 /var/log/auth.log를, Red Hat 계열은 /var/log/messages와 /var/log/secure를 씁니다. 원인을 찾을 때는 애플리케이션 로그, 서비스의 재시작 기록, 커널 로그를 같은 시각으로 맞춰 나란히 놓고 봅니다.

코어 덤프로 죽은 순간 보기

프로그램이 잘못된 메모리에 접근해 세그멘테이션 오류(segmentation fault)로 죽으면, 커널은 그 순간의 메모리와 레지스터를 코어 덤프(core dump) 파일로 남길 수 있습니다. 다음 프로그램은 NULL 포인터를 strlen에 넘겨 죽습니다.

#include <stdio.h>
#include <string.h>

static size_t name_length(const char *name)
{
    return strlen(name);                 /* name이 NULL이면 여기서 죽는다. */
}

int main(void)
{
    const char *name = NULL;             /* 설정을 읽지 못해 NULL로 남았다고 하자. */
    printf("%zu\n", name_length(name));
    return 0;
}

gcc -g -O0 -o crash crash.c       # -g: 디버그 정보를 넣는다
ulimit -c unlimited               # 이 셸에서 코어 덤프 크기 제한을 푼다
./crash                           # 세그멘테이션 오류로 죽는다
cat /proc/sys/kernel/core_pattern # 코어 덤프가 어디로 가는지
coredumpctl list                  # systemd-coredump가 받았다면 그 목록
coredumpctl debug crash           # 가장 최근 덤프를 디버거(기본은 gdb)로 연다

코어 덤프가 어디에 저장되는지는 core_pattern이 정합니다. 요즘 배포판은 대개 이 값이 |로 시작해 덤프를 systemd-coredump 같은 프로그램에 넘기므로, 현재 디렉터리에 core 파일이 생기지 않고 coredumpctl로 찾아야 합니다. gdb가 열리면 bt로 죽은 순간의 호출 스택을 보고, frame 1처럼 스택의 한 단계로 옮겨 가 print name이나 info locals로 변수의 값을 확인합니다. 이 프로그램이라면 스택의 맨 위에 strlen이, 그 아래에 name_length와 main이 보이고, name의 값이 0, 곧 NULL이라는 것을 알 수 있습니다.

코어 덤프에는 프로세스의 메모리가 통째로 들어 있으므로 비밀번호나 토큰 같은 민감한 정보도 함께 담깁니다. 운영 서버에서는 덤프를 저장할 곳의 접근 권한을 제한하고, 크기와 보관 기간을 정해 두어야 합니다.

perf로 CPU 시간이 쓰인 곳 찾기

perf는 Linux 커널과 함께 개발되는 성능 분석 도구입니다. CPU의 하드웨어 성능 계수기와 커널의 이벤트를 써서, 프로그램이 어디에서 CPU 시간을 쓰는지, 캐시 미스나 컨텍스트 스위칭이 얼마나 일어나는지를 잽니다.

sudo perf top                                      # 지금 CPU를 많이 쓰는 함수(실시간)
perf stat ./myprogram                              # 실행 동안의 사이클, 명령 수, 문맥 교환, 페이지 폴트
perf stat -e cache-references,cache-misses ./myprogram
sudo perf record -g -p 1234 -- sleep 30            # 30초 동안 호출 스택을 표본으로 수집
sudo perf report                                   # 함수별로 표본이 얼마나 모였는지
sudo perf trace -p 1234                            # strace보다 가볍게 시스템 콜 추적

perf record는 일정한 간격으로 CPU가 실행 중인 위치와 호출 스택을 표본으로 모읍니다. perf report에서 어떤 함수가 표본의 45%를 차지한다면, 측정한 동안 그 프로세스가 CPU에서 실행되던 표본의 45%가 그 함수에 있었다는 뜻입니다. 디스크를 기다리며 잠든 시간은 CPU에서 실행되지 않았으므로 기본 CPU 표본에는 잡히지 않습니다. 수집한 스택을 플레임 그래프(flame graph)로 그리면 어떤 호출 경로가 CPU 시간을 많이 쓰는지 한눈에 볼 수 있으며, 그래프의 가로 폭은 표본의 양이지 시간의 순서가 아닙니다.

그림처럼 strace -c, perf report, 플레임 그래프의 백분율은 분모가 서로 다릅니다. 숫자를 비교하기 전에, 각 도구가 어떤 프로세스를 얼마 동안 무엇을 기준으로 셌는지 먼저 맞춰야 합니다.

최근에는 eBPF로 만든 도구도 많이 씁니다. eBPF는 검증을 거친 작은 프로그램을 커널 안에서 실행해, 커널을 고치거나 프로세스를 멈추지 않고도 사건을 모아 요약합니다. bcc 도구 모음의 execsnoop은 새로 실행되는 프로그램을, opensnoop은 열리는 파일을, biolatency는 디스크 I/O의 지연 분포를 보여 주며, strace보다 부담이 훨씬 적어 운영 중인 서버에서도 쓸 수 있습니다.

정리

• USE 방법은 자원마다 사용률, 포화, 오류를 빠짐없이 확인해 의심 가는 자원을 찾는 점검표입니다.
• /proc은 커널이 읽을 때마다 만들어 주는 정보이며, 부하 평균은 실행 대기와 D 상태 태스크 수의 지수 이동 평균이므로 CPU 수와 비교해 읽습니다.
• strace는 시스템 콜과 그 결과를 보여 주어 실패한 호출을 찾기 좋지만, 추적 대상을 크게 느리게 만듭니다.
• 커널 로그는 OOM과 하드웨어 오류를, 코어 덤프와 gdb는 프로그램이 죽은 순간의 호출 스택과 변수를 보여 줍니다.
• perf는 CPU 시간이 쓰인 곳을 표본으로 찾으며, 도구마다 백분율의 분모가 다르므로 그대로 비교하면 안 됩니다.

연습 문제

1. 백분율의 분모

어떤 프로그램이 실제로 10초 동안 실행되었고, strace -c가 집계한 시스템 콜의 커널 CPU 시간은 모두 0.2초, 그 가운데 read가 0.13초, write가 0.04초였습니다. 같은 실행을 perf로 기록했더니 CPU 표본 1,000개 가운데 hash_lookup이 450개였습니다. read, write, hash_lookup의 비율을 각 도구의 기준으로 구하고, "read가 6.5초를 썼다"는 해석이 왜 틀렸는지 설명하세요.

2. CPU는 한가한데 부하가 높다

CPU가 4개인 서버에서 uptime이 보여 주는 부하 평균이 8.0, 3.0, 1.0인데, top을 보니 CPU의 60%가 놀고 있습니다. 이 상황을 어떻게 해석하고, 다음으로 무엇을 확인해야 하나요?

3. 운영 서버에 strace를 붙여도 될까

초당 수만 번의 시스템 콜을 부르는 운영 중인 서버가 가끔 느려집니다. 원인을 찾으려고 strace -f -p로 붙이려 할 때 무엇을 조심해야 하나요? 대안도 제시하세요.

다음 글 성능 튜닝과 OS 면접 주제에서는 커널 파라미터를 조정해 성능을 바꾸는 방법과, 운영체제 면접에서 자주 나오는 주제를 앞의 장들과 연결해 정리합니다.