Clinic.js로 Node.js 서버 프로파일링 하기

Clinic.js는 Node.js 런타임 분석도구로 Doctor, Flame, Bubbleprof, Heap Profiler의 4가지 분석 도구를 지원해준다.

설치

$ npm install -g clinic

사용하기

1. 프로파일링 실행

아래 명령어로 프로파일링 할 Node.js 애플리케이션을 시작 할 수 있다. Nest.js 로 작성된 서버로 테스트 해보았다.

$ clinic doctor -- node dist/main
To generate the report press: Ctrl + C
[Nest] 51844  - 2023. 01. 16. 오후 8:31:28     LOG [NestFactory] Starting Nest application...
[Nest] 51844  - 2023. 01. 16. 오후 8:31:28     LOG [InstanceLoader] AppModule dependencies initialized +15ms
[Nest] 51844  - 2023. 01. 16. 오후 8:31:28     LOG [InstanceLoader] MemberModule dependencies initialized +0ms
[Nest] 51844  - 2023. 01. 16. 오후 8:31:28     LOG [RoutesResolver] AppController {/}: +3ms
[Nest] 51844  - 2023. 01. 16. 오후 8:31:28     LOG [RouterExplorer] Mapped {/, GET} route +1ms
[Nest] 51844  - 2023. 01. 16. 오후 8:31:28     LOG [RoutesResolver] GetMembersController {/}: +0ms
[Nest] 51844  - 2023. 01. 16. 오후 8:31:28     LOG [RouterExplorer] Mapped {/members, GET} route +1ms
[Nest] 51844  - 2023. 01. 16. 오후 8:31:28     LOG [NestApplication] Nest application successfully started +1ms

프로파일링이 시작되면 서버가 작동하고, 작동한 서버에 테스트 할 요청을 보내 프로파일링을 수행 할 수 있다.

2. 프로파일링 종료

Ctrl + C를 눌러 프로파일링을 종료 할 수 있다.

Analysing data
Generated HTML file is file://frontend/.clinic/60300.clinic-doctor.html

프로파일링을 종료하면 결과를 확인 할 수 있는 HTML이 열리게 되고, 생성된 HTML 파일은 /.clinic 에서 다시 확인 할 수 있다.

3. 부하 테스트 하기

서버로 사용되는 애플리케이션의 경우, 단일 요청에서는 문제가 없지만 많은 요청을 한꺼번에 처리할 때 문제가 생기는 경우가 많다. 이때를 프로파일링 하기 위해 Clinic.js는 벤치마킹 도구인 Autocannon 이라는 라이브러리를 사용해서 부하 상황에서 서버가 어떻게 동작 하는 지 프로파일링 할 수 있는 방법을 지원해 준다.

# autocannon 설치
$ npm install -g autocannon

# 부하 테스트 실행
$ clinic doctor --autocannon [ -m POST /api/item -i my-data.json ] -- node server.js

Clinic.js 공식 홈페이지에서 더 다양한 CLI 명령어를 확인 할 수 있다.

---

Clinic.js의 4가지 분석도구

Clinic.js는 Doctor, Flame, Bubbleprof, Heap Profiler의 4가지 분석 도구를 제공해준다.

1. Doctor

doctor 분석도구를 활용하면 애플리케이션의 성능 문제를 종합적으로 진단 할 수 있다. 그리고 문제가 발견되면 더 자세히 조사할 수 있는 다음 방법에 대한 조언까지 받을 수 있다.

doctor에 표시되는 그래프는 CPU Usage, Memory Usage, Event Loop Delay, Active Handles 이렇게 총 4가지 섹션으로 나뉘는데 만약 비정상적인 부분이 감지 되면 빨간색으로 하이라이팅 해준다.

Doctor 실행

$ clinic doctor -- node index.js

1-1. CPU Usage (단위: %)

Node.js 프로세스가 시스템의 사용 가능한 CPU 용량 중 몇 퍼센트를 사용했는지 보여줍니다.
시스템에 여러 개의 코어가 있는 경우 CPU 사용량이 100%를 초과할 수 있다.

- CPU 사용량이 너무 높게 튀는 경우:
서버에 높은 부하(CPU Load)가 걸리고 있다는 신호일 수 있다.
CPU 사용량이 높은 경우 Node.js의 "이벤트 루프 delay 현상"이 뒤따를 수 있다.

