PrometheusTimer 누수를 제거한 날 (힙 덤프)

 

운영의 그라파나에서 힙이 살려달라고 소리치고 있었다.

운영 중이던 서버의 메모리 사용량이 점점 이상하게 상승하고 있었다.  
모든 요청은 정상적으로 처리되고 있었고, 로그에도 특별한 이상 징후는 없었다.  
그러나 **Grafana는 JVM Heap Usage 경고를 쉬지 않고 터뜨렸다.**

문제가 있다는 건 확실했지만, 당시까지는 정확히 어떤 메트릭, 어떤 요청이 문제였는지  
Docker에서 구동되는 Spring 서버의 내부 상태를 들여다볼 수단이 없었다.

Docker 설정을 바꾸기 시작했다

무엇보다 먼저, 문제가 발생했을 때 원인을 정확히 파악할 수 있도록 환경을 정비해야 했다.
그래서 JVM이 OOM으로 죽을 경우 자동으로 힙덤프를 남기도록 Dockerfile부터 수정했다.

ENTRYPOINT ["java",
    "-Xms1g", "-Xmx1g",
    "-XX:+UseG1GC",
    "-XX:+UnlockExperimentalVMOptions",
    "-Xlog:gc*:file=/var/log/gc/gc.log:time,level,tags:filecount=5,filesize=20M",
    "-XX:+HeapDumpOnOutOfMemoryError",
    "-XX:HeapDumpPath=/var/log/gc/heapdump.hprof",
    "-jar", "app.jar"]

왜 이런 설정을 했는가?

• -Xms1g, -Xmx1g: 힙 사이즈를 명확히 고정
  → 운영 중 힙이 튀는 현상을 방지하고, 일관된 덤프 환경 보장
• -XX:+UseG1GC:
  → G1 GC는 힙이 커지기 시작할 때의 Young GC / Old GC 비율을 명확하게 확인할 수 있다.
  운영에서 예측 가능한 GC 로그 분석이 가능해짐
• -XX:+HeapDumpOnOutOfMemoryError:
  → OOM이 터졌을 때 실질적인 root cause 분석을 가능하게 함
• -Xlog:gc* → 셀렉터 (gc*):
  • **gc***는 GC와 관련된 모든 이벤트를 로깅하겠다는 의미
    • 여기서 gc*는 GC 이벤트를 다 포함한다
    • gc: GC 발생
    • gc+pause: GC가 일어나는 동안의 잠금
    • gc+heap: 힙 관련 GC
    • gc+region: 특정 메모리 영역에서 GC가 발생할 때
  • 아웃풋 (file=/var/log/gc/gc.log):
    • 로그를 파일로 출력하겠다는 설정.
    • /var/log/gc/gc.log 파일에 GC 이벤트를 저장.
  • 데코레이터 (time, level, tags):
    • 로그에 시간(time), 레벨(level), 태그(tags) 정보를 포함시키겠다는 설정.
    • time: 로그에 타임스탬프를 추가
    • level: 로그의 상세 레벨을 추가 (e.g., DEBUG, INFO, WARN)
    • tags: 로그에 추가적인 태그 정보(예: GC의 종류, 힙 영역 등)를 추가
  • 아웃풋 옵션 (filecount=5, filesize=20M):
    • 파일 로테이션 설정을 의미함.
    • 최대 5개의 파일이 20MB씩 저장된다.
      → 각 파일 크기가 20MB를 넘으면 새로운 파일로 롤오버된다. 이 방식으로 GC 로그가 분할 저장된다.

Docker Run 시 옵션도 함께 조정했다

-v /var/log/gc:/var/log/gc \
--memory=3g \

• -v /var/log/gc:/var/log/gc:
  → JVM 내부의 /var/log/gc 경로에 쓰이는 GC 로그와 힙덤프 파일을
  EC2 밖에서 직접 접근 가능하게 하려는 목적
  즉, 컨테이너 죽은 후에도 .hprof 파일을 수거할 수 있음
• --memory=3g:
  → 컨테이너 전체 메모리는 3GB, JVM 힙은 1GB
  → JVM 외부 메타 영역, off-heap, native lib 영역에 2GB 정도 여유 확보
  → Full GC나 ClassLoader 메모리, Netty I/O Buffer 등이 원인일 경우도 고려한 운영 여유분

 

운영의 실전 상황에서,문제가 언제 터질지 모르고 로그도, 힙도 남지 않으면

분석 자체가 불가능하다.

그래서 이 단계에서부터 환경을 추적 가능한 상태로 만드는 것이
가장 중요한 첫 번째 단계였다.

 

그리고 기다렸다.

아니나 다를까, 딱 하루가 지나자 힙은 다시 포화 상태에 도달했다.

결국 직접 힙덤프를 뜨고 분석을 하기로 했다.

