..

방치된 코드가 API를 느리게 만든 이유

  1. 요약
  2. 문제 정의
  3. 문제 분석
  4. 설계 및 구현
  5. 한계점
  6. 회고

1. 요약

API 서비스의 간헐적 지연 현상을 분석해 제거하고, 꼬리 지연(P95 이상) 94% 개선

  • synchronized 기반 동기 로깅으로 인한 간헐적 응답시간 지연을,
  • 분산 큐 + Spring Batch 비동기 로깅으로 개선했습니다.
지표 개선 전 개선 후 개선율
P95 3,983.20ms 231ms 94.2%
P99 5,190.01ms 321.01ms 93.8%
평균 응답 시간 427.62ms 166.10ms 61.1%

(더 많은 차트는 주석을 참조하세요)1


2. 문제 정의

2.1. 현상

저희 회사는 Spring Boot, OpenShift, Oracle 기반의 웹 및 API 서비스를 운영하고 있습니다.

그런데, 평소에는 빠르던 API 서비스가 간헐적으로 5초 이상 걸리는 현상을 확인했습니다. APM에서 확인해 보니, 트랜잭션들이 줄지어 지연되고 있었습니다.

주로 다음과 같은 특성을 보입니다:

  • 하나의 트랜잭션이 늦어지면, 뒤따르는 트랜잭션들도 함께 지연됩니다.
  • 함께 지연된 트랜잭션들은 동시에 종료됩니다.

2.2. 원인

임시 방편으로 구현된 뒤 방치된 API 로그 Aspect 때문이었습니다.

ConcurrentLinkedQueue<LogDto> q = new ConcurrentLinkedQueue<LogDto>();

@Around
public Object ... {
  synchronized(q) {
    while (!q.isEmpty()) {
      var dto = q.poll();
      dao.insertLog(dto); // 실제로는 9개의 쿼리
    }
  }
}

해당 코드는 명백한 안티패턴입니다.

  • 요청별 스레드가 synchronized 블록 내에서 경합할 수 있기 때문입니다.
  • Pod별 요청을 각 JVM이 관리하는 방식은 분산 환경에 적합하지도 않습니다.

팀 내에서도 이 코드의 존재를 알고 있지만, 병목 현상이 거의 발견되지 않는다는 이유에서 묵인되고 있었습니다.

(트랜잭션 묶임 현상의 상세 분석은 주석을 참조하세요)2


3. 문제 분석

개선이 필요하긴 합니다. 하지만 당장 필요한지는 다른 문제였습니다. 그래서 의사 결정을 위해 다음 두 가지를 먼저 확인하고자 했습니다:

a. synchronized가 주범인가?

b. synchronized를 고치면 좋은가?

3.1. synchronized가 주범인가?

트랜잭션의 간헐적 지연은 synchronized 때문입니다. 하지만 그 원인이 외부에 있었다면 이야기가 달라집니다. 이를테면, 너무 많은 리소스를 사용하는 서비스가 부하를 일으켰기 때문에 병목이 자주 발생했다면? synchronized를 개선하는 건 급선무가 아닐 수 있습니다.

저는 그래서 외부 요인들이 어떻게 변화했는지를 찾아 보기로 했습니다. 지난 한 달 응답시간이 5,000ms 이상인 트랜잭션들을 추출하고, 해당 시간대의 주요 지표들을 살펴 보았습니다.

가설 1: 느린 쿼리가 원인이다

  • 분석: 주요 지연되는 쿼리들을 EXPLAIN 실행 또는 직접 운영환경에서 실행
  • 결과: 쿼리 실행 시간은 일관되게 짧음
  • 판정: ❌ 기각 — 이 가설은 트랜잭션이 연달아 지연되는 현상을 설명할 수 없음

가설 2: 사용자 부하가 원인이다

  • 분석: 분당 평균/최대 TPS를 엑셀 차트로 분석
  • 결과: 평균 TPS 1~2, 최대 TPS 40
  • 판정: ❌ 기각 — 부하 자체가 매우 낮아 병목 원인으로 보기 어려움

