멀티스레드 분산 환경에서의 로깅(1)

 

---

서론

담당하고 있는 프로젝트에서 사용자 수가 점점 늘어나고, Batch 작업 갯수가 늘어나기 시작했습니다.

드물게 에러가 발생하기도 하는데, 이 때 어떤 상황인지 파악하고 원인을 알아내기 위해 로그를 추적하기 시작합니다.

Kibana로 로그 모니터링을 하고 있으나 한 가지 문제점을 경험했습니다.

멀티 스레드 및 분산 환경의 모든 로그를 하나로 모아보니 굉장히 많은 로그가 적재되고, 내가 원하는 로그를 찾기가 정말 어려워졌습니다.

 

이 포스팅에서는 이러한 문제점에 대해 알아보고, 다음 포스팅을 통해 하나의 요청에서 파생된 로그들을 쉽게 구분할 수 있도록 하는 방법인 MDC Filter에 대해 알아볼 계획입니다.

---

상황 가정

테스트에 사용된 모든 코드는 Github Repository에서 확인할 수 있습니다.

테스트를 위한 상황을 가정하겠습니다.

예매 시스템이라 가정하고 AOP를 통해 요청의 시작과 끝에 로깅을 합니다.

그리고 비즈니스 로직을 처리하는 Service Layer에서 예상 처리 시간에 대한 로깅을 한다고 가정하겠습니다.

 

단, 실패 상황 재현을 위해 서비스 레이어에서는 낮은 확률로 실패를 하도록 구현하였습니다.

 

로깅 AOP 클래스

@Aspect
@Component
@Slf4j
public class LoggingAOP {

    @Before("execution(* com.example.multithreadlogging.*Controller.*(..))")
    public void appLogging(JoinPoint joinPoint) {
        log.info("[{}] timestamp: {}", getCurrentThreadName(), getCurrentTimestamp());
    }

    @AfterReturning(pointcut = "execution(* com.example.multithreadlogging.*Controller.*(..))", returning = "result")
    public void afterLogging(JoinPoint joinPoint, Object result) {
        log.info("[{}] result: {}", getCurrentThreadName(), result.toString());
    }

    @AfterThrowing(pointcut = "execution(* com.example.multithreadlogging.*Controller.*(..))", throwing = "exception")
    public void afterThrowing(JoinPoint joinPoint, Throwable exception) {
        log.error("[{}] result: {}", getCurrentThreadName(), exception.getMessage());
    }

    private String getCurrentTimestamp() {
        SimpleDateFormat format = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
        String timestamp = format.format(new Date());
        return timestamp;
    }

    private String getCurrentThreadName() {
        return Thread.currentThread().getName();
    }
}

이 클래스는 클라이언트의 요청 시각과 결과 반환 값을 각각 로깅합니다.

스레드 이름을 함께 로깅하기 때문에 할당된 스레드의 이름으로 요청을 구분하기 위한 목적입니다.

 

로그 결과 확인

성능 테스트 도구인 K6를 이용하여 동시에 여러 사용자가 요청 보내는 시나리오를 구성했습니다.

100명의 사용자가 5초간 동일 요청을 보내는 시나리오를 실행하게 되면 초당 297회의 요청을 보내는 결과를 얻게 됩니다.

단일 서비스 환경에서 로그는 약 5000줄이 적재된 것을 볼 수 있습니다.

테스트 시나리오 수행 결과

로그 결과

에러 로그 분석 과정

만약, 에러가 발생하여 그 지점을 찾으려고 한다면 실패했던 지점을 먼저 찾게됩니다.

실제 환경에선 다양한 응답 코드와 메세지가 있겠지만 이 상황에선 Exception을 던지는 경우로 제한하겠습니다.

"ERROR"를 필터링 하게 되면 아래의 결과를 얻게 됩니다.

에러 발생 로그를 확인했으니 "왜" 발생했는지 확인해야 합니다.

유추하기 위해서 "시간", "스레드 이름" 정도를 가지고 접근할 수 있습니다.

 

20:57:16 근처이면서 스레드가 70번인 케이스를 필터링 해보겠습니다.

 

네! 비교적 쉽게 찾았습니다.

3939번째 줄에 있는 StackTrace를 보고 에러 원인을 분석하고 조치하면 되겠습니다.

 

간과하고 있는 것

지금까지의 테스트 환경에서는 실제 환경과 다소 다른 부분이 있습니다.

분산 환경이 아닌 단순 멀티스레드 환경이라는 것, 요청 수가 매우 적다는 점, 로그가 매우 단순하다는 점입니다.

실제 환경에서는 복잡한 비즈니스 로직으로 인해 더 다양한 로그가 기록되고, 분산 환경인 경우 별도 설정이 없다면 스레드 이름까지 겹치게 됩니다.

 

그럼 위에서 문제 지점을 찾기 위해 수단으로 사용했던 "발생 시각", "스레드 이름"은 더 이상 신뢰할 수 있는 정보가 아니게 됩니다.

 

지금 제 실무 환경에서는 쿠버네티스를 사용하여 여러 컨테이너를 관리하고 있습니다.

각 애플리케이션에서 수시로 로그를 기록하고 있고, 각 로그는 하나로 합쳐 Kibana를 통해 모니터링 합니다.

 

만약 10개의 애플리케이션에서 남긴 각각의 로그를 하나로 합친다면 어떻게 될까요?

발생 시각을 통해 추적해보아도 동일 시간에 찍힌 로그가 엄청나게 많고, 심지어 운이 안좋다면 동일 에러가 동일 시간대에 찍혀있습니다.

특히나, 주어진 시간 내에 요청을 처리하지 못해 Timeout이 뜨는 경우 Waiting Pool에 있던 모든 요청이 실패하는 케이스는 엄청난 에러 로그가 동시간에 찍히게 됩니다.

DB Error의 경우 하나의 컨테이너만 영향도가 있는 것이 아니라, 모든 컨테이너에 영향을 미치므로 10개의 컨테이너가 모두 똑같은 에러 로그를 찍게 됩니다.

 

이 경우, 로그 분석 자체에 엄청난 시간이 소요될 것입니다.

 

에러로그가 이쯤 있었는데....

 

로그를 통해 문제를 추적하는 것이 왜 중요할까요?

대부분의 서버 개발자는 에러 상황 발생후 아래와 같은 절차를 따릅니다.

1. 문제 발생(에러 Alert 확인)

2. 문제 확인(로그 분석)

3. 원인 분석(코드 검토)

4. 가설 설정 및 테스트

5. 대안 구현(코드 수정)

6. 검증

7. 문서화

8. 리뷰(공유) 및 개선

 

이 과정을 "트러블 슈팅"이라고 합니다.

보시다시피 로그를 분석하는 과정은 초입단계입니다. 로그 분석이 제대로 이뤄지지 않거나 지체되면 대안을 모색하는 것에 굉장한 어려움을 겪게 됩니다.

 

결론

멀티스레드 및 분산 환경에서 정말 많은 로그가 적재됩니다.

그리고 분산환경에서는 로그 메시지가 섞일 수 있습니다.

에러가 발생하게 되면 로그를 통해 추적하게 될텐데, 이 상황에선 각 요청에 대한 로그를 명확히 구분하기가 어려워지게 됩니다.

따라서, 이러한 환경에서는 하나의 요청에서 파생된 로깅인지 식별할 수 있는 무언가가 필요합니다.

 

 

다음 포스팅 보기

2023.06.04 - [Tech/Java&Spring] - 멀티스레드 분산 환경에서의 로깅(2)

멀티스레드 분산 환경에서의 로깅(2)