typescript 메서드 실행 시간 측정기 decorator 로 구현해보기

Peter·2022년 10월 8일
2

typescript

목록 보기
1/2
post-thumbnail

시간 측정기 decorator 의 필요성

API 개발 후, 테스트 중에 속도가 빠르지 않으면 어느 지점인 병목인지 확인하기 위해 각 메서드 호출 시간을 측정하는 일이 많아졌습니다. 테스트를 위해 임시로 아래와 같이 코드를 추가했다가 지우고 하는 일을 반복하게 되었었는데, "뭔가 간단하게 하는 방법은 없을까?" 하는 생각이 들었습니다. (가끔 테스트용 코드를 지우지 않는 실수를 저지르기도 했습니다.ㅜㅜ)

console.time('method1');
method1(param1);
console.timeEnd('method1');
console.time('method2');
await method2(param2);
console.timeEnd('method2');
console.time('method3');
await method3(param3);
console.timeEnd('method3');
console.time('method4');
method4(param4);
console.timeEnd('method4');
console.time('method5');
await method5(param5);
console.timeEnd('method5');
console.time('method6');
method6(param6);
console.timeEnd('method6');

이러한 기능은 스프링 프레임워크를 학습할 때 배웠던 AOP 를 이용해 좀더 깔끔하게 해결 할 수 있을 것 같았고, 현재 사용하고 있는 Nest.jS 에서도 NestInterceptor 라는 인터페이스를 구현하면 비슷하게 사용할 수 있어 보였습니다.
NestInterceptor 를 이용하여 구현해볼까 하다가, typescript decorator 로 직접 구현해보는 것도 재미있을 것 같아서 한번 시도해보았습니다.

Method Decorator

method 의 "메서드명, 파라미터, 실행 시간"을 로그로 찍어주는 Method Decorator 를 우선 만들어 보았습니다.

export function MethodTimeMeter(logLevel: string) {
  return function (target: any, propertyKey: string, descriptor: PropertyDescriptor) {
    const originMethod = descriptor.value;
    descriptor.value = function (...args) {
      const startTime = Date.now();
      const result = originMethod.apply(this, args);
      const endTime = Date.now();
      log(propertyKey, args, endTime - startTime, logLevel);
      return result;
    };
  };
}

function log(property, args, timeDiff, logLevel) {
  console.log(`[${logLevel}][${new Date().toISOString()}] ${property}(args : ${JSON.stringify(args)}) +${timeDiff}ms`);
}

method decorator 구조에 대해 간단하게 설명하자면, target 은 해당 decorator 가 달린 target Class 를 참조하고, propertyKey 는 프로퍼티 이름을 참조하고, descriptor는 해당 프로퍼티의 정보를 알려줍니다.
decorator 를 메서드에 사용했으니, propertyKey 는 메서드명이 되고, descriptor.value 는 해당 메서드 자체를 참조하게 됩니다.

그리고 간단하게 테스트용 클래스를 작성하여 테스트해보았습니다.

class MethodTimeMeterTestClass {
  @MethodTimeMeter('DEBUG')
  async method1(timeToDelay: number) {
    await wait(timeToDelay);
    return;
  }

  @MethodTimeMeter('INFO')
  method2(n: number) {
    let sum = 0;
    for (let i = 0; i < n; i++) {
      sum += i;
    }
    return sum;
  }
}

const wait = timeToDelay => new Promise(resolve => setTimeout(resolve, timeToDelay));
it('test', async () => {
  const testClass = new MethodTimeMeterTestClass();
  await testClass.method1(3000);
  testClass.method2(1000000000);
});

그런데, 결과가 뭔가 이상합니다.

  console.log
    [DEBUG][2022-10-08T06:32:16.657Z] method1(args : [3000]) +1ms

      at log (common/decorators/time-meter.ts:60:11)

  console.log
    [INFO][2022-10-08T06:32:21.212Z] method2(args : [1000000000]) +1557ms

      at log (common/decorators/time-meter.ts:60:11)

3초 기다리는 함수가 1ms 걸렸다니...
가만 생각해보니 아래 부분이 문제였습니다.

const result = originMethod.apply(this, args);

