디자인 패턴을 활용한 로그 추적기 만들기 - 1

2022. 6. 12. 22:02개발/디자인패턴

 김영한님의 [Spring 핵심 원리-고급편]은 AOP로 가기위한 여정을 약 16시간동안 풀어낸다. 그 과정에서 다양한 디자인 패턴을 학습하게 되는데 Notion으로만 정리해뒀던 자료를 복습하며 블로그에도 한번 옮겨보려고 한다.

 

 

스프링 핵심 원리 - 고급편 - 인프런 | 강의

스프링의 핵심 원리와 고급 기술들을 깊이있게 학습하고, 스프링을 자신있게 사용할 수 있습니다., - 강의 소개 | 인프런...

www.inflearn.com

 작성된 코드는 실제 강의와 코드와 조금 다릅니다. 복습을 위해 스스로 만든 부분도 있고, 코드의 단순화를 위해 비즈니스 로직을 간소화하기도 했습니다. 정확한 코드는 강의를 통해 확인해주세요 :^)

 

목표는 Rest  API 요청에 대한 메소드 콜 Stack과 메소드별 시간을 로그로 남기는 것이다. 최종적으로 아래와 같은 모습이 나와야한다. 

 

1. 노가다 방식 


모든 메소드 별로 시간 측정을 위한 코드를 직접 작성한다. ( 메소드 콜을 표시하는 화살표는 여기서 구현하지 않음 )

시간 측정 로직이 변경되면 모든 메소드를 열어서 로직을 변경해야하는 불편함이 있다.

Controller 클래스
Service 클래스


방법2. 시간 측정 코드를 별도의 클래스로 분리


시간 측정과 콜 스택을 출력을 담당하는 클래스인 Watch를 만들었다. Watch 클래스는 Method의 이름과 시작 시간 정보를 담고 있는 MethodTime 클래스를 가지고 있다.

 

여기서 핵심은 Controller와 Service에 존재했던 로그와 관련된 기능적인 코드를 모두 한곳에 모았다는 것!

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

import java.util.UUID;

@Slf4j
@Component
public class Watch {

    private String requestId; // Watch를 소유하고있는 request ID를 표시
    private int depth =0; // 메소드의 Depth를 측정하기 위한 용도

    // 메소드 시간 측정 시작
    public MethodTime startWatch(String methodName){
        requestId = createRequestId();
        depth++;
        log.info("[{}] {} | {} 메소드 시작 " , requestId,depthCallArrow(depth),methodName);
        return new MethodTime(methodName,System.currentTimeMillis(),requestId);
    }

    // 메소드 시간 측정 종료
    public void endWatch(MethodTime methodTime){

        long durationMillis = System.currentTimeMillis() - methodTime.getMethodStartMillis();
        log.info("[{}] {} | {} 메소드 종료, 소요시간 : {} 초" , methodTime.getRequestId(),
                depthReturnArrow(depth),methodTime.getMethodName(), (float)durationMillis/1000 );
        depth--;
        if(depth == 1) releaseWatch();

    }

    // 요청ID 만들기
    private String createRequestId(){
        if(requestId == null) return UUID.randomUUID().toString().substring(0,8);
        return requestId;
    }

    // 시계 반납
    private void releaseWatch(){
        requestId = null;
    }

    private String depthCallArrow(int depth){
        StringBuilder result= new StringBuilder();
        for(int i=0; i<depth; i++){
            result.append("--");
        }
        return result + "->";

    }

    private String depthReturnArrow(int depth){
        StringBuilder result= new StringBuilder("<-");
        for(int i=0; i<depth; i++){
            result.append("--");
        }
        return result.toString();

    }

}
public class MethodTime {

    private String methodName;
    private long methodStartMillis;
    private String requestId;


    public MethodTime(String methodName, long methodStartMillis, String requestId) {
        this.methodName = methodName;
        this.methodStartMillis = methodStartMillis;
        this.requestId = requestId;
    }

    public String getMethodName() {
        return methodName;
    }

    public void setMethodName(String methodName) {
        this.methodName = methodName;
    }

    public long getMethodStartMillis() {
        return methodStartMillis;
    }

    public void setMethodStartMillis(long methodStartMillis) {
        this.methodStartMillis = methodStartMillis;
    }

    public String getRequestId() {
        return requestId;
    }

    public void setRequestId(String requestId) {
        this.requestId = requestId;
    }

}

Controller와 Service 코드를 아래와 같이 변경할 수 있다. 이전과 달리 로그 기능을 직접 구현하지 않고 Watch를 통해 호출만 하고 있다.