/usr/local/openjdk-21/bin/jcmd 1 GC.heap_dump /tmp/dump/heapdump.hprof
Eclipse Memory Analyzer Tool을 켰다.

 

 

눈에 띄는 건 하나였다.
io.micrometer.prometheusmetrics.PrometheusTimer 인스턴스가 힙을 130MB나 점유하고 있었다.

 

Spring Boot의 micrometer를 켰다고 해서 타이머가 이 정도로 힙을 잠식한다면,
이미 GitHub 이슈든 어디서든 이 문제는 논의되었어야 한다.
그런데 그런 흔적이 보이지 않았다.

문제는 내 쪽에 있다는 결론에 도달했다.
내가 직접 만든 monikit이라는 라이브러리가 타이머를 과도하게 생성하고 있다는 합리적 의심이 들었다.

 

 

원인을 좁히기 위한 실험 환경 구성

직접 타이머가 등록되는 지점을 추적해보기 위해,
Timer.Builder.register() 메서드를 감싸는 AOP를 작성했다.

 

@Aspect
@Component
public class TimerRegisterSpy {

	@Around("execution(* io.micrometer.core.instrument.Timer.Builder.register(..))")
	public Object interceptTimerRegister(ProceedingJoinPoint joinPoint) throws Throwable {
		Object result = joinPoint.proceed();

		System.out.println("🔥 Timer REGISTERED");

		Arrays.stream(Thread.currentThread().getStackTrace())
			.filter(el -> el.getClassName().startsWith("com.monikit"))
			.forEach(el -> System.out.println("\t↳ at " + el));

		return result;
	}
}

 

또한, 타이머 등록 상태를 실시간으로 확인할 수 있도록 MeterRegistryInspector 컴포넌트도 추가했다

 

@Component
public class MeterRegistryInspector {

	private final MeterRegistry registry;

	public MeterRegistryInspector(MeterRegistry registry) {
		this.registry = registry;
	}

	@Scheduled(fixedRate = 5000)
	public void report() {
		List<Meter> timers = registry.getMeters().stream()
			.filter(m -> m instanceof Timer)
			.toList();

		System.out.println("📊 Total PrometheusTimers: " + timers.size());

		timers.stream()
			.limit(10)
			.forEach(m -> System.out.println(" - " + m.getId().getName() + " " + m.getId().getTags()));
	}
}

 

 

대량 요청 실험

정말 문제가 monikit 내부의 메트릭 수집 방식 때문인지 확인하기 위해,
로컬에서 서버를 띄운 뒤 다음과 같은 명령어로 10,000개의 요청을 보냈다

for i in $(seq 1 10000); do
  curl -s "http://localhost:8088/api/v1/product/group/$i" > /dev/null &
  if (( $i % 100 == 0 )); then wait; fi
done

 

요청 경로는 매번 바뀌었고, 기대한 대로라면 타이머는 경로마다 개별적으로 생성되었을 것이다.
그리고 실제로 MeterRegistryInspector가 출력하는 로그에서
타이머 수가 요청 수에 따라 계속해서 증가하는 것을 확인할 수 있었다.

ㅋㅋㅋ.... 타이머 10000개..

 

 

똑같은 문제는 로컬에서도 재현됐다

운영에서 확인한 덤프와 동일한 조건으로,
로컬에서도 10,000개의 요청을 반복해서 보낸 후 힙덤프를 떴다.

그리고 확인했다.
정확히 같은 증상이 재현됐다.

 

문제의 코드 
문제의 핵심은 monikit.metric.HttpResponseDurationMetricsBinder에 있었다.

package com.monikit.metric;

import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.TimeUnit;

import io.micrometer.core.instrument.MeterRegistry;
import io.micrometer.core.instrument.Timer;
import io.micrometer.core.instrument.binder.MeterBinder;

/**
 * HTTP 응답 시간을 기록하는 `MeterBinder`
 */

public class HttpResponseDurationMetricsBinder implements MeterBinder {

    private final ConcurrentMap<String, Timer> timerCache = new ConcurrentHashMap<>();
    private MeterRegistry meterRegistry;

    @Override
    public void bindTo(MeterRegistry registry) {
        this.meterRegistry = registry;
    }

    /**
     * 동적으로 Timer를 기록하는 메서드
     */
    public void record(String path, int statusCode, long responseTime) {
        String timerKey = "http_response_duration|" + path + "|" + statusCode;

        Timer timer = timerCache.computeIfAbsent(timerKey, key ->
            Timer.builder("http_response_duration")
                .description("Time taken for HTTP responses")
                .tag("path", path)
                .tag("status", String.valueOf(statusCode))
                .publishPercentiles(0.5, 0.95, 0.99)
                .register(meterRegistry)
        );

        timer.record(responseTime, TimeUnit.MILLISECONDS);
    }
}