method1 은 비동기 함수이니, 위와 같이 처리하면 기다리지 않고 다음 라인을 실행하게 됩니다. (물론 result 에는 Promise 객체가 넘어 옵니다.)
그래서, 해당 method 가 async 인 경우 await 해주고, async 가 아닌 경우 기존 작성한 로직을 실행시키면 됩니다.

export function MethodTimeMeter(logLevel: string) {
  return function (target: any, propertyKey: string, descriptor: PropertyDescriptor) {
    const originMethod = descriptor.value;
    if (descriptor.value.constructor.name === 'AsyncFunction') {
      descriptor.value = async function (...args) {
        const startTime = Date.now();
        const result = await originMethod.apply(this, args);
        const endTime = Date.now();
        log(propertyKey, args, endTime - startTime, logLevel);
        return result;
      };
    } else {
      descriptor.value = function (...args) {
        const startTime = Date.now();
        const result = originMethod.apply(this, args);
        const endTime = Date.now();
        log(propertyKey, args, endTime - startTime, logLevel);
        return result;
      };
    }
  };
}

위와 같이 로직을 변경해주니 테스트 결과가 정상적으로 나옵니다.

  console.log
    [DEBUG][2022-10-08T06:34:30.703Z] method1(args : [3000]) +3000ms

      at log (common/decorators/time-meter.ts:53:11)

  console.log
    [INFO][2022-10-08T06:34:32.335Z] method2(args : [1000000000]) +1560ms

      at log (common/decorators/time-meter.ts:53:11)

Class Decorator

그런데, 분석해보고 싶은 로직이 상당히 많은 method 를 연쇄적으로 호출한다면, method 마다 일일이 Method Decorator 를 달아주는 것도 귀찮아 보입니다.
그래서 Class Decorator 를 달아서 class 하위에 있는 method 전체에 실행시간 측정 로깅을 적용하도록 만들어 보았습니다.

export function ClassTimeMeter(logLevel: any) {
  return (target: any) => {
    Object.getOwnPropertyNames(target.prototype)
      .filter(propertyKey => isNonConstructorMethod(target, propertyKey))
      .forEach(propertyKey => {
        const descriptor = Object.getOwnPropertyDescriptor(target.prototype, propertyKey);
        const originMethod = descriptor.value;
        if (descriptor.value.constructor.name === 'AsyncFunction') {
          descriptor.value = async function (...args) {
            const startTime = Date.now();
            const result = await originMethod.apply(this, args);
            const endTime = Date.now();
            log(propertyKey, args, endTime - startTime, logLevel);
            return result;
          };
        } else {
          descriptor.value = function (...args) {
            const startTime = Date.now();
            const result = originMethod.apply(this, args);
            const endTime = Date.now();
            log(propertyKey, args, endTime - startTime, logLevel);
            return result;
          };
        }
        Object.defineProperty(target.prototype, propertyKey, descriptor);
      });
    return target;
  };
}

function isNonConstructorMethod(target, propertyKey) {
  const propertyValue = target.prototype[propertyKey];
  const isMethod = propertyValue instanceof Function;
  return isMethod && propertyKey !== 'constructor';
}

로직은 간단합니다. 기본적으로 우선 만들어 두었던 Method Decorator 로직을 재활용하는데, class 의 property 를 순회하며 해당 property 가 method 인 경우만 필터링 하여 로직을 적용하면 됩니다.

@ClassTimeMeter('DEBUG')
class MethodTimeMeterTestClass {
  async method1(timeToDelay: number) {
    await wait(timeToDelay);
    return;
  }

  method2(n: number) {
    let sum = 0;
    for (let i = 0; i < n; i++) {
      sum += i;
    }
    return sum;
  }
}

이제 위와 같이 class 에 한번 만 ClassTimeMeter 데코레이터를 달아주면, class 내 모든 method 에 실행 시간 측정 로거가 장착됩니다.

  console.log
    [DEBUG][2022-10-08T08:05:46.056Z] method1(args : [3000]) +3001ms

      at log (common/decorators/time-meter.ts:61:11)

  console.log
    [DEBUG][2022-10-08T08:05:47.636Z] method2(args : [1000000000]) +1556ms

      at log (common/decorators/time-meter.ts:61:11)

0개의 댓글