@Slf4j
@RestController
@RequiredArgsConstructor
public class PlaneController {

    private final PlaneService planeService;
    private final Watch watch;

    @GetMapping("/api/v1/planes")
    public ResponseEntity<List<Plane>> findAllPlanes(){

        MethodTime methodTime = watch.startWatch("PlaneController.findAllPlanes"); // 측정 시작
        List<Plane> allPlanes = planeService.findAllPlanes(); // 핵심 로직
        watch.endWatch(methodTime); // 측정 종료
        return new ResponseEntity<>(allPlanes,HttpStatus.OK);

    }

}
@Slf4j
@Service
@RequiredArgsConstructor
public class PlaneService {

    private final PlaneRepository planeRepository;
    private final Watch watch;

    public List<Plane> findAllPlanes() {

        MethodTime methodTime = watch.startWatch("PlaneService.findAllPlanes"); // 측정 시작
        List<Plane> allPlanes = planeRepository.findAll(); // 핵심로직
        sleep(2500); // 테스트를 위한 2.5초의 딜레이
        watch.endWatch(methodTime); // 측정 종료

        return allPlanes;
    }

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

    }

}

1회 실행시 성공적으로 결과가 출력된다. 

API로 2.5초 이내에 2회 요청(첫번째 요청이 끝나기전에 두번째 요청 수행)하면 아래와 같은 로그가 출력된다.

서로 다른 요청(쓰레드)임에도 같은 request ID가 출력된다.

 [방법2]는 치명적인 결함이 하나 있는데 Watch 클래스가 Spring bean이라는 점이다. bean은 싱글톤 객체이기 때문에 Stateless하게 작성해야한다. 하지만 [방법2]에선 requestId와 depth 필드를 모든 쓰레드가 공유하도록 코드가 작성됐다.

(동시성 문제 발생)


방법3. ThreadLocal을 사용해서 Watch의 동시성 문제 해결하기


동시성 문제를 해결하기 위해 먼저 requestId 와 depth 필드를 하나로 묶기 위한 클래스를 만든다. (ThreadLocal을 사용하기 편하게 만듦)

@Data
public class RequestDepth {

    private String requestId; // Watch를 소유하고있는 request ID를 표시
    private int depth; // 메소드의 Depth를 측정하기 위한 용도

    public RequestDepth() {
        this.depth = 0;
        this.requestId = UUID.randomUUID().toString().substring(0,8);
    }

    // 요청ID 만들기
    public String createRequestId(){
        if(requestId == null) return UUID.randomUUID().toString().substring(0,8);
        return requestId;
    }

    public void addDepth(){
        depth++;
    }

    public void minusDepth(){
        depth--;
    }

}

ThreadLocal을 적용해서 Watch 클래스를 변경한다.

syncRequestDepth 메소드를 통해서 ThreadLocal에서 관리할 RequestDepth의 인스턴스를 생성한다. 이미 존재한다면 Pass

endMethodWatch 를 사용해 메소드에서 시계의 사용이 끝났다면 반환하도록 한다. 가장 마지막 메소드까지 사용이 끝(depth가 0)나면 ThreadLocal에서 제거한다.

endMethodWatch 에 있는 remove가 중요한데 만약, remove를 해주지 않으면 이후에 들어오는 Thread가 기존에 존재하는 ThreadLocal의 자원을 재사용하게 된다. 

@Slf4j
@Component
public class Watch {


    private final ThreadLocal<RequestDepth> requestDepth = new ThreadLocal<>();

    // 메소드 시간 측정 시작
    public MethodTime startWatch(String methodName){

        syncRequestDepth();
        requestDepth.get().addDepth();
        String requestId = requestDepth.get().getRequestId();

        int depth = requestDepth.get().getDepth();
        log.info("[{}] {} | {} 메소드 시작 " , requestId,depthCallArrow(depth),methodName);
        return new MethodTime(methodName,System.currentTimeMillis(),requestId);
    }

    // 메소드 시간 측정 종료
    public void endWatch(MethodTime methodTime){
        int depth = requestDepth.get().getDepth();
        long durationMillis = System.currentTimeMillis() - methodTime.getMethodStartMillis();
        log.info("[{}] {} | {} 메소드 종료, 소요시간 : {} 초" , methodTime.getRequestId(),
                depthReturnArrow(depth),methodTime.getMethodName(), (float)durationMillis/1000 );

        endMethodWatch();

    }
		
