[트러블 슈팅] 레디스 일부 요청 임베딩 캐싱 실패 원인 파악 - 100-hours-a-week/5-yeosa-wiki GitHub Wiki

1. 트러블

a. 요약

k6을 사용해 레디스로 동시에 여러 요청 보냈을 때, 일부 요청이 아예 이미지 캐싱 실패. (요청 중 일부 사진 실패가 아니라 모든 사진에 대해서)

b. 에러 상황

가. `connection reset by peer`

의미: 클라이언트가 서버에 연결한 후 데이터를 읽으려 했지만, 서버 측에서 강제로 커넥션을 끊음 (RST 신호 전송).
보통 다음의 원인으로 발생
- FastAPI 서버에서 예외나 오류로 인해 커넥션을 비정상 종료 (e.g. raise, sys.exit, SegFault, OOM)
- 서버가 죽었거나 재시작 중
- 응답을 전송하기 전에 프로세스가 크래시났거나 응답 쓰기 중 실패 발생

나. `EOF`

의미: 서버가 예상보다 일찍 응답 스트림을 닫음. 즉, 응답을 다 받지 못하고 스트림이 끊겼다는 뜻.
보통 서버가 응답을 완료하지 못하고 중간에 죽었거나, response.body()를 다 채우기 전에 연결을 닫았을 때 발생.

기존 코드 (예외 던지기가 제대로 안되고 있음) - 나중에 블로그 쓸 리소스

import json, logging
from typing import Any
import traceback
import os
import asyncio
import time
from dotenv import load_dotenv

import torch
from app.config.redis import get_redis

load_dotenv()
logger = logging.getLogger(__name__)

try:
    raw_ttl = os.getenv("REDIS_CACHE_TTL")
    if raw_ttl is None:
        raise ValueError("REDIS_CACHE_TTL이 .env 파일에 없습니다.")
    REDIS_CACHE_TTL = int(raw_ttl)
except ValueError as e:
    raise EnvironmentError(str(e))
except Exception as e:
    raise EnvironmentError("REDIS_CACHE_TTL이 정수로 지정되어야 합니다.")

async def get_cached_embedding(key: str) -> Any | None:
    redis = get_redis()
    try:
        t0 = time.perf_counter()
        value = await redis.get(key)
        t1 = time.perf_counter()

        if value is None:
            logger.warning(f"[Redis GET] key='{key}' not found")
            return None

        logger.info(f"[Redis GET] key='{key}' found, took {t1 - t0:.4f} seconds")

        return torch.tensor(json.loads(value))
    except Exception as e:
        logger.error(f"[Redis GET ERROR] key='{key}' failed: {e}", exc_info=True)
        return None

async def set_cached_embedding(key: str, value: Any) -> None:
    redis = get_redis()
    try:
        if isinstance(value, torch.Tensor):
            value = value.cpu().float().tolist()

        t0 = time.perf_counter()
        ttl = int(REDIS_CACHE_TTL)
        await redis.set(key, json.dumps(value), ex=ttl)
        t1 = time.perf_counter()

        logger.info(f"[Redis SET] key='{key}' succeeded, took {t1 - t0:.4f} seconds, TTL={ttl}")
    except Exception as e:
        logger.error(f"[Redis SET ERROR] key='{key}' failed: {e}", exc_info=True)
        raise

async def del_embedding_cache(key: str) -> None:
    redis = get_redis()

    # 시간 테스트
    t0 = time.perf_counter()
    await redis.delete(key)
    t1 = time.perf_counter()
    print(f"[Redis DEL] key='{key}' took {t1 - t0:.4f} seconds")

async def clear_embedding_cache() -> None:
    redis = get_redis()
    keys = await redis.keys("*")
    if keys:
        await redis.delete(*keys)

async def get_cached_embeddings_parallel(keys: list[str]) -> tuple[list[Any | None], list[str]]:
    """
    비동기로 여러 키를 Redis에서 조회합니다. 실패한 키도 기록합니다.
    """
    t0 = time.perf_counter()

    results = await asyncio.gather(
        *(get_cached_embedding(key) for key in keys),
        return_exceptions=True
    )

    t1 = time.perf_counter()
    print(f"[Redis BULK GET] {len(keys)} keys took {t1 - t0:.4f} seconds")

    final_results = []
    missing_keys = []

    for key, result in zip(keys, results):
        if isinstance(result, Exception):
            missing_keys.append(key)
            logger.warning(
                f"[Redis ERROR] key='{key}' 조회 실패: {type(result).__name__}: {result}",
                extra={"traceback": traceback.format_exception_only(type(result), result)}
            )
            final_results.append(None)
        elif result is None:
            missing_keys.append(key)
            logger.info(f"[Redis MISS] key='{key}' not found in cache.")
            final_results.append(None)
        else:
            final_results.append(result)

    return final_results, missing_keys

2. 해결 과정

a. 가설: Redis 에러가 발생했을 것이다

Redis 응답 보고 에러 분석하기

b. Redis 응답 확인

가. 공식 문서

Get 요청
- Get the value of key. If the key does not exist the special value nil is returned. An error is returned if the value stored at key is not a string, because GET only handles string values.
→ 캐시 미스 나면 nil 반환, 값이 string이 아니면 에러 반환
Set 요청
- 공식문서
  
  SET
  
  Syntax
```
SET key value [NX | XX] [GET] [EX seconds | PX milliseconds |
  EXAT unix-time-seconds | PXAT unix-time-milliseconds | KEEPTTL]
```
  **Available since:Redis Open Source 1.0.0Time complexity:**O(1)ACL categories:@write, @string, @slow
  
  Set key to hold the string value. If key already holds a value, it is overwritten, regardless of its type. Any previous time to live associated with the key is discarded on successful SET operation.
  
  Options
  
  The SET command supports a set of options that modify its behavior:
  - EX seconds -- Set the specified expire time, in seconds (a positive integer).
  - PX milliseconds -- Set the specified expire time, in milliseconds (a positive integer).
  - EXAT timestamp-seconds -- Set the specified Unix time at which the key will expire, in seconds (a positive integer).
  - PXAT timestamp-milliseconds -- Set the specified Unix time at which the key will expire, in milliseconds (a positive integer).
  - NX -- Only set the key if it does not already exist.
  - XX -- Only set the key if it already exists.
  - KEEPTTL -- Retain the time to live associated with the key.
  - GET -- Return the old string stored at key, or nil if key did not exist. An error is returned and SET aborted if the value stored at key is not a string.
  Note: Since the SET command options can replace SETNX, SETEX, PSETEX, GETSET, it is possible that in future versions of Redis these commands will be deprecated and finally removed.
  
  Examples
  
  redis> SET mykey "Hello" "OK" redis> GET mykey "Hello" redis> SET anotherkey "will expire in a minute" EX 60 "OK" redis>
  
  Code examples
  
  Python
  
  res **=** r**.**set("bike:1", "Process 134") print(res) *# >>> True*res **=** r**.**get("bike:1") print(res) *# >>> "Process 134"*
  
  Node.js
  
  Java-Sync
  
  Go
  
  C#
  
  Patterns
  
  Note: The following pattern is discouraged in favor of the Redlock algorithm which is only a bit more complex to implement, but offers better guarantees and is fault tolerant.
  
  The command SET resource-name anystring NX EX max-lock-time is a simple way to implement a locking system with Redis.
  
  A client can acquire the lock if the above command returns OK (or retry after some time if the command returns Nil), and remove the lock just using DEL.
  
  The lock will be auto-released after the expire time is reached.
  
  It is possible to make this system more robust modifying the unlock schema as follows:
  - Instead of setting a fixed string, set a non-guessable large random string, called token.
  - Instead of releasing the lock with DEL, send a script that only removes the key if the value matches.
  This avoids that a client will try to release the lock after the expire time deleting the key created by another client that acquired the lock later.
  
  An example of unlock script would be similar to the following:
