strace -f로 멀티프로세스/스레드 시스템 콜 한 번에 추적하기

strace nginxstrace sh script.sh로 걸어보면 부모 프로세스의 fork/execve까지만 잡히고, 실제 작업을 하는 워커/자식 프로세스 내부는 안 보인다. -f(--follow-forks)가 이 문제를 해결한다. 이 글에서는 -f/-ff/-e trace=로 멀티프로세스·멀티스레드 프로그램을 추적하는 방법을 실제 실행 결과로 정리한다.

-f와 -ff

-ffork/vfork/clone으로 생기는 자식(스레드 포함)을 자동으로 추적에 추가한다. -ff는 여기에 --output-separately를 더해 -o 파일이름별로 파일이름.PID로 나눠 쓴다.

PID 프리픽스 형식조건
7743 execve(...) (숫자만)-o 파일로 저장할 때 (이 글의 예시 대부분)
[pid 7743] ... (대괄호)-o 없이 터미널로 출력하며 프로세스 간 호출이 실제로 겹칠 때

셸 파이프라인 — -f 유무 비교

$ strace -o /tmp/no_f.log sh -c 'cat /etc/os-release | grep VERSION'
$ cat /tmp/no_f.log
execve("/usr/bin/sh", ["sh", "-c", "cat /etc/os-release | grep VERSION"], ...) = 0
...
pipe2([3, 4], 0)                       = 0
clone(...) = 7446
clone(...) = 7447
close(3)                               = 0
close(4)                               = 0
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 7446

-f 없이는 clone된 PID만 보이고 cat/grep 내부 동작은 안 보인다. -f를 붙이면:

$ strace -f -o /tmp/with_f.log sh -c 'cat /etc/os-release | grep VERSION'
$ grep -E 'clone\(|execve\(|openat.*os-release|write\(1' /tmp/with_f.log
8196  clone(...)     = 8197
8197  execve("/usr/bin/cat", ["cat", "/etc/os-release"], ...) = 0
8197  openat(AT_FDCWD, "/etc/os-release", O_RDONLY|O_CLOEXEC) = 3
8197  write(1, "PRETTY_NAME=\"Ubuntu 24.04.4 LTS\""..., 400) = 400
8196  clone(...)     = 8198
8198  execve("/usr/bin/grep", ["grep", "VERSION"], ...) = 0
8198  write(1, "VERSION_ID=\"24.04\"\nVERSION=\"24.0"..., 79) = 79

8197=cat, 8198=grep. grep VERSIONVERSION_ID 한 줄이 아니라 VERSION/VERSION_CODENAME까지 세 줄(79바이트)을 매칭한 것도 드러난다(부분 문자열 매칭). 원본 로그엔 동적 링커 호출과 <unfinished ...>/<... resumed> 수백 줄이 섞여 있어 위 예시는 grep으로 걸러낸 것이다.

멀티프로세스 파이썬을 -ff로 분리 추적

import multiprocessing
import os
import time


def worker(worker_id):
    pid = os.getpid()
    path = f"/tmp/worker_{worker_id}.log"
    with open(path, "w") as f:
        f.write(f"worker {worker_id} pid={pid}\n")
    time.sleep(0.2)


if __name__ == "__main__":
    procs = []
    for i in range(3):
        p = multiprocessing.Process(target=worker, args=(i,))
        p.start()
        procs.append(p)
    for p in procs:
        p.join()
    print("all workers done")
$ strace -f -ff -o /tmp/mp_trace -- python3 mp_trace_demo.py
$ ls /tmp/mp_trace.*
/tmp/mp_trace.7860  /tmp/mp_trace.7861  /tmp/mp_trace.7862  /tmp/mp_trace.7863

$ grep openat /tmp/mp_trace.7861
openat(AT_FDCWD, "/tmp/worker_0.log", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 6

메인(7860)과 워커 3개(7861~7863)가 파일별로 나뉘어 각 프로세스 흐름을 끊김 없이 읽을 수 있다.

-e trace=로 노이즈 줄이기

자주 쓰는 범주: network, file, process, signal, ipc, desc, memory. 콤마로 나열 가능.

$ strace -f -e trace=network,file -o /tmp/net_trace.log -- curl -s https://example.com -o /dev/null
$ grep -E 'connect|openat' /tmp/net_trace.log
7934  openat(AT_FDCWD, "/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 7
7934  connect(7, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("172.66.147.243")}, 16) = 0
7933  openat(AT_FDCWD, "/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 6

DNS 조회·연결이 curl 본 프로세스(7933)가 아니라 별도 스레드(7934)에서 일어나는 것도 -f 없이는 안 보인다. connectEINPROGRESS 없이 바로 = 0인 것도 실제 확인한 값(블로킹 connect). 특정 콜만 나열(-e trace=openat,connect,execve)도 가능.

이미 떠 있는 프로세스에 -f -p로 붙기

-f -p <PID>는 대상이 멀티스레드면 스레드 전부에 붙는다. 대상이 지금 셸의 자식/후손이 아니면(다른 터미널, systemd 서비스 등) Yama ptrace_scope=1에 막혀 Operation not permitted가 날 수 있다 — root로 붙거나 대상이 prctl(PR_SET_PTRACER, ...)로 미리 허용해야 한다.

$ pgrep -f my_threaded_app.py
8064

$ strace -f -tt -e trace=futex,write -p 8064
strace: Process 8064 attached with 3 threads
[pid  8066] 00:01:50.483133 futex(0xb49280, FUTEX_WAIT_BITSET_PRIVATE, 0, {...} 
[pid  8067] 00:01:50.483243 futex(0xb49280, FUTEX_WAKE_PRIVATE, 1 
[pid  8066] 00:01:50.483264 <... futex resumed>) = -1 EAGAIN (Resource temporarily unavailable)
[pid  8067] 00:01:50.483278 <... futex resumed>) = 0
[pid  8067] 00:01:50.483389 write(1, "worker-2 tick\n", 14 
[pid  8067] 00:01:50.483437 <... write resumed>) = 14

attached with 3 threads로 attach 시점 스레드 수(메인+워커 2개)를 확인. 대괄호 형식은 두 스레드가 futex로 서로를 깨우며 진짜 겹쳐 실행되기 때문. Python GIL 특성상 futex 노이즈가 -e trace=futex,write로 걸러도 상당히 남는다.

주의사항

  • -f는 ptrace 기반이라 프로세스 수만큼 오버헤드 증가. 장시간 전체 추적은 성능 저하 유발.
  • -ff는 fork가 잦을수록 파일 수도 비례 증가 — fd/디스크 용량 고려.
  • 도커 기본 seccomp 프로필은 ptrace(2)를 막는다. --cap-add=SYS_PTRACE 또는 --security-opt seccomp=unconfined 필요.
  • -f는 attach 이후 생성된 자식만 추적. 이미 떠 있던 자식은 -p 추가 필요.
  • 출력이 인터리빙되면 -tt 타임스탬프나 grep '\[pid 12345\]'로 필터링. 프로세스 많으면 처음부터 -ff.

마무리

-f로 자식까지 추적 범위를 넓히고, 프로세스가 많으면 -ff -o로 파일 분리, -e trace=로 관심 콜만 남기면 된다. 멀티스레드 프로세스는 -f -p로 스레드 전체에 붙는다.

참고

답글 남기기