    private void syncRequestDepth(){

        if(requestDepth.get() == null) requestDepth.set(new RequestDepth());


    }

    // 시계 반납
    private void endMethodWatch(){
        requestDepth.get().minusDepth();
        if(requestDepth.get().getDepth() == 0) requestDepth.remove();


    }

    private String depthCallArrow(int depth){
        StringBuilder result= new StringBuilder();
        for(int i=0; i<depth; i++){
            result.append("--");
        }
        return result + "->";

    }

    private String depthReturnArrow(int depth){
        StringBuilder result= new StringBuilder("<-");
        for(int i=0; i<depth; i++){
            result.append("--");
        }
        return result.toString();

    }

}

 

2.5초 이내 2회 요청을 수행해보자.

각 쓰레드가 독립적인 requestId를 가지며 depth간 간섭이 없기때문에 호출 로그가 정상적으로 표시된다.

쓰레드별로 자신만의 requestId를 가지게 된다.


방법4. 템플릿 메소드 패턴


현재까지 작성한 Controller와 Service를 보면 Watch의 실행과 종료를 직접 호출해줘야한다. 

비즈니스 로직만 담당하는 메소드에 책임이 하나 부여된것이다. ( 단일 책임 원칙에 어긋난다. )

템플릿 메소드 패턴을 통해 Controller와 Service에서 Watch를 직접 실행하는 코드를 제거한다.

 

시간 측정을 시작,종료하는 템플릿을 하나 만든다. 시간 측정 시작/종료 사이에 비즈니스 로직을 수행할 수 있도록 call 추상 메소드를 만든다. (비즈니스 로직은 자식 클래스에서 직접 작성한다.)

@RequiredArgsConstructor
public abstract class AbstractTemplate<T> {

    private final Watch watch;

    public T execute(String methodName){

        MethodTime methodTime = watch.startWatch(methodName);
        T result = call();
        watch.endWatch(methodTime);
        return result;
    }

    protected abstract T call();

}

 

Controller에선 Template의 call 메소드에 자신의 비즈니스 로직을 작성하면 된다.

명시적인 상속 대신에 익명 클래스를 사용해서 비즈니스 로직을 작성했다. 

@Slf4j
@RestController
@RequiredArgsConstructor
public class PlaneController {

    private final PlaneService planeService;
    private final Watch watch;

    @GetMapping("/api/v1/planes")
    public ResponseEntity<List<Plane>> findAllPlanes(){

        AbstractTemplate<List<Plane>> abstractTemplate = new AbstractTemplate(watch){

            @Override
            protected List<Plane> call() {
                return planeService.findAllPlanes(); // 핵심 로직
            }
        };

        List<Plane> allPlanes = abstractTemplate.execute("PlaneController.findAllPlanes");

        return new ResponseEntity<>(allPlanes,HttpStatus.OK);

    }

}

실행 결과

템플릿 메소드 패턴의 문제점은 기본적으로 Template을 상속받아야 하기때문에 자식(비즈니스 로직이 존재하는 클래스)과 부모(AbstractTemplate)가 강결합되는 문제가 있다. 자식은 그냥 부모 클래스에게 자신의 비즈니스 로직만 던져주면 되는데 상속까지 받아서 문제를 해결하고 있다. ( 심지어 자식 클래스는 부모쪽에 있는 메소드 중 어느것도 사용하지 않는다. ) 또한 상속은 기본적으로 부모 클래스의 변화에 상당히 취약하다.


방법5. 전략 패턴


전략패턴은 상속에서 오는 단점을 해결하기 위한 방법이다. ( 상속대신 인터페이스를 통한 Composition을 활용함! )

전략은 쉽게 변하는 부분을 말한다. 해당 예제에선 비즈니스 로직이 전략이라 생각하면 된다.

 

 강의에선 전략패턴으로 Controller와 Service를 구현하는 방법을 알려주진 않아서 직접 작성해봤다.(올바르게 쓴건진 잘 모르겠음) 작성하고 보니 방법6과 흡사한 모습이 되었다. 

public interface WatchStrategy {

    Object call();
}

전략패턴에서 Context는 고정적인 부분을 담당한다. 즉, Context에 전략을 바꿔끼워주면 된다. 

해당 예시에서 Context는 시간 측정을 시작/종료하는 로직이다.

@RequiredArgsConstructor
@Component
public class WatchStrategyContext {

    private final Watch watch;

    // 전략을 입력받아 처리한다
    // 전략 = 비즈니스 로직
    public Object execute(WatchStrategy watchStrategy,String methodName){
        MethodTime methodTime = watch.startWatch(methodName);
        Object result = watchStrategy.call();
        watch.endWatch(methodTime);
        return result;
    }

}