```
if redis.call("get",KEYS[1]) == ARGV[1]
then
    return redis.call("del",KEYS[1])
else
    return 0
end
```
  The script should be called with EVAL ...script... 1 resource-name token-value
  
  RESP2 Reply
  
  Any of the following:
  - Nil reply: GET not given: Operation was aborted (conflict with one of the XX/NX options).
  - Simple string reply: OK. GET not given: The key was set.
  - Nil reply: GET given: The key didn't exist before the SET.
  - Bulk string reply: GET given: The previous value of the key.
  RESP3 Reply
  
  Any of the following:
  - Null reply: GET not given: Operation was aborted (conflict with one of the XX/NX options).
  - Simple string reply: OK. GET not given: The key was set.
  - Null reply: GET given: The key didn't exist before the SET.
  - Bulk string reply: GET given: The previous value of the key.
  History
  - Starting with Redis version 2.6.12: Added the EX, PX, NX and XX options.
  - Starting with Redis version 6.0.0: Added the KEEPTTL option.
  - Starting with Redis version 6.2.0: Added the GET, EXAT and PXAT option.
  - Starting with Redis version 7.0.0: Allowed the NX and GET options to be used together.
- Set 성공하면 OK 반환.

나. Redis python client

Redis python client는 응답 형태가 다름

import redis

# Redis 클라이언트 연결 (localhost:6379)
client = redis.Redis(host='localhost', port=6379, db=0)

# 1. SET 성공 여부 확인
key = "test:key"
value = "Hello, Redis!"
set_result = client.set(key, value)
print(f"✅ SET 성공 여부: {set_result}")  # True 예상

# 2. GET 성공 확인
get_result = client.get(key)
print(f"📦 GET 결과: {get_result}")  # b'Hello, Redis!' 예상

# 3. GET 실패 (존재하지 않는 키 조회)
miss_result = client.get("nonexistent:key")
print(f"🛑 GET 실패 결과: {miss_result}")  # None 예상

아래와 같이 응답 변경

c. 가설 및 결론: 캐시 미스는 레디스 비동기 write 중 조회가 일어났기 때문일 것이다. - 거짓

임베딩 실패가 터졌는데 서버 쪽에서는 에러 안뜸.

가. 추정한 원인

임베딩 후에 레디스에 비동기로 작성
그동안 자바 서버에서 요청을 보냄
아직 레디스에 쓰기가 완료되기 전에 조회를 했던 것이라고 예상

나. 검증

sleep을 두 요청 사이에 줬으나 코드를 확인해보니 임베딩부터 실패하고 같은 이미지에 대해 카테고리 요청 실패

다. 결론

캐시 미스의 원인은 레디스가 원인이 아니다. 이전 임베딩 실패가 원인.

d. 결론: Redis 문제가 아니다

매번 실패하는 사진들이 동일한 것 같음. 21~40 실패, 360-380 성공

e. 가설 및 결론: 해당 사진 누락됐거나 이전 작업이 실패해서 set 요청 자체가 안 갔을 것이다.(레디스 이전의 문제일 것이다) - 참

WARN[0004] Request Failed                                error="Post \"http://0.0.0.0:8000/api/albums/embedding\": EOF"
WARN[0004] Request Failed                                error="Post \"http://0.0.0.0:8000/api/albums/embedding\": EOF"
WARN[0004] Request Failed                                error="Post \"http://0.0.0.0:8000/api/albums/embedding\": EOF"
WARN[0004] Request Failed                                error="Post \"http://0.0.0.0:8000/api/albums/embedding\": read tcp 127.0.0.1:58628->127.0.0.1:8000: read: connection reset by peer"

End Of File - 서버 쪽에서 연결을 끊음 connection reset by peer - 서버에서 강제로 연결을 닫음

로그

