메서드 앞뒤를 감싸 로그를 남기면, JFR 없이도 어느 구간이 느린지 대략 알 수 있습니다.
long t0 = System.nanoTime();
List<Order> orders = orderMapper.selectByUser(userId);
log.debug("select: {}ms", (System.nanoTime() - t0) / 1_000_000);
t0 = System.nanoTime();
List<OrderDto> dtos = orders.stream().map(this::toDto).toList();
log.debug("convert: {}ms", (System.nanoTime() - t0) / 1_000_000);이 방식은 임시 진단용입니다. 운영에 계속 남기면 로그가 과다해져 2.8절의 "로그 과다" 병목 그 자체가 됩니다. 원인을 찾으면 코드를 제거하거나 조건부 로깅으로 낮춥니다.
여러 요청이 섞여 실행되는 서버 로그에서는 MDC(Mapped Diagnostic Context)로 요청 ID 를 붙여야 한 요청의 흐름을 따라갈 수 있습니다.
MDC.put("reqId", UUID.randomUUID().toString().substring(0, 8));
long t0 = System.nanoTime();
try {
return service.process(req);
} finally {
log.info("elapsed={}ms", (System.nanoTime() - t0) / 1_000_000);
MDC.clear();
}reqId 로 로그를 필터링하면 같은 요청이 어느 구간에서 시간을 썼는지 시간순으로 재구성할 수 있습니다. 동시 사용자가 많은 운영 환경에서 필수적인 습관입니다.
HikariCP 풀 크기를 정할 때 "일단 크게" 잡는 대신, 목표 TPS 와 평균 쿼리 시간으로 역산합니다.
필요 풀 크기 ≈ 목표 TPS × 평균 응답 시간(초)
예: 목표 TPS 50, 평균 쿼리 80ms(0.08초)
필요 풀 크기 ≈ 50 × 0.08 = 4여유를 감안해도 이 예시라면 풀 크기 10 이상은 과잉일 가능성이 큽니다. 풀을 과도하게 키우면 Oracle 세션 수만 늘고 실제 처리량은 늘지 않습니다. 커넥션 풀 고갈이 의심되면 풀 크기보다 먼저 쿼리 시간을 줄이는 것이 순서상 맞습니다.