CPU‐Heavy 코루틴 테스트 - 100-hours-a-week/5-yeosa-wiki GitHub Wiki

코루틴 코드

async def embed_controller(req: ImageRequest, request: Request) -> JSONResponse:
   """
    이미지 임베딩을 수행하는 컨트롤러입니다.

    Args:
        req: 이미지 파일명 목록을 포함한 요청 객체
        request: FastAPI 요청 객체

    Returns:
        JSONResponse: 성공 메시지와 데이터를 포함한 응답
    """
    logger.info(
        "이미지 임베딩 요청 처리 시작",
        extra={"total_images": len(req.images)},
    )

    image_refs = req.images

    # 1. 이미지 로드
    image_loader = request.app.state.image_loader

    images = await image_loader.load_images(image_refs)

    logger.debug(
        "이미지 로드 완료",
        extra={"loaded_images": len(images)},
    )

    # 2. 모델 및 전처리 로드
    clip_model = request.app.state.clip_model
    clip_preprocess = request.app.state.clip_preprocess
    
    # 3. 모델 추론(이미지 임베딩, torch) -> 직접 메인 스레드에서 실행
    embed_images(
        clip_model,
        clip_preprocess,
        images,
        image_refs,
        batch_size=DEFAULT_BATCH_SIZE,
        device=DEFAULT_DEVICE,
    )

    logger.info(
        "이미지 임베딩 완료",
        extra={"processed_images": len(image_refs)},
    )

    return JSONResponse(
        status_code=201,
        content={"message": "success", "data": None},
    )

1. 테스트 목적

a. 가정

현재 FastAPI 서버는 async def 경로에서 torch 추론 연산을 직접 실행하고 있다.
torch 연산은 CPU-bound 작업으로, 이벤트 루프를 점유할 가능성이 있다.

b. 예상 결과

torch 연산이 이벤트 루프에서 직접 실행될 경우, 요청이 순차적으로 처리될 것이다.
동시 요청 수가 증가할수록 응답 시간이 선형적으로 증가할 것으로 예상된다.

(N개의 요청이면, 평균 응답 시간은 대략 N × torch 연산 시간)

2. 테스트 설계

a. 도구

부하 테스트 도구: k6
테스트 스크립트: thread-separation-test.js

b. 방식

-vus N --iterations N --duration 1s 형태로 테스트 실행

→ N명의 사용자가 동시에 1번씩 요청을 보냄
동시 요청 수(VUs)를 1~5까지 점차 증가
torch 연산은 이미지 30장에 대해 평균 3.5초 정도 걸리는 CPU 연산

c. 요청 형식

POST /api/albums/embedding

{
  "images": ["img001.jpg", ..., "img030.jpg"]
}

3. 테스트 결과

동시 요청 수 (VUs)	평균 응답 시간 (`http_req_duration`)
1	3.68초
2	7.05초
3	10.67초
4	13.48초
5	16.55초

모든 요청이 정상적으로 처리됨 (status is 201, 실패율 0%)

실행 스크립트

import http from 'k6/http';
import { check } from 'k6';

// 서버 주소 및 요청 데이터
const url = 'http://34.64.196.15:8001/api/albums/embedding';

const payload = JSON.stringify({
  images: Array.from({ length: 30 }, (_, i) =>
    `img${String(i + 1).padStart(3, '0')}.jpg`
  )
});

const params = {
  headers: {
    'Content-Type': 'application/json',
  },
};

export default function () {
  const res = http.post(url, payload, params);

  check(res, {
    'status is 201': (r) => r.status === 201,
    'response includes success': (r) => r.body.includes('success'), // 필요 시 수정
  });
}

k6 run --vus 1 --iterations 1 --duration 1s thread-separation-test.js

█ TOTAL RESULTS

checks_total.......................: 2 0.541335/s

checks_succeeded...................: 100.00% 2 out of 2

checks_failed......................: 0.00% 0 out of 2

✓ status is 201

✓ response includes success

HTTP

http_req_duration.......................................................: avg=3.68s min=3.68s med=3.68s max=3.68s p(90)=3.68s p(95)=3.68s

{ expected_response:true }............................................: avg=3.68s min=3.68s med=3.68s max=3.68s p(90)=3.68s p(95)=3.68s