가설 3: 시스템 리소스가 병목이다

  • 분석: 분당 DB active connection pool, 힙 메모리 사용률(eden/old), GC 빈도를 엑셀 차트로 분석
  • 결과: 트랜잭션 지연 시점과 리소스 사용률 간 상관관계 없음
  • 판정: ❌ 기각 — 지연과 함께 변하는 리소스 부하 패턴이 없음


이쯤 되니 시간도 많이 걸리고, “의사 결정을 위해 빠르게 조사한다”는 취지를 벗어나기 시작합니다. 그래서 접근법을 바꿨습니다.


3.2. synchronized를 고치면 좋은가?

앞선 분석에서 외부 요인을 배제했으니, 이제 synchronized 자체를 의심해 볼 차례입니다.

가설

synchronized 블록을 제거하고 로깅을 비동기로 분리하면, 트랜잭션 간 “줄서기” 현상이 사라지고 응답 시간이 개선될 것이다.

이 가설을 검증하려면, synchronized가 있을 때와 없을 때를 비교해야 합니다.

그런데 synchronized만 제거하면 어떻게 될까요? 여러 스레드가 동시에 DB insert를 시도하게 되어 또 다른 경합이 발생합니다. 결국 synchronized 제거만으로는 근본적인 해결이 어렵고, 로깅 자체를 API 흐름에서 분리해야 합니다.

그래서 일단 로깅을 아예 생략한 버전을 만들어서 best-case 성능을 측정해 보기로 했습니다. 실제 비동기 구현에서는 큐 적재 시간이 추가되지만, 이 실험의 목적은 “개선 가치가 있는지”를 빠르게 판단하는 것이었습니다.

실험 설계

먼저 현실 환경을 모사해야 합니다. 운영 환경의 인기 API를 조사해 보니, 약 2~4%의 트랜잭션이 5초 이상 지연되고 있었습니다. 이 비율을 개발 환경에서 재현하면 비교적 공정한 실험이 가능합니다.

단계 1: 문제 재현

로깅 단계에서 3% 확률로 5초 지연되는 테스트용 Aspect를 추가했습니다.

@Around((... insertLog(..)))  // 로그를 추가할 때에는
public Object ... {
  if (ThreadLocalRandom.current().nextInt(100) < 3) { // 3% 확률로
    try {
      Thread.sleep(5000); // 5초 지연
    } catch (InterruptedException e) {
      Thread.currentThread().interrupt();
    }
  }
}

단계 2: 대조군과 실험군 구성

테스트용 컨트롤러를 만들어 두 가지 엔드포인트를 준비했습니다.

@GetMapping("/old")
public String ... {
  // ➊ 대조군
  // 기존 로직을 그대로 호출합니다. 3% 확률 지연이 일어납니다.
}
@GetMapping("/new")
public String ... {
  // ➋ 실험군
  // 로깅을 생략하여 비동기 로깅의 이상적인 상한(upper bound)을 측정합니다.
}

개발 환경을 운영 환경과 최대한 비슷하게 구성한 뒤, JMeter로 각 엔드포인트에 동일한 부하를 가했습니다.

단계 3: 결과 분석

APM에서 트랜잭션 데이터를 CSV로 내려받아 분석했습니다.

평균은 소폭 개선에 그쳤지만, P95/P99가 80%정도 개선될 것으로 예측됐습니다. 이는 “대부분의 요청은 빠르지만, 일부가 심하게 느려지는” 현상이 해소된다는 의미입니다.

(3,000건 요청 기준. 자세한 결과는 주석을 참조하세요)3

판정: ✅ 채택

이 정도 개선이라면 비동기 로깅을 구현할 가치가 충분하다고 판단했습니다.


4. 설계 및 구현

4.1. 설계

핵심 전략은 synchronized를 없애고, 로깅 작업을 API 서비스와 분리하는 것입니다.

기존: Request → API Querying → Logging (DB Insert) → Response
개선: Request → API Querying → Cache offer         → Response
                                 ↓
                           Hazelcast Queue
                                 ↓
                    별도 Consumer(Batch)가 DB Insert

캐시는 이미 사용중인 Hazelcast를 활용했습니다. 분산 큐 기능을 제공합니다.

4.2. 구현

Producer (Spring Boot)

