Devin.KR
통합 검색 Ctrl K

CPU 프로파일링 - 느린 함수 찾기

개발자KR 조회 20

이 장에서 배우는 것

앞 장에서 힙 스냅샷(heap snapshot)을 통해 메모리 누수를 찾는 방법을 살펴보았다. 애플리케이션의 메모리 사용량이 안정적임에도 응답 속도가 현저히 느려지거나 타임아웃이 발생한다면 CPU 병목을 의심해야 한다. Node.js는 단일 스레드로 자바스크립트를 실행하므로, 하나의 함수가 CPU를 오래 점유하면 다른 모든 요청 처리가 지연된다. 이 장에서는 내장된 CPU 프로파일러를 사용하여 이런 병목 지점을 정확히 찾아내는 방법을 배운다.

  • 프로세스의 CPU 점유 상태를 기록하는 원리 이해하기
  • 명령줄 플래그를 사용하여 프로파일 데이터 추출하기
  • 플레임 그래프를 시각적으로 분석하여 느린 함수 식별하기
  • 자주 발생하는 문자열 처리와 직렬화 병목 현상 해결하기
  • 최적화 전후의 성능 지표를 비교하는 기준 세우기

문제 상황

로그 수집 서버는 수많은 클라이언트로부터 동시에 로그 데이터를 받아 파일이나 데이터베이스에 기록하는 역할을 한다. 평소에는 요청당 수 밀리초 안에 응답을 반환하지만, 트래픽이 몰리거나 특정 패턴의 로그가 들어올 때 전체 서버의 응답 시간이 수 초 이상으로 늘어나는 현상이 발생한다. 모니터링 도구에서 메모리 사용량은 일정하지만 CPU 사용률이 100%에 도달해 떨어지지 않는 것을 확인했다. 서버를 재시작하면 일시적으로 정상화되지만, 곧 다시 같은 현상이 반복된다.

단일 스레드 기반의 이벤트 루프(event loop) 아키텍처에서는 한 요청의 처리가 끝날 때까지 다른 비동기 이벤트의 콜백 실행을 대기시킨다. 파일 입출력이나 네트워크 요청 같은 비동기 작업은 운영체제 커널이나 스레드 풀로 넘겨지므로 메인 스레드를 막지 않지만, 복잡한 연산이나 과도한 반복문, 무거운 문자열 처리는 자바스크립트 실행 스레드를 직접 차단한다. 이를 블로킹 현상이라고 부른다. 시스템 전체의 성능 저하 원인이 수만 줄의 코드 중 어디에 숨어 있는지 직관이나 추측만으로 찾아내는 것은 매우 어렵다. 특정 함수의 실행 시간을 하나씩 측정하는 방식도 비효율적이므로, 프로그램 전체의 실행 흐름을 분석하는 도구가 필요하다.

CPU 프로파일러와 샘플링

CPU 프로파일링은 프로그램이 실행되는 동안 어떤 함수가 얼마나 자주 호출되고, 얼마나 많은 시간을 소비하는지 기록하는 과정이다. Node.js에 내장된 V8 엔진은 샘플링(sampling) 방식을 사용하여 이 작업을 수행한다. 샘플링 방식은 아주 짧은 일정한 주기마다 현재 실행 중인 함수의 호출 스택(call stack)을 기록하는 기법이다. 특정 함수가 여러 번의 샘플링 주기 동안 계속 호출 스택의 최상단에 등장한다면, 해당 함수가 CPU를 오래 점유하고 있다는 뜻이다.

샘플링 방식은 모든 함수 호출을 빠짐없이 기록하는 트레이싱 방식과 달리 실행 성능에 미치는 영향이 적다. 따라서 부하 테스트 환경이나 제한적인 운영 환경에서도 비교적 안전하게 사용할 수 있다. 명령줄에서 스크립트를 실행할 때 --cpu-prof 플래그를 추가하면 프로세스가 종료될 때까지의 기록을 디스크에 파일로 저장한다. 저장된 데이터는 크롬 브라우저의 개발자 도구 등에서 시각화하여 분석할 수 있다.

플레임 그래프 읽는 법

프로파일링 결과를 가장 효과적으로 분석하는 방법은 플레임 그래프(flame graph)를 보는 것이다. 플레임 그래프는 수집된 호출 스택 데이터를 블록 형태로 쌓아 올린 시각화 도구다.