2025-06-04 11:07:44 +0900] [71807] [INFO] Application startup complete.
2025-06-04 11:07:47.787 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:07:47.787 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:07:47.788 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[START] 이미지 임베딩 요청 시작 - 총 이미지 수: 20
2025-06-04 11:07:47.789 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[START] 이미지 임베딩 요청 시작 - 총 이미지 수: 20
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:07:47.789
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:07:47.790
2025-06-04 11:07:47.793 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:07:47.793 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:07:47.795 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[START] 이미지 임베딩 요청 시작 - 총 이미지 수: 20
2025-06-04 11:07:47.794 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[START] 이미지 임베딩 요청 시작 - 총 이미지 수: 20
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:07:47.796
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:07:47.796
2025-06-04 11:07:47.798 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:07:47.798 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[START] 이미지 임베딩 요청 시작 - 총 이미지 수: 20
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:07:47.799
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:07:49.804
[INFO] 요청-응답 소요 시간: 2.01 s
[INFO] 응답 역직렬화 완료: 3.25 ms
[INFO] 임베딩 완료 - 처리된 이미지 수: 20
-----[Redis Set Start]-----
[Redis SET] key='img001.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img002.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img003.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:07:49.813
[INFO] 요청-응답 소요 시간: 2.02 s
[INFO] 응답 역직렬화 완료: 2.14 ms
[INFO] 임베딩 완료 - 처리된 이미지 수: 20
-----[Redis Set Start]-----
[Redis SET] key='img004.jpg' succeeded, took 0.0059 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img241.jpg' succeeded, took 0.0034 seconds, TTL=300
-----[Redis Set Start]-----
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:07:49.821
[INFO] 요청-응답 소요 시간: 2.03 s
[INFO] 응답 역직렬화 완료: 2.13 ms
[INFO] 임베딩 완료 - 처리된 이미지 수: 20
-----[Redis Set Start]-----
[Redis SET] key='img005.jpg' succeeded, took 0.0062 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img242.jpg' succeeded, took 0.0044 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img121.jpg' succeeded, took 0.0023 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img243.jpg' succeeded, took 0.0017 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img006.jpg' succeeded, took 0.0026 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img122.jpg' succeeded, took 0.0014 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img244.jpg' succeeded, took 0.0014 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img007.jpg' succeeded, took 0.0013 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img123.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img245.jpg' succeeded, took 0.0015 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img008.jpg' succeeded, took 0.0020 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img124.jpg' succeeded, took 0.0029 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img246.jpg' succeeded, took 0.0026 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img009.jpg' succeeded, took 0.0020 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img125.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img247.jpg' succeeded, took 0.0013 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img010.jpg' succeeded, took 0.0014 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img126.jpg' succeeded, took 0.0015 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img248.jpg' succeeded, took 0.0014 seconds, TTL=300
-----[Redis Set Start]-----
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:07:49.835
[INFO] 요청-응답 소요 시간: 2.04 s
[Redis SET] key='img011.jpg' succeeded, took 0.0013 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img127.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img249.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img012.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img128.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[INFO] 응답 역직렬화 완료: 1.85 ms
[INFO] 임베딩 완료 - 처리된 이미지 수: 20
-----[Redis Set Start]-----
[Redis SET] key='img250.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img013.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img481.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img129.jpg' succeeded, took 0.0013 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img482.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img251.jpg' succeeded, took 0.0016 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img014.jpg' succeeded, took 0.0015 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img483.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img130.jpg' succeeded, took 0.0016 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img252.jpg' succeeded, took 0.0014 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img484.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img015.jpg' succeeded, took 0.0015 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img131.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img485.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img253.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img016.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img486.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img132.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img487.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img254.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img017.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img488.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img133.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img489.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img255.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img018.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img490.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img134.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img491.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img256.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img019.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img492.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img135.jpg' succeeded, took 0.0017 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img257.jpg' succeeded, took 0.0020 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img493.jpg' succeeded, took 0.0016 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img020.jpg' succeeded, took 0.0022 seconds, TTL=300
[SUCCESS] 임베딩 결과 캐싱 완료
[Redis SET] key='img494.jpg' succeeded, took 0.0014 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:07:49.848 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
[Redis SET] key='img495.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:07:49.849 | INFO     | fastapi.routing:app:301 - embed 함수 성공
[Redis SET] key='img136.jpg' succeeded, took 0.0033 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img496.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img258.jpg' succeeded, took 0.0031 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img137.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img259.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:07:49.851
[INFO] 요청-응답 소요 시간: 2.05 s
[Redis SET] key='img138.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img260.jpg' succeeded, took 0.0012 seconds, TTL=300
[SUCCESS] 임베딩 결과 캐싱 완료
[INFO] 응답 역직렬화 완료: 1.46 ms
[INFO] 임베딩 완료 - 처리된 이미지 수: 20
-----[Redis Set Start]-----
2025-06-04 11:07:49.853 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
[Redis SET] key='img497.jpg' succeeded, took 0.0031 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:07:49.853 | INFO     | fastapi.routing:app:301 - embed 함수 성공
[Redis SET] key='img139.jpg' succeeded, took 0.0022 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img361.jpg' succeeded, took 0.0024 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img498.jpg' succeeded, took 0.0022 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:07:49.855 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
[Redis SET] key='img362.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:07:49.856 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis SET] key='img499.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img363.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img140.jpg' succeeded, took 0.0030 seconds, TTL=300
[SUCCESS] 임베딩 결과 캐싱 완료
[Redis SET] key='img500.jpg' succeeded, took 0.0009 seconds, TTL=300
[SUCCESS] 임베딩 결과 캐싱 완료
2025-06-04 11:07:49.857 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:07:49.858 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:07:49.858 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-06-04 11:07:49.859 | INFO     | fastapi.routing:app:301 - embed 함수 성공
[Redis SET] key='img364.jpg' succeeded, took 0.0025 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img365.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img366.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:07:49.861 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:49.862 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
2025-06-04 11:07:49.862 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:49.863 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis SET] key='img367.jpg' succeeded, took 0.0026 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:07:49.864 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:49.865 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis BULK GET] 20 keys took 0.0140 seconds
categorize_controller 임베딩 로드 후
[]
[Redis SET] key='img368.jpg' succeeded, took 0.0076 seconds, TTL=300
-----[Redis Set Start]-----
[Redis BULK GET] 20 keys took 0.0086 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:07:49.877 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
2025-06-04 11:07:49.877 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
[Redis SET] key='img369.jpg' succeeded, took 0.0068 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img370.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img371.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img372.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img373.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img374.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img375.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img376.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img377.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis BULK GET] 20 keys took 0.0219 seconds
categorize_controller 임베딩 로드 후
[]
[Redis SET] key='img378.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img379.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:07:49.884 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
[Redis SET] key='img380.jpg' succeeded, took 0.0006 seconds, TTL=300
[SUCCESS] 임베딩 결과 캐싱 완료
2025-06-04 11:07:49.886 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:07:49.886 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-06-04 11:07:49.888 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:49.889 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis BULK GET] 20 keys took 0.0261 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:07:49.891 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
[Redis BULK GET] 20 keys took 0.0079 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:07:49.897 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
2025-06-04 11:07:49.902 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:07:49.903 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:07:49.903 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
2025-06-04 11:07:49.905 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:07:49.905 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:07:49.906 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
2025-06-04 11:07:49.906 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:07:49.907 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:07:49.908 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
2025-06-04 11:07:49.909 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:07:49.910 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:07:49.910 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
2025-06-04 11:07:49.911 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:07:49.912 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:07:49.912 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
2025-06-04 11:07:52.910 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:52.911 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:52.912 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
2025-06-04 11:07:52.913 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis GET] key='img381.jpg' not found
[Redis GET] key='img382.jpg' not found
[Redis GET] key='img383.jpg' not found
[Redis GET] key='img384.jpg' not found
[Redis GET] key='img385.jpg' not found
[Redis GET] key='img501.jpg' not found
[Redis GET] key='img502.jpg' not found
[Redis GET] key='img503.jpg' not found
[Redis GET] key='img504.jpg' not found
[Redis GET] key='img386.jpg' not found
[Redis GET] key='img387.jpg' not found
[Redis GET] key='img388.jpg' not found
[Redis GET] key='img389.jpg' not found
[Redis GET] key='img390.jpg' not found
[Redis GET] key='img391.jpg' not found
[Redis GET] key='img392.jpg' not found
[Redis GET] key='img393.jpg' not found
[Redis GET] key='img394.jpg' not found
[Redis GET] key='img395.jpg' not found
[Redis GET] key='img396.jpg' not found
[Redis GET] key='img397.jpg' not found
[Redis GET] key='img398.jpg' not found
[Redis GET] key='img399.jpg' not found
[Redis GET] key='img400.jpg' not found
[Redis BULK GET] 20 keys took 0.0074 seconds
categorize_controller 임베딩 로드 후
['img381.jpg', 'img382.jpg', 'img383.jpg', 'img384.jpg', 'img385.jpg', 'img386.jpg', 'img387.jpg', 'img388.jpg', 'img389.jpg', 'img390.jpg', 'img391.jpg', 'img392.jpg', 'img393.jpg', 'img394.jpg', 'img395.jpg', 'img396.jpg', 'img397.jpg', 'img398.jpg', 'img399.jpg', 'img400.jpg']
일부 이미지의 임베딩이 없음
2025-06-04 11:07:52.921 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:07:52.924 | ERROR    | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img381.jpg', 'img382.jpg', 'img383.jpg', 'img384.jpg', 'img385.jpg', 'img386.jpg', 'img387.jpg', 'img388.jpg', 'img389.jpg', 'img390.jpg', 'img391.jpg', 'img392.jpg', 'img393.jpg', 'img394.jpg', 'img395.jpg', 'img396.jpg', 'img397.jpg', 'img398.jpg', 'img399.jpg', 'img400.jpg']}
2025-06-04 11:07:52.926 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[START] 이미지 임베딩 요청 시작 - 총 이미지 수: 20
2025-06-04 11:07:52.926 | ERROR    | fastapi.routing:app:301 - categorize 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img381.jpg', 'img382.jpg', 'img383.jpg', 'img384.jpg', 'img385.jpg', 'img386.jpg', 'img387.jpg', 'img388.jpg', 'img389.jpg', 'img390.jpg', 'img391.jpg', 'img392.jpg', 'img393.jpg', 'img394.jpg', 'img395.jpg', 'img396.jpg', 'img397.jpg', 'img398.jpg', 'img399.jpg', 'img400.jpg']}
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:07:52.927
2025-06-04 11:07:52.928 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:07:52.929 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[START] 이미지 임베딩 요청 시작 - 총 이미지 수: 20
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:07:52.930
[Redis GET] key='img505.jpg' not found
[Redis GET] key='img506.jpg' not found
[Redis GET] key='img507.jpg' not found
[Redis GET] key='img508.jpg' not found
[Redis GET] key='img509.jpg' not found
[Redis GET] key='img510.jpg' not found
[Redis GET] key='img511.jpg' not found
[Redis GET] key='img512.jpg' not found
[Redis GET] key='img513.jpg' not found
[Redis GET] key='img514.jpg' not found
[Redis GET] key='img515.jpg' not found
[Redis GET] key='img516.jpg' not found
[Redis GET] key='img517.jpg' not found
[Redis GET] key='img518.jpg' not found
[Redis GET] key='img519.jpg' not found
[Redis GET] key='img520.jpg' not found
[Redis BULK GET] 20 keys took 0.0201 seconds
categorize_controller 임베딩 로드 후
['img501.jpg', 'img502.jpg', 'img503.jpg', 'img504.jpg', 'img505.jpg', 'img506.jpg', 'img507.jpg', 'img508.jpg', 'img509.jpg', 'img510.jpg', 'img511.jpg', 'img512.jpg', 'img513.jpg', 'img514.jpg', 'img515.jpg', 'img516.jpg', 'img517.jpg', 'img518.jpg', 'img519.jpg', 'img520.jpg']
일부 이미지의 임베딩이 없음
2025-06-04 11:07:52.935 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:52.935 | ERROR    | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img501.jpg', 'img502.jpg', 'img503.jpg', 'img504.jpg', 'img505.jpg', 'img506.jpg', 'img507.jpg', 'img508.jpg', 'img509.jpg', 'img510.jpg', 'img511.jpg', 'img512.jpg', 'img513.jpg', 'img514.jpg', 'img515.jpg', 'img516.jpg', 'img517.jpg', 'img518.jpg', 'img519.jpg', 'img520.jpg']}
2025-06-04 11:07:52.936 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
2025-06-04 11:07:52.936 | ERROR    | fastapi.routing:app:301 - categorize 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img501.jpg', 'img502.jpg', 'img503.jpg', 'img504.jpg', 'img505.jpg', 'img506.jpg', 'img507.jpg', 'img508.jpg', 'img509.jpg', 'img510.jpg', 'img511.jpg', 'img512.jpg', 'img513.jpg', 'img514.jpg', 'img515.jpg', 'img516.jpg', 'img517.jpg', 'img518.jpg', 'img519.jpg', 'img520.jpg']}
[Redis GET] key='img021.jpg' not found
[Redis GET] key='img022.jpg' not found
[Redis GET] key='img023.jpg' not found
[Redis GET] key='img024.jpg' not found
[Redis GET] key='img025.jpg' not found
[Redis GET] key='img026.jpg' not found
[Redis GET] key='img027.jpg' not found
[Redis GET] key='img028.jpg' not found
[Redis GET] key='img029.jpg' not found
[Redis GET] key='img030.jpg' not found
[Redis GET] key='img031.jpg' not found
[Redis GET] key='img032.jpg' not found
[Redis GET] key='img033.jpg' not found
[Redis GET] key='img034.jpg' not found
[Redis GET] key='img035.jpg' not found
[Redis GET] key='img036.jpg' not found
[Redis GET] key='img037.jpg' not found
[Redis GET] key='img038.jpg' not found
[Redis GET] key='img039.jpg' not found
[Redis GET] key='img040.jpg' not found
[Redis BULK GET] 20 keys took 0.0111 seconds
categorize_controller 임베딩 로드 후
['img021.jpg', 'img022.jpg', 'img023.jpg', 'img024.jpg', 'img025.jpg', 'img026.jpg', 'img027.jpg', 'img028.jpg', 'img029.jpg', 'img030.jpg', 'img031.jpg', 'img032.jpg', 'img033.jpg', 'img034.jpg', 'img035.jpg', 'img036.jpg', 'img037.jpg', 'img038.jpg', 'img039.jpg', 'img040.jpg']
일부 이미지의 임베딩이 없음
2025-06-04 11:07:52.948 | ERROR    | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img021.jpg', 'img022.jpg', 'img023.jpg', 'img024.jpg', 'img025.jpg', 'img026.jpg', 'img027.jpg', 'img028.jpg', 'img029.jpg', 'img030.jpg', 'img031.jpg', 'img032.jpg', 'img033.jpg', 'img034.jpg', 'img035.jpg', 'img036.jpg', 'img037.jpg', 'img038.jpg', 'img039.jpg', 'img040.jpg']}
2025-06-04 11:07:52.949 | ERROR    | fastapi.routing:app:301 - categorize 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img021.jpg', 'img022.jpg', 'img023.jpg', 'img024.jpg', 'img025.jpg', 'img026.jpg', 'img027.jpg', 'img028.jpg', 'img029.jpg', 'img030.jpg', 'img031.jpg', 'img032.jpg', 'img033.jpg', 'img034.jpg', 'img035.jpg', 'img036.jpg', 'img037.jpg', 'img038.jpg', 'img039.jpg', 'img040.jpg']}
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:07:53.629
[INFO] 요청-응답 소요 시간: 698.90 ms
[INFO] 응답 역직렬화 완료: 1.53 ms
[INFO] 임베딩 완료 - 처리된 이미지 수: 20
-----[Redis Set Start]-----
[Redis SET] key='img141.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img142.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img143.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img144.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img145.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img146.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img147.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img148.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img149.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img150.jpg' succeeded, took 0.0011 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img151.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img152.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img153.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img154.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img155.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img156.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img157.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img158.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img159.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img160.jpg' succeeded, took 0.0023 seconds, TTL=300
[SUCCESS] 임베딩 결과 캐싱 완료
2025-06-04 11:07:53.647 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:07:53.649 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-06-04 11:07:53.652 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:53.652 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis BULK GET] 20 keys took 0.0071 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:07:53.660 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
2025-06-04 11:07:53.662 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:07:53.663 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:07:53.664 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:07:53.708
[INFO] 요청-응답 소요 시간: 780.83 ms
[INFO] 응답 역직렬화 완료: 1.38 ms
[INFO] 임베딩 완료 - 처리된 이미지 수: 20
-----[Redis Set Start]-----
[Redis SET] key='img261.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img262.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img263.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img264.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img265.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img266.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img267.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img268.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img269.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img270.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img271.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img272.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img273.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img274.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img275.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img276.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img277.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img278.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img279.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img280.jpg' succeeded, took 0.0006 seconds, TTL=300
[SUCCESS] 임베딩 결과 캐싱 완료
2025-06-04 11:07:53.723 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:07:53.724 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-06-04 11:07:53.725 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:07:53.726 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis BULK GET] 20 keys took 0.0065 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:07:53.733 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
2025-06-04 11:07:53.735 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:07:53.736 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:07:53.736 | INFO     | fastapi.routing:app:301 - categorize 함수 성공