이 메서드는 요청 path를 그대로 tag로 사용했기 때문에,
/api/v1/product/group/508869, /api/v1/product/group/508870 …
이런 식으로 요청이 들어올 때마다 다른 타이머가 생성되었다.
결국 요청 수 = PrometheusTimer 수 였고, 그만큼 Heap에 Timer 객체가 쌓였다.

수정된 코드

다음은 문제 해결을 위해 수정한 코드다.

package com.monikit.metric;

import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.TimeUnit;

import io.micrometer.core.instrument.MeterRegistry;
import io.micrometer.core.instrument.Timer;
import io.micrometer.core.instrument.binder.MeterBinder;

/**
 * HTTP 응답 시간을 기록하는 `MeterBinder`
 */

public class HttpResponseDurationMetricsBinder implements MeterBinder {

    private static final int MAX_TIMER_COUNT = 100;
    private final ConcurrentMap<String, Timer> timerCache = new ConcurrentHashMap<>();
    private MeterRegistry meterRegistry;

    @Override
    public void bindTo(MeterRegistry registry) {
        this.meterRegistry = registry;
    }

    /**
     * 동적으로 Timer를 기록하는 메서드
     */
    public void record(String path, int statusCode, long responseTime) {
        String normalizedPath = normalizePath(path);
        String key = normalizedPath + "|" + statusCode;

        if (timerCache.size() >= MAX_TIMER_COUNT && !timerCache.containsKey(key)) {
            return;
        }

        Timer timer = timerCache.computeIfAbsent(key, k ->
            Timer.builder("http_response_duration")
                .description("Time taken for HTTP responses")
                .tag("path", normalizedPath)
                .tag("status", String.valueOf(statusCode))
                .publishPercentiles(0.5, 0.95, 0.99)
                .register(meterRegistry)
        );

        timer.record(responseTime, TimeUnit.MILLISECONDS);
    }

    private String normalizePath(String path) {
        if (path == null) return "unknown";
        return path.replaceAll("\\d+", "{id}"); // 정수 치환
    }

}

 

AOP에서도 조건 필터링 추가

이와 함께, AOP 기반 로깅에서 사용하는 Dynamic Rule 평가 기준도 보강했다.

기존에는 조건을 만족하면 무조건 메트릭을 등록했지만,
이제는 thresholdMillis 값보다 실제 실행 시간이 작으면 메트릭 등록 자체를 생략하도록 변경했다.

이 로직은 DynamicMatcher 내부에서 처리되고,
monikit 1.1.4 버전에서 반영되었다.

 

 

-monikit v1.1.4 릴리즈 노트 보기-

Release 1.1.4 · ryu-qqq/moni-kit

 

 

다시 한번 요청을 보내고, 힙을 확인했다

10,000개의 요청을 다시 로컬에서 시뮬레이션하고,
동일하게 힙덤프를 떴다.

 

 

확실했다.
타이머 수는 100개 이하로 제한되었고,
더 이상 PrometheusTimer가 Retained Heap에서 주범으로 등장하지 않았다.

 

그제서야 진짜 중요한 걸 깨달았다

처음엔 "관측을 많이 하면 좋다"고 생각했다.
많이 남겨야 많이 분석할 수 있고, 그게 더 신뢰할 수 있는 운영이라고 믿었다.

하지만 이번 경험을 통해 분명히 알게 됐다.

로그와 메트릭은 무조건 많이 남긴다고 좋은 게 아니다.

 

오히려 무의미한 측정은 시스템을 망가뜨리고,
진짜 필요한 신호를 찾지 못하게 만든다.

"느리면 수집하고, 빠르면 잊는다."
관측도 전략이 필요하다는 걸 몸으로 배운 셈이었다.

 

그런데 한 가지가 계속 마음에 걸렸다

그래도 여전히 궁금했던 건 이거였다.

왜 PrometheusTimer는 그렇게 많이 생성됐고, GC가 도저히 청소를 못했을까?

 

micrometer가 내부적으로 어떻게 동작하길래,
이렇게 생성된 타이머들이 메모리에 남아있는 걸까?

그래서 그 다음엔 실제로 micrometer 내부 코드를 까보기 시작했다.

 

 

private final Map<Meter.Id, Meter> meterMap = new ConcurrentHashMap();

이 ConcurrentHashMap에 getOrCreateMeter로 put을 하기 때문에
명시적으로 내가 지우지않는이상 JVM이 해당 미터를 지우지않고 계속 가지고 가는거다.

private Meter getOrCreateMeter(@Nullable DistributionStatisticConfig config, BiFunction<Meter.Id, DistributionStatisticConfig, ? extends Meter> builder, Meter.Id originalId, Function<Meter.Id, ? extends Meter> noopBuilder) {
    Meter m = (Meter)this.preFilterIdToMeterMap.get(originalId);
    .....

                    this.meterMap.put(mappedId, m);
         
         
                }
            }
        }

        return m;
    }
}