TypeORM Slow Query 모니터링 With Loki, Grafana

백엔드·2025년 2월 11일

들어가며

현재 팀에서는 총 4개의 서버를 운영하고 있습니다:

광고주용 백엔드 서버
메가·매크로 인플루언서용 백엔드 서버
나노·마이크로 인플루언서용 백엔드 서버
내부 운영을 위한 백오피스 서버

기존의 Slow Query 모니터링 시스템은 다음과 같이 동작했습니다.
RDS에서 Slow Query가 발생하면 해당 로그가 CloudWatch slow-query logs에 저장되고, 이를 Lambda 함수가 트리거하여 일정 시간 이상 실행된 쿼리를 감지한 후 Slack으로 알림을 발송하는 방식이었습니다.

그러나 이 방식에는 몇 가지 한계가 있었습니다.
4개의 서버가 동일한 DB를 공유하기 때문에, 어느 서버의 어떤 API에서 Slow Query가 발생했는지 정확히 파악하는 데 시간이 걸리는 문제가 있었습니다.

최근 Loki와 Grafana를 활용해 로그 모니터링 시스템을 구축하였는데, 이를 기반으로 Slow Query 모니터링 시스템도 개선해보았습니다.

기존 Slow Query 모니터링 방식

해당 링크를 통해 자세한 구현 방식을 알 수 있습니다.

NestJS 기반 백엔드 로그 관리

현재 각 백엔드 서버에서는 winston 라이브러리를 사용하여 로그를 Loki 서버로 전송하고, Grafana를 통해 로그를 시각적으로 모니터링하고 있습니다.

백엔드 서버 내부에서는 nestjs-cls 라이브러리를 활용해 각 요청마다 고유한 requestId를 저장하고, 이를 로그에 포함하여 관리합니다.
이를 통해 requestId를 기준으로 로그를 그룹화하여 특정 요청에 대한 전체 흐름을 추적할 수 있습니다.

예를 들어, Log Interceptor를 활용하여:

요청이 시작될 때 로그를 기록하고, 어떤 API 요청인지에 대한 정보를 남깁니다.
요청이 종료될 때 로그를 기록하여 처리 결과를 추적합니다.

에러 로그에 대한 requestId를 검색하면 해당 에러 로그가 어떤 API에서 발생했는지 쉽게 파악할 수 있습니다.

TypeORM Custom Logger를 활용한 Slow Query 및 Query Error 로깅

TypeORM을 초기화할 때 Custom Logger를 등록하여 Slow Query 및 Query Error를 효과적으로 로깅할 수 있습니다. 이를 통해 성능 저하를 유발하는 쿼리를 추적하고, 쿼리 실행 오류를 보다 쉽게 분석할 수 있습니다.

TypeORM 모듈 설정

TypeORM 모듈을 초기화할 때, maxQueryExecutionTime 설정을 통해 Slow Query를 정의하고, Custom Logger를 등록합니다.

export class TypeOrmModule {
  private static instance?: DynamicModule;

  static forRoot({ useClass, entityPath }: ITypeOrmModuleOptions): DynamicModule {
    if (!this.instance) {
      initializeTransactionalContext();

      this.instance = OrmModule.forRootAsync({
        imports: [useClass],
        inject: [ConfigServiceKey, TypeOrmLoggerService],
        useFactory: async (
          configService: CreplanetConfigServiceInterface,
          typeOrmLoggerService: TypeOrmLoggerService,
        ): Promise<TypeOrmModuleOptions> => {
          const dbConfig = configService.getDbConfig();
          const env = configService.getAppConfig().ENV;
          const isLocal = env === Env.local || env === Env.test;

          const options: DataSourceOptions = {
            type: 'mysql',
            host: dbConfig.DB_HOST,
            port: Number(dbConfig.DB_PORT),
            database: dbConfig.DB_DATABASE,
            username: dbConfig.DB_USERNAME,
            password: dbConfig.DB_PASSWORD,
            entities: [
              env === Env.test
                ? resolve('libs/unify-entity/**/*.entity.ts')
                : resolve(`dist/apps/${entityPath}/libs/unify-entity/**/*.entity.js`),
            ],
            namingStrategy: new SnakeNamingStrategy(),
            synchronize: env === Env.test ? true : false,
            dropSchema: env === Env.test ? true : false,
            logging: false,
            logger: isLocal ? 'advanced-console' : typeOrmLoggerService,
            maxQueryExecutionTime: 3000,
          };

          return options;
        },
        async dataSourceFactory(options?: DataSourceOptions) {
          if (!options) throw new Error('Invalid options passed');

          return addTransactionalDataSource(new DataSource(options));
        },
      });
    }

    return this.instance;
  }
}

maxQueryExecutionTime: 3000 설정을 통해 3초 이상 실행된 쿼리를 Slow Query로 간주하고, logQuerySlow 메서드를 실행합니다.

TypeORM Custom Logger 구현

Custom Logger를 구현하여 Slow Query와 Query Error를 로깅합니다.