가로축은 시간의 흐름이 아니라 해당 함수가 실행되면서 CPU를 점유한 전체 시간의 비율을 나타낸다. 가로 길이가 긴 블록일수록 CPU를 많이 사용한 것이다. 세로축은 함수의 호출 관계, 즉 호출 스택의 깊이를 의미한다. 맨 아래에는 프로그램의 진입점이나 루트 작업이 있고, 위로 올라갈수록 내부에서 호출된 하위 함수가 나타난다.

플레임 그래프를 볼 때는 최상단에 있으면서 가로로 넓은 블록을 찾는 데 집중해야 한다. 호출 스택의 끝부분에 있으면서 폭이 넓은 블록은 자신이 직접 복잡한 연산을 수행하느라 시간을 보내고 있는 함수다. 반면, 하위 함수들을 호출하기만 하고 실제 연산은 하지 않는 상위 함수 역시 폭이 넓게 표시되지만 병목의 직접적인 원인은 아닐 확률이 높다. 따라서 뾰족하게 솟아오른 기둥의 꼭대기 부근에서 가장 넓은 면적을 차지하는 블록을 우선적으로 조사한다.

플레임 그래프의 가로축은 CPU 점유율을, 세로축은 호출 스택을 나타내며 최상단의 넓은 블록이 병목 원인이다.

잦은 병목 지점: 정규식과 JSON

Node.js 서버에서 CPU 병목을 일으키는 아주 흔한 원인은 복잡한 정규 표현식과 대용량 JSON 파싱이다.

정규 표현식 엔진은 일치하는 패턴을 찾기 위해 문자열을 탐색하다가 실패하면, 이전 분기점으로 돌아가 다른 경로를 탐색한다. 이를 백트래킹(backtracking)이라고 한다. 특정 정규식 패턴이 악의적으로 조작되거나 우연히 일치하기 어려운 형태의 긴 문자열과 만나면, 이 탐색 경로가 기하급수적으로 늘어나면서 CPU를 심하게 소모한다.

또한, 자바스크립트 객체를 완전히 분리된 복사본(깊은 복사)으로 만들기 위해 객체를 JSON 문자열로 변환했다가 다시 객체로 복원하는 JSON.parse(JSON.stringify(obj)) 방식을 종종 사용한다. 이 방식은 코드가 간결하지만, 데이터 크기가 클 경우 객체를 순회하며 문자열을 생성하고, 다시 문자열을 분석하여 트리를 구성하는 무거운 동기 작업을 연속으로 수행하므로 이벤트 루프를 길게 멈추게 한다.

정규식 백트래킹은 조건에 맞지 않을 때 이전 상태로 돌아가 가능한 모든 조합을 탐색하며 CPU 시간을 낭비한다.

완성 코드

다음은 문제가 있는 정규식과 JSON 처리를 포함한 비효율적인 서버와, 이를 개선한 서버의 예제다. 두 방식의 성능 차이를 확인하기 위한 부하 테스트 클라이언트 스크립트도 함께 작성한다.

server.mjs

import { createServer } from 'node:http';

function parseSlow(data) {
  // 비효율적인 정규식 (기하급수적 백트래킹 유발 가능성)
  const logPattern = /^([a-zA-Z0-9]+)*\[ERROR\]/;
  const isError = logPattern.test(data.message);

  // 무거운 동기 JSON 직렬화/역직렬화를 통한 깊은 복사
  const result = [];
  if (data.records && Array.isArray(data.records)) {
    for (const record of data.records) {
      const clone = JSON.parse(JSON.stringify(record));
      result.push(clone);
    }
  }
  return { isError, count: result.length };
}

function parseFast(data) {
  // 정규식을 단순 문자열 검색으로 대체
  const isError = typeof data.message === 'string' && data.message.includes('[ERROR]');

  // 필요한 속성만 추출하여 얕은 복사 수행
  const result = [];
  if (data.records && Array.isArray(data.records)) {
    for (const record of data.records) {
      result.push({ id: record.id, value: record.value });
    }
  }
  return { isError, count: result.length };
}

