Spring boot AOP를 활용한 로그 추적하기, 메서드 시간 측정하기

https://loy124.tistory.com/397

AOP정의 및 Advice, Pointcut 작성 정리

위 게시글에서는 간단하게 AOP의 정의 및 정리를 진행해 보았다. 

 

 

이제 배운 AOP를 활용해서 2가지를 해보려고 한다.

• 메서드별  Log 남기기 
• 메서드별 시간 측정하기 
  • 해당 시간 측정하기는 annotation을 만든 후 Annotation이 존재하는 경우에만 측정하도록 진행한다.

 

 

 

https://start.spring.io/ 에 접속해서 프로젝트를 Generate 해주었다.

 

IntelliJ를 활용해 프로젝트를 열고 

 

build.gradle을 수정해준다.

plugins {
	id 'java'
	id 'org.springframework.boot' version '3.0.8'
	id 'io.spring.dependency-management' version '1.1.0'
}

group = 'com.project'
version = '0.0.1-SNAPSHOT'

java {
	sourceCompatibility = '17'
}

configurations {
	compileOnly {
		extendsFrom annotationProcessor
	}
}

repositories {
	mavenCentral()
}

dependencies {
	implementation 'org.springframework.boot:spring-boot-starter-web'
	implementation 'org.springframework.boot:spring-boot-starter-aop'
	compileOnly 'org.projectlombok:lombok'
	runtimeOnly 'io.micrometer:micrometer-registry-prometheus'
	annotationProcessor 'org.projectlombok:lombok'
	testImplementation 'org.springframework.boot:spring-boot-starter-test'
}

tasks.named('test') {
	useJUnitPlatform()
}

org.springframework.boot:spring-boot-starter-aop 를 추가해주었다.

 

수정하고 gradle 갱신은 까먹지 말고 진행하자!

Gradle 갱

 

 

 

그다음 member Package에 Controller, Serivce, Respository를 정의해준다. 

실제 DB 커넥션은 진행하지 않을것이기 떄문에 정말 간단한 로직만 작성해주었다. 

 

 

 

MemberRepository

@Repository
@Slf4j
public class MemberRepository {
    public void findAll(){
        
    }
}

 

MemberService

@Slf4j
@Service
@RequiredArgsConstructor
public class MemberService {
    private final MemberRepository memberRepository;

    public void findUserList(){
        memberRepository.findAll();


    }
}

 

MemberController

@RestController
@RequiredArgsConstructor
@Slf4j
public class MemberController {
    private final MemberService memberService;

    @GetMapping("member")
    public String getUserList(){

        memberService.findUserList();
        return "ok";
    }

}

 

이제 각 Controller, Service, Repository 마다 현재 메서드를 로그로 출력할수 있는 코드를 작성해 주겠다. 

 

 

 

로그 추적하기

 

utils package를 만들고 LogAspect Class를 만들어준다.

 

package com.project.study.utils;

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.stereotype.Controller;
import org.springframework.stereotype.Service;

import java.util.Random;
import java.util.UUID;

@Aspect
@Component
@Slf4j
public class LogAspect {

    @Before("execution(* com.project.study..*(..))")
    public void doLog(JoinPoint joinPoint){

        //쓰레드 환경에서 UUID 관리
        String traceId = MDC.get("traceId");

        //traceId가 비어있는 경우에만 만들기
        if(traceId == null){
            traceId = UUID.randomUUID().toString().substring(0, 8);
            MDC.put("traceId", traceId);
        }

        //클래스.메서드
        String target = joinPoint.getSignature().toShortString();

        log.info("start [traceId]={} {} ",traceId, target);

    }

    @After("execution(* com.project.study..*(..))")
    public void doEndLog(JoinPoint joinPoint){
        String traceId = MDC.get("traceId");
        Class<?> targetClass = joinPoint.getTarget().getClass();
        String target = joinPoint.getSignature().toShortString();
        log.info("end   [traceId]={} {}", traceId, target);
        if(targetClass.isAnnotationPresent(Controller.class)){
            MDC.remove("traceId");
        }


    }


}

 

 

StudyApplication이 컴포넌트 스캔을 통해 LogAspect의 Componet를 스캔하고 

등록된 로직을 수행하는 방식이다. 

 

여기서 MDC라는 개념을 활용했는데

 

스프링은 일반적으로 다중 쓰레드 환경에서 싱글톤이 보장되는 환경이다.

하나의 싱글톤인 인스턴스 필드 값을 여러 쓰레드가 동시에 접근한다면 동시성 이슈가 발생하게 된다.

 

이를 활용하기 위해 나온 대책이 ThreadLocal 이다.

 

ThreadLocal

• 해당 쓰레드만 접근할 수 있는 특별한 저장소

 

