TypeORM 쿼리 진입점 로깅하기 #1

이호영·2024년 2월 13일

TypeORM 쿼리 진입점 로깅

목록 보기

1/2

📖 예제 코드: https://github.com/2hoyeong/nestjs-typeorm-entry-log

서비스를 운영하다 보면 다양한 대상을 모니터링해야 합니다. 보편적으로 Sentry를 통한 에러 모니터링부터 Response Time, 성능 지표 등 다양한 대상이 있는데 그중에서 슬로우 쿼리도 모니터링합니다.

쿼리가 느리다는 건 DB가 많은 데이터를 조회해야 하거나 복잡한 조회 조건으로 인해 많은 연산을 필요로 하는 경우가 많습니다. 슬로우 쿼리가 많이 발생하면 할수록 DB 인스턴스에 부하가 발생하며 커넥션을 긴 시간 동안 점유하고 있어 심각한 경우 장애로 이루어질 수 있기 때문에 꼭 모니터링이 필요합니다.

Slow 쿼리 모니터링

슬로우 쿼리 로그는 위와 같이 전달됩니다. 보통 MySQL에서 제공하는 slow_query_log 옵션을 이용해 MySQL이 로깅하는 내용을 바탕으로 전달됩니다. 많은 데이터를 제공하고 있지만, 중요한 한 가지가 빠져있습니다.

바로 어떤 서비스에서 해당 쿼리문을 실행했는지 알 수 없는 점입니다. 실행된 쿼리문 모니터링 알림을 통해 전달되지만, ORM을 사용하기 때문에 쿼리문만 가지고 어떤 서비스에서 어떤 함수가 호출되었는지 거꾸로 찾기는 쉽지 않습니다.

그런데 재밌는 사실이 있습니다. MySQL이 쿼리문을 로깅할 때, 주석도 함께 로깅합니다.

이렇게 쿼리문에 주석을 추가하고 슬로우 쿼리를 발생시키면, 주석까지 하나의 쿼리문으로 파악하여 함께 로깅됩니다.

그렇다면 쿼리를 작성할 때 주석에 어떤 함수에서 실행됐는지 작성한다면 손쉽게 어떤 함수에서 슬로우 쿼리가 발생했는지 쉽게 알 수 있을 테니 추가해 보겠습니다.

쿼리 로깅 추가

서비스 진입점 추가

팀에서는 Repository를 작성할 때 규칙이 있습니다.

import { Repository, SelectQueryBuilder } from 'typeorm';
import { Injectable } from '@nestjs/common';
import { InjectRepository } from '@nestjs/typeorm';
import { Platform } from '../../common/entities/platform/platform.entity';

@Injectable()
export class PlatformRepository {
  constructor(@InjectRepository(Platform) private readonly repository: Repository<Platform>) {}

  createQueryBuilder(alias = 'platform'): SelectQueryBuilder<Platform> {
    return this.repository.createQueryBuilder(alias);
  }
	...
}

이렇게 레포지토리에서 createQueryBuilder 함수를 한번 래핑 하여 사용하도록 하고 있습니다. 이는 기존에 typeorm 0.2 버전에서 0.3으로 올라가면서 Custom Repository 패턴을 사용하는 방법에 약간의 변화가 있었는데 그것에 대응하는 것과 더불어 팀 SQL 컨벤션에 맞게 명시적으로 alias를 적용하도록 하기 위해 이렇게 되어 있습니다.

그러면 쉽게 “어떤 서비스에서 호출했는지”를 추가하는 건 쉽게 가능합니다.

constructor(
  @InjectRepository(Platform) private readonly repository: Repository<Platform>,
  private readonly configService: ConfigService,
) {}

createQueryBuilder(alias = 'platform'): SelectQueryBuilder<Platform> {
  return this.repository.createQueryBuilder(alias).comment(this.configService.get('app.projectName'));
}

이렇게 하면 서비스 이름이 주석으로 들어가 어떤 서비스에서 호출했는지 쉽게 확인이 가능합니다.

로그를 찍어보면 위와 같이 출력됩니다. 이 쿼리문을 슬로우 쿼리 로그 내역에서 확인할 수 있습니다.

하지만 위 코드는 몇 가지 문제가 있습니다.

어떤 서비스에서 호출한지는 알지만, 어떤 함수에서 호출됐는지는 여전히 찾아야 합니다.
config에 정의된 서비스 이름을 가져와야 하기 때문에, ConfigService가 모든 Repository에 주입되어야 합니다.
createQueryBuilder 를 사용하지 않는 함수는 여전히 로깅되지 않습니다.

차근차근 이 문제들을 해결해 보겠습니다.

함수 진입점 추가

어떤 함수에서 진입했는지 추가하기 위해선 다음과 같은 방법이 있을 수 있습니다.

doSomething() {
	...
	this.createQueryBuilder().comment(`${this.configService.get('app.projectName')}.${PlatformRepository.name}.doSomething`);
	...
}

이렇게 함수마다 어떤 함수에서 호출했는지 주석을 추가하면 됩니다.

하지만 서비스 전체에 많은 Repository들이 존재하고, 그 Repository에도 많은 함수들이 존재하는데 하나하나 작성하기는 쉽지 않습니다. 게다가 가장 큰 문제는 사람이 실수할 수 있다는 점입니다.

함수 이름은 상수로 작성해야 하여 혹여나 함수 이름이 변경되었을 때 주석을 변경하지 않는다면 추적이 쉽지 않을 수 있습니다. 또한 아예 작성하지 않을 수도 있습니다.