import { LoggerService } from '@app/external/logger/logger.service';
import { Injectable } from '@nestjs/common';
import { Logger, QueryRunner } from 'typeorm';

@Injectable()
export class TypeOrmLoggerService implements Logger {
  constructor(private readonly loggerService: LoggerService) {}
  
  // ...

  logQueryError(error: string, query: string, parameters?: any[], queryRunner?: QueryRunner): void {
    this.loggerService.error(
      'Query Error',
      { query, parameters, error },
      undefined,
      this.extractRequestIdFromQueryRunner(queryRunner!),
    );
  }

  /**
   * slow 쿼리 로깅.
   * 참고) maxQueryExecutionTime값이 설정되어 있어야 하고 실행시간이 해당값을 초과하는 쿼리만 로깅됨
   */
  async logQuerySlow(time: number, query: string, parameters: any[], queryRunner?: QueryRunner) {
    const sql =
      query + (parameters.length > 0 ? ' -- PARAMETERS: ' + this.stringifyParams(parameters) : '');

    await this.loggerService.error(
      'Slow Query',
      `[QuerySlow] 실행시간: ${time}(ms), 쿼리: ${sql}`,
      undefined,
      this.extractRequestIdFromQueryRunner(queryRunner!),
    );
  }
 
  // ...
}

logQuerySlow 메서드는 Slow Query가 발생했을 때 실행되며, loggerService를 통해 로그를 남깁니다.
logQueryError 메서드는 쿼리 실행 중 오류가 발생했을 때 실행됩니다.

Slow Query가 발생하면 로그가 Loki 서버로 전송되어 Grafana에서 확인할 수 있습니다. 이를 통해 어떤 서버에서 Slow Query가 발생했는지 파악할 수 있고, 로그에 포함된 requestId를 사용하여 해당 쿼리가 어떤 API에서 발생했는지 추적할 수 있습니다.

Slow Query 로그에서 Request ID 누락 문제

그러나 Slow Query 로그를 확인해 보니 requestId가 누락된 것을 발견했습니다.

팀에서 구현한 loggerService는 내부 메서드를 사용할 때 requestId를 명시적으로 전달하지 않으면, 로그 인터셉터에서 요청이 시작될 때 cls(Context Local Storage) 컨텍스트에 저장된 requestId를 자동으로 부여하여 로그에 포함시키는 방식으로 처리되어 있는데요.

logQuerySlow 메서드가 실행되는 시점에 requestId를 확인한 결과, undefined가 반환되었습니다. 즉, logQuerySlow 메서드가 실행되는 시점에서는 요청에 대한 cls 컨텍스트에서 requestId를 찾을 수 없었습니다.

따라서 logQuerySlow는 request 요청과 동일한 CLS 컨텍스트 내에서 실행되지 않는다는 추측을 할 수 있었습니다. logQuery와는 달리 logQueryError 및 logQuerySlow 메서드는 cls 컨텍스트 내에서 실행되지 않으며, 그로 인해 cls에 저장된 requestId를 가져오지 못하게 됩니다. 이로 인해 Slow Query 로그를 통해 어떤 API에서 발생했는지 추적할 수 없는 문제가 발생하게 됩니다.

QueryRunner 내부에서 Request ID가 존재하는 이유

다행히 QueryRunner를 확인해 보니 requestId가 존재하는 것을 발견했습니다.

저희 팀은 트랜잭션 관리를 위해 typeorm-transactional을 사용하고 있으며, 해당 라이브러리의 설명에는 다음과 같은 내용이 있습니다:

A Transactional Method Decorator for typeorm that uses ALS or cls-hooked to handle and propagate transactions between different repositories and service methods

즉, typeorm-transactional은 ALS(AsyncLocalStorage) 또는 cls-hooked를 사용하여 트랜잭션 컨텍스트를 관리하고 전파합니다.

typeorm-transactional이 CLS(AsyncLocalStorage)를 활용하여 트랜잭션 컨텍스트를 관리하고 있다면, 이는 요청별로 관리되기 때문에 nestjs-cls 라이브러리에서 사용하는 CLS 컨텍스트와 동일한 컨텍스트를 공유할 가능성이 있습니다. 따라서 QueryRunner에서 requestId가 존재하는 이유는 트랜잭션 컨텍스트와 CLS 컨텍스트가 동일한 요청 컨텍스트를 통해 관리되기 때문이라고 추측해보았습니다.

이 부분은 제 추측이므로, 정확한 이유를 아신다면 댓글로 알려주시면 감사하겠습니다.

QueryRunner에서 Request ID 추출

이러한 특성을 이용하여 QueryRunner에서 requestId를 추출하는 방법을 적용했습니다.

  private extractRequestIdFromQueryRunner(queryRunner: QueryRunner): string {
    const runner = queryRunner as any;
    const metadata = runner['databaseConnectionPromise'];
    const resourceStore = Object.getOwnPropertySymbols(metadata).find(
      (symbol) => symbol.toString() === 'Symbol(kResourceStore)',
    )!;
    const store: { requestId: string } = metadata[resourceStore];
    const requestId = store?.requestId;

    return requestId;
  }