http_req_failed.........................................................: 0.00% 0 out of 1

http_reqs...............................................................: 1 0.270667/s

EXECUTION

iteration_duration......................................................: avg=3.69s min=3.69s med=3.69s max=3.69s p(90)=3.69s p(95)=3.69s

iterations..............................................................: 1 0.270667/s

vus.....................................................................: 1 min=1 max=1

vus_max.................................................................: 1 min=1 max=1

NETWORK

data_received...........................................................: 163 B 44 B/s

data_sent...............................................................: 549 B 149 B/s
k6 run --vus 2 --iterations 2 --duration 1s thread-separation-test.js

█ TOTAL RESULTS

checks_total.......................: 4 0.565675/s

checks_succeeded...................: 100.00% 4 out of 4

checks_failed......................: 0.00% 0 out of 4

✓ status is 201

✓ response includes success

HTTP

http_req_duration.......................................................: avg=7.05s min=7.05s med=7.05s max=7.05s p(90)=7.05s p(95)=7.05s

{ expected_response:true }............................................: avg=7.05s min=7.05s med=7.05s max=7.05s p(90)=7.05s p(95)=7.05s

http_req_failed.........................................................: 0.00% 0 out of 2

http_reqs...............................................................: 2 0.282838/s

EXECUTION

iteration_duration......................................................: avg=7.06s min=7.06s med=7.06s max=7.07s p(90)=7.07s p(95)=7.07s

iterations..............................................................: 2 0.282838/s

vus.....................................................................: 2 min=2 max=2

vus_max.................................................................: 2 min=2 max=2

NETWORK

data_received...........................................................: 326 B 46 B/s

data_sent...............................................................: 1.1 kB 155 B/s
k6 run --vus 3 --iterations 3 --duration 1s thread-separation-test.js

█ TOTAL RESULTS

checks_total.......................: 6 0.559954/s

checks_succeeded...................: 100.00% 6 out of 6

checks_failed......................: 0.00% 0 out of 6

✓ status is 201

✓ response includes success

HTTP

http_req_duration.......................................................: avg=10.67s min=10.67s med=10.67s max=10.67s p(90)=10.67s p(95)=10.67s

{ expected_response:true }............................................: avg=10.67s min=10.67s med=10.67s max=10.67s p(90)=10.67s p(95)=10.67s

http_req_failed.........................................................: 0.00% 0 out of 3

http_reqs...............................................................: 3 0.279977/s

EXECUTION

iteration_duration......................................................: avg=10.71s min=10.71s med=10.71s max=10.71s p(90)=10.71s p(95)=10.71s

iterations..............................................................: 3 0.279977/s

vus.....................................................................: 3 min=3 max=3

vus_max.................................................................: 3 min=3 max=3

NETWORK

data_received...........................................................: 489 B 46 B/s

data_sent...............................................................: 1.6 kB 154 B/s
k6 run --vus 4 --iterations 4 --duration 1s thread-separation-test.js

█ TOTAL RESULTS

checks_total.......................: 8 0.592284/s

checks_succeeded...................: 100.00% 8 out of 8

checks_failed......................: 0.00% 0 out of 8

✓ status is 201

✓ response includes success

HTTP

http_req_duration.......................................................: avg=13.48s min=13.48s med=13.48s max=13.48s p(90)=13.48s p(95)=13.48s

{ expected_response:true }............................................: avg=13.48s min=13.48s med=13.48s max=13.48s p(90)=13.48s p(95)=13.48s

http_req_failed.........................................................: 0.00% 0 out of 4

http_reqs...............................................................: 4 0.296142/s

EXECUTION

iteration_duration......................................................: avg=13.5s min=13.5s med=13.5s max=13.5s p(90)=13.5s p(95)=13.5s

iterations..............................................................: 4 0.296142/s

vus.....................................................................: 4 min=4 max=4

vus_max.................................................................: 4 min=4 max=4

NETWORK

data_received...........................................................: 652 B 48 B/s

data_sent...............................................................: 2.2 kB 163 B/s
k6 run --vus 5 --iterations 5 --duration 1s thread-separation-test.js

█ TOTAL RESULTS

