들어가며
미니 프로젝트를 진행하며 원하는 기능에서 api 퍼포먼스(=성능) 가 생각했던 것 보다 나오지 않았다.
-> Chrome 개발자도구 네트워크 탭의 통해 load 를 통해 api 응답이 몇초만에 왔는지 확인할 수 있었다.
그래서 위 api 성능을 더 잘내기 위해 어디서 시간초를 많이 소요하는지 체크를 해보고 싶었다.
그래서 방법을 찾던 중에 Aop 를 사용하여 간단하게 로깅을 할 수 있다는 것을 알았다.
그래서 나중에 혹시또 사용할 수도 있으니 사용했던 방법을 기록해보려고 한다.
build.gradle 추가
implementation 'org.springframework.boot:spring-boot-starter-aop'
application.yml 로깅 추가
logging:
level:
kr:
co:
qrbank:
merchantsigunup: INFO
Main
@EnableAspectJAutoProxy // 스프링 앱에서 애스펙트 메커니즘 활성화 한다.
@SpringBootApplication
public class MerchantSignupApplication {
public static void main (String[] args) {
SpringApplication.run(MerchantSignupApplication.class, args);
}
}
애스펙트 로직을 구현할 메소드를 정의하고 어드바이스 어노테이션을 사용하여 언제 어떤 것을 가로챌지 스프링에 지시한다.
@Around("execution(* spring.*.*(..))")
public void log(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
proceedingJoinPoint.proceed();
}
- @Around : 어떤 메소드 호출을 가로채야 하는지 지정한다.
- 위 @Around 안에 뜻은 , 메소드의 리턴타입, 클래스, 매개변수 관계없이 스프링이 spring 에 속한 패키지에 있는 클래스에 정의된 모든 메소드를 가로챈다
Aspect와 Bean Lifecycle
Spring AOP는 프록시 기반으로 동작합니다.
따라서 AOP가 적용될 대상 메소드가 프록시를 통해 호출되어야 합니다.
예를 들어, Aspect와 함께 사용되는 서비스가 같은 클래스 내에서 호출되면 AOP가 적용되지 않을 수 있습니다.
아래와 같은 코드는 AOP가 적용되지 않습니다.
@Component
public class MyService {
@Autowired
private MyService self;
public void someMethod() {
self.someOtherMethod(); // 자가 참조로 인해 AOP 불가
}
}
Aspect가 적용될 클래스의 메소드는 다른 Bean에서 호출되어야 합니다.
@Component
public class MyService {
public void someMethod() {
// AOP가 적용됨
}
}
@Component
public class AnotherService {
@Autowired
private MyService myService;
public void someOtherMethod() {
myService.someMethod(); // AOP가 적용됨
}
}
@Slf4j
@Aspect
@Component
public class TimingAspect {
/*
- 반환타입 상관없음
- kr.co.spring..* 패키지 하위에 모든 클래스 및 메소드를 aop 한다.
- (..) 메소드 파라미터 의미 0개 이상의 파라미터가 있다.
*/
@Around("execution(* kr.co.spring..*(..))")
public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
long start = System.nanoTime();
Object proceed = joinPoint.proceed();
long executionTime = System.nanoTime() - start;
log.info("JoinPoint : {} executed in : {}ms", joinPoint.getSignature(), executionTime);
return proceed;
}
}
위 로직을 정의 해두고 이제 API 호출을 해보았습니다.
적용 후 실행결과
하지만 저는 Controller -> Service, Service -> Repository 이런식으로
로직이 다른 로직을 탈 때 마다 몇초가 소요되는지가 궁금했습니다.
그래서 직접 코드에 로깅을 해보며 테스트를 해봤습니다.
Controller
@PostMapping("/signup")
public ResponseEntity<?> signUp (
Model model,
@Valid @ModelAttribute SignUpDTO sign,
@RequestParam("files") MultipartFile[] multipartFile) {
long start = System.nanoTime();
signupService.signUp(sign, multipartFile);
long executionTIme = System.nanoTime() - start;
log.info("[Execution time]: [{} ms]", executionTIme);
return ResponseEntity.ok().build();
}
Service
public void signUp(SignUpDTO sign, MultipartFile[] files) {
if (sign == null) throw new RuntimeException("SignUpDTO is Null");
if (files == null || files.length == 0) throw new RuntimeException("Files is Null or empty");
try {
long startTime = System.nanoTime();
List<String> fileUrls = s3StorageService.upload(files, sign);
for (String fileUrl : fileUrls) {
log.info("File uploaded to S3: {}", fileUrl);
}
long endTime = System.nanoTime()-startTime;
log.info("Execution time: {}ms", endTime);
} catch (Exception e) {
log.error("Failed to upload files to S3", e);
throw new RuntimeException(e);
}
}
이런식으로 로직이 타는 곳 마다 로그를 찍어봤습니다.
실질적인 로직이 시작되기 전 로그 1번, 로직이 다 실행되고 난 후 1번 로그를 찍어봤습니다.
저는 일단 예외상황은 고려하지 않고, 정상 플로우 기준으로만 로그를 찍어봤습니다.
실행 후 결과
결과는 AOP 에서 로깅한 결과랑 거의 비슷한 것을 체크했습니다.
* 참고로 nanoTime 으로 체크시 말 그대로 나노 초를 사용하기 때문에 Seconds 로 변환이 필요할 떄가 있을 때는 아래코드를 사용하자
double seconds = (end - start) / 1000000000.0;
왜 비슷한 결과가 나올까? 생각을 해봤습니다.
생각을 결과로는 아마 AOP와 메소드 내부의 시간 측정이 거의 같은 시점에서 실행되기 때문에 결과가 유사할 수 도 있을 것 같았습니다.
예를 들어, 메소드 내부에서 시간 측정이 끝나는 시점과 AOP에서 측정이 끝나는 시점이 매우 근접해있어 시간 차이가 거의 안나거나 똑같은 결과를 로그로 찍는다고 생각합니다.
그래서 든 생각이 더 deep 하게 추적을 해보고 싶다면 오픈소스 및 툴을 사용해야 할 것 같습니다.
작은 프로젝트 및 토이프로젝트 정도는 Aop 를 통한 로그도 나쁘지 않지만,
규모가 있는 프로젝트에서 병목현상을 좀더 면밀하게 관찰을 해보고 싶으시다면 Zipkin, Jaeger, OpenTelemetry 등의 분산 추적 도구를 사용하면, 전체 요청의 흐름과 각 단계별 시간을 더 세밀하게 추적할 수 있다고 하네요
아마 위 같은 툴을 써야 하는 상황은 MSA 아키텍쳐를 사용하여 모듈이 분리가 많이 되어있는 상황이라면
자주 사용할 것 같다고 생각이 듭니다.
추가적으로 인텔리제이 IDE는 AOP 를 설정할 경우 IDE 에서 AOP 되고 있다는 표시를 해줍니다.
결론
참고로 다른 방법으로는
long start = System.currentTimeMillis();
현재 시간을 구하는 다른 메소드로 currentTimeMillis()의 리턴형은 long 값이며, 1/1000초의 값을 리턴한다.
즉 1000ms 단위로 결과가 나온다는 뜻이다.
여러 방법이 있으므로 각자 편한 방법을 사용하자..