const server = createServer((req, res) => {
  if (req.method !== 'POST') {
    res.writeHead(405);
    res.end('Method Not Allowed\n');
    return;
  }

  let body = '';
  req.on('data', chunk => { body += chunk; });
  req.on('end', () => {
    try {
      const parsedBody = JSON.parse(body);
      if (req.url === '/slow') {
        parseSlow(parsedBody);
        res.writeHead(200);
        res.end('Slow processing done\n');
      } else if (req.url === '/fast') {
        parseFast(parsedBody);
        res.writeHead(200);
        res.end('Fast processing done\n');
      } else {
        res.writeHead(404);
        res.end('Not Found\n');
      }
    } catch (err) {
      res.writeHead(400);
      res.end('Bad Request\n');
    }
  });
});

server.listen(3000, () => {
  console.log('Server listening on port 3000');
});

client.mjs

import { request } from 'node:http';
import { Buffer } from 'node:buffer';
import { performance } from 'node:perf_hooks';

// 부하를 유발하기 위한 거대한 데이터 생성
const generatePayload = () => {
  const records = Array.from({ length: 10000 }, (_, i) => ({ id: i, value: `val-${i}` }));
  return JSON.stringify({
    // 정규식 엔진의 백트래킹을 유발하는 문자열
    message: 'aaaaaaaaaaaaaaaaaaaaaaaaaaa!',
    records
  });
};

const payload = generatePayload();

function sendRequest(path) {
  return new Promise((resolve) => {
    const startTime = performance.now();
    const req = request(
      {
        hostname: 'localhost',
        port: 3000,
        path: path,
        method: 'POST',
        headers: {
          'Content-Type': 'application/json',
          'Content-Length': Buffer.byteLength(payload)
        }
      },
      (res) => {
        res.on('data', () => {});
        res.on('end', () => {
          const endTime = performance.now();
          resolve(endTime - startTime);
        });
      }
    );
    req.write(payload);
    req.end();
  });
}

async function runTest() {
  console.log('--- 비효율적인 경로 측정 ---');
  let slowTotal = 0;
  for (let i = 0; i < 3; i++) {
    const time = await sendRequest('/slow');
    slowTotal += time;
    console.log(`${i + 1}회: ${time.toFixed(2)}ms`);
  }
  console.log(`평균: ${(slowTotal / 3).toFixed(2)}ms\n`);

  console.log('--- 개선된 경로 측정 ---');
  let fastTotal = 0;
  for (let i = 0; i < 3; i++) {
    const time = await sendRequest('/fast');
    fastTotal += time;
    console.log(`${i + 1}회: ${time.toFixed(2)}ms`);
  }
  console.log(`평균: ${(fastTotal / 3).toFixed(2)}ms`);
}

runTest();

줄별 해설

server.mjs의 parseSlow 함수는 두 가지 심각한 병목을 포함하고 있다. 첫 번째는 /^([a-zA-Z0-9]+)*\[ERROR\]/ 패턴의 정규식이다. 반복 수량자인 +를 괄호로 묶고 다시 * 수량자를 적용했기 때문에, 엔진은 문자열 조합을 나눌 수 있는 모든 경우의 수를 시도한다. 끝에 ! 문자가 있어 최종 일치에 실패하므로, 이 정규식은 실패를 선언하기 전까지 막대한 연산을 수행한다. 두 번째는 요소가 1만 개인 배열을 순회하며 JSON.parse(JSON.stringify(record))를 반복 호출하는 부분이다. 이 작업은 V8 엔진의 메인 스레드를 점유하여 비동기 콜백 처리를 막는다.

반면 parseFast 함수는 정규식 대신 내장 메서드인 includes를 사용하여 백트래킹 발생 여지를 완전히 없앴다. 객체 복사 역시 문자열 변환 과정을 거치지 않고, 빈 객체 리터럴을 생성하여 필요한 속성인 id와 value만 직접 할당하는 방식으로 개선했다.

client.mjs 스크립트는 node:http 모듈을 사용하여 각각의 경로에 동일한 페이로드를 전송한다. performance.now()를 통해 요청 시작부터 응답 완료까지의 밀리초 단위 시간을 정밀하게 측정한다. 3회씩 반복하여 결과를 평균 내는 이유는 Node.js 런타임의 초기화 비용이나 JIT 컴파일러의 최적화 대기 시간을 상쇄하여 좀 더 일관된 수치를 얻기 위함이다.

실행 결과

터미널 두 개를 열어 한쪽에서 서버를 실행하고, 다른 한쪽에서 클라이언트를 실행한다. 프로파일 데이터를 남기기 위해 서버 실행 시 --cpu-prof 플래그를 추가한다.