위 ThreadLocal 기반으로 동작하는 기능이 바로 MDC이다.

 

MDC란?

로그에 추가적인 정보를 연결해서 구분/필터링 할떄 사용된다.

• MDC.put("Key값", Value값) 
  • MDC에 값을 등록할때 사용한다
• MDC.get("Key값")
  • MDC에 저장된 값을 꺼내올 때 사용한다. 
• MDC.remove("Key값")
  • 쓰레드로컬 기반은 값을 설정할 경우 잔존해 있기 때문에 반드시 remove or clear를 통해 값을 비워줘야한다. 
• MDC.clear()
  • MDC 내부 값을 전부 비워준다. 

 

이제 작성했던 코드의 @After 코드를 보겠다. 

    @After("execution(* com.project.study..*(..))")
    public void doEndLog(JoinPoint joinPoint){
        String traceId = MDC.get("traceId");
        Class<?> targetClass = joinPoint.getTarget().getClass();
        String target = joinPoint.getSignature().toShortString();
        log.info("end   [traceId]={} {}", traceId, target);
        if(targetClass.isAnnotationPresent(Controller.class)){
            MDC.remove("traceId");
        }

    }

targetClass.isAnnotationPresent(Controller.class) 를 통해 해당 Controller가 존재하는 경우에만 MDC를 초기화할수 있도록 하였다. 

 

실행 예시

[nio-8080-exec-2] com.project.study.utils.LogAspect : start [traceId]=5b47ccf3 MemberController.getUserList()    
[nio-8080-exec-2] com.project.study.utils.LogAspect : start [traceId]=5b47ccf3 MemberService.findUserList() 
[nio-8080-exec-2] com.project.study.utils.LogAspect : start [traceId]=5b47ccf3 MemberRepository.findAll() 
[nio-8080-exec-2] com.project.study.utils.LogAspect : end   [traceId]=5b47ccf3 MemberRepository.findAll()
[nio-8080-exec-2] com.project.study.utils.LogAspect : end   [traceId]=5b47ccf3 MemberService.findUserList()
[nio-8080-exec-2] com.project.study.utils.LogAspect : end   [traceId]=5b47ccf3 MemberController.getUserList()

MDC는 사용을 끝내게 되면 반드시 초기화를 해야한다고 했는데

호출 순서가 컨트롤러 -> 서비스 -> 레포지토리 -> 레포지토리(실행완료) -> 서비스(실행완료) -> 컨트롤러(실행완료)

의 순이다.

@After인 경우 로직이 실행되고 나서 상태를 말하기 때문에 Controller Annotation을 가지고 있는 경우에는

컨트롤러(실행완료)에 도달하게 된다. 따라서 해당 타이밍에 MDC를 초기화 해주는 로직을 넣어주었다. 

 

 

 

메서드 시간 측정하기

해당 메서드 측정은 @TimeTrace 어노테이션이 존재하는 경우에만 측정할수 있게 진행할것이다 . 

 

먼저 측정시간을 테스트하기 위해 DB 커넥션이 되었다고 가정하고 시간이 오래 걸리도록 유도하는

sleep 함수를 MemberRepository에 추가해준다.

 

@Repository
@Slf4j
public class MemberRepository {

    @TimeTrace
    public void findAll(){
        sleep(1500);
    }

    private void sleep(int mills) {
        try{
            Thread.sleep(1000);
        }catch (InterruptedException e){
            e.printStackTrace();
        }
    }
}

 

이제 TimeTrace Annotation을 utils/annotation에 만든다. 

 

 

 

TimeTrace

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface TimeTrace {
}

 

어노테이션을 만들었으니 이제

해당 어노테이션을 메서드에 달면 동작할수 있는 Aspect 를 만들어보자. 

 

 

package com.project.study.utils;

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.springframework.stereotype.Component;

import java.util.UUID;

@Aspect
@Slf4j
@Component
public class TimeTraceAspect {

    @Around("@annotation(com.project.study.utils.annotation.TimeTrace)")
    public void doTrace(ProceedingJoinPoint joinPoint) throws Throwable {

        long startTIme = System.currentTimeMillis();

        joinPoint.proceed();

        long endTIme = System.currentTimeMillis();

        long resultTime = endTIme - startTIme;
        String target = joinPoint.getSignature().toShortString();
        log.info("메서드 시간 측정 {} , {} ms", target, resultTime);

    }
}

 

이번에는 @Around를 활용해서 진행해 보았다. 

 

joinPoint.proceed

• aop가 적용된 메서드를 수행하고 리턴되는 데이터를 받는 메서드

 

 

 

위와 같이 메서드 시간 측정이 잘 나온다면 정상적으로 실행 된다고 할수 있다.

 

https://github.com/loy124/aop-trace-study

GitHub - loy124/aop-trace-study