[목적] MSA 기반 이벤트 처리 시스템에서 상품 조회 부분의 비동기 처리

[문제] 잘못된 설정 시, 전체 처리 지연 혹은 메모리 오버헤드 및 GC 부하 발생

[목표]

1. Executor 최적 설정값 찾기
2. 초당 처리량 100 건, 버스트 1000건 까지도 처리 가능하도록 안정화

[진행 과정]

• 측정 환경

  인스턴스 유형	t3.xlarge
  vCPU	4
  메모리	16GiB

• 측정 방식

  1. 기존 Thread Pool 을 최적화 하기 위해서 Wait time과 Cpu time 측정
  • 호출할 Call을 감싸 시간을 기록하는 클래스 생성

  @Component
  public class HttpTiming {
  
      private static final ThreadMXBean threadMx = ManagementFactory.getThreadMXBean();
      private static final Path LOG_PATH = Paths.get("http-timing.csv");
      private static volatile boolean headerWritten = false;
  
      // 누적합계와 호출 횟수를 기록할 Atomic 변수
      private static final AtomicLong totalSumMs = new AtomicLong(0);
      private static final AtomicLong callCount = new AtomicLong(0);
  
      /**
       * 외부 호출(W/C) 측정
       */
      public <T> T measureWaitCpu(Callable<T> httpCall) throws Exception {
          if (threadMx.isThreadCpuTimeSupported() && !threadMx.isThreadCpuTimeEnabled()) {
              threadMx.setThreadCpuTimeEnabled(true);
          }
  
          long startCpuNanos  = threadMx.getCurrentThreadCpuTime();
          long startWallNanos = System.nanoTime();
  
          T result = httpCall.call();
  
          long endWallNanos = System.nanoTime();
          long endCpuNanos  = threadMx.getCurrentThreadCpuTime();
  
          long totalNanos = endWallNanos - startWallNanos;
          long cpuNanos   = endCpuNanos  - startCpuNanos;
          long waitNanos  = totalNanos    - cpuNanos;
  
          double totalMs = totalNanos / 1_000_000.0;
          double cpuMs   = cpuNanos   / 1_000_000.0;
          double waitMs  = waitNanos  / 1_000_000.0;
          double ratio   = cpuNanos > 0 ? waitNanos / (double) cpuNanos : 0;
  
          // 누적값 업데이트
          long count = callCount.incrementAndGet();
          long sum   = totalSumMs.addAndGet((long) totalMs);
          double avgLatency = sum / (double) count;
  
          // 콘솔 출력
          System.out.printf(
                  "HTTP call: total=%.2fms, CPU=%.2fms, WAIT=%.2fms, W/C=%.2f, AVG_LATENCY=%.2fms (over %d calls)%n",
                  totalMs, cpuMs, waitMs, ratio, avgLatency, count
          );
  
          writeCsv(totalMs, cpuMs, waitMs, ratio, avgLatency, count);
  
          return result;
      }
  
      private void writeCsv(double total, double cpu, double wait, double wcratio,
                            double avgLatency, long count) {
          try {
              // 헤더 기록
              if (!headerWritten) {
                  synchronized(HttpTiming.class) {
                      if (!headerWritten) {
                          Files.writeString(
                                  LOG_PATH,
                                  "timestamp,total_ms,cpu_ms,wait_ms,w_c_ratio,avg_latency_ms,call_count" + System.lineSeparator(),
                                  StandardOpenOption.CREATE, StandardOpenOption.APPEND
                          );
                          headerWritten = true;
                      }
                  }
              }
              // 데이터 라인 작성
              String line = String.format(
                      "%s,%.2f,%.2f,%.2f,%.2f,%.2f,%d%n",
                      Instant.now(), total, cpu, wait, wcratio, avgLatency, count
              );
              Files.writeString(LOG_PATH, line, StandardOpenOption.CREATE, StandardOpenOption.APPEND);
          } catch (IOException e) {
              LoggerFactory.getLogger(HttpTiming.class)
                      .warn("Failed to write HTTP timing log", e);
          }
      }
  }
  

  • 측정 결과

  timestamp	total_ms	cpu_ms	wait_ms	w_c_ratio
  2025-07-28T03:33:06.889Z	22.45	0.00	22.45	0.00
  2025-07-28T03:33:06.893Z	28.50	0.00	28.50	0.00
  2025-07-28T03:33:23.206Z	14.95	0.00	14.95	0.00
  2025-07-28T03:33:23.207Z	15.50	0.00	15.50	0.00
  2025-07-28T03:33:31.299Z	15.78	0.00	15.78	0.00
  2025-07-28T03:33:31.299Z	16.42	0.00	16.42	0.00
  2025-07-28T03:33:33.605Z	16.98	0.00	16.98	0.00
  2025-07-28T03:33:33.605Z	17.56	0.00	17.56	0.00
  2025-07-28T03:33:35.610Z	5.74	0.00	5.74	0.00
  2025-07-28T03:33:35.611Z	6.38	0.00	6.38	0.00
  …	…	…	…	…

  • 문제점
    • 현재 w_c_ratio 를 보면 전부 0임을 알 수 있음. → Feign Client의 외부 호출이 Blocking 방식이기 때문에 모든 시간을 전부 네트워크 I/O 대기로 사용하게 됨.
    • 이렇게 되면 Pool size = core * (1 + W/C) 가 0 혹은 무한대가 되기 때문에 적정값 측정이 불가함. → 목표 처리량을 기준으로 Thread 수를 지정하고 그에 맞춰 테스트 진행하기로 함.

1. 목표 초당 처리량 x 평균 대기 시간으로 예상 Pool size 산출

   • 테스트 스크립트
   • 측정 결과 (Thread: 29, Ramp-up: 30, Duration: 180)

   지표	값
   표본 수	653 건
   평균 응답 시간	6 ms
   P(50)	7 ms
   P(90)	8 ms
   P(95)	8 ms
   P(99)	10 ms
   최소 응답 시간	5 ms
   최대 응답 시간	23 ms
   처리량	3.64 req/s

   • 결과 계산

     Pool size = QPS x 평균 대기 시간(= 평균 응답 시간)

                 = `100 req/s x 0.006 s` = `0.6` → `1`
     

결론: 여유롭게 2~4 스레드 정도만 잡아도 충분하다고 판단.

❗ 버스트 대비

순간적으로 1000 req/s 를 커버해야 할 땐 1000 x 0.006 = 6 → 8~12 스레드를 잡아 처리하도록 함

[최종 결과]

@Bean(name = "feignClientTaskExecutor")
public ThreadPoolTaskExecutor feignClientTaskExecutor() {
    ThreadPoolTaskExecutor exec = new ThreadPoolTaskExecutor();
    exec.setCorePoolSize(4);
    exec.setMaxPoolSize(12);
    exec.setQueueCapacity(50);
    exec.setThreadNamePrefix("feign-task");
    exec.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
    exec.initialize();
    return exec;
}