MDC를 사용해 멀티쓰레드 로깅하기 (for 쓰레드간 Context 전달)
■ Intro
멀티쓰레드 환경의 비동기 로깅을 해야했고, MDC를 활용했다.
상황을 설명하자면 요청 경로는 동일하게 들어오지만 중간에 쓰레드가 나뉘는 코드가 있었는데, 요청의 컨텍스트를 유지하고 있어야 했다. 예를들어 처리시간을 로깅하려면 처리시작 시간을 보유하고 있어야 어디선가 처리가 끝날 때 총 처리 시간을 구할 수 있다. 비동기일 경우 처리가 끝나는 시점을 모르기 때문에, 그런 최적의 방법에 대한 고민이 필요했다.
결론적으로 MDC + TaskDecorator + AOP를 통해서 구현했다. 비동기 처리의 완료시점을 확실히 하는 것이 중요하므로 MDC를 사용하여 쓰레드를 트래킹하는 것이 적절해보였다. TaskDecorator가 MDC 컨텍스트를 분기 대상 쓰레드로 넘겨서 종료시점까지 정보를 유지하려는 방법이다. 또한 AOP로 시점을 특정하는 것이 명확하다고 판단해서 로깅용 Aspect 클래스도 하나 만들었다.
모두 다 기존 코드를 건드리지 않고 싶었던 것이 핵심이었다.
■ MDC 개념
□ MDC (Mapped Diagnostic Context)
- MDC는 로깅을 목적으로 설계되었다. ThreadLocal에 의해 현재 쓰레드 범위 내 정보를 로그에 활용할 수 있다.
- MDC는 key/value 구조다. 이에 따라 get, put 등의 메서드를 가진다.
- MDC는 멀티 클라이언트, 멀티 쓰레드 환경에서 활용 가능하다. 다른 클라이언트와 값을 구별하여 로그를 추적할 수 있다. 쓰레드마다 ThreadLocal을 통해 Id값을 가질 수 있고, 따라서 쓰레드가 살아있는 동안 쓰레드별 실행흐름 트래킹이 가능하다. 그러나 비동기 쓰레드와 호출한 쓰레드의 MDC 영역이 달라, 실행흐름이 다른 쓰레드로 넘어가면 정보를 유지하지 못하다는 문제가 있다. 이를 TaskDecorator를 통해 해결한다.
아래서 더 자세히 보자.
□ 분기된 쓰레드에서 MDC를 유지하는 방법
다음과 같이 MDC 컨텍스를 TaskDecorator를 통해 다른 쓰레드로 넘겨줘서, 다음 쓰레드에서 정보를 유지한다. 아래의 TaskDecorator를 TaskExecutor에 추가하면 된다.
* TaskDecorator: 비동기 작업 실행 전후에 추가 작업 수행이 필요할 때 사용한다.
(TaskDecorator, TaskExecutor은 모두 Spring 기능인데, 아래서 더 짚어볼 것이다)
import org.slf4j.MDC;
import org.springframework.core.task.TaskDecorator;
import java.util.Map;
public class LoggingTaskDecorator implements TaskDecorator {
@Override
public Runnable decorate(Runnable task) {
Map<String, String> callerThreadContext = MDC.getCopyOfContextMap();
return () -> {
if (callerThreadContext != null) {
MDC.setContextMap(callerThreadContext);
}
try {
task.run();
} finally {
MDC.clear();
}
};
}
}
이렇게 만든 TaskDecorator를 ThreadPoolTaskExecutor에 등록해두면 된다.
예를 들면 이와 같이 등록한다.
@Configuration
@EableAsync
public class CustomTaskExecutorConfig {
public Executor taskExecutor() {
ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
executor.setCorePoolSize(~~);
executor.setMaxPoolSize(~~);
executor.setQueueCapacity(~~);
executor.setThreadNamePrefix("~~~");
executor.setTaskDecorator(new XxxxxTaskDecorator());
executor.initialize();
return executor;
}
}
도움이 된 블로그를 남긴다: https://hyune-c.tistory.com/20
표준 예외 처리에서 로깅까지 (2)
Step 3. 비동기 로직 @Configuration @EnableAsync public class AsyncConfiguration implements AsyncConfigurer { } 먼저 비동기 사용을 위한 설정을 추가합니다. @RestController public class AsyncTestController { private final AsyncService a
hyune-c.tistory.com
■ Code Sample
동작 확인을 위해 샘플코드를 작성했다.
https://github.com/yyeennyy/yensolution/tree/main/logging/async-return-log%20(aop%20and%20mdc)
yensolution/logging/async-return-log (aop and mdc) at main · yyeennyy/yensolution
Contribute to yyeennyy/yensolution development by creating an account on GitHub.
github.com
api 호출부터 해서 끝까지 비동기 호출을 총 두번 하도록 했는데,
결과적으로 MDC 컨텍스트가 끝까지 넘어감을 확인했다.
호출 한번은 TaskExecutor로 했고, 두번째 호출은 @Async 메서드를 호출해봤다.
[설명]
1. 컨트롤러가 API 요청을 받으면 startTime을 기록한다. 그리고 새로운 thread를 TaskExecutor를 통해 실행한다.
2. 새로운 thread에서 랜덤 시간동안 대기하다가 endTime을 기록한다.
3. 다른 서비스의 @Async 메서드를 호출하여 랜덤 시간동안 대기하다 종료한다.
그럼 이제 @Async 메서드의 종료를 감지하는 AOP에서 "처리시간(Processing Time)"이 로그에 남아야 성공이다. 왜냐하면 처리시간은 startTime 정보를 (MDC에) 유지하고 있어야 계산가능한 값이기 때문이다.
다음은 실행 결과이다.
MDC 컨텍스트가 최종쓰레드까지 잘 넘어가 processing time이 잘 계산되어 찍힌다.
2024-10-11T15:02:56.537+09:00 INFO 18192 --- [demo] [ async-task-4] com.example.demo.LogAspect : req ecb793f2-7260-4d54-9d3c-2a3544d7f71d: processing time 1096790200
2024-10-11T15:03:01.436+09:00 INFO 18192 --- [demo] [ async-task-5] com.example.demo.LogAspect : req 480ae268-795c-4519-bd59-fc7d9132a508: processing time 4621084500
2024-10-11T15:03:04.173+09:00 INFO 18192 --- [demo] [ async-task-2] com.example.demo.LogAspect : req 1f092f59-cc45-458a-88df-61a3ce983634: processing time 5965984500
2024-10-11T15:03:14.526+09:00 INFO 18192 --- [demo] [ async-task-5] com.example.demo.LogAspect : req 4121ecae-38ae-4c49-bdbf-985ff3374f79: processing time 1248142100
2024-10-11T15:03:15.711+09:00 INFO 18192 --- [demo] [ async-task-2] com.example.demo.LogAspect : req 79d4d238-e280-45db-9da3-09f22dffb9f4: processing time 1386251100
2024-10-11T15:03:20.433+09:00 INFO 18192 --- [demo] [ async-task-3] com.example.demo.LogAspect : req 7189c2ff-b03d-4ea8-b952-a9a7c14f96eb: processing time 2803170000
2024-10-11T15:03:23.841+09:00 INFO 18192 --- [demo] [ async-task-3] com.example.demo.LogAspect : req f36c807d-3afd-459c-8866-e5bba341391d: processing time 2662844300
2024-10-11T15:03:26.138+09:00 INFO 18192 --- [demo] [ async-task-2] com.example.demo.LogAspect : req 12cc51b8-7f0a-4fbf-b4e8-be6e6dc3d4dc: processing time 3926893300
2024-10-11T15:03:29.527+09:00 INFO 18192 --- [demo] [ async-task-3] com.example.demo.LogAspect : req 45f8b03a-a5ec-4b52-a40d-f1ef999f41a8: processing time 4714729500
2024-10-11T15:03:31.147+09:00 INFO 18192 --- [demo] [ async-task-2] com.example.demo.LogAspect : req e2f99044-1998-44d6-9fd8-40081f9cffb8: processing time 5257876100
2024-10-11T15:03:32.283+09:00 INFO 18192 --- [demo] [ async-task-3] com.example.demo.LogAspect : req 19f8a2d1-62aa-4441-96cf-488319ea09de: processing time 4761885800
2024-10-11T15:03:32.541+09:00 INFO 18192 --- [demo] [ async-task-1] com.example.demo.LogAspect : req 30d83153-0142-4f43-a014-6ca82e0e88eb: processing time 4709388400
2024-10-11T15:03:33.416+09:00 INFO 18192 --- [demo] [ async-task-5] com.example.demo.LogAspect : req 41d32804-5a16-4b11-bd87-63c2a34d95e3: processing time 5639482000
2024-10-11T15:03:34.908+09:00 INFO 18192 --- [demo] [ async-task-1] com.example.demo.LogAspect : req 98d0ad9e-54bc-49f9-a057-e935c98e4ca3: processing time 7924615400
2024-10-11T15:03:35.684+09:00 INFO 18192 --- [demo] [ async-task-2] com.example.demo.LogAspect : req 8b5583f0-32fe-44c9-b137-bef4e723c210: processing time 6276172200
□ 주의점: new Thread().start()와 ThreadExecutor 차이를 이해하기
새로운 Thread를 실행시킬 때,
그냥 new Thread() 하고 start() 시키면 TaskDecorator를 통하지 않아서 MCD 컨텍스트가 안 넘어간다.
[나쁜 예]
CustomThread thread = new CustomThread(~~~);
thread.start();
[좋은 예]
taskExecutor.execute(new CustomThread(~~~));
이를 이해하려면 TaskExecutor를 통해 Thread를 실행하는 것과, new Thread를 start()하는 것의 차이점을 알아야 한다. new Thread()를 직접 start()하는 것은 간단한 테스트 정도에만 사용하기로 하자.
| taskExecutor.execute() | new Thread().start() | |
| 쓰레드 재사용 여부 | 스레드 풀 기반으로, 기존 스레드를 재사용한다. |
매번 새로운 스레드를 생성한다. |
| 따라서 리소스 절약 & 효율적이다. | 스레드 생성 비용이 크다. | |
| 관리 용이성 | Spring에서 자동 관리한다. | 직접 관리해줘야 한다. |
| 확장성 | 설정을 통해 병렬 작업 제어가 쉽다. | 병렬 작업 제어가 어렵다. |
*참고로 TaskExecutor 구현체 중, 매번 새로운 스레드를 생성할 수 있는 SimpleAsyncTaskExecutor라는 구현체가 있다. 그러나 가장 일반적인 것은 ThreadPoolTaskExecutor이다.
정리하자면,
MDC 컨텍스트를 다른 스레드에 넘겨주기 위해서는 TaskDecorator를 TaskExecutor에 등록해줘야 하므로, 그냥 new Thread().start()하면 안되고, decorator가 등록된 TaskExecutor를 통해 execute(new Thread())해주어야 한다.
*@EnableAsync 를 활성화할 경우, Spring은 내부적으로 TaskExecutor를 사용해 비동기 작업을 처리하며, 설정된 TaskExecutor가 없으면 기본 TaskExecutor를 만들어서 사용한다. 또한 @Async도 마찬가지로 TaskExecutor를 사용하여 별도 쓰레드에서 메서드를 실행한다. 개발자가 직접 TaskExecutor의 execute()를 호출하지 않고도, 간단히 비동기 작업을 수행할 수 있게 한다.
■ Thread 구현체의 run()에 AOP 적용하기
솔직히 MDC 컨텍스트를 넘겨주는 것은 TaskExecutor에 TaskDecorator를 잘 등록해주면 되므로 별 문제가 안될 수 있다.
그것보다 비동기 메서드에 AOP를 적용하는 방법에 대한 고민을 좀 했다.
이때 최우선적으로 고려한 것은 다음의 두 가지다.
- 현재 코드를 건드리지 않기
- 추후 다른 개발자에게 미칠 영향
내 상황은 어떤 Thread 구현체가 있고, run()이 구현된 상태였다. 그래서 이 Thread의 run()을 로깅하기 위한 고민이 필요했다. run()의 시작과 끝을 어떻게 로깅해야 할까? 로깅하는 위치를 한곳으로 통일하고 싶었기 때문에 이번에도 동기 메서드 로깅처럼 AOP를 적용하고 싶었다.
하지만 run()에 AOP를 적용하려고 생각해봤을 때, 가장 먼저 다음 문제점을 짚어볼 수 있다.
.
.
이 내용은 길어져서 다른 글로 뺀다!!
To be conti...
.
.
Ref.
[로깅 그리고 MDC]
https://velog.io/@belljun3395/%EB%A1%9C%EA%B9%85-%EA%B7%B8%EB%A6%AC%EA%B3%A0-MDC
[표준 예외 처리에서 로깅까지 (2)]
https://hyune-c.tistory.com/20
[Spring의 동기, 비동기, 배치 처리시 항상 context를 유지하고 로깅하기]
https://blog.gangnamunni.com/post/mdc-context-task-decorator/