PM2 재시작 루프로 CPU 100%가 된 원인과 해결

명령과 계산을 처리하는 서버의 CPU 사용률이 거의 100%에 붙어 있었다.
재부팅하면 잠깐 조용해졌지만 오래가지 않았다.
얼마 지나지 않아 다시 같은 상태가 됐다.

보통 이런 상황에서는 실행 중인 프로세스와 CPU 사용량을 실시간으로 보여 주는 top부터 연다.
나도 그랬다.
그런데 이번에는 목록 맨 위에 계속 머무는 프로세스가 없었다.
잠깐 CPU를 쓰고 사라지는 이름만 바뀌어 보였다.
Docker나 네트워크, 디스크 읽기·쓰기 작업인 I/O도 의심했지만, 화면 한 장만으로는 어느 쪽도 확실하게 지목할 수 없었다.

CPU 100%는 원인이 아니라 결과다

CPU 사용률이 100%라는 숫자만으로 애플리케이션이 계산을 많이 했다고 결론내릴 수 없다.
Linux는 CPU 시간을 사용자 코드, 운영체제 내부 작업, I/O를 기다리는 시간과 아무 일도 하지 않은 시간 등으로 나눠 보여 준다.

이 값도 단독 진단은 아니다.
컨테이너의 CPU 제한, 가상 서버의 steal time, 여러 코어의 평균 때문에 화면을 해석하는 기준이 달라질 수 있다.
다만 top의 프로세스 순위와 CPU 시간의 구성을 함께 보면 다음 조사 방향을 좁힐 수 있다.

이번 서버에서는 한 프로세스의 user 시간이 계속 높지 않았고 system 비중이 높았다.
그래서 코드 프로파일러로 함수 하나를 찾기보다 운영체제가 왜 프로세스를 계속 만들고 있는지부터 살폈다.

계속 바뀌는 범인

나중에 생각해 보니 top은 사진에 가까웠다.
현관 앞에서 누군가 계속 초인종을 누르고 달아나는데 1분마다 사진만 찍으면, 빈 현관만 남을 수 있다.
이럴 때 필요한 것은 사진보다 출입 기록이다.

먼저 CPU 시간을 용도별로 나눠 보여 주는 mpstat를 실행했다.
애플리케이션 계산에 쓰이는 시간만 높은 것이 아니라 system CPU 비중이 높았고, 아무 일도 하지 않은 CPU 시간을 뜻하는 idle은 0%에 가까웠다.
system CPU는 운영체제가 프로세스 생성이나 파일·네트워크 처리 같은 일을 수행한 시간이다.
한 프로세스가 무거운 계산을 하는 상황보다 운영체제가 프로세스를 만들고 정리하는 데 바쁜 상황을 의심할 만한 신호였다.

질문을 “지금 누가 CPU를 쓰고 있나?”에서 “어떤 시스템 호출이 계속 일어나고 있나?”로 바꿨다.

아래 진단은 Linux 서버를 전제로 한다.
mpstat는 보통 sysstat 패키지에 포함되고, perf는 실행 중인 커널과 맞는 도구가 필요하다.
execsnoop은 BCC나 eBPF 기반 도구가 설치돼 있어야 하며 배포판에 따라 명령 이름과 설치 방법이 다르다.
시스템 전체의 실행을 읽기 때문에 해당 권한도 필요하다.

mpstat 1
sudo perf top
sudo execsnoop

pm2 status
pm2 logs --lines 200

mpstat 1의 1은 1초마다 새 측정값을 보여 달라는 뜻이라 순간 변화가 아닌 반복 패턴을 보기 좋다.
perf top은 CPU 시간을 많이 쓰는 커널 함수와 코드 경로를 실시간으로 보여 주고, execsnoop은 execve()로 새 프로그램이 실행될 때 부모 PID와 명령 인자를 기록한다.
둘 다 운영 서버를 계속 켜 두고 보는 도구는 아니다.
짧은 관찰 창에서 패턴을 확인하고 종료해야 추적 자체의 출력과 부하를 줄일 수 있다.
pm2 logs --lines 200에서는 끝없이 쌓인 로그를 전부 읽는 대신 최근 200줄부터 확인했다.

PM2는 Node 애플리케이션이 종료되면 다시 실행해 주는 프로세스 관리자이고, nvm은 사용할 Node 버전을 바꾸는 도구다.
종료 코드는 프로그램이 끝날 때 운영체제에 남기는 숫자로, 보통 0은 정상 종료이고 그 밖의 값은 실패 원인을 구분하는 데 쓴다.
perf에서는 새 프로세스의 바탕을 만드는 clone, 그 프로세스에서 다른 프로그램을 실행하는 execve, 커널 내부의 생성 과정인 copy_process가 반복해서 보였다.
이어 execsnoop으로 execve()의 부모 PID와 명령 인자를 따라갔다.
nvm은 보통 독립 실행 파일이 아니라 셸 함수라서 nvm이라는 별도 프로세스가 항상 보이는 것은 아니다.
대신 PM2 아래에서 실행된 셸 명령에 nvm use와 npx serve가 반복해서 나타났고, 뒤이어 Node 프로세스가 짧게 시작됐다가 종료됐다.
execsnoop만으로 보이지 않는 프로세스 생성 구간은 perf의 커널 경로와 함께 판단했다.

