[Spring] Spring Micrometer + Grafana Tempo 찍먹 하기

Spring Logging 구축하기 - (메서드 로그)

지난 포스팅에서는 API 요청이 들어오면 호출되는 메서드를 로깅하였습니다.

그런데 최근에 모니터링 도구를 도입하면서 메서드를 로깅하는 것이 Trace란 것을 알게 되었습니다.

그리고 당연히 Trace를 쉽게 할 수 있도록 해주는 라이브러리가 있었습니다.

 

직접 만든 메서드 로깅 시스템은 만들면서 공부를 할 수 있었던 점에 만족하고 프로젝트에 외부 Tracing 도구를 도입하기로 하였습니다.

 

나름 자주 언급되는 APM에는 Datadog, PinPoint등이 있는데 Datadog의 경우에는 유료 솔루션이고

PinPoint의 경우는 직접 구축하면 되지만 꽤나 무겁기 때문에 프리티어에 배포 중인 프로젝트에는 좀 무리가 있다고 생각 되었습니다.

Spring Actuator + Prometheus + Grafana

 

그래서 먼저 저는 Spring Actuator + Prometheus + Grafana로 metrics 기반 모니터링 시스템을 구축하였습니다.

Spring Actuator + Prometheus + Grafana 조합의 아쉬운점은 metrics 수집 및 분석에 집중되어 있다는 점이였습니다.

 

즉 서버로부터 CPU, Memory 상태를 계속해서 수집하고 분석해서 잘 보여주지만

제가 기존에 만들었던 메서드 로깅(Trace)은 기본적으로 지원되지 않습니다.

 

그래서 별도로 Tracing을 도입한 과정을 정리해보려고 합니다.

Spring Actuator + Prometheus + Grafana는 워낙 정보가 많이 있기 때문에 별도로 다루지는 않습니다.

Spring micrometer-tracing

제가 기존에 만들었던 메서드 로깅은 APM에서 Trace라고 불립니다.

어떠한 요청이 오면 수행되는 과정들을 추적,기록하며, MSA와 같은 환경에서는 A서버에서 B서버로 요청을 보내는 과정들을

기록하고 추적합니다. 그래서 어떠한 단계에서 병목이 발생하는지 분석하기가 쉽습니다.

 

Spring boot 공식문서를 확인해보니 Trace를 쉽게 도입할 수 있도록 충분히 제공하고 있었습니다.

Trace 수집 도구인 micrometer 공식문서와 구글링 그리고 Gemeni를 통해 도움을 받으면서 도입을 해보았습니다.

implementation(platform("io.micrometer:micrometer-tracing-bom:latest.release")) // 1
implementation("io.micrometer:micrometer-tracing-bridge-brave") // 2
implementation("io.zipkin.reporter2:zipkin-reporter-brave") // 3

 

먼저 프로젝트 build.gradle에 위 3개의 의존성을 추가해주었습니다.

brave는 tracer입니다. tracer는 말 그대로 추적을 하는 도구입니다.

 

즉 micrometer tracing(1)은 어떤 형식으로 추적을 해야하는지 정의되어 있는 인터페이스 모음이고

bridge-brave(2)는 중간에서 brave tracer가 micrometer Trace API에 정의되어 있는대로 처리할 수 있도록 연결을 해줍니다.

 

brave tracer는 데이터를 zipkin이라는 도구가 처리할 수 있는 데이터 형태로 수집합니다.

따라서 zipkin-reporter(3)은 brave tracer가 수집한 데이터를 zipkin 서버로 전송해주는 역할을 합니다.

 

zipkin은 간단하게 말하면 grafana처럼 데이터를 수집해서 시각적으로 보여주는 도구입니다. 

그러나 저는 zipkin을 사용하지는 않고 뒤에서 나올 Grafana Tempo를 사용합니다.

Grafana Tempo도 zipkin 형식 데이터를 수집하고 시각화해주는 도구입니다.

 

이제 의존성 추가는 끝났으니 API 요청이 오면 Trace 될 수 있도록 설정을 해주겠습니다.