$ node --cpu-prof server.mjs
Server listening on port 3000

다른 터미널에서 클라이언트를 실행한 결과는 다음과 같다.

$ node client.mjs
--- 비효율적인 경로 측정 ---
1회: 624.12ms
2회: 618.45ms
3회: 615.80ms
평균: 619.46ms

--- 개선된 경로 측정 ---
1회: 7.21ms
2회: 3.45ms
3회: 2.10ms
평균: 4.25ms

서버 터미널에서 Ctrl+C를 눌러 프로세스를 종료하면, 실행했던 디렉터리에 CPU.202610...cpuprofile과 같은 이름의 파일이 생성된 것을 확인할 수 있다.

실무에서 자주 틀리는 것

원인 분석 없는 맹목적인 최적화

성능이 느리다는 이유만으로 프로파일링 데이터 없이 코드부터 수정하는 것은 매우 위험하다. 흔히 특정 비즈니스 로직 함수가 복잡해 보인다는 이유로 캐싱 기법을 도입하지만, 실제로는 그 함수가 전체 실행 시간의 1%도 차지하지 않을 수 있다.

틀린 접근:

// 프로파일링 없이 막연히 반복문이 문제라고 단정하고 캐시를 붙인다.
const cache = new Map();
function processData(data) {
  if (cache.has(data.id)) return cache.get(data.id);
  // 복잡해 보이는 로직...
  cache.set(data.id, result);
  return result;
}

고친 접근:

// 1. --cpu-prof 플래그로 먼저 병목이 어디인지 확인한다.
// 2. 플레임 그래프에서 가장 폭이 넓은 블록을 찾아낸다.
// 3. 병목 원인이 외부 API 대기 시간이라면 캐싱이 유효하지만, 
//    그렇지 않다면 메모리만 낭비하게 된다. 항상 측정이 선행되어야 한다.

프로파일링을 운영 환경에 그대로 켜두기

명령줄 플래그를 사용한 프로파일링은 트레이싱 방식보다는 가볍지만, 여전히 샘플링을 위해 백그라운드 스레드를 사용하고 메모리에 스택 정보를 계속 쌓아둔다. 이를 운영 환경에 상시 켜두면 오히려 애플리케이션의 성능을 저하시키고 디스크 공간을 빠르게 고갈시킨다.

틀린 실행:

$ node --cpu-prof server.mjs
# 이 상태로 운영 트래픽을 무기한으로 받는다.

고친 실행:

# 로컬 부하 테스트 환경에서만 사용하거나,
# 운영 환경에서는 문제 발생 시 짧은 시간 동안만 수동으로 수집하고 즉시 끈다.

미세 최적화에 집착하기

자바스크립트 내장 배열 메서드인 map이나 forEach 대신 기본 for 루프를 사용하면 미세하게 더 빠를 수 있다. 하지만 플레임 그래프에서 해당 반복문이 차지하는 비중이 매우 작다면, 코드의 가독성을 해치면서까지 반복문 형태를 바꿀 필요가 없다. 가장 넒은 면적을 차지하는 블록부터 해결하는 것이 원칙이다.

틀린 접근:

// 플레임 그래프 점유율이 0.1%인 함수에서 가독성을 포기하고 최적화한다.
for (let i = 0, len = arr.length; i < len; i++) {
  // 로직 처리...
}

고친 접근:

// 프로파일러에서 가장 넓은 상위 블록(예: 무거운 JSON.parse)을 우선적으로 개선한다.
// 점유율이 낮은 구간은 유지보수하기 좋은 내장 메서드를 그대로 사용한다.
arr.forEach(item => {
  // 로직 처리...
});

한눈에 보기

