원인 불명 CPU사용량 급증에 대처했던 방법 (3)

1년이 지난 지금, AI와 함께 다시 돌아보다

왜 다시 돌아보게 되었는가

이전 두 편의 글 (원인 불명 CPU사용량 급증에 대처했던 방법 1편, 2편)에서, Datadog 프로파일링이 원인이라는 것까지는 찾아냈지만 “정확히 왜?”에 대한 답은 결국 내지 못하고 글을 마무리했었다.

2편의 마지막에 이렇게 적었었다.

더 깊게 파보기에는, 시간을 쏟는 공수 대비 효과가 적다고 판단했습니다.

맞는 판단이었다. 이미 해결 방법(프로파일링 끄기)은 나와있는 상태였고, 다른 업무에 집중하는 것이 옳았다. 그런데 그 이후로도 가끔씩 머릿속에서 이 문제가 떠올랐다. “그래서 진짜 원인이 뭐였는데?”라는 질문이 해소되지 않은 채로 남아있었기 때문이다.

최근 블로그를 정리하면서 예전 글들을 다시 읽게 되었고, 이번에는 AI(Claude)에게 당시 수집했던 증거들을 전부 보여주고 분석을 요청해봤다. 혼자서는 놓쳤던 부분들이 꽤 보여서, 그 내용을 기록으로 남기려 한다.

CASE 1 다시 보기: SIGPROF 무한 반복

미해결 의문 1: 왜 일부 인스턴스에서만 발생했는가?

당시 글에서 이렇게 적었었다.

Datadog의 프로파일링 signal과 Node.js의 워커 스레드/이벤트 루프 상태가 우연히 맞물리면서 SIGPROF 시그널이 점점 누적되는 현상이 발생한 것으로 보입니다.

솔직히 이건 “잘 모르겠다”를 점잖게 적은 것에 가까웠다.

AI에게 당시 strace 결과를 보여줬더니, 이런 포인트를 짚어줬다.

strace에서 프로파일러 스레드(pid 2911)가 tgkill()로 직접 SIGPROF를 보내고 있습니다. 이건 커널의 setitimer()가 주기적으로 보내는 것이 아니라, ddprof의 스레드가 명시적으로 시그널을 발사하고 있다는 뜻입니다.

이 지적을 보고 다시 strace 결과를 살펴봤다.

[pid  2911] getpid()                    = 2853
[pid  2911] tgkill(2853, 2853, SIGPROF) = 0

맞다. pid 2911(v8:ProfEv 스레드)이 getpid()로 PID를 가져온 뒤, tgkill()로 직접 SIGPROF를 쏘고 있다. 커널 타이머가 보내는 게 아니라, ddprof가 자체적으로 시그널을 보내고 있었던 것이다. 그렇다면, 이 스레드의 루프에 rate limiting 버그가 있거나, 특정 조건에서 throttle 없이 tight loop에 빠질 수 있다는 뜻이 된다.

그리고 이건 “왜 일부 인스턴스에서만 발생했는가?”에 대한 설명이 된다. 프로파일러 스레드가 tight loop에 진입하는 조건이 race condition이라면, 확률적으로 일부 인스턴스에서만 걸려드는 것이 자연스럽다. V8 GC 타이밍, JIT 컴파일 상태, 특정 메모리 레이아웃 등이 맞물려야 발생하는 것이다.

시간이 지날수록 더 많은 인스턴스에서 발생했던 것도 설명이 된다. 각 인스턴스가 단위 시간당 일정 확률로 이 조건에 걸려드니까, 시간이 지나면 자연스럽게 걸려드는 인스턴스가 늘어나는 것이다.

미해결 의문 2: 왜 한번 올라가면 절대 돌아오지 않는가?

이것도 당시에는 명확하게 설명하지 못했었다. AI의 분석은 단순했다.

프로파일러 스레드가 한번 tight loop에 진입하면, “내가 CPU를 과도하게 쓰고 있으니 멈춰야겠다”는 자기 교정 로직이 없기 때문입니다. 외부에서 프로세스를 죽이거나 설정을 바꾸지 않는 한, 스스로 안정 상태로 돌아올 수 없는 구조입니다.

피드백 루프가 한쪽 방향으로만 동작한다는 것이다. 프로파일러가 SIGPROF를 쏘고 → 핸들링에 CPU를 쓰고 → 프로파일러 스레드는 상관없이 계속 쏘고 → CPU가 더 올라가고. 여기서 “CPU가 너무 높으니 시그널 빈도를 줄이자”는 피드백이 없다. 당연한 것 같으면서도, 명확하게 정리하고 나니 속이 시원해지는 느낌이다.