Aspect에서는 DB가 아닌 Hazelcast Queue로 로그를 적재합니다.

@Around
public Object ... {
  cacheOffer();
}
private void cacheOffer() {
  boolean offered = queue.offer(json);
  if (!offered) {
    logger.warn("큐가 가득 찼거나 타임아웃입니다.");
    fallback();
  }
}

큐가 가득 차거나 타임아웃 시, 기존 동기 방식으로 진행합니다.

private void fallback() {
  try {
    insertLog();  // 기존의 동기 로깅 그대로 활용
  } catch (Exception e) {
    logger.error("폴백도 실패했습니다.");
  }
}


Consumer (Spring Batch)

배치 크기만큼 로그를 모아 처리하는 tasklet을 구현했습니다.

@Override
public RepeatStatus execute(...) {
  List<String> batch = new ArrayList<>();

  while (batch.size() < BATCH_SIZE) {   // 공통 프레임워크로부터 주입
    String json = queue.poll();
    if (json == null) break;
    batch.add(json);
  }

  if (batch.isEmpty()) {
    return FINISHED;
  }

  for (String json : batch) {
    insertLog(json);  // 기존 로깅 방식 그대로 사용
  }

  return queue.isEmpty() ? FINISHED : CONTINUABLE;
}

저희 시스템은 별도의 배치 관리 시스템을 사용하고 있어, 실행 주기나 배치 크기 등은 설정으로 제어 가능합니다.

(자세한 설정과 산정 근거는 주석을 참조하세요)4

4.3. 결과

개선 결과는 요약과 동일합니다.


5. 한계점

이 분석에는 다음과 같은 제약이 있습니다.

5.1. 한정적인 표본으로 실험됨

다른 API, 다른 기간에서는 지연 현상이 덜 또는 더 발생할 수 있습니다.

  • 지연 현상을 분석한 데이터가 한정적이기 때문입니다. 3%의 지연 확률은 이렇게 추정되었습니다:

    • 단일 API의
    • 6일간 데이터에서
    • 지연 시간 상위 트랜잭션만 표본 조사
  • 특정 표본만 조사한 이유는, 개별 트랜잭션을 클릭해 상세 정보를 확인하며 분석해야 했기 때문입니다. APM(제니퍼5)의 상세 검색이 제한적이어서였습니다.

5.2. 단순화된 테스트 설계에 의존함

3%확률, 5초 고정의 지연은 운영 환경의 실제 지연 패턴을 대표하지 않습니다.

  • 실제 지연의 원인은 DB 락 경합, GC, 네트워크 등 복합적입니다. 지연 시간도 수백ms ~ 수초까지 다양하게 분포합니다.

JMeter 부하는 운영 환경의 실제 부하를 대표하지 않습니다.

  • JMeter 실험은 thread 3, loop count 1000으로 이루어졌습니다. 표본으로 조사된 시간대에 API 동시 사용자가 3명이었기 때문입니다.

  • 하지만 실제 TPS는 다양합니다. 더 낮거나 높은 부하에서는 다른 양상이 나타날 수 있습니다.

5.3. 효과 측정의 한계

운영 환경에서의 개선 수치는 다를 수 있습니다.

  • 운영 환경에 배포하려면 고객사의 승인을 받아야 합니다. 하지만 프로젝트 일정상 1월 중에는 배포를 수행할 수 없었습니다.

  • 때문에 개발 환경에서 최대한 비슷한 환경으로 개선 수치를 측정했습니다.

  • 실제 운영 시에는 캐시나 배치 안정성(부족한 큐 크기, 장애 복구, 메시지 유실 등)에 따른 오버헤드가 없는지 모니터링이 필요합니다.


6. 회고

6.1. 여러 개선 후보 분석

개선 대상 후보를 찾으며, 현재 시스템의 문제점을 다각도로 분석할 수 있었습니다.

후보 기각 사유
page=1만 로깅 → 전체 페이지 로깅 비즈니스 효용은 높으나, 기술적 효용은 부족함
offset → keyset 페이지네이션 정형화된 문제로 언제든 개선 가능
synchronized 로깅 → batch draining ✅ 채택 — 안티패턴이 명백하나, 실제 병목 여부 검증 필요