- CPU 사용량이 예상보다 낮은 경우:
느린 데이터베이스 쿼리 또는 파일 쓰기와 같이 I/O 바운드 작업이 완료될 때까지 CPU가 대기하고 있다는 신호일 수 있다.

1-2. Memory Usage (단위: MB)

Memory Usage 섹션에는 RSS, Total Heap Allocated, Heap Used로 3가지 지표가 표시된다.

• RSS(Resident Set Size)
• Node.js 프로세스에서 할당된 모든 메모리를 나타내고. 3개의 선 중에 가장 가장 높은 값으로 찍힌다.
• 아래 Total Heap Allocated 값에서 힙영역에 저장되지 않는 메모리 값까지 더해 진 값.
• Node.js에서 힙 영역에 저장되지 않는 것은 JS 코드 자체, 원시 값 이나 변수 포인터, 버퍼 콘텐츠용 메모리 풀 등이 있다.
• Total Heap Allocated
• 힙영역에 데이터를 저장하기 위해 미리 할당된 힙 공간의 총 양
• Node.js에서 힙영역에는 문자열, 객체, 함수 클로저와 같이 참조가 있는 항목이 저장 된다.
• Heap Used
  실제 힙영역에 현재 저장 되어있는 가비지 콜렉팅 되지 않은 데이터의 총 양
  
  

만약 Heap Used 지표가 어느 영역에서 지속적으로 증가한다면 가비지 콜렉팅이 잘 작동하지 않고, 메모리 누수가 생겼음을 의심해 볼 수 있다.
반대로 Heap Used의 급격한 하락과 함께 Event Loop Delay는 증가한다면, 가비지 콜렉팅 이벤트 때문에 이벤트 루프의 실행도 멈추게 되었다고 유추 할 수 있다.

1-3. Event Loop Delay(단위: ms)

런타임에서 CPU 바운드 작업 때문에 Node.js의 이벤트 루프가 차단된 시간을 나타낸다.

Node.js는 싱글쓰레드로 동작하기 때문에 CPU 바운드 작업이 런타임에서 계속 실행 중이라면 그동안 이벤트 루프로 진입 되지 못하게 되어 이벤트 루프 내 각 페이즈 큐에 등록 된 작업은 CPU 바운드 작업이 완료 될때 까지 delay 되는데 이를 이벤트 루프 delay라고 한다.

Q. 만약 서버에서 CPU를 많이 점유하는 요청을 처리하는 중에 다른 작업이 들어오면 어떻게 될까?

// CPU 바운드 요청
req1(): string {
  let a = 0;
  for (let i = 0; i < 10000000000; i++) {
    a++;
  }
  console.log(a);
  return 'hello1';
}

// 다른 요청
req2(): string {
  return 'hello2';
}

A. req1 이 실행되는 동안 req2 요청이 들어와도 req2 요청을 처리 하지 못하고, req1의 처리가 끝날때까지 req2 요청의 처리가 delay 된다.

아래는 Nest.js에서 req1이 실행되는 요청을 두번 보낸 후 doctor를 통해 얻은 결과 인데, req1이 요청이 처리 될때마다 event loop가 delay되는 것을 확인 할 수 있었다.

1-4. Active Handles

현재 활성화된 I/O 핸들의 수를 보여줍니다.
libuv 에서 파일 쓰기 또는 데이터베이스 쿼리와 같은 작업을 운영 체제에 비동기적으로 위임할때 Node.js는 "핸들"을 저장한다. 이 중에서 Active Handle은 아직 완료된 것으로 보고되지 않은 작업을 말한다. 따라서 Active Handle 지표를 확인 하면, 얼마나 많은 I/O 작업을 비동기적으로 수행 중 인지 알 수 있다.

Active Handle 지표는 요청이 처리되고 완료됨에 따라 오르락내리락하는 질서 있는 패턴을 따라야 한다. Active Handles 수와 함께 CPU 사용량이 뛴다면, 들어오는 요청을 처리 하기 위해 CPU 사용량이 증가한거구나! 라고 유추 할 수 있다.

2. Flame

Next.js 앱을 flame 분석도구로 프로파일링 해본 결과, sentry 패키지가 꾀 많은 CPU를 사용하고 있었다.

Flame 분석도구를 통해 얻을 수 있는 정보는 다음과 같다.

• 프로파일링 시간 동안 호출 된 함수의 콜스텍
• 각 함수가 CPU를 사용한 시간

Flame 실행