CASE 2 다시 보기: SIGSEGV 무한 반복

AI에게 strace 결과와 ddprof의 sigsegv_handler 코드를 함께 보여줬더니, 내가 당시에 세웠던 가설에 대해 반론을 제시했다.

당시 나의 가설

2편에서 이렇게 추측했었다.

핸들러에서 버퍼를 다루거나, backtrace, backtrace_symbols_fd 함수를 실행하는 도중에 SIGSEGV시그널이 다시 발생 됨

즉, 시그널 핸들러 안에서 또 SIGSEGV가 터져서 재귀적으로 무한 반복된다는 가설이었다.

AI의 반론: 그 핸들러는 실행되고 있지 않다

AI가 strace 증거를 근거로 이렇게 반론했다.

ddprof의 sigsegv_handler는 fprintf(), printf(), backtrace_symbols_fd(), exit(-1)을 호출합니다. 그런데 strace에서 보이는 패턴은 read(7) → write(22) → write(8) → rt_sigreturn입니다. fprintf나 exit의 흔적이 전혀 없습니다. 실제로 실행되는 핸들러는 ddprof의 것이 아닐 가능성이 높습니다.

이건 생각해보지 못했던 부분이다. strace에 찍힌 시스템 콜 패턴과, 내가 코드에서 찾은 핸들러의 동작이 일치하지 않는다는 것이다.

AI는 이 패턴이 self-pipe trick이라고 했다.

read(7) → write(22) → write(8) → rt_sigreturn 패턴은, Node.js(libuv)가 시그널을 비동기적으로 처리하기 위해 사용하는 self-pipe trick의 전형적인 패턴입니다. 시그널이 오면 파이프에 1바이트를 써서 이벤트 루프에 알리고, 나중에 이벤트 루프가 처리하는 방식입니다.

그렇다면 시그널 핸들러 등록 순서가 중요해진다. sigaction()으로 마지막에 등록한 쪽의 핸들러가 실행되니까, ddprof가 먼저 핸들러를 설치하고 나중에 Node.js가 자신의 핸들러로 덮어썼다면, ddprof의 sigsegv_handler는 호출되지 않는다.

그래서 결국 실행되는 것은 Node.js 쪽의 SIGSEGV 핸들러이고, 이 핸들러는 exit()를 호출하지 않고 rt_sigreturn으로 정상 복귀한다.

그러면 왜 무한 루프인가?

이 부분이 핵심이다. AI의 설명을 듣고 ‘아..’ 했던 부분이다.

시그널 핸들러가 rt_sigreturn으로 정상 복귀하면, CPU는 시그널이 발생했던 바로 그 명령어(faulting instruction)를 다시 실행합니다. 원인(NULL 포인터)이 해결되지 않았으니, 같은 명령어가 다시 SIGSEGV를 발생시키고, 핸들러가 다시 호출되고, 다시 복귀하고, 다시 같은 명령어를 실행하고… 영원히 반복됩니다.

내 가설은 “핸들러 안에서 SIGSEGV가 재발생한다”였는데, 실제로는 더 단순했다. 핸들러는 정상적으로 끝나지만, 복귀한 지점의 코드가 여전히 잘못된 메모리를 참조하고 있어서 바로 다시 SIGSEGV가 터지는 것이다.

ddprof의 핸들러가 실행됐다면 exit(-1)로 프로세스가 종료됐을 것이다. 그런데 Node.js의 핸들러가 대신 실행되면서, 프로세스가 죽지도 않고 복구도 안 되는 최악의 상태에 빠진 것이다.

si_addr=0xe3a8의 의미

AI가 SIGSEGV의 fault address에 대해서도 분석을 해줬다.

si_addr=0xe3a8은 약 58KB 정도의 매우 낮은 주소입니다. 이건 전형적인 NULL 포인터 + 구조체 오프셋 패턴입니다. 예를 들어 ((struct SomeStruct*)NULL)->field처럼, NULL인 포인터를 통해 구조체의 특정 필드에 접근하려다 발생한 것으로 보입니다.

당시에는 si_addr 값을 보면서도 이게 의미하는 바를 깊이 생각해보지 못했었다. NULL 포인터 역참조에 구조체 오프셋이 더해진 주소라는 것이고, ddprof 내부의 어떤 구조체 포인터가 NULL 상태에서 접근이 시도된 것이다.

write(22)가 EAGAIN인 이유

당시에도 확인했지만 왜 EAGAIN이 발생하는지에 대한 설명은 하지 못했었다.