로그 분석 결과 set 요청이 가지 않았음

f. 가설 및 결론: GPU 로직 문제로 set 요청이 가지 않았을 것이다. - 거짓

로그

[2025-06-04 11:43:41 +0900] [76410] [INFO] Application startup complete.
Redis 연결 성공
[2025-06-04 11:43:41 +0900] [76411] [INFO] Application startup complete.
2025-06-04 11:43:54.377 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:43:54.377 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:43:54.378 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
2025-06-04 11:43:54.378 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:43:54.379
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:43:54.380
2025-06-04 11:43:54.380 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:43:54.381 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:43:54.382
2025-06-04 11:43:54.382 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:43:54.382 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:43:54.383 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
2025-06-04 11:43:54.383 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:43:54.384
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:43:54.384
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:43:57.115
[INFO] GPU 요청-응답 소요 시간: 2.74 s
[CHECK] GPU 응답 첫 번째 이미지 파일명: img481.jpg
-----[Redis Set Start]-----
[Redis SET] key='img481.jpg' succeeded, took 0.0020 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img482.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:43:57.124
[INFO] GPU 요청-응답 소요 시간: 2.74 s
[CHECK] GPU 응답 첫 번째 이미지 파일명: img001.jpg
-----[Redis Set Start]-----
[Redis SET] key='img483.jpg' succeeded, took 0.0060 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img001.jpg' succeeded, took 0.0024 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img484.jpg' succeeded, took 0.0025 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img002.jpg' succeeded, took 0.0013 seconds, TTL=300
-----[Redis Set Start]-----
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:43:57.132
[INFO] GPU 요청-응답 소요 시간: 2.75 s
[Redis SET] key='img485.jpg' succeeded, took 0.0015 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img003.jpg' succeeded, took 0.0016 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img486.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img004.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img487.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img005.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img488.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[CHECK] GPU 응답 첫 번째 이미지 파일명: img121.jpg
-----[Redis Set Start]-----
[Redis SET] key='img006.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img489.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img121.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img007.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img122.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img490.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img008.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img123.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img491.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img124.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img009.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img125.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img492.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img010.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img126.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img493.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img011.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img127.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img494.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img128.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img012.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img495.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img129.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img013.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img130.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img496.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img014.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img131.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img497.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img132.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img015.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img498.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img133.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img016.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img499.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img134.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img017.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img135.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img500.jpg' succeeded, took 0.0008 seconds, TTL=300
[Redis SET] key='img136.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:43:57.147 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
[Redis SET] key='img137.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
2025-06-04 11:43:57.147 | INFO     | fastapi.routing:app:301 - embed 함수 성공
[Redis SET] key='img018.jpg' succeeded, took 0.0019 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img138.jpg' succeeded, took 0.0012 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img019.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img139.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img020.jpg' succeeded, took 0.0006 seconds, TTL=300
[Redis SET] key='img140.jpg' succeeded, took 0.0008 seconds, TTL=300
2025-06-04 11:43:57.150 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:43:57.150 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-06-04 11:43:57.151 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:43:57.151 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-06-04 11:43:57.152 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:43:57.153 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
2025-06-04 11:43:57.153 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:43:57.154 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
2025-06-04 11:43:57.157 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:43:57.160 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis BULK GET] 20 keys took 0.0112 seconds
categorize_controller 임베딩 로드 후
[]
[Redis BULK GET] 20 keys took 0.0144 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:43:57.173 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
2025-06-04 11:43:57.173 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
[Redis BULK GET] 20 keys took 0.0202 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:43:57.181 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
2025-06-04 11:43:57.194 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:43:57.195 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:43:57.195 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
2025-06-04 11:43:57.195 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:43:57.197 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:43:57.197 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
2025-06-04 11:43:57.199 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:43:57.199 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:43:57.201 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:43:57.557
[INFO] GPU 요청-응답 소요 시간: 3.18 s
[CHECK] GPU 응답 첫 번째 이미지 파일명: img361.jpg
-----[Redis Set Start]-----
[Redis SET] key='img361.jpg' succeeded, took 0.0013 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img362.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img363.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img364.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img365.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img366.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img367.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img368.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img369.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img370.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img371.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img372.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img373.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img374.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img375.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img376.jpg' succeeded, took 0.0010 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img377.jpg' succeeded, took 0.0009 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img378.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img379.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img380.jpg' succeeded, took 0.0006 seconds, TTL=300
2025-06-04 11:43:57.577 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:43:57.577 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-06-04 11:43:57.579 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:43:57.580 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis BULK GET] 20 keys took 0.0104 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:43:57.592 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
2025-06-04 11:43:57.595 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:43:57.595 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:43:57.596 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
[INFO] GPU 서버 응답 수신 시각: 2025-06-04 11:43:57.676
[INFO] GPU 요청-응답 소요 시간: 3.29 s
[CHECK] GPU 응답 첫 번째 이미지 파일명: img241.jpg
-----[Redis Set Start]-----
[Redis SET] key='img241.jpg' succeeded, took 0.0008 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img242.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img243.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img244.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img245.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img246.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img247.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img248.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img249.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img250.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img251.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img252.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img253.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img254.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img255.jpg' succeeded, took 0.0006 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img256.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img257.jpg' succeeded, took 0.0005 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img258.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img259.jpg' succeeded, took 0.0007 seconds, TTL=300
-----[Redis Set Start]-----
[Redis SET] key='img260.jpg' succeeded, took 0.0006 seconds, TTL=300
2025-06-04 11:43:57.691 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 성공
2025-06-04 11:43:57.691 | INFO     | fastapi.routing:app:301 - embed 함수 성공
2025-06-04 11:43:57.693 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:43:57.694 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis BULK GET] 20 keys took 0.0064 seconds
categorize_controller 임베딩 로드 후
[]
2025-06-04 11:43:57.701 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 시작
2025-06-04 11:43:57.703 | INFO     | concurrent.futures.thread:_worker:83 - categorize_images 함수 성공
2025-06-04 11:43:57.704 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 성공
2025-06-04 11:43:57.704 | INFO     | fastapi.routing:app:301 - categorize 함수 성공
2025-06-04 11:44:00.209 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:44:00.209 | INFO     | fastapi.routing:app:301 - embed 함수 시작
2025-06-04 11:44:00.210 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
2025-06-04 11:44:00.210 | INFO     | app.utils.logging_decorator:async_wrapper:61 - embed_controller 함수 시작
[INFO] GPU 서버 전송 시작 시각: 2025-06-04 11:44:00.212
2025-06-04 11:44:00.211 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
[Redis GET] key='img501.jpg' not found
[Redis GET] key='img504.jpg' not found
[Redis GET] key='img503.jpg' not found
[Redis GET] key='img502.jpg' not found
[Redis GET] key='img505.jpg' not found
2025-06-04 11:44:00.213 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis GET] key='img021.jpg' not found
[Redis GET] key='img023.jpg' not found
[Redis GET] key='img022.jpg' not found
[Redis GET] key='img024.jpg' not found
[Redis GET] key='img025.jpg' not found
[Redis GET] key='img506.jpg' not found
[Redis GET] key='img507.jpg' not found
[Redis GET] key='img508.jpg' not found
[Redis GET] key='img509.jpg' not found
[Redis GET] key='img510.jpg' not found
[Redis GET] key='img511.jpg' not found
[Redis GET] key='img512.jpg' not found
[Redis GET] key='img513.jpg' not found
[Redis GET] key='img514.jpg' not found
[Redis GET] key='img515.jpg' not found
[Redis GET] key='img516.jpg' not found
[Redis GET] key='img517.jpg' not found
[Redis GET] key='img518.jpg' not found
[Redis GET] key='img519.jpg' not found
[Redis GET] key='img026.jpg' not found
[Redis GET] key='img520.jpg' not found
[Redis GET] key='img027.jpg' not found
[Redis BULK GET] 20 keys took 0.0090 seconds
categorize_controller 임베딩 로드 후
['img501.jpg', 'img502.jpg', 'img503.jpg', 'img504.jpg', 'img505.jpg', 'img506.jpg', 'img507.jpg', 'img508.jpg', 'img509.jpg', 'img510.jpg', 'img511.jpg', 'img512.jpg', 'img513.jpg', 'img514.jpg', 'img515.jpg', 'img516.jpg', 'img517.jpg', 'img518.jpg', 'img519.jpg', 'img520.jpg']
일부 이미지의 임베딩이 없음
[Redis GET] key='img028.jpg' not found
[Redis GET] key='img029.jpg' not found
[Redis GET] key='img030.jpg' not found
[Redis GET] key='img031.jpg' not found
[Redis GET] key='img032.jpg' not found
[Redis GET] key='img033.jpg' not found
[Redis GET] key='img034.jpg' not found
[Redis GET] key='img035.jpg' not found
2025-06-04 11:44:00.221 | ERROR    | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img501.jpg', 'img502.jpg', 'img503.jpg', 'img504.jpg', 'img505.jpg', 'img506.jpg', 'img507.jpg', 'img508.jpg', 'img509.jpg', 'img510.jpg', 'img511.jpg', 'img512.jpg', 'img513.jpg', 'img514.jpg', 'img515.jpg', 'img516.jpg', 'img517.jpg', 'img518.jpg', 'img519.jpg', 'img520.jpg']}
[Redis GET] key='img036.jpg' not found
[Redis GET] key='img037.jpg' not found
[Redis GET] key='img038.jpg' not found
[Redis GET] key='img039.jpg' not found
[Redis GET] key='img040.jpg' not found
[Redis BULK GET] 20 keys took 0.0100 seconds
categorize_controller 임베딩 로드 후
2025-06-04 11:44:00.223 | ERROR    | fastapi.routing:app:301 - categorize 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img501.jpg', 'img502.jpg', 'img503.jpg', 'img504.jpg', 'img505.jpg', 'img506.jpg', 'img507.jpg', 'img508.jpg', 'img509.jpg', 'img510.jpg', 'img511.jpg', 'img512.jpg', 'img513.jpg', 'img514.jpg', 'img515.jpg', 'img516.jpg', 'img517.jpg', 'img518.jpg', 'img519.jpg', 'img520.jpg']}
['img021.jpg', 'img022.jpg', 'img023.jpg', 'img024.jpg', 'img025.jpg', 'img026.jpg', 'img027.jpg', 'img028.jpg', 'img029.jpg', 'img030.jpg', 'img031.jpg', 'img032.jpg', 'img033.jpg', 'img034.jpg', 'img035.jpg', 'img036.jpg', 'img037.jpg', 'img038.jpg', 'img039.jpg', 'img040.jpg']
일부 이미지의 임베딩이 없음
2025-06-04 11:44:00.224 | ERROR    | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img021.jpg', 'img022.jpg', 'img023.jpg', 'img024.jpg', 'img025.jpg', 'img026.jpg', 'img027.jpg', 'img028.jpg', 'img029.jpg', 'img030.jpg', 'img031.jpg', 'img032.jpg', 'img033.jpg', 'img034.jpg', 'img035.jpg', 'img036.jpg', 'img037.jpg', 'img038.jpg', 'img039.jpg', 'img040.jpg']}
2025-06-04 11:44:00.225 | ERROR    | fastapi.routing:app:301 - categorize 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img021.jpg', 'img022.jpg', 'img023.jpg', 'img024.jpg', 'img025.jpg', 'img026.jpg', 'img027.jpg', 'img028.jpg', 'img029.jpg', 'img030.jpg', 'img031.jpg', 'img032.jpg', 'img033.jpg', 'img034.jpg', 'img035.jpg', 'img036.jpg', 'img037.jpg', 'img038.jpg', 'img039.jpg', 'img040.jpg']}
2025-06-04 11:44:00.601 | INFO     | fastapi.routing:app:301 - categorize 함수 시작
2025-06-04 11:44:00.602 | INFO     | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 시작
categorize_controller 임베딩 로드 전
[Redis GET] key='img381.jpg' not found
[Redis GET] key='img382.jpg' not found
[Redis GET] key='img383.jpg' not found
[Redis GET] key='img384.jpg' not found
[Redis GET] key='img385.jpg' not found
[Redis GET] key='img386.jpg' not found
[Redis GET] key='img387.jpg' not found
[Redis GET] key='img388.jpg' not found
[Redis GET] key='img389.jpg' not found
[Redis GET] key='img390.jpg' not found
[Redis GET] key='img391.jpg' not found
[Redis GET] key='img392.jpg' not found
[Redis GET] key='img393.jpg' not found
[Redis GET] key='img394.jpg' not found
[Redis GET] key='img395.jpg' not found
[Redis GET] key='img396.jpg' not found
[Redis GET] key='img397.jpg' not found
[Redis GET] key='img398.jpg' not found
[Redis GET] key='img399.jpg' not found
[Redis GET] key='img400.jpg' not found
[Redis BULK GET] 20 keys took 0.0042 seconds
categorize_controller 임베딩 로드 후
['img381.jpg', 'img382.jpg', 'img383.jpg', 'img384.jpg', 'img385.jpg', 'img386.jpg', 'img387.jpg', 'img388.jpg', 'img389.jpg', 'img390.jpg', 'img391.jpg', 'img392.jpg', 'img393.jpg', 'img394.jpg', 'img395.jpg', 'img396.jpg', 'img397.jpg', 'img398.jpg', 'img399.jpg', 'img400.jpg']
일부 이미지의 임베딩이 없음
2025-06-04 11:44:00.606 | ERROR    | app.utils.logging_decorator:async_wrapper:61 - categorize_controller 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img381.jpg', 'img382.jpg', 'img383.jpg', 'img384.jpg', 'img385.jpg', 'img386.jpg', 'img387.jpg', 'img388.jpg', 'img389.jpg', 'img390.jpg', 'img391.jpg', 'img392.jpg', 'img393.jpg', 'img394.jpg', 'img395.jpg', 'img396.jpg', 'img397.jpg', 'img398.jpg', 'img399.jpg', 'img400.jpg']}
2025-06-04 11:44:00.607 | ERROR    | fastapi.routing:app:301 - categorize 함수 예외 발생: 428: {'message': 'embedding_required', 'data': ['img381.jpg', 'img382.jpg', 'img383.jpg', 'img384.jpg', 'img385.jpg', 'img386.jpg', 'img387.jpg', 'img388.jpg', 'img389.jpg', 'img390.jpg', 'img391.jpg', 'img392.jpg', 'img393.jpg', 'img394.jpg', 'img395.jpg', 'img396.jpg', 'img397.jpg', 'img398.jpg', 'img399.jpg', 'img400.jpg']}