특히 offset → keyset 페이지네이션은 강력한 후보였지만, synchronized 개선 효용이 더 클 것이라고 판단해 제외했습니다.

6.2. 데이터의 분석과 해석

저는 수학이나 통계학에 대해서는 잘 모릅니다. 하지만 개선 효과를 설득력 있게 보여주려면, 직관적으로 해석할 수 있는 지표와 차트가 필요했습니다.

엑셀과 파이썬으로 트랜잭션 데이터를 직접 분석하려는 시도가 분석에 도움이 많이 됐습니다. 히스토그램의 빈도 구간을 설정하고, scipy와 matplotlib로 시각화하는 경험이 특히 유익했습니다.

처음에는 KDE(분포를 부드러운 곡선으로 시각화하는 방법)로 전후 효과를 비교하려 했습니다. 한눈에 전후 분포를 비교할 수 있기 때문입니다. 하지만 KDE는 원본 데이터 전체가 있어야 그릴 수 있습니다. 폐쇄망에서 전체 표본을 반출할 수 없었기에, 백분위수 차트로 대신했습니다.

6.3. 캐시를 이용한 배포 최소화

실험을 자주 하다 보니, 배포 없이 실험 파라미터를 변경하고 싶었습니다. OpenShift의 ConfigMap을 활용하는 것이 정석이나, 해당 권한이 고객사에 있어 임의 수정이 사실상 불가능한 상황이었습니다.

그래서 Hazelcast를 활용한 캐시 기반 프로퍼티를 직접 구현했습니다.

  • 모든 Pod가 동일한 설정값을 공유할 수 있도록 분산 맵을 활용했습니다.
  • 설정값을 조회하는 오버헤드가 테스트 결과에 영향을 미치지 않도록 ConcurrentHashMap을 사용했습니다.
  • Hazelcast 이벤트 리스너를 통해 값이 변경될 때마다 로컬 캐시가 즉시 업데이트되도록 구성했습니다.

(구현 pseudo 코드는 주석을 참조하세요)5

이 방식을 통해 코드 수정이나 재배포 없이도 다양한 시나리오를 빠르고 유연하게 실험할 수 있었습니다.

6.4. Spring Batch 캐시 환경 설정

Spring Boot 프로젝트와 다르게, Spring Batch 프로젝트는 캐시를 사용하고 있지 않았습니다. 두 프로젝트는 서로 다른 환경에서 관리되고 있었기에, 캐시 사용을 위한 설정이 필요했습니다.

다행히 타 팀의 프로젝트에서 사용중인 캐시 설정을 찾을 수 있었습니다. JUnit으로 로컬 환경부터 구축해 PoC를 먼저 검증하고, 개발 환경에 적용하는 방식을 택했습니다.

6.5. 알맞은 직렬화 방식 선택하기

Spring Boot(Producer)와 Spring Batch(Consumer)는 서로 다른 프로젝트로 관리됩니다. Java Serializable로 DTO를 구현했으나, 두 프로젝트 간 클래스 경로가 맞지 않는 문제가 발생했습니다.

물론 Hazelcast에서 제공하는 직렬화 방식을 사용해도 해결할 수 있었지만, 보다 간단하고 콘솔에서도 읽을 수 있는 JSON을 활용하기로 했습니다.

ObjectMapper를 사용해 Producer(Boot)는 DTO → JSON로, Consumer(Batch)는 JSON → DTO로 변환합니다.


긴 글 읽어주셔서 감사합니다.