이제야 top에서 범인이 또렷하지 않았던 이유가 설명됐다.
하나의 프로세스가 계속 CPU를 차지한 것이 아니라, PM2가 짧은 프로세스를 끝없이 만들어 내고 있었다.
프로세스를 만들고(fork 또는 clone) 프로그램을 실행하는(exec) 동작이 폭주하는 상태라 fork/exec storm이라고 부른다.

PM2의 재시작 횟수가 말해 준 것

PM2 쪽 기록을 다시 보니 앱 네 개에 각각 약 1만 9천 회 수준의 재시작 흔적이 남아 있었다.
오류 로그도 100MB 이상 쌓여 있었다.

숫자가 컸지만 이것만으로 원인을 확정하지는 않았다.
PM2의 재시작은 원인이 아니라, 앱이 계속 실패한 결과일 수도 있기 때문이다.
그래서 문제를 일으키는 것으로 보이는 앱을 멈추고 CPU를 다시 봤다.
CPU idle이 곧바로 약 96%까지 올라왔다.

이 전후 비교가 전환점이었다.
적어도 현재의 CPU 포화가 PM2 아래의 재시작 흐름과 직접 연결돼 있다는 것은 확인할 수 있었다.

충돌은 .npmrc에 남아 있었다

앱 시작 흐름을 따라가다 nvm use가 정상적으로 끝나지 않는 것을 봤다.
npm의 사용자별 설정 파일인 .npmrc에는 전역 패키지를 설치할 기준 경로를 뜻하는 prefix가 고정돼 있었다.

nvm은 Node 버전을 바꿀 때 버전별 경로를 전환한다.
반면 npm의 고정 prefix는 패키지를 특정 경로에 두려고 한다.
시작 명령은 이 두 설정의 충돌로 실패했고, PM2는 앱을 살리려고 다시 실행했다.
같은 초기화와 실패가 계속 반복됐다.

설정은 바로 지우지 않았다.
먼저 PM2를 실행하는 서비스 계정으로 설정의 출처와 실패 범위를 읽기 전용 명령으로 확인했다.

npm config get userconfig
npm config get prefix --location=user
printf 'NPM_CONFIG_PREFIX=%s\n' "${NPM_CONFIG_PREFIX-}"
printf 'PREFIX=%s\n' "${PREFIX-}"

pm2 show "<target-app-name>"
pm2 logs "<target-app-name>" --lines 200 --nostream

.npmrc 전체를 출력하지 않은 이유는 인증 토큰 같은 비밀값이 함께 들어 있을 수 있기 때문이다.
위 명령은 사용자 설정 파일의 위치, prefix가 들어온 경로, 대상 앱의 종료 코드와 재시작 횟수만 좁혀 본다.
로그인한 셸 사용자와 PM2 서비스 계정이 다르면 같은 설정을 읽지 않으므로, 반드시 실제 앱을 실행하는 계정에서 확인해야 한다.

사용자 설정의 prefix가 실제로 남아 있고 nvm이 실패하는 실행 계보와 연결된 것을 확인한 뒤에만 설정 파일을 백업하고 해당 항목을 지웠다.
실제 사용자명과 경로를 뺀 변경 형태는 다음과 같다.

npm_user_config="$(npm config get userconfig)"
cp "$npm_user_config" "$npm_user_config.before-nvm-fix"
npm config delete prefix --location=user

설정을 바꾼 뒤에는 PM2 전체를 한꺼번에 흔들기보다 문제가 난 대상만 다시 시작한다.
그래야 다른 앱의 상태 변화가 검증 결과에 섞이지 않는다.

pm2 restart "<target-app-name>"
pm2 status

--location=user는 프로젝트나 시스템 전체 설정이 아니라 현재 사용자의 설정에서만 prefix를 지우도록 범위를 한정한다.
pm2 status에서는 지정한 앱이 시작과 종료를 반복하지 않고 online을 유지하는지 봤다.

npm config get prefix와 .npmrc를 함께 확인하는 편이 좋다.
NPM_CONFIG_PREFIX나 PREFIX 환경 변수가 셸 프로필 또는 서비스 설정에 따로 있다면 파일 한 줄만 지워서는 해결되지 않는다.
이번 기록에서 확인한 직접 충돌은 사용자 .npmrc의 prefix였다.

재시작 루프를 끊자 CPU idle이 돌아왔다