로그 분석 결과 gpu 서버로 요청이 가고 있지 않음
왜 gpu 요청을 안 보낸 이미지로 카테고리 요청이 갔는가.

g. 가설 및 결론: k6에서 요청을 보내지 않았을 것이다. - 참

가. 기존 k6 script

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

export const options = {
    vus: 5,         // 동시에 5명
    iterations: 30, // 총 30회 (각 VU당 6회씩)
};

const embeddingUrl = 'http://0.0.0.0:8000/api/albums/embedding';
const categoriesUrl = 'http://0.0.0.0:8000/api/albums/categories';

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

export default function () {
    // VU 번호 (1~5), ITER 번호 (0~5)
    const vu = __VU;
    const iter = __ITER;

    // 1~600 중 고유한 20장씩 계산
    const groupIndex = (vu - 1) * 6 + iter; // 0~29
    const start = groupIndex * 20 + 1;
    const end = start + 19;

    const images = [];
    for (let i = start; i <= end; i++) {
        images.push(`img${String(i).padStart(3, '0')}.jpg`);
    }

    const payload = JSON.stringify({ images });

    // 1. 임베딩 요청
    http.post(embeddingUrl, payload, params);

    // 2. 카테고리 요청
    http.post(categoriesUrl, payload, params);

    sleep(3);
}
import http from 'k6/http';
import { sleep } from 'k6';