Controller와 Service에선 Context를 호출해서 전략(비즈니스 로직)을 끼워주면 된다.

@Slf4j
@RestController
@RequiredArgsConstructor
public class PlaneController{

    private final PlaneService planeService;
    private final WatchStrategyContext watchStrategyContext;

    @GetMapping("/api/v1/planes")
    public ResponseEntity<List<Plane>> findAllPlanes(){

        // Context에 전략을 주입한다.
        // Context => 시간 측정 기능(Watch)
        // 전략 => 비즈니스 로직
        // 즉, Context에 비즈니스 로직(전략)만 바꿔끼워주면 된다.
        List<Plane> allPlanes = (List<Plane>) watchStrategyContext.execute(planeService::findAllPlanes, "PlaneController.findAllPlanes");

        return new ResponseEntity<>(allPlanes,HttpStatus.OK);

    }

}
@Slf4j
@Service
@RequiredArgsConstructor
public class PlaneService {

    private final PlaneRepository planeRepository;
    private final WatchStrategyContext watchStrategyContext;

    public List<Plane> findAllPlanes() {

        return (List<Plane>) watchStrategyContext.execute(() ->{
            sleep(2500);
            return planeRepository.findAll();
            }, "PlaneService.findAllPlanes");
    }

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

    }

}

방법6. 템플릿 콜백 패턴


[방법6]이 [방법5]와 비슷하다고 했는데 알고보니 템플릿 콜백 패턴이 전략 패턴에서 콜백 부분이 강조된 것이라고 한다. 템플릿 콜백 패턴이란 용어는 GoF에 등장한 것은 아니고 Spring에서 워낙 자주 쓰이는 패턴이다보니 이름이 붙어버린 케이스.

 

콜백이란? 인수로 넘어간 실행가능한 코드이다. 주로 프론트엔드 개발시 팝업을 종료할때 종료후 수행할 코드를 다른 화면으로 넘길때 주로 쓰이는것 같다. 자바8 이전에는 함수형 프로그래밍이 없어서 다형성을 통한 코드 인스턴스 넘기기가 가능했는데 Java8이 후엔 Lambda를 통해 콜백을 주로 쓰는듯 하다.

 

인수로 넘길 콜백을 인터페이스를 정의한다. 

public interface WatchCallback<T>{

    T call();

}

 

콜백을 인수로 받아서 이를 실행하기 위한 템플릿 클래스를 작성한다. 템플릿은 전략 패턴에서 본 Context와 같은 기능을 한다. ( 고정적 )

@RequiredArgsConstructor
@Component
public class WatchTemplate {

    private final Watch watch;

    public <T> T execute(WatchCallback<T> callback,String methodName){
        MethodTime methodTime = watch.startWatch(methodName);
        T result = callback.call();
        watch.endWatch(methodTime);
        return result;
    }

}

 

Controller에선 템플릿에 실행 가능한 코드를 넘겨주기만 하면 된다. [방법5]와 마찬가지로 익명 내부 클래스를 사용한다.

@Slf4j
@RestController
@RequiredArgsConstructor
public class PlaneController{

    private final PlaneService planeService;
    private final WatchTemplate watchTemplate;

    @GetMapping("/api/v1/planes")
    public ResponseEntity<List<Plane>> findAllPlanes(){

        List<Plane> allPlanes = watchTemplate.execute(new WatchCallback<List<Plane>>() {
            @Override
            public List<Plane> call() {
                return planeService.findAllPlanes();
            }
        }, "PlaneController.findAllPlanes");

        return new ResponseEntity<>(allPlanes, HttpStatus.OK);

    }

}

처음에 비하면 비즈니스 로직이 많이 간단해 졌다. 하지만 시간측정을 실행하기 위해선 적어도 한번은 Controller와 Service에서 시간 측정과 관련된 코드를 호출해야한다. [방법6]에서도 Controller에서 템플릿에 있는 execute 메소드를 직접 호출해야하는 불편함이 있다. 다음번엔 어떻게 이 문제를 해결하는지 학습후 포스팅 하겠다.

 

 

현재 게시글에 작성된 코드의 커밋 history


 

GitHub - 92SooJong/airline-backend: (학습용) 항공기 관리 백엔드 시스템

(학습용) 항공기 관리 백엔드 시스템 . Contribute to 92SooJong/airline-backend development by creating an account on GitHub.

github.com