MDC를 활용해 쓰레드 전환을 이해해보다.

멀티쓰레드 환경에서는 항시적으로 로그가 뒤섞이곤 한다.

 

여러 요청이 동시에 처리될 때

동일한 요청에 대한 로그가 연속적으로 쌓이는것이 아니기 때문이다.

 

 

이 문제를 해결하는 한 가지 방법으로, MDC(Mapped Diagnostic Context)를 활용할 수 있다.

 

각 HTTP 요청에 대한 UUID를 MDC에 저장하고,

이 UUID를 모든 로그 메시지에 자동으로 포함시키는 방식이다.

이를 통해 로그를 분석할 때 각 요청을 명확하게 구분할 수 있다.

 

이처럼 MDC는 주로 로그에 추가적인 컨텍스트 정보를 자동으로 포함시키는 기능을 제공한다.

덕분에 멀티스레드 환경에서도 요청별 또는 사용자별로 로그를 일관되게 관리할 수 있어

로그 추적이 훨씬 간편해진다.

 

 

---

 

MDC를 이용해 특정 로그를 제외시키는 것은 일반적인 사용 사례는 아닐 수 있지만,

비동기 작업이나 스케줄링 작업처럼 빈번하게 호출되는데

의도치 않게 로그 양이 너무 많아지는 경우에는 유용할 수 있다.

 

너무 빈번하게 발생하는 불필요한 로그를 제거하여

가독성을 높이고 로그의 혼잡을 줄이는 데 도움을 줄 수 있기 때문이다.

 

 

 

 

 

이 스케쥴링 코드에 MDC.put("ignore", "true") 와

MDC.clear() 를 추가한 이유가 뭘까?

 

reloadAds() 메소드는 1분마다 실행되는 스케줄링 작업이다.

이 작업에서 발생하는 로그가 너무 빈번하게 찍혀서 다른 중요한 로그의 가독성을 방해할 수 있었다.

그래서 이 메소드에서 생성되는 로그를 필터링하여 로그의 혼잡을 줄이기로 했다.

 

MDC.put("ignore", "true")를 사용해 해당 스케줄링 로그를 제외시키고,

작업이 끝난 후 MDC.clear()로 설정을 복원하여 이후 로그에 영향을 미치지 않도록 한 것이다.

 

 

MDC (Mapped Diagnostic Context)는

현재 실행 중인 쓰레드에 메타 정보를 넣고 관리하는 공간이다.

MDC는 내부적으로 Map을 관리하고 있어 (key, value) 형태로 값을 저장한다.

 

메타 정보를 쓰레드별로 관리하기 위해서

내부적으로 "쓰레드 로컬"을 사용하고 있다.

 

 

 

 

 

MDC는 로그의 컨텍스트 정보를 설정하는 기능으로,

애플리케이션의 요청 처리 과정에서 가장 먼저 실행되는 필터에 적용하여

필터에서 설정한 MDC 값이 이후의 모든 로그에서 사용되도록 한다.

 

 

• decide 메소드는 로그 이벤트를 필터링할지를 결정하는 메소드
• MDC.get("ignore")는 MDC에서 "ignore"라는 키에 대응하는 값을 가져옴
• StringUtils.isNotEmpty(MDC.get("ignore"))는 "ignore" 키에 값이 설정되어 있는지를 확인
  • 값이 설정되어 있으면, FilterReply.DENY를 반환하여 해당 로그를 필터링(즉, 출력하지 않음)
  • 값이 설정되어 있지 않으면, FilterReply.ACCEPT를 반환하여 해당 로그를 출력함

 

 

그리고 마지막에 MDC.clear()을 꼭 해주어야 한다.

 

MDC는 쓰레드 별로 저장되는 "쓰레드 로컬"을 사용하기 때문에

요청이 완료될 때 clear 처리를 하지 않으면

다른 요청이 이 쓰레드를 재사용할 때 데이터가 남아있을 수 있기 때문이다.

 

 

 

---