@Aspect
@Component
class TracingAspect(
    private val tracer: Tracer
) {
    @Around("(@within(org.springframework.web.bind.annotation.RestController) || @within(org.springframework.stereotype.Repository) || @within(org.springframework.stereotype.Service) || @within(org.springframework.stereotype.Component)) && execution(public * *(..)) && within(com.eager..*)")
    fun processMethodLog(joinPoint: ProceedingJoinPoint): Any? {
        if (!ApiTransactionContextHolder.isActive()) { // HTTP 요청인지 확인 (기존에 만든 로깅 시스템 이용)
            return joinPoint.proceed()
        }

        val methodName = "${joinPoint.signature.declaringTypeName}.${joinPoint.signature.name}"
        val span = tracer.nextSpan().name(methodName)
        span.start()
        return runCatching { tracer.withSpan(span).use { joinPoint.proceed() } }
            .onFailure { e -> span.error(e) }
            .also { span.end() }
            .getOrThrow()
    }
}

 

기존에 제가 만들었던 메서드 로깅과 똑같이 AOP를 사용합니다. 단지 이번에는 brave tracer를 사용할 뿐입니다.

 

위 코드에서는 span이라는 것이 등장합니다. span은 작업 컨텍스트라고 표현할 수 있습니다.

예시로 로그인이라는 API가 처리되는 과정에서 생성되는 span은 DB 조회 -> 비밀번호 검사 -> 토큰 생성 이렇게 볼 수 있습니다.

 

저는 메서드 하나가 작업이라고 취급하기로 결정해서 메서드가 호출 될 때 마다 span을 생성합니다.

 

tracer.nextSpan()을 통해 새로운 span(depth + 1)을 생성하고 start 해줍니다.

start가 되면 해당 작업이 끝날 때 까지 데이터를 수집합니다.

그리고 tracer.withSpan(span)을 통해 tracer context를 새로 생성된 span으로 설정합니다.

그리고 작업(joinPoint.proceed)을 진행합니다. 새로 생성한 span context에서 작업을 진행시켜야 depth가 나타날 수 있습니다.

 

그리고 만약 작업을 처리하던 도중 예외가 발생하면 span.error를 통해 예외를 기록할 수 있습니다.

또한 span은 start 되고나서 end가 되어야 데이터가 기록되고 저장되기에 꼭 end를 해줘야 합니다.

 

이렇게 하면 Tracing 처리는 완료 되었습니다. 이제 부가적인 설정을 합니다.

@Configuration
class TracingConfig {
    @Bean
    fun noActuator(): ObservationPredicate {
        return ObservationPredicate { _, context ->
            if (context is ServerRequestObservationContext) {
                return@ObservationPredicate !context.carrier.requestURI.startsWith("/actuator")
            }
            return@ObservationPredicate true
        }
    }

    @Bean
    fun noSpringSecurity(): ObservationPredicate {
        return ObservationPredicate { name, _ -> !name.startsWith("spring.security") }
    }
}

 

일반적으로 위 설정을 하지 않으면 metrics 수집을 위한 /actuator 요청과 spring.security의 필터 체인들이 trace 수집 데이터에

포함되어 복잡해질 수 있습니다. ObservationPredicate를 Bean으로 등록하면 알아서 필터링 되기 때문에 저는 추가 해주었습니다.

management.zipkin.tracing.endpoint=http://localhost:9411/api/v2/spans
management.tracing.sampling.probability=1

 

마지막으로 properties에 위와 같은 옵션을 주었습니다.

첫번째는 zipkin reporter가 어디로 trace 데이터를 전송할지 정하는 것인데 이건 곧 구성할 tempo의 주소입니다.

 

두번째는 tracing의 비율을 설정합니다. 실제 실무 배포 환경에서는 성능 상의 문제로 모든 요청에 tracing을 하지 않고 일정 비율만 tracing 한다고도 합니다. 그러나 저의 경우는 그냥 경험이기 때문에 1로 설정해서 모든 요청을 tracing 합니다.

 

이제 애플리케이션에서의 설정은 완료되었습니다.

Grafana Tempo

위에서 언급 되었던 것 처럼 brave는 zipkin이라는 도구에서 시각화 할 수 있는 형태의 trace 데이터로 수집된다고 했습니다.

