표준 예외 처리에서 로깅까지 (2)

Step 3. 비동기 로직

@Configuration
@EnableAsync
public class AsyncConfiguration implements AsyncConfigurer {

}

먼저 비동기 사용을 위한 설정을 추가합니다.

@RestController
public class AsyncTestController {

    private final AsyncService asyncService;

    @GetMapping("/api/test/async")
    public void asyncTest() throws InterruptedException {
        for (int i = 1; i <= 100; i++) {
            MDC.put("tid", String.valueOf(i));
            asyncService.async(i);
        }

        Thread.sleep(3000L);
    }
}

@Service
public class AsyncService {

    @Async
    public void async(Integer tid) throws InterruptedException {
        Thread.sleep((long) (Math.random() * 1000 + 1));
        log.info("### mdc.tid={}, inputValue={}", MDC.get("tid"), tid);
    }
}

다음은 controller와 service를 만듭니다.

controller에서는 모든 비동기 처리가 끝나기 전 서버 종료를 방지하기 위해 3 초의 sleep을 적용합니다.
service에서는 무작위 처리를 위해 1초 이하의 sleep을 적용합니다.

 

---

여기까지가 전 글의 내용입니다.
이제 문제를 해결하기 전에 원인을 알아보고 진행하겠습니다.

Spring에서는 webRequest 당 하나의 쓰레드를 할당해서 작업을 처리합니다.
이 정보는 ThreadLocal에 저장되며, MDC는 MDCAdapter의 구현에 따라 이 정보를 가져와 처리하기에
정보를 공유할 수 있습니다.

하지만 비동기 처리를 위해서 사용하는 TaskExecutor는 새로운 쓰레드를 만드는데,
이때 기존 쓰레드의 context 가 공유되지 않습니다.

 

Step 3-1. 생성되는 쓰레드에 context 공유하기

public class MDCTaskDecorator implements TaskDecorator {

    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> copyOfContextMap = MDC.getCopyOfContextMap();

        return () -> {
            if (copyOfContextMap != null) {
                MDC.setContextMap(copyOfContextMap);
            }

            runnable.run();
        };
    }
}

새로 생성되는 쓰레드에 context를 복사하기 위한 TaskDecorator를 구현합니다.

 

public class AsyncConfiguration implements AsyncConfigurer {

    @Bean
    public TaskExecutor taskExecutor() {
        ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();

        taskExecutor.setTaskDecorator(new MDCTaskDecorator());
        taskExecutor.setCorePoolSize(20);
        taskExecutor.setMaxPoolSize(50);
        taskExecutor.setQueueCapacity(100);

        return taskExecutor;
    }
}

구현한 TaskDecorator를 AsyncConfiguration에 추가합니다.
이때 비동기 처리를 위한 적절히 배압 설정을 합니다.
본 예제에서는 100 건이 동시에 들어옴으로 QueueCapacity를 100으로 설정했습니다.

 

비동기 로직에도 MDC 를 활용한 로깅이 적용된 것을 확인할 수 있습니다.

 

마치며..

처음에는 UUID로 logId를 남기면서 잘 만들었다고 생각했는데, 지금 보니 전혀 실용적이지 않은 구현이었네요.
어쩌면 지금도 전혀 실용적이지 않을 수 있지만
아마 다음 버전을 작성한다면 레이어별 수행 시간을 체크하고 slack 알림을 하는 것까지는 구현할 것 같습니다.
같이 처리할 수 있을지 모르겠지만 slowquery 모니터링까지도 고려하고 있습니다.

사실 요즘 구성이 잘 되어 있는 회사는 kafka로 메시지 큐를 구성하고 elastic과 kibana로 로그를 관리합니다.
하지만 지금 회사의 규모에서는 오버 스펙이기도 하고 기반 기술의 공부가 부족하기에 이 정도만 적용해도 충분할 것 같습니다.

언젠가는 전부 설계하고 구현할 수 있게 되기를..