$ clinic flame -- node index.js

2-1. 프로파일링 시간 동안 호출 된 함수의 콜스텍

flame 그래프의 각 블록은 스택으로 보여지며, 아래에서 위 방향으로 각 블록의 호출 순서를 나타낸다.(아래 블록이 위 블록 호출)
각 블록의 텍스트 색깔은 코드가 어디에서 실행되었는지에 따라 다르다.

• 흰색 텍스트 : 프로파일링 중인 애플리케이션의 코드에서 실행된 블록
• 파란색 텍스트 : node_modules 안의 있는 종족 코드들에서 실행된 블록

2-2. 블록의 너비 = 각 함수가 CPU를 사용한 시간

각 블록의 너비는 CPU를 사용하고 있던 시간을 나타내고, 블록의 너비가 클수록 그래프의 왼쪽에 블록이 위치한다.
스택의 아래쪽에 위치한 블록의 너비는 실제로 아래 블록의 함수가 CPU를 점유한 시간을 의미하는 것이 아니라 위쪽에 위치한 블록이 CPU를 사용하는 동안 아래 블록은 그만큼 대기했다는 것을 의미 한다.

2-3. 스택 맨 위에서 각 함수가 관찰된 시간 = Hot 한 정도 = 이벤트루프 차단 정도

만약 특정 블록이 스택의 맨위에서 길게 관찰된다는 것은 그 블록 자체가 그만큼 많이 CPU를 점유했다는 것을 말한다.
이렇게 스택의 맨위에서 길게 잡히는 블록을 "Hot" 하다고 한다.
위에 이벤트 루프 delay 에서도 말했듯이 Node.JS는 싱글쓰레드로 동작하기 때문에 특정 함수가 CPU를 많이 점유하고 있으면 그만큼 이벤트루프는 delay된다.

이렇게 "Hot" 한 블록은 그래프에서 더 밝은 색깔의 띠로 표시되고, 코드를 최적화할 위치를 찾을 때 가장 "Hot"한 블록에서 부터 최적화 방안을 찾는 것이 좋다.

flame 분석도구에서 옵션 설정 하기

패널의 오른쪽에 있는 "Options"을 클릭하면 고급 옵션이 있는 메뉴가 열리고, 블록을 종류별로 보이게 하거나 안보이게 지정 할 수 있다.

flame 분석도구의 옵션 종류:

• [응용 프로그램 이름] : 프로파일링 중인 앱 내부의 코드
• Dependencies : node_modules 내에 있는 종속성 코드
• Node JS : Node.js 코어 내부의 코드
• V8 : V8 JavaScript 엔진 내부의 코드

3. Bubbleprof

이 그래프를 활용하면 어떤 비동기 작업이 오래걸렸는지 분석할 수 있다.

bubble : 그래프에서 동그란 부분으로, 비동기 작업 그룹을 나타내고, 그 그룹 내에서 더 많은 시간을 보낼수록 이 더 커진다.
bubble 사이의 선 : 비동기 작업이 한 공간에서 다른 공간으로 넘어갈 때마다 새로운 bubble이 생기고, 이 bubble 사이의 선이 길수록 다른 비동기 작업으로 넘어가는데 더 많은 시간이 걸렸음을 의미한다.

Bubbleprof 실행

$ clinic bubbleprof -- node index.js

4. Heap Profiler

어떤 함수에 많은 메모리가 할당 되었는지 확인 할 수있다.
flame 분석도구와 동일한 구성으로 되어있고, 차이점은 각 블록의 너비가 CPU 사용 시간이 아니라 "메모리 할당량"을 나타낸다는 점만 다르고, 나머지 부분은 동일 하다.

Heap Profiler 실행

$ clinic heapprofiler -- node index.js

---

작성일 기준으로 2022년 8월 이후로 커밋이 없어서 관리가 안되는 느낌이 있지만, 공식문서 설명이 엄청 친절하게 잘나와있어서 사용하면서 많은 도움이 되었던 것 같다. 그리고 doctor 분석을 수행 하고 문제가 발견되면 하단에 더 자세히 조사할 수 있는 다음 방법에 대한 조언까지 해주는데, 이 조언도 Node.js의 특성에 대한 설명까지 자세하게 나와있어서 분석에 대한 인사이트가 없었는데, clinic.js를 사용하면서 많은 인사이트를 얻을 수 있었다.

참고

https://clinicjs.org/documentation/