그래서 zipkin을 사용하면 수집 된 trace 데이터를 볼 수 있습니다.

 

그런데 저는 이미 metrics 기반 모니터링 시스템에서 Grafana를 사용하고 있고 Grafana에서 제공하는 Tempo라는 도구도

zipkin 데이터를 수집하고 시각화 해주기 때문에 Tempo를 사용해보기로 했습니다.

sudo docker pull grafana/tempo

 

저는 docker 환경이기 때문에 먼저 grafana/tempo 이미지를 받아주었습니다.

 

그리고 tempo의 설정 파일을 작성해야 하는데 이게 워낙 생소하고 어려워서 공식 레포지토리에서 제공하는 샘플을 수정해서

사용했습니다.

target: all
server:
  http_listen_port: 3200

query_frontend:
  search:
    duration_slo: 5s
    throughput_bytes_slo: 1.073741824e+09
    metadata_slo:
        duration_slo: 5s
        throughput_bytes_slo: 1.073741824e+09
  trace_by_id:
    duration_slo: 100ms
  metrics:
    max_duration: 200h                
    query_backend_after: 5m
    duration_slo: 5s
    throughput_bytes_slo: 1.073741824e+09

distributor:
  receivers:                          
    zipkin:
      endpoint: "0.0.0.0:9411"

ingester:
  max_block_duration: 5m               

compactor:
  compaction:
    block_retention: 720h              

metrics_generator:
  registry:
    external_labels:
      source: tempo
      cluster: apm-local
  storage:
    path: /var/tempo/generator/wal
    remote_write:
      - url: http://prometheus:9090/api/v1/write
        send_exemplars: true
  traces_storage:
    path: /var/tempo/generator/traces
  processor:
    local_blocks:
      filter_server_spans: false
      flush_to_storage: true

storage:
  trace:
    backend: local
    wal:
      path: /var/tempo/wal
    local:
      path: /var/tempo/blocks

overrides:
  defaults:
    metrics_generator:
      processors: [service-graphs, span-metrics, local-blocks]
      generate_native_histograms: both

 

 

저의 경우 target: all을 설정하기 전까지는 zipkin receiver가 동작하지 않았습니다.

이거 때문에 엄청 삽질을 했는데 찾아보니 원래 tempo는 분산 시스템으로 구성하는게 기본이라고 합니다.

 

그래서 target: all 옵션을 설정을 해줘야 하나의 tempo 컨테이너에서 수신, 저장, 조회 모든 기능이 동작하게 된다고 합니다.

sudo docker run --name=tempo -v ~/tempo.yaml:/etc/tempo.yaml -p 3200:3200 -p 9411:9411 --user=root -it -d grafana/tempo -config.file=/etc/tempo.yaml

 

이후 docker run을 통해 컨테이너를 시작했습니다.

이후 grafana - Data sources에서 tempo를 추가 해줍니다. 

 

이후 Drilldown - trace를 들어가면 시각화 된 데이터 나타납니다.

 

그리고 각 요청에 대한 상세 trace도 시각화 데이터로 볼 수 있었습니다.

정리

micrometer tracing + tempo를 단순히 도입하는 과정 자체도 오래 걸려서 커스터마이징도 잘 못했고

일반적인 기능만 사용하였습니다.

 

그런데도 기능이 너무 강력해서 왜 외부 솔루션, 라이브러리를 사용하는지 알 것 같습니다.

 

기존에 사용했던 EFK 스택을 지금 보면 좀 허전하긴 하네요. (메서드 호출 과정도 단순한 String인데 길면 잘리기도 합니다.)

 

이제 EFK 스택에는 Request,Response 데이터를 위주로 보관하도록 변경하고 시스템 모니터링, tracing은 이번에 구축한 APM을

사용해야겠습니다.

 

추가적으로 메서드 trace는 실무에서 핵심 비즈니스 로직, 부하 예상 지점에만 사용되는 것 같기도 합니다.

또한 모든 요청에 trace를 수행하는 것은 성능 문제도 발생할 수 있다는 것을 고려해야하니 적절한 방안도 생각해봐야겠습니다.