이 문제를 해결하기 위해서 JavaScript에 있는 Proxy와 Decorator를 사용해 보겠습니다.

Proxy란?
Proxy는 특정 객체를 감싸 프로퍼티 읽기, 쓰기와 같은 객체에 가해지는 작업을 중간에서 가로채는 객체로, 가로채진 작업은 Proxy 자체에서 처리되기도 하고, 원래 객체가 처리하도록 그대로 전달되기도 합니다.
[출처: https://ko.javascript.info/proxy]

Decorator를 하나 선언합니다. Decorator로 전달되는 매개변수들 중에는 우리가 원하는 값들이 들어 있습니다.

export function AddEntryPointComment() {
  return function (target: any, propertyKey: string, descriptor: PropertyDescriptor) {
    const originalMethod = descriptor.value;

    const prototype = Object.getPrototypeOf(originalMethod);
    if (prototype.constructor.name === 'AsyncFunction') {
			descriptor.value = async function (...args: any[]) {
        return await originalMethod(...args);
			};
    } else {
      descriptor.value = function (...args: any[]) {
        return originalMethod(...args);
      };
    }

    return descriptor;
  };
}

⚠️ 일단은 문제를 하나씩 해결하기 위해 NestJS 데코레이터가 아닌, JavaScript의 데코레이터를 선언하는 코드로 진행하겠습니다.

각 매개변수는 다음과 같은 값을 가지고 있습니다.

target: 데코레이터가 적용되는 대상을 참조합니다. 클래스 데코레이터의 경우 클래스의 생성자 함수이며, 메서드 또는 속성 데코레이터의 경우 이는 클래스의 프로토타입입니다.
propertyKey: 데코레이터가 적용되는 메서드 또는 속성의 이름입니다.
descriptor: 데코레이터가 적용되는 메서드의 속성 설명자입니다.

우리가 원하는 정보(어떤 클래스의 어떤 함수가 호출되었는지)를 모두 가지고 있습니다. 이 값을 이용하면 어떤 함수가 호출되던지 호출되는 컨텍스트 정보를 가져올 수 있습니다.

앞서 Proxy를 이용하면 함수의 호출이나 일기, 쓰기 같은 작업을 가로챌 수 있다고 했습니다. createQueryBuilder 함수가 호출될 때 작업을 가로채서 컨텍스트 정보를 주석에 주입해 보겠습니다.

const createProxy = (thisArg: any, targetName: string, propertyKey: string) => {
  return new Proxy(thisArg, {
    get: function (target, propKey, receiver) {
      if (propKey === 'createQueryBuilder') {
        const origin = target[propKey];
        const entrypoint = `${config.projectName}.${targetName}.${propertyKey}`;
        return (...args: any[]) => origin.call(target, ...args).comment(entrypoint);
      }
      return Reflect.get(target, propKey, receiver);
    },
  });
};

Proxy를 선언합니다. Proxy는 생성자로 가로챌 대상 target 과 가로챈 함수의 동작을 정의하는 handler 를 전달받습니다.

우리가 Proxy를 정의하는 대상은 함수가 아닌 Repository 객체인 것을 잊지 말아야 합니다. 내부 함수 중 [[Get]] 를 가로채기 위해 handler에 get 속성에 트랩 함수를 정의합니다.

createQueryBuilder 일 때는 원래 함수를 호출하고, 호출한 결과에 TypeORM 함수인 comment 에 알고 있는 정보인 현재 컨텍스트 정보들을 주석으로 추가하도록 하면 Proxy 선언은 끝입니다.

export function AddEntryPointComment() {
  return function (target: any, propertyKey: string, descriptor: PropertyDescriptor) {
    const originalMethod = descriptor.value;
    const prototype = Object.getPrototypeOf(originalMethod);
    if (prototype.constructor.name === 'AsyncFunction') {
      descriptor.value = async function (...args: any[]) {
        const proxy = ProxyFactory(this, target.constructor.name, propertyKey);
        return await originalMethod.call(proxy, ...args);
      };
    } else {
      descriptor.value = function (...args: any[]) {
        const proxy = ProxyFactory(this, target.constructor.name, propertyKey);
        return originalMethod.call(proxy, ...args);
      };
    }

    return descriptor;
  };
}

그런 다음에 현재 메소드의 this를 Proxy로 바인딩 하여 함수를 호출하도록 합니다.
이제 만든 데코레이터를 함수에 적용하면 쿼리문에 진입점 주석이 추가될 것입니다.

@AddEntryPointComment()
async getAllPlatforms(): Promise<Platform[]> {
  const queryBuilder = this.createQueryBuilder().where('status = :status', { status: PlatformStatus.Activated });
  return queryBuilder.getMany();
}

로깅을 하고 싶은 함수에 데코레이터를 추가하고 로그를 확인해 보면

쿼리문 맨 앞에 주석으로 [서비스 이름].[Repository class 이름].[함수 이름]이 추가된 것을 확인할 수 있습니다.

이 과정을 통해 “1. 어떤 서비스에서 호출한지는 알지만, 어떤 함수에서 호출됐는지는 여전히 찾아야 합니다.” 문제를 해결했습니다. 또한 함수 이름이 변경되었을 때 주석에 상수로 작성된 함수 이름 변경을 실수로 변경하지 않는 문제를 해결했습니다.

하지만 아직 모든 함수에 데코레이터를 적용해야 하는 문제처럼 아직 남은 문제가 많이 있습니다. 다음 글에서 문제를 계속해서 해결해 나가보겠습니다.

이호영

안녕하세요!

다음 포스트

TypeORM 쿼리 진입점 로깅하기 #1