References

  1. 백분위수별 응답 시간 비교

    가끔 발생하던 느린 응답들이 사라졌습니다.

    응답시간별 분포 히스토그램

    응답 시간이 낮은 구간에 더 많이 밀집해 있습니다. 성능이 일정해졌다는 의미입니다.

  2. 트랜잭션 묶임 현상의 상세 분석

    동기 로깅 방식에서 synchronized 블록은 여러 트랜잭션을 묶어 처리합니다. 아래는 2개의 요청이 같은 pod에 동시에 들어왔을 때의 예시입니다.

    sequenceDiagram
        participant A as 요청 A
        participant B as 요청 B
        participant Q as ConcurrentQueue
        participant DB as DB
    
        Note over A,B: 두 요청이 거의 동시에 시작
    
        A->>A: API Querying
        B->>B: API Querying
    
        A->>Q: 큐에 로그 추가
        A->>Q: Lock 획득
        activate Q
    
        B->>Q: 큐에 로그 추가
        B->>Q: Lock 대기
    
        Note over Q,DB: 요청 A가 큐를 비울 때까지<br/>요청 B는 대기
    
        Q->>DB: A의 로그 저장
        Q->>DB: B의 로그 저장
    
        Q-->>A: Lock 해제 & 응답 (느림)
        deactivate Q
    
        B->>Q: Lock 획득 → 큐가 비어있음 → 즉시 해제
        Q-->>B: 응답 (느림)
    
        Note over A,B: 두 요청이 거의 동시에 종료<br/>(A가 B의 로그까지 처리했기 때문)
    
    • 요청 A는 자신의 로그 + B의 로그를 모두 처리하느라 응답이 지연됨
    • 요청 B는 synchronized 블록에서 대기하느라 응답이 지연됨
    • API 응답 시간에 다른 요청의 로깅 시간까지 포함됨
    • 실제 운영에서는 최대 5개 요청이 한 번에 묶이는 현상 관측됨

  3. JMeter 모의 실험 결과

    액션 플랜을 위해 진행한 모의 실험입니다. 해당 실험의 근거와 한계는 후술합니다.

    테스트 설정: Number of Threads 3, Ramp-up period 0, loop count 1000

    지표 대조군 (동기, 고의적 지연) 실험군 (비동기) 개선율
    응답시간 평균 586ms 453ms 22.7%
    P95 3,123ms 718ms 77.0%
    P99 5,296ms 1,040ms 80.4%
    총 소요시간 10분 01초 7분 36초 -
    지연 발생 3,000건 중 103건 0건(지연 없음) -

    각 실험은 pod를 새로 배포하고, pod별로 웹페이지를 여러 번 조회하여 warm-up 시킨 뒤 진행하였습니다. 

  4. Hazelcast Queue 설정 및 용량 산정

    배치 시스템에서 사용하는 Hazelcast Queue의 설정은 다음과 같습니다.

    QueueConfig queueConfig = new QueueConfig("logQueue");
    queueConfig.setMaxSize(100000);  // 최대 100,000건
    queueConfig.setBackupCount(1);   // 백업 노드 1개
    

    용량 및 안전성 분석은 다음과 같습니다.

    기본 용량 산정 (최대 부하 시나리오)

    • JSON 문자열 평균 크기: 약 500 bytes (모든 필드가 최댓값을 사용한다고 가정)
    • 일일 최대 예상 로그: 100,000건 (관측된 최대 일일 호출건수 중 50%가 API라고 가정)
    • 일일 예상 메모리: 100,000 × 500 = 50 MB

    Backpressure 안전성 (Peak Time 기준)

    • 최대 TPS: 40 (관측된 최대 트래픽)
    • 분당 적재량: 2,400건 (약 1.2 MB)
    • 결론: 최대 부하가 약 41분 지속되더라도 작동 가능
    • 임계 성능: 1분 주기 배치 drain 기준 최대 1,666 TPS까지 수용 가능

  5. 캐시 기반 프로퍼티 구현

    테스트용 설정값들을 캐시에 저장하고, 이벤트 리스너로 변경이 반영되게 합니다.

    private final Map<String, Object> configMap = new ConcurrentHashMap<>();
    
    @PostConstruct
    public void init() {
      configMap.put("테스트?", false);
      configMap.put("지연확률", 3);
      configMap.put("지연시간", 5000);
    
      map.addEntryListener(event -> {   // 런타임 도중 변경
          configMap.put(event.getKey(), event.getValue());
      }, true);
    }
    

    분기 처리나, 실험용 파라미터 변경에 사용했습니다.

    @Around
    public Object ... {
      if (테스트?) {
        // 신규 비동기 로깅
      } else {
        // 기존 동기 로깅
      }
    }
    
    @Around
    public Object ... {
      if (random.nextInt(100) < 지연확률) {
        Thread.sleep(지연시간);
      }
    }