이번 사건에서 정리한 것은 사용자 .npmrc의 고정 prefix와 nvm의 경로 전환이 충돌해 앱 시작이 실패하고, PM2가 그 실패를 계속 재시도하던 흐름이다.
설정을 정리한 뒤 앱은 online을 유지했다.
문제 앱을 멈췄을 때 CPU idle이 약 96%로 돌아왔고, 수정 뒤 관찰한 범위는 85~97%였다.
처음의 0%에 가까운 idle과 지속적인 CPU 100% 상태가 관찰 기간에는 다시 나타나지 않았다.

재발 감시는 네 값을 같은 시간축에 놓으면 된다.
PM2 재시작 횟수의 증가량, 같은 prefix 오류의 발생 횟수, 초당 프로세스 생성량, system CPU와 idle이다.
계획된 배포 뒤에도 재시작 횟수와 prefix 오류가 늘지 않고 프로세스 생성량과 CPU가 기준 범위로 돌아오면 같은 루프가 다시 생기지 않았다고 판단할 수 있다.

이 조사 순서는 system CPU가 높고 top의 상위 프로세스가 계속 바뀔 때 특히 유효하다.
그때는 순간의 1등보다 부모 프로세스가 어떤 명령을 반복해서 만드는지 따라간다.
반대로 한 프로세스가 계속 CPU를 차지한다면 애플리케이션 프로파일링이 먼저다.
nvm을 쓰지 않거나 npm config get prefix, .npmrc, NPM_CONFIG_PREFIX, PREFIX에서 충돌이 확인되지 않았다면 이 글의 삭제 명령을 그대로 적용할 이유도 없다.

장기 대책은 시작 환경을 덜 흔들리게 만드는 쪽이다.
명시적인 Node 경로나 고정된 런타임 이미지를 사용하고, PM2의 재시작 지연 또는 지수 백오프를 추가하면 시작 실패가 짧은 시간에 폭주하는 속도를 낮출 수 있다.
백오프는 실패가 반복될수록 다음 재시도까지의 간격을 늘리는 방식이다.
이는 원인 수정을 대신하지 않는다.
설정 방법은 PM2 Restart Strategies에서, prefix와 관련 환경 변수의 충돌 조건은 nvm Compatibility Issues에서 확인했다.

재시작 제한은 장애를 숨기지 않고 실패 속도를 늦추는 안전장치로 둔다.
예를 들어 아래 값은 앱이 너무 빨리 죽으면 불안정한 시작으로 보고, 재시도 사이에 지연을 두는 구성의 형태를 보여 준다.

module.exports = {
  apps: [{
    name: 'web',
    script: './dist/main.js',
    min_uptime: '30s',
    max_restarts: 5,
    exp_backoff_restart_delay: 1000,
  }],
};

min_uptime: '30s'는 30초를 채워야 정상적으로 시작한 실행으로 간주한다는 기준이다.
그보다 빨리 종료되는 불안정한 실행이 연속 5회에 이르면 max_restarts: 5에 따라 PM2가 앱을 errored 상태로 두고 자동 재시작을 멈춘다.
exp_backoff_restart_delay: 1000은 첫 지연을 1초로 두고 반복 실패 때 재시도 간격을 점차 늘린다.
숫자는 서비스의 정상 기동 시간과 복구 요구에 맞춰 정해야 한다.
원인을 고치지 않은 채 재시도만 늦추면 장애 시간은 그대로 남으므로 알림과 종료 로그를 함께 연결한다.

같은 증상에서 다시 사용할 판단 순서

1. mpstat 1로 user, system, iowait, idle의 반복 패턴을 본다.
2. 한 PID가 오래 높은지, 짧은 PID가 계속 바뀌는지 구분한다.
3. 프로세스 생성이 의심되면 짧은 시간 동안 execsnoop으로 부모와 명령을 기록한다.
4. PM2 재시작 횟수와 종료 로그를 같은 시간대에 맞춘다.
5. 대상 앱 하나를 멈추는 분리 실험으로 CPU 변화가 연결되는지 확인한다.
6. 실제 서비스 계정의 npm·nvm 설정 출처를 읽기 전용으로 확인한다.
7. 원인을 수정한 뒤 대상 앱만 다시 시작하고 재시작 증가량과 CPU를 함께 본다.

이번에는 PM2 아래에서 짧은 실행이 반복되고, 대상 앱을 멈추자 idle이 약 96%로 돌아왔으며, .npmrc의 prefix 충돌을 정리한 뒤 85~97% 범위를 유지했다.
따라서 “PM2가 CPU를 많이 썼다”보다 “앱 시작 실패를 PM2가 무제한에 가깝게 반복했다”가 더 정확한 설명이다.

PM2가 나쁜 도구라서 생긴 문제도, CPU가 높은 모든 서버에 .npmrc를 지워야 한다는 결론도 아니다.
프로세스가 짧아 관측 화면에서 사라질 때는 현재 순위보다 실행 계보를 보고, 재시작 관리자는 원인 프로세스를 계속 되살릴 수 있다는 점을 함께 확인해야 한다.

참고 자료

• PM2 — Restart strategies
• PM2 — Ecosystem file options
• nvm — Compatibility issues
• npm — Configuration
• BCC — execsnoop