export const options = {
    vus: 5,         // 동시에 5명
    iterations: 30, // 총 30회 (각 VU당 6회씩)
};

문제점
- 임베딩 요청의 성공 여부에 상관 없이 카테고리 요청을 보냄
- 임베딩 요청 실패 시, 서버에 임베딩 캐싱되지 않았기에 캐시 미스 발생

나. 개선 k6 script

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

export const options = {
    vus: 5,         // 동시에 5명
    iterations: 30, // 총 30회 (각 VU당 6회씩)
};

const embeddingUrl = 'http://0.0.0.0:8000/api/albums/embedding';
const categoriesUrl = 'http://0.0.0.0:8000/api/albums/categories';

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

export default function () {
    const vu = __VU;
    const iter = __ITER;

    const groupIndex = (vu - 1) * 6 + iter;
    const start = groupIndex * 20 + 1;
    const end = start + 19;

    const images = [];
    for (let i = start; i <= end; i++) {
        images.push(`img${String(i).padStart(3, '0')}.jpg`);
    }

    const payload = JSON.stringify({ images });

    // 1. 임베딩 요청 (응답 대기)
    const embedRes = http.post(embeddingUrl, payload, params);

    // ✅ 응답이 201(success)일 때만 카테고리 요청 전송
    if (embedRes.status === 201) {
        // 2. 카테고리 요청
        http.post(categoriesUrl, payload, params);
    } else {
        console.warn(`[WARN] 임베딩 실패 - status: ${embedRes.status}`);
    }

    sleep(3);
}