이 SIGSEGV 루프가 극도로 빠르게 돌면서 fd 22(파이프)에 16바이트씩 계속 쓰려고 합니다. 리눅스 파이프 버퍼는 기본 64KB인데, Consumer 쪽이 읽는 속도보다 SIGSEGV 루프가 쓰는 속도가 압도적으로 빠르니 순식간에 버퍼가 가득 찬 것입니다.

논리적으로 맞는 것 같다. SIGSEGV가 발생하고 핸들러가 복귀하고 다시 SIGSEGV가 발생하는 이 사이클은 거의 CPU 클럭 수준으로 빠르게 반복될 것이다. 어떤 Consumer가 파이프에서 읽어가더라도 이 속도를 따라잡을 수는 없다.

두 패턴의 관계

AI에게 “두 패턴이 관련이 있을 수 있을까?”라고 물었더니, 이런 시나리오를 제시했다.

1. SIGPROF 폭격(CASE 1)으로 CPU가 과부하에 걸립니다.
2. 과부하 상태에서 ddprof 내부의 어떤 포인터가 race condition으로 NULL이 됩니다.
3. 해당 포인터를 통한 메모리 접근 시 SIGSEGV가 발생합니다(CASE 2).
4. SIGSEGV 무한 루프에 진입합니다.

즉, CASE 1이 CASE 2의 트리거였을 가능성이 있습니다.

이건 확인할 방법이 없지만, 논리적으로는 설득력이 있다. SIGPROF 폭격으로 인해 context switching이 과도하게 발생하면, ddprof 내부의 상태 관리가 꼬일 수 있다. 멀티스레드 환경에서 과부하 상태의 race condition은 NULL 포인터를 만들어내기 충분하다.

만약 그때로 돌아간다면

이 분석을 하면서, “그때 이런 것들을 해봤으면 더 명확한 답을 얻을 수 있었겠구나” 하는 것들이 보였다.

/proc에서 시그널 핸들러 확인

cat /proc/<PID>/status | grep Sig

이 명령으로 어떤 시그널에 핸들러가 설치되어 있는지, 어떤 시그널이 마스킹되어 있는지 확인할 수 있다. SIGSEGV 핸들러가 실제로 누구의 것인지(ddprof인지, Node.js인지) 확인하는 데 도움이 되었을 것이다.

메모리 매핑 확인

cat /proc/<PID>/maps

si_addr=0xe3a8 주소가 정말로 unmapped인지, 아니면 mapped이지만 권한이 없는 영역인지 확인할 수 있다. NULL 포인터 역참조가 맞는지 확인하는 가장 직접적인 방법이었을 것이다.

GDB로 faulting instruction 직접 확인

gdb -p <PID>

GDB로 프로세스에 attach해서, SIGSEGV가 발생하는 정확한 명령어와 콜스택을 확인할 수 있었을 것이다. 어떤 코드가 NULL 포인터를 역참조하고 있는지 한 번에 알 수 있었을 것이다.

strace -k 옵션

strace -k -p <PID>

-k 옵션을 사용하면 각 시스템 콜마다 커널 스택 트레이스를 함께 출력해준다. 시그널 핸들러의 호출 경로를 더 명확하게 볼 수 있었을 것이다.

글을 마치며

당시 2편의 글을 마무리하며 이렇게 적었었다.

결국 원인을 명확하게 찾아내지 못했다.

1년이 지나서 AI의 도움을 빌려 다시 돌아보니, 당시 수집했던 증거들 안에 이미 답의 단서가 있었다. strace 결과의 시스템 콜 패턴, si_addr의 값, 파이프의 EAGAIN 에러. 이것들을 조금만 더 깊이 들여다봤으면 더 명확한 그림을 그릴 수 있었을 것이다.

그렇다고 당시의 판단이 틀렸다고 생각하지는 않는다. 공수 대비 효과라는 것은 현실적으로 중요한 기준이고, 해결 방법이 이미 있는 상태에서 root cause를 끝까지 파는 것은 개인적인 만족 외에는 비효율적이었다.

다만, 이렇게 시간이 흐른 뒤에 다시 돌아볼 수 있다는 것. 그리고 혼자서는 놓쳤던 부분을 AI라는 도구를 통해 새로운 시각으로 볼 수 있다는 것. 이건 꽤 재미있는 경험이었다.

개발이라는 것은 결국 모르는 것을 알아가는 과정이고, 그 과정이 1년 뒤에 다시 이어질 수도 있구나 하는 생각이 든다.

그때 끝까지 파보지 못했던 아쉬움이, 지금이라도 조금은 해소된 것 같다.