흔히 겪는 CPU 병목 지점과 해결책
원인 특징 확인 방법 해결책
정규식 백트래킹 특정 패턴과 불일치하는 문자를 만날 때 탐색 시간이 기하급수적으로 증가한다. 플레임 그래프에서 RegExp 관련 내장 함수가 가장 넓게 표시된다. 정규식을 단순화하거나, includes 등 내장 문자열 검색 메서드로 대체한다.
거대한 객체 복사 JSON.stringify 방식의 깊은 복사는 동기적으로 스레드를 막는다. 최상단에 JSON.parse와 stringify 블록이 매우 넓은 면적을 차지한다. 필요한 속성만 선택적으로 복사하는 얕은 복사 함수를 직접 작성한다.
동기 파일 입출력 readFileSync 등은 파일 데이터를 모두 읽을 때까지 실행 흐름을 멈춘다. fs.readFileSync 블록이 전체 요청 처리 시간의 대부분을 차지한다. 프로미스 기반의 fs.promises.readFile이나 스트림을 사용한다.
과도한 반복 연산 거대한 배열에 대한 순회나 중첩 반복문이 오랜 시간 스레드를 점유한다. 작성한 특정 비즈니스 로직 함수가 플레임 그래프의 상단에 솟아오른다. 불필요한 반복을 줄이거나, 다음 장에서 배울 워커 스레드로 넘긴다.
프로파일링 도구 비교
도구 및 방법 장점 단점 권장 사용처
--cpu-prof 플래그 별도 코드 수정 없이 시작부터 종료까지 전체 실행 구간을 간편하게 기록한다. 파일을 수동으로 찾아 외부 도구(개발자 도구 등)로 불러와야 한다. 로컬 부하 테스트 시 전체 성능의 거시적인 흐름을 한 번에 파악할 때
node:inspector 모듈 특정 함수나 위험 구간만 선택하여 코드로 정밀하게 제어할 수 있다. 애플리케이션 코드를 직접 수정해야 하며 구현 과정이 다소 번거롭다. 특정 API 엔드포인트나 의심되는 함수 블록의 성능만 집중적으로 측정할 때

연습 문제

  1. 프로파일링 결과, 수만 건의 데이터를 처리하는 라우트에서 배열의 map, filter, reduce가 연속으로 호출된 지점이 가장 넓은 플레임 그래프 블록을 형성하고 있었다. CPU 블로킹을 유발하는 이유를 설명하고 개선 방향을 제시하라.
  2. 로컬 테스트 환경에서 --cpu-prof를 사용하여 프로파일링을 완료했다. fs.readFileSync 함수 호출이 대부분의 점유 시간을 차지하고 있다. 이 현상이 단일 스레드 이벤트 루프에 미치는 영향을 설명하라.
  3. 특정 라우트의 성능을 비교하기 위해 테스트 스크립트를 작성하여 단 한 번의 HTTP 요청만으로 시간을 측정했다. 측정 전후 비교 원칙을 바탕으로 이 방식이 왜 위험한지 설명하라.

정답과 해설

1번 정답: 배열 메서드를 체이닝하여 여러 번 연속으로 호출하면, 매 단계마다 불필요한 중간 배열 객체가 메모리에 할당되고 배열 순회가 여러 번 반복된다. 데이터 크기가 클수록 이 과정에서 발생하는 연산이 메인 스레드를 장시간 점유한다. 이를 하나의 reduce나 단순한 for 반복문 하나로 통합하면 순회 횟수를 1회로 줄이고 중간 객체 생성을 막아 CPU 오버헤드를 크게 낮출 수 있다.

2번 정답: 동기 파일 입출력 함수는 디스크에서 데이터를 완전히 읽어올 때까지 V8 스레드의 진행을 완전히 멈춘다. 메인 스레드가 멈추면 이벤트 루프도 정지하므로, 해당 파일을 요청한 클라이언트뿐만 아니라 연결된 다른 모든 클라이언트의 비동기 콜백 처리까지 지연된다. 따라서 가급적 비동기 함수인 fs.promises.readFile을 사용하여 입출력 대기 시간을 커널로 위임해야 한다.

3번 정답: Node.js의 V8 엔진은 초기에 코드를 인터프리터로 실행하다가, 자주 호출되는 함수를 식별하면 백그라운드에서 JIT 컴파일러를 통해 기계어로 최적화한다. 애플리케이션 시작 직후의 첫 번째 요청은 아직 이러한 최적화가 이루어지기 전이므로 실행 시간이 유독 길게 측정된다. 따라서 여러 번 반복 호출하여 충분히 코드가 달궈진 상태에서 평균 시간을 측정해야 운영 환경과 유사한 신뢰할 수 있는 결과를 얻을 수 있다.

댓글 0

아직 댓글이 없습니다. 첫 댓글을 남겨 보세요.

댓글을 남기려면 로그인이 필요합니다.