개선 사항
- 임베딩 요청 성공 시, 카테고리 요청 보내도록 수정
결론
- 수정 후 더이상 캐시 미스는 발생하지 않음
- set 요청이 되지 않았던 것은 레디스 문제가 아닌 k6 스크립트 작성 문제였음
- 어떠한 이유로 임베딩 요청 실패 발생 → 이후 카테고리 요청 시, 캐시 미스

h. 에러 메시지 분석 → 어플리케이션 레벨 문제가 아니다.

가. connection reset by peer

서버에서 이미 수립된 TCP 연결을 강제로 닫았을 때 클라이언트가 받는 에러

나. 에러 상황 분석 (클라이언트 상황)

연결은 정상적으로 수립됨 (3-way handshake 완료)
요청을 보내는 도중 또는 응답을 받기 전에
서버 쪽에서 해당 TCP 커넥션을 RST 패킷으로 종료함

(예: FastAPI가 예외 발생 or 커넥션을 강제 종료)

i. 연결이 죽은 이유 식별

가. 가설: gunicorn 설정에서 연결 시간과 관련된 옵션을 잘못 설정했을 것이다. - 참

timeout: 마스터 프로세스가 워커 프로세스의 응답을 얼마동안 기다려주는지
설정값: timeout 0으로 워커 프로세스에 시간 제한 두지 않고 기다림
관련 개념

🔧 `timeout`

t INT, -timeout INT

기본값: 30

워커가 설정된 시간(초) 동안 응답이 없으면, 해당 워커는 강제 종료되고 재시작

값은 양의 정수 또는 0

0으로 설정하면 모든 워커에 대한 타임아웃이 비활성화되어, 사실상 무제한 타임아웃이 적용

일반적으로 기본값인 30초면 충분

동기(synchronous) 워커를 사용할 경우, 이 값을 눈에 띄게 높여야 할 상황이라면 그에 따른 영향을 충분히 이해하고 있는 경우에만 설정