[ MDC 적용 안 했을 때 로그 예시 ]

 

 

 

 

 

 

 

당연히 로그를 전부 찍는다.

 

 

 

[ MDC 적용 했을 때 로그 예시 ]

 

 

 

 

요청이 들어올 때 HTTP 요청을 처리하는 필터에서 발생한 로그는 찍었지만,

아래 부분에 대해서는 원하는대로 로그가 찍히지 않은 것을 확인할 수 있다.

 

log.debug("getAds clientInfo : {}", clientInfo);
log.debug("getAds request : {}", request);

 

 

하지만 쿼리 관련 로그도 찍히길 원치 않았는데,

제외되지 않고 찍힌다...

 

 

 

---

메소드에 MDC를 적용했는데 원치 않는 로그가 찍힌 이유가 뭘까?

 

이유는 위에서 말한

메타정보를 내부적으로 "쓰레드 로컬"을 사용하기 때문이다.

 

쓰레드명을 보면

[ctor-http-nio-5] 로 찍혔던 쓰레드명이

DB 조회를 할 때는 [ock-scheduler-1]로 바뀐것을 볼 수 있다.

 

 

웹플럭스 코드에서 DB 조회하는 코드에는 async() 처리를 했는데

그 코드가 아래 내용을 포함하고 있다.

 

 

 

 

 

비동기 작업의 실행 스레드

async 메소드의 subscribeOn(blockingScheduler) 설정에 따라

비동기 작업이 blockingScheduler에서 실행된다.

이 때문에 쿼리 관련 로그가 block-scheduler-1 스레드에서 찍히는 것이다.

 

 

쓰레드명이 [ctor-http-nio-5] -> [ock-scheduler-1] 로 바뀌었기 때문에

MDC는 인식을 하지 못하고

ock-scheduler-1 쓰레드에 대해서는 로그를 찍어버리는 것이다.

 

 

 

---

 

그럼 어떻게 해야 DB 조회하는 로그도 안 찍을 수 있을까?

 

아래와 같이 코드를 수정하니

DB를 조회하는 쿼리로그도 찍히지 않았다.

 

 

MDC.put("ignore", "true")를 설정하여 요청의 모든 로그가 필터링되도록 한다.

 

externalAdsSupplier.getAds(clientInfo, request)를 호출한 후,

doOnNext에서 MDC.clear()를 호출하여 MDC를 복원한다.

 

 

 

 

 

getCustInfoFromDB()

• 비동기 작업에서 MDC를 복사하여 설정하는 것이 중요하다.
• MDC.putCloseable("ignore", "true")를 사용하여 비동기 스레드에서도 MDC 값을 설정한다.
• MDC.MDCCloseable을 사용하여 try-with-resources 블록 내에서 MDC 값을 설정하고
  • 작업이 끝난 후 자동으로 MDC를 복원한다.

핵심 포인트

• MDC.putCloseable()는 기존의 MDC 값을 복사하는 것이 아니라,
  • 현재 스레드에서 새로운 MDC 값을 설정하고 블록이 끝나면 자동으로 복원한다.
• 비동기 작업에서 MDC 값을 설정할 때 MDC.putCloseable()을 사용하면 로그의 일관성을 유지할 수 있다.

 

 

---

맺음말

 

 

이번 포스팅에서는 멀티스레드 환경에서의 쓰레드 전환에 대해 살펴보았다.

 

쓰레드 전환은 비동기 작업에서 컨텍스트 정보를 유지하는 데 영향을 미쳐 자원 관리와 디버깅을 복잡하게 만들 수 있다.

비동기 작업이 빈번하게 발생하는 시스템에서는 쓰레드 전환이 자주 일어나며,

이를 잘 이해하는 것이 시스템의 성능과 안정성을 크게 향상시킬 수 있다.

 

쓰레드 전환을 효과적으로 이해하고 적절히 관리하는 것이 매우 중요하다.

이를 통해 복잡한 멀티스레드 환경에서도 시스템의 신뢰성과 효율성을 유지할 수 있을 것이다.