단계별 성능 측정

#backend #java #monitoring #performance

하나의 API 요청 안에서 각 기능별 시간을 누적하다가, 요청이 끝날 때 한 번에 로그로 출력하는 구조네요.

ThreadLocal로 컨텍스트를 유지하는 방식이 가장 깔끔합니다.

전체 구조

Request → Filter(시작) → Controller → Service → Repository → Filter(종료+로그출력)
                              ↓           ↓          ↓
                         AOP가 각 단계 시간을 PerformanceContext에 누적

1. PerformanceContext — ThreadLocal로 요청당 컨텍스트 유지

@Component
public class PerformanceContext {

    private static final ThreadLocal<List<StepRecord>> steps = 
        ThreadLocal.withInitial(ArrayList::new);
    private static final ThreadLocal<Long> requestStart = new ThreadLocal<>();

    public void startRequest() {
        steps.get().clear();             // 이전 요청 데이터 초기화
        requestStart.set(System.nanoTime());
    }

    public void record(String stepName, long elapsedMs) {
        steps.get().add(new StepRecord(stepName, elapsedMs));
    }

    public String buildSummary() {
        long totalMs = (System.nanoTime() - requestStart.get()) / 1_000_000;
        StringBuilder sb = new StringBuilder("\n==== API Performance Summary ====\n");

        for (StepRecord step : steps.get()) {
            sb.append(String.format("  %-40s %5dms\n", step.name(), step.elapsedMs()));
        }

        sb.append("---------------------------------\n");
        sb.append(String.format("  %-40s %5dms\n", "TOTAL", totalMs));
        sb.append("=================================");
        return sb.toString();
    }

    public void clear() {
        steps.remove();
        requestStart.remove();
    }

    public record StepRecord(String name, long elapsedMs) {}
}

2. @TrackTime — 측정할 메서드에 붙이는 어노테이션

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface TrackTime {
    String value() default "";   // 로그에 표시할 이름 (비어있으면 메서드명 사용)
}

3. PerformanceAspect — AOP로 시간 측정 후 Context에 기록

@Aspect
@Component
@RequiredArgsConstructor
public class PerformanceAspect {

    private final PerformanceContext performanceContext;

    @Around("@annotation(trackTime)")
    public Object track(ProceedingJoinPoint joinPoint, TrackTime trackTime) throws Throwable {
        String stepName = trackTime.value().isBlank()
            ? joinPoint.getSignature().toShortString()
            : trackTime.value();

        long start = System.nanoTime();
        try {
            return joinPoint.proceed();
        } finally {
            long elapsed = (System.nanoTime() - start) / 1_000_000;
            performanceContext.record(stepName, elapsed);
        }
    }
}

4. PerformanceFilter — 요청 시작/종료 시점 제어

@Component
@RequiredArgsConstructor
public class PerformanceFilter extends OncePerRequestFilter {

    private static final Logger log = LoggerFactory.getLogger(PerformanceFilter.class);
    private final PerformanceContext performanceContext;

    @Override
    protected void doFilterInternal(HttpServletRequest request,
                                    HttpServletResponse response,
                                    FilterChain filterChain) throws ServletException, IOException {
        performanceContext.startRequest();
        try {
            filterChain.doFilter(request, response);
        } finally {
            log.info("[{} {}]{}", 
                request.getMethod(), 
                request.getRequestURI(),
                performanceContext.buildSummary());
            performanceContext.clear();   // 반드시 ThreadLocal 정리
        }
    }
}

5. 실제 사용 — 각 레이어에 어노테이션만 붙이면 끝

@RestController
@RequiredArgsConstructor
public class OrderController {

    private final OrderService orderService;

    @PostMapping("/api/orders")
    public ResponseEntity<OrderResponse> createOrder(@RequestBody OrderRequest request) {
        return ResponseEntity.ok(orderService.createOrder(request));
    }
}

@Service
@RequiredArgsConstructor
public class OrderService {

    private final UserService userService;
    private final ProductService productService;
    private final OrderRepository orderRepository;

    @TrackTime("1. 주문 처리 (Service)")
    public OrderResponse createOrder(OrderRequest request) {
        User user = userService.validateUser(request.getUserId());
        Product product = productService.checkStock(request.getProductId());
        return orderRepository.save(user, product);
    }
}

@Service
public class UserService {

    @TrackTime("2. 유저 검증 (UserService)")
    public User validateUser(Long userId) {
        // DB 조회, 권한 체크 등
    }
}

@Service
public class ProductService {

    @TrackTime("3. 재고 확인 (ProductService)")
    public Product checkStock(Long productId) {
        // 재고 조회
    }
}

@Repository
public class OrderRepository {

    @TrackTime("4. 주문 저장 (Repository)")
    public OrderResponse save(User user, Product product) {
        // INSERT 쿼리
    }
}

출력 결과

INFO  [POST /api/orders]
==== API Performance Summary ====
  2. 유저 검증 (UserService)                   12ms
  3. 재고 확인 (ProductService)                 8ms
  4. 주문 저장 (Repository)                    23ms
  1. 주문 처리 (Service)                       48ms   ← 하위 포함한 전체
---------------------------------
  TOTAL                                        51ms   ← Filter 기준 전체
=================================

핵심 포인트 정리

역할	클래스	설명
컨텍스트 저장	`PerformanceContext`	ThreadLocal로 요청별 격리
시간 측정	`PerformanceAspect`	AOP로 비침투적 측정
시작/종료 제어	`PerformanceFilter`	로그 출력 + ThreadLocal 정리
측정 대상 지정	`@TrackTime`	어노테이션만 붙이면 자동 수집

ThreadLocal을 쓰므로 멀티스레드 환경에서도 요청끼리 간섭 없이 각자의 데이터를 독립적으로 유지합니다. finally에서 clear()를 반드시 호출해야 스레드 풀 재사용 시 데이터가 오염되지 않습니다.

DEV Community