Node.js API 서버 메모리 누수 디버깅 해보기
안녕하세요, End-User 스쿼드의 백엔드 엔지니어 최성국입니다!
아임웹은 기존의 주문 시스템을 개선하고 고객들의 판매, 구매 경험을 향상하기 위해 OMS(Order Management System)라는 새로운 시스템을 개발하고 있는데요.
어느 날 갑자기 발생한 테스트 환경 OMS API의 성능 저하 현상을 분석하고 해소한 경험을 공유해보려고 해요. 글 작성 현재는 클로즈 베타 테스트 중으로 곧 엄청난 기능으로 찾아뵙겠습니다.
어쩌다 시작된 걸까요?
평화로운 점심시간이 지난 오후, 프론트엔드 개발팀으로부터 테스트 환경 OMS API가 갑자기 느려졌다는 제보를 받게 되어, 다른 백엔드 엔지니어분께서 빠르게 대처를 시도해 주셨습니다.
저는 이 이슈가 발생하기 직전에 nestjs-cls 라이브러리를 사용하여, 애플리케이션에서 발생하는 각종 로그들을 하나의 고유 ID를 통해 맥락을 연결하는 작업을 진행했어요.
그래서 스테이징 서버 배포 시기와 메모리 사용량 증가 추이를 토대로, 우선 최근에 제가 작업한 기능을 원인으로 의심하여 해당 기능을 롤백하셨네요. 제가 작업한 기능이 롤백 되었다는 내용을 공유받은 뒤에 이슈를 인지하게 되었고, 이때부터 나름대로 조사를 시작하게 되었습니다.
메모리 사용량이 증가했다는 이야기를 들었으니, 일단 AWS에서 메모리 사용량 지표부터 살펴봤어요.
애플리케이션이 배포 과정 및 API Health-check에 의해 재시작되며 메모리 사용량이 떨어졌지만(①), 의심되는 원인이 제거 되었는데도 금세 오르기 시작(②)합니다.
메모리 사용량이 떨어지지 않고 계속해서 증가하는 것으로 봐서는, 애플리케이션이 사용하지 않는 데이터를 메모리에 계속 담고 있는 것 같죠?
또, 11월 3일 새벽 3시 자동 배포 이후 한밤중에는 사용량이 올라가지 않고(②~③) 오전 9시경부터 급격하게 올라가기 시작(③)하네요. 아무래도 업무 시간과 관련이 있을 수도 있겠어요.
최근에 배포된 애플리케이션의 로직에 원인이 있을 것이라 생각하고 애플리케이션 단에서 디버깅을 시도해 보았습니다.
애플리케이션 디버깅해 보기
OMS API는 Node.js 기반의 Nest.js 프레임워크로 개발되고 있어요. Node.js 런타임을 디버깅할 수 있는 적절한 도구가 필요하겠죠?
저는 구글 크롬 브라우저의 개발자 도구인 DevTools 중 원격으로 자바스크립트 디버깅을 할 수 있도록 해주는 ‘Inspector’(chrome://inspect)로 Node.js 애플리케이션이 메모리를 가장 많이 쓰는 부분을 찾아보겠습니다.
Node.js는 실행할 때 --inspect 파라미터를 넘기면 디버그 모드로 실행되고, 디버거를 연결하여 프로세스를 추적할 수 있게 돼요.
node main.js --inspecthttps://nodejs.org/en/guides/debugging-getting-started
OMS API는 모놀리식 서비스가 아닌 MSA 환경을 구축하기 위해, 모노리포 구조로 하나의 코드 저장소에 여러 API 애플리케이션으로 나누어져 있어요.
이 중 아임웹 사이트 관리자가 사용하는 웹 애플리케이션을 위한 백엔드인 ‘어드민 API’를 기준으로 디버깅을 하려고 했고, 로컬 머신에 어드민 API 서버를 켜봤습니다.
nest start admin그런데 Node.js(node)가 아닌 Nest.js CLI(nest start)를 실행하기 때문에 --inspect 파라미터를 사용할 수 없네요.
Nest.js CLI 문서를 보니, --debug 파라미터를 사용하면 Node.js에 --inspect 파라미터를 사용한다고 합니다.
이렇게 어드민 API를 디버깅 모드로 실행했어요.
nest start admin --debug
그런 다음 크롬 주소창에 chrome://inspect를 입력하여 개발자 도구 화면에 접속하면, 위와 같이 기본적으로 자동으로 디버깅을 할 프로세스를 찾아주고, 디버깅할 프로세스 아래의 Inspect 버튼을 누르면 다음과 같은 창이 열립니다.
지금은 메모리를 과도하게 사용하는 문제를 찾고 있기 때문에 Memory 탭을 통해 추적할 것이고, 어떤 코드가 메모리를 그렇게 많이 할당받는지 알아보기 위해 Allocation sampling 기능을 사용할 거예요.
이 글 초반에 ‘업무 시간과 관련이 있다’, 즉 ‘아임웹 구성원들이 사용하기 시작할 때부터 발생하는 이슈가 아닐까’라는 추측을 했다고 말씀드렸죠?
Start 버튼을 눌러 메모리 프로파일링을 시작하고, 높은 사용량을 재현하기 위해 API를 매우 많이 호출해서 부하를 주겠습니다.
ab -c 10 -n 1000 -H 'authorization: ~' <http://localhost>:<port>/admin/<path>/<:param>💡
ab는 리눅스/맥 운영체제에 기본적으로 설치되어 있는 HTTP 부하 테스트 명령어입니다.
모든 호출이 종료되면 프로파일링을 종료하고, Tree 보기로 Total Size 기준으로 역순 정렬하여 메모리를 가장 많이 할당받은 함수를 순서대로 추적해 볼게요.
전체 메모리 중 90% 이상 차지하는 프로세스가 있네요. 저 로직을 기준으로 따라가 보죠!
오픈 소스 라이브러리의 소스 코드 분석해 보기
우선 executeQuery라는 함수에서 PickType을 사용하는데, 이 함수가 가장 많은 메모리를 할당받은 것으로 보이네요.
executeQuery는 쿼리 빌더를 SQL문으로 변환하여 데이터베이스에 요청하는 메소드입니다.
// ...
import { PickType } from '@nestjs/swagger';
// ...
@Injectable()
export class BaseRepository<T> {
// ...
private async executeQuery(
queryBuilder: Knex.QueryBuilder,
filter: CrudFilter<T>,
): Promise<T | T[] | Partial<T> | Partial<T>[]> {
// ...
if (filter.select) {
return plainToInstance(filter.dto ?? **PickType(this.entity, filter.select)**, rows) as Partial<T> | Partial<T>[];
}
return plainToInstance(filter.dto ?? this.entity, rows);
}
// ...
}OMS API 소스 코드 일부 발췌
위와 같이 @nestjs/swagger 패키지의 PickType을 사용한 코드가 보입니다. 그럼 PickType은 메모리를 왜 이렇게 많이 할당받았을까요?
프로파일 결과를 다시 보면, PickType 아래에서는 inheritValidationMetadata 함수, 그리고 그 안의 map 함수에 사용된 익명 함수가 메모리를 가장 많이 할당받았네요.
@nestjs/swagger 패키지의 소스 코드를 받아 더 따라가 봅시다.
// ...
import {
inheritPropertyInitializers,
inheritTransformationMetadata,
inheritValidationMetadata**
} from '@nestjs/mapped-types';
// ...
export function PickType<T, K extends keyof T>(
classRef: Type<T>,
keys: readonly K[]
): Type<Pick<T, (typeof keys)[number]>> {
const fields = modelPropertiesAccessor
.getModelProperties(classRef.prototype)
.filter((item) => keys.includes(item as K));
// ...
inheritValidationMetadata(classRef, PickTypeClass, isInheritedPredicate);**
inheritTransformationMetadata(classRef, PickTypeClass, isInheritedPredicate);
// ...
return PickTypeClass as Type<Pick<T, (typeof keys)[number]>>;
}inheritValidationMetadata 함수는 @nestjs/mapped-types 패키지에서 가져왔네요. 다시 한번 소스 코드를 받아 볼게요.
export function inheritValidationMetadata(
parentClass: Type<any>,
targetClass: Function,
isPropertyInherited?: (key: string) => boolean,
) {
if (!isClassValidatorAvailable()) {
return;
}
try {
const classValidator: typeof import('class-validator') = require('class-validator');
const metadataStorage: import('class-validator').MetadataStorage = (
classValidator as any
).getMetadataStorage
? (classValidator as any).getMetadataStorage()
: classValidator.getFromContainer(classValidator.MetadataStorage);
// ...
return targetMetadata
// ...
.map((value) => {
// ...
metadataStorage.addValidationMetadata({
...value,
target: targetClass,
});
return value.propertyName;
});
} catch (err) {
logger.error(
`Validation ("class-validator") metadata cannot be inherited for "${parentClass.name}" class.`,
);
logger.error(err);
}
}위와 같이 Array.map() 함수의 내용을 볼 수 있어요.
간단히 설명하자면, class-validator 패키지가 객체의 데이터를 검사할 수 있도록 @IsString(), @IsNumber 등의 데코레이터를 설정한 속성들의 메타데이터 정보를 MetadataStorage라고 하는 공간에 저장하는 코드입니다.
getMetadataStorage라는 함수와 addValidationMetadata라는 함수가 눈에 들어오네요. 프로세스 어딘가에 전역 객체를 만들어 두고 데이터를 계속 추가하는 것 같아요.
이번에는 class-validator 패키지를 참조하네요. 또 소스 코드를 받아 따라가 봅시다.
/**
* Gets metadata storage.
* Metadata storage follows the best practices and stores metadata in a global variable.
*/
export function getMetadataStorage(): MetadataStorage {
const global = getGlobal();
if (!global.classValidatorMetadataStorage) {
global.classValidatorMetadataStorage = new MetadataStorage();
}
return global.classValidatorMetadataStorage;
}/**
* This function returns the global object across Node and browsers.
*
* Note: `globalThis` is the standardized approach however it has been added to
* Node.js in version 12. We need to include this snippet until Node 12 EOL.
*/
export function getGlobal() {
if (typeof globalThis !== 'undefined') {
return globalThis;
}
// ...
}역시 전역 객체를 만들어 두고 사용하네요.
OMS API는 Node.js 런타임을 사용하니까, globalThis.classValidatorMetadataStorage 속성에 MetadataStorage 클래스의 객체를 할당하여 싱글턴으로 사용하고 있겠습니다.
/**
* Storage all metadatas.
*/
export class MetadataStorage {
private validationMetadatas: Map<any, ValidationMetadata[]> = new Map();
private constraintMetadatas: Map<any, ConstraintMetadata[]> = new Map();
// ...
/**
* Adds a new validation metadata.
*/
addValidationMetadata(metadata: ValidationMetadata): void {
const existingMetadata = this.validationMetadatas.get(metadata.target);
if (existingMetadata) {
existingMetadata.push(metadata);
} else {
this.validationMetadatas.set(metadata.target, [metadata]);
}
}
// ...
}그리고 PickType을 통해 새로 만들어진 클래스의 메타데이터를 inheritValidationMetadata 함수에서 metadataStorage의 속성인 validationMetadatas의 Map 객체에 담아줍니다.
그런데 다시 생각해 보니,
metadataStorage.addValidationMetadata({
...value,
target: targetClass,
});
return value.propertyName;이 부분, 결국에는 Map에 담기만 하고 해제하지 않을 것 같아요.
‘이러면 PickType이 실행될 때마다 메모리 사용량이 계속 늘기만 하는 거 아닌가?’라는 생각을 하며…
결론 검증해 보기
런타임에 총 1만 번의 PickType을 실행하는 테스트용 코드를 작성해서 실행해 봤습니다.
import { getMetadataStorage, IsString } from 'class-validator';
import { PickType } from '@nestjs/mapped-types';
class Test {
@IsString()
propertyA: string;
}
Array.from({ length: 10000 })
.fill(0)
.forEach(() => PickType(Test, ['propertyA']));
console.log(getMetadataStorage());$ yarn ts-node test.ts
yarn run v1.22.19
$ /Users/seonggukchoi/Projects/imweb/oms-api/node_modules/.bin/ts-node test.ts
MetadataStorage {
validationMetadatas: Map(10001) {
[class Test] => [ [ValidationMetadata] ],
[class PickClassType] => [ [Object] ],
[class PickClassType] => [ [Object] ],
[class PickClassType] => [ [Object] ],
[class PickClassType] => [ [Object] ],
[class PickClassType] => [ [Object] ],
...진짜네…
PickType을 실행할 때마다 새로운 클래스가 정의되고, 이 클래스의 메타데이터가 MetadataStorage 객체에 들어가고 사라지지 않네요.
다시 처음에 봤던 BaseRepository.executeQuery() 메소드로 돌아가서, 해당 메소드는 데이터베이스에 SQL을 실행할 때 사용되기 때문에 PickType을 굉장히 많이 실행할 것입니다.
그 말은 즉, OMS API 대부분의 API를 호출할 때마다 메모리 사용량이 늘어나겠네요!
아임웹 구성원들만이 사용하는 테스트 환경인 만큼, 아임웹의 업무 시간에 영향을 받는다는 가설도 맞는 것 같습니다.
결과
@Injectable()
export class BaseRepository<T> {
// ...
private async executeQuery(
queryBuilder: Knex.QueryBuilder,
filter: CrudFilter<T>,
): Promise<T | T[] | Partial<T> | Partial<T>[]> {
// ...
if (!this.entity && !filter.dto) {
return rows;
}
return plainToInstance(filter.dto ?? this.entity, rows) as Partial<T> | Partial<T>[];
}
// ...
}위 내용을 최근에 PickType을 사용한 코드를 작성하신 백엔드 엔지니어분께 공유했고, 위처럼 PickType을 사용하지 않도록 바로 수정해 주셔서 바로 디버깅을 시도해 보았습니다.
11,041,288 바이트(약 10MB, 63.95%)의 메모리를 할당받던 executeQuery가 이제는 매우 적은 양의 메모리를 할당받게 되었네요.
이제 배포만 하면 이슈가 종결될 것 같습니다.
변경된 내용을 13시 45분경 테스트 환경 OMS API에 배포하고 이 글을 쓰는 18시경까지 모니터링 한 결과, 메모리 누수는 해소된 것 같아 보이네요! 🎉
@nestjs/swagger, @nestjs/mapped-types(거의 같은 구조입니다.)의 PickType, OmitType 등 서브 클래스 생성 함수들은 비즈니스 로직에서 실행되도록 사용하지 말고, 애플리케이션 초기화 시 클래스 정의 시점 정도에만 사용하는 것이 바람직할 것 같습니다.
그래서 결론은…
Node.js 애플리케이션 환경에서 발생한 성능 이슈를 디버거를 이용한 메모리 분석, 그리고 소스 코드 분석을 통해 원인을 파악하고 수정하는 과정을 쭉 보여 드렸습니다.
이 글을 통해 ‘Node.js 환경에서 이런 방식으로 트러블슈팅 하는 방법도 있구나’ 정도의 인사이트 얻어 가셨으면 좋겠습니다.
긴 글 읽어주셔서 감사합니다!