**비동기 워커(asynchronous worker)**를 사용하는 경우, 이 설정은 단지 워커 프로세스가 여전히 통신 중인지를 판별하는 용도로 사용되며, 요청 처리에 걸리는 시간과는 직접적인 관련이 없음
keepalive: 서버가 연결을 끊지 않고 다음 요청이 올때까지 얼마나 기다리는가
설정값: keepalive 3초로 다음 요청이 오기까지 연결을 3초동안 유휴 상태에서 유지 가능

j. 현재 k6 script는 연결을 재활용한다.

k6는 HTTP 커넥션을 재사용할까?

기본적으로 재사용

k6의 http 모듈은 HTTP/1.1 keep-alive를 기본으로 활성화
따라서 동일한 VU(가상 유저) 내에서는:
- 같은 host (0.0.0.0:8000)
- 같은 params (헤더 등)
- 커넥션이 keepalive 타임아웃 안에 유지되고 있다면
  
  → 커넥션을 재사용하여 새로운 요청을 보냄.

✅ k6는 연결이 끊기면 자동으로 새 TCP 커넥션을 생성하여 재연결

❌ 기존 커넥션이 끊겼다고 해서 요청 자체를 실패시키지는 않음

상세 설명

k6의 http.post(...)나 http.get(...) 등 요청 함수는

HTTP 커넥션이 끊겨도 내부적으로 다음과 같이 처리:

기존 커넥션이 닫혀 있으면 (예: 서버가 keepalive 타임아웃 후 종료)
자동으로 새 커넥션을 생성하여 요청을 다시 보냄
클라이언트(k6)는 이 과정에서 특별한 에러를 내지 않음
→ 성공적으로 요청이 전달되고 응답도 정상 처리

k. 가설: keepalive 시간과 재요청 시간이 정확히 일치해 연결 종료로 요청 실패 발생했을 것이다. - 참

가. k6 스크립트 요청 간 간격 3초, keepalive 설정 3초

서버는 연결 유휴 상태로 3초가 지나면 rst 패킷을 보내 연결을 종료
k6 script에서 정확히 3초 sleep 후, 다음 iteration 진행
이로 인해 연결 종료와 재요청이 겹침
이미 연결 종료된 상태라면 이를 감지하고 재연결 가능하나, 연결 지속으로 인지하고 요청 보내는 타이밍에 rst 패킷으로 강제 종료하여 요청이 실패함

나. keepalive 시간 10초로 임시 수정

문제 해결됨.

다. k6 연결 유지 관련 옵션

🔧 `noConnectionReuse`

true로 설정하면 HTTP keep-alive 기능이 비활성화됨
즉, 모든 HTTP 요청마다 새로운 TCP 연결을 생성
이 설정은 커넥션을 재사용하지 않는 클라이언트를 시뮬레이션하거나, 매 요청마다 새로운 DNS 조회를 유도하고 싶을 때 유용

export const options = {
  noConnectionReuse: true,
};

또는 CLI로 설정:

k6 run --no-connection-reuse script.js

🔧 `noVUConnectionReuse`

true로 설정하면 각 Virtual User(VU) 의 한 iteration이 끝날 때마다 커넥션을 끊음
즉, 같은 VU라도 iteration이 바뀌면 새로운 연결을 사용하지만,
iteration 내부에서는 여전히 커넥션이 재사용될 수 있음

export const options = {
  noVUConnectionReuse: true,
};

🌐 DNS 관련 옵션

k6는 새로운 HTTP 연결이 생성될 때만 DNS 조회를 수행
더 자주 DNS 조회를 수행하고 싶다면 noConnectionReuse와 함께 다음 설정을 사용:

export const options = {
  noConnectionReuse: true,
  dns: {
    ttl: '0',        // DNS 캐싱 비활성화
    select: 'random', // IP 주소 중 무작위 선택
    policy: 'any',
  },
};

✅ 기본 동작

기본값은 둘 다 false
즉, 기본적으로 k6는 최대한 커넥션을 재사용하여 성능을 최적화

글 draft (1)

3. 결론

이번 문제의 원인은 크게 아래 2가지
- keepalive와 재요청 시간이 우연히 겹침
  - 서버가 연결을 강제 해제하여 요청 실패
- 임베딩이 위 이유로 실패했는데 후속 요청이 임베딩 성공 여부 확인하지 않고 진행됨
  - 임베딩 실패했었기에 캐시 미스 발생
느낀점
- 캐시 미스라는 단편적인 로그로 레디스 문제일거라 추측했지만 실제 원인은 완전히 다른 곳에 있어서 흥미로웠음.
- connection reset by peer 에러를 트러블 슈팅 초기부터 보았으니 에러 로그 의미에 깊이 생각하지 않아 문제 해결이 늦어짐.
  - 추후에는 에러 로그를 꼼꼼히 이해하기

[트러블 슈팅] 레디스 일부 요청 임베딩 캐싱 실패 원인 파악 - 100-hours-a-week/5-yeosa-wiki GitHub Wiki

1. 트러블

a. 요약

b. 에러 상황

가. connection reset by peer

나. EOF

2. 해결 과정

a. 가설: Redis 에러가 발생했을 것이다

b. Redis 응답 확인

가. 공식 문서

SET

Options

Examples

Code examples

Patterns

RESP2 Reply

RESP3 Reply

History

나. Redis python client

c. 가설 및 결론: 캐시 미스는 레디스 비동기 write 중 조회가 일어났기 때문일 것이다. - 거짓

가. 추정한 원인

나. 검증

다. 결론

d. 결론: Redis 문제가 아니다

e. 가설 및 결론: 해당 사진 누락됐거나 이전 작업이 실패해서 set 요청 자체가 안 갔을 것이다.(레디스 이전의 문제일 것이다) - 참

f. 가설 및 결론: GPU 로직 문제로 set 요청이 가지 않았을 것이다. - 거짓

g. 가설 및 결론: k6에서 요청을 보내지 않았을 것이다. - 참

가. 기존 k6 script

나. 개선 k6 script

h. 에러 메시지 분석 → 어플리케이션 레벨 문제가 아니다.

가. connection reset by peer

나. 에러 상황 분석 (클라이언트 상황)

i. 연결이 죽은 이유 식별

가. 가설: gunicorn 설정에서 연결 시간과 관련된 옵션을 잘못 설정했을 것이다. - 참

🔧 timeout

j. 현재 k6 script는 연결을 재활용한다.

k6는 HTTP 커넥션을 재사용할까?

기본적으로 재사용

상세 설명

k. 가설: keepalive 시간과 재요청 시간이 정확히 일치해 연결 종료로 요청 실패 발생했을 것이다. - 참

가. k6 스크립트 요청 간 간격 3초, keepalive 설정 3초

나. keepalive 시간 10초로 임시 수정

다. k6 연결 유지 관련 옵션

🔧 noConnectionReuse

🔧 noVUConnectionReuse

🌐 DNS 관련 옵션

✅ 기본 동작

3. 결론

가. `connection reset by peer`

나. `EOF`

🔧 `timeout`

🔧 `noConnectionReuse`

🔧 `noVUConnectionReuse`