checks_total.......................: 10 0.603395/s

checks_succeeded...................: 100.00% 10 out of 10

checks_failed......................: 0.00% 0 out of 10

✓ status is 201

✓ response includes success

HTTP

http_req_duration.......................................................: avg=16.55s min=16.55s med=16.55s max=16.55s p(90)=16.55s p(95)=16.55s

{ expected_response:true }............................................: avg=16.55s min=16.55s med=16.55s max=16.55s p(90)=16.55s p(95)=16.55s

http_req_failed.........................................................: 0.00% 0 out of 5

http_reqs...............................................................: 5 0.301698/s

EXECUTION

iteration_duration......................................................: avg=16.57s min=16.57s med=16.57s max=16.57s p(90)=16.57s p(95)=16.57s

iterations..............................................................: 5 0.301698/s

vus.....................................................................: 5 min=5 max=5

vus_max.................................................................: 5 min=5 max=5

NETWORK

data_received...........................................................: 815 B 49 B/s

data_sent...............................................................: 2.7 kB 166 B/

4. 로그 분석

vus 5명일 때의 전체 로그

2025-05-14 06:33:09.964 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-05-14 06:33:09.964 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
2025-05-14 06:33:09,964 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:09.967 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-05-14 06:33:09.968 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
2025-05-14 06:33:09,968 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:09.969 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-05-14 06:33:09.969 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
2025-05-14 06:33:09,969 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:09.969 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-05-14 06:33:09.969 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
2025-05-14 06:33:09,969 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:09.978 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-05-14 06:33:09.978 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
2025-05-14 06:33:09,978 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:10.584 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 시작
2025-05-14 06:33:10,584 INFO    이미지 임베딩 시작
2025-05-14 06:33:14,300 INFO    이미지 임베딩 완료
2025-05-14 06:33:14.301 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 성공
2025-05-14 06:33:14.301 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-05-14 06:33:14.301 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-05-14 06:33:14.302 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 시작
2025-05-14 06:33:14,302 INFO    이미지 임베딩 시작
2025-05-14 06:33:17,514 INFO    이미지 임베딩 완료
2025-05-14 06:33:17.514 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 성공
2025-05-14 06:33:17.515 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-05-14 06:33:17.515 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-05-14 06:33:17.516 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 시작
2025-05-14 06:33:17,516 INFO    이미지 임베딩 시작
2025-05-14 06:33:20,523 INFO    이미지 임베딩 완료
2025-05-14 06:33:20.524 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 성공
2025-05-14 06:33:20.524 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-05-14 06:33:20.524 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-05-14 06:33:20.526 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 시작
2025-05-14 06:33:20,526 INFO    이미지 임베딩 시작
2025-05-14 06:33:23,504 INFO    이미지 임베딩 완료
2025-05-14 06:33:23.504 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 성공
2025-05-14 06:33:23.505 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-05-14 06:33:23.505 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-05-14 06:33:23.505 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 시작
2025-05-14 06:33:23,505 INFO    이미지 임베딩 시작
2025-05-14 06:33:26,483 INFO    이미지 임베딩 완료
2025-05-14 06:33:26.483 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_images 함수 성공
2025-05-14 06:33:26.484 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-05-14 06:33:26.484 | INFO     | fastapi.routing:app:301 - embed 함수 성공
INFO:     211.244.225.166:53665 - "POST /api/albums/embedding HTTP/1.1" 201 Created
INFO:     211.244.225.166:53667 - "POST /api/albums/embedding HTTP/1.1" 201 Created
INFO:     211.244.225.166:53668 - "POST /api/albums/embedding HTTP/1.1" 201 Created
INFO:     211.244.225.166:53666 - "POST /api/albums/embedding HTTP/1.1" 201 Created
INFO:     211.244.225.166:53669 - "POST /api/albums/embedding HTTP/1.1" 201 Created

a. 요청 수신 시각

2025-05-14 06:33:09,964 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:09,968 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:09,969 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:09,969 INFO    이미지 임베딩 요청 처리 시작
2025-05-14 06:33:09,978 INFO    이미지 임베딩 요청 처리 시작

즉, 5개의 요청이 거의 동시에 수신됨

→ 이건 k6 --vus 5를 사용해 정확히 동시에 요청을 보낸 결과와 일치

b. 이미지 임베딩 시작/완료 시각

2025-05-14 06:33:10,584 INFO    이미지 임베딩 시작
2025-05-14 06:33:14,300 INFO    이미지 임베딩 완료
2025-05-14 06:33:14,302 INFO    이미지 임베딩 시작
2025-05-14 06:33:17,514 INFO    이미지 임베딩 완료
2025-05-14 06:33:17,516 INFO    이미지 임베딩 시작
2025-05-14 06:33:20,523 INFO    이미지 임베딩 완료
2025-05-14 06:33:20,526 INFO    이미지 임베딩 시작
2025-05-14 06:33:23,504 INFO    이미지 임베딩 완료
2025-05-14 06:33:23,505 INFO    이미지 임베딩 시작
2025-05-14 06:33:26,483 INFO    이미지 임베딩 완료

각 요청은 정확히 3~3.5초 간격으로 순차 실행됨

→ 완전한 직렬 처리 구조임을 의미

c. 응답 시점 비교

# 마지막 임베딩 완료 시각
2025-05-14 06:33:26,484 INFO    이미지 임베딩 완료
INFO:     211.244.225.166:53665 - "POST /api/albums/embedding HTTP/1.1" 201 Created
INFO:     211.244.225.166:53667 - "POST /api/albums/embedding HTTP/1.1" 201 Created
INFO:     211.244.225.166:53668 - "POST /api/albums/embedding HTTP/1.1" 201 Created
INFO:     211.244.225.166:53666 - "POST /api/albums/embedding HTTP/1.1" 201 Created
INFO:     211.244.225.166:53669 - "POST /api/albums/embedding HTTP/1.1" 201 Created

응답이 모든 요청이 완료된 후에야 시작됨
즉, torch 연산이 루프를 점유하는 동안 응답도 보낼 수 없음

d. 결론: 이벤트 루프가 완전히 점유되었음

동시에 요청을 받아도 이벤트 루프는 torch 연산을 마치기 전까지 다음 요청의 실제 처리를 시작하지 못함
소켓은 수신하지만, embed_images() 실행이 전부 직렬로 실행되기 때문에 응답은 순차적으로 밀려남
즉, 이벤트 루프 자체가 CPU 바운드 연산으로 막혀버린 상태

e. 이 로그가 보여주는 핵심

증거	설명
동일한 수신 시각	모든 요청이 동시에 들어왔음을 증명
임베딩 함수 시작 시각이 3~4초 간격	torch 연산이 병렬이 아닌 직렬로 실행되었음을 명확히 보여줌
모든 임베딩이 끝난 후 응답	요청 처리 전체가 병목으로 이어졌다는 실질적 결과

5. 결과 분석

a. 응답 시간 선형 증가

동시 요청 수가 늘어날수록 응답 시간이 N배로 증가함
- 요청 1개 → 3.68초
- 요청 5개 → 16.55초 ≈ 3.3초 × 5

b. 의미하는 바

요청이 동시에 처리되지 않고, torch 연산이 직렬 처리되고 있음
이는 다음과 같은 구조적 병목을 시사:
- torch 연산이 이벤트 루프 내에서 실행되고 있으며
- 루프 점유로 인해 다른 요청 수신 및 처리 지연이 발생
- 결국 모든 요청이 순차적으로 처리되고 응답도 처리 종료 후에만 반환됨
- 응답 또한 이벤트 루프에서 처리되므로, 전체 요청에 대한 연산이 종료된 후에야 응답이 한 번에 되는 것을 확인할 수 있음

c. 핵심 인사이트

현재 구조는 CPU 바운드 연산을 async def 내부에서 직접 실행하고 있기 때문에, FastAPI + Uvicorn 단일 이벤트 루프 환경에서는 병렬 요청이 직렬 처리됨

6. 다음 단계 제안

torch 연산을 run_in_executor()로 분리하여 이벤트 루프를 점유하지 않도록 개선
동일 조건(-vus N --iterations N)으로 개선 후 테스트 재실행
개선 전후의 응답 시간 차이(p95, avg)를 비교하여 구조 개선 효과를 정량화