--- task_id: task-3018 scope: task doc_type: baseline-measurement author: 헤임달 (Heimdall) / 개발2팀 QA date: 2026-08-25 target: whisper-gpu.service (수정 전 구동 프로세스, PID 4102039) --- # task-3018 수정 전 기준선(baseline) 재현 측정 ## S (상황) `whisper-gpu.service` 는 `/home/jay/workspace/services/whisper-gpu/server.py` 의 **수정 전 코드**를 메모리에 들고 2026-08-25 20:49:13 KST 부터 계속 구동 중이었다. 토르가 같은 파일을 수정 중이나 서비스는 재시작되지 않았으므로, 본 측정은 **수정 전 동작**을 관측한 것이다. 측정 시각: 2026-08-25 23:03 ~ 23:08 KST 서비스 무결성: 측정 전후 `MainPID=4101977`, `ActiveEnterTimestamp=Tue 2026-08-25 20:49:13 KST` **불변** (재시작 없음). `insuwiki-youtube-pipeline.timer` = `inactive` 유지. ## C (복잡성) — 검증 대상 가설 **H1 — 전사 중 서버 이벤트 루프가 완전히 블로킹된다.** 근거 코드 (`server.py:378-407`, 읽기 전용 확인): ```python async with _gpu_lock: # :390 logger.info("전사 시작: ...") # :391 model = get_model_instance(model_name) # :392 ← 동기 호출, executor 밖 segments_raw, info = await loop.run_in_executor( # :393 제너레이터만 즉시 반환(lazy) None, lambda: model.transcribe(...)) segments = [ # :400-407 ← 실제 GPU 연산이 여기서 소비됨 {...} for seg in segments_raw # 이벤트 루프 스레드 ] ``` `/v1/health` (`server.py:520-521`) 은 순수 async 코루틴이므로 이벤트 루프가 막히면 응답 불가 → 블로킹 여부의 직접 프로브로 유효하다. ## Q (질문) → A (실측 답) ### 1. 유휴 시 `/v1/health` 응답 시간 (실제 출력) ``` 2026-08-25T23:03:12+09:00 health_1 time_total=0.018685 http=200 health_2 time_total=0.018389 http=200 health_3 time_total=0.018744 http=200 ``` 측정 종료 후 재확인 (23:08:22 경): ``` 0.018455 0.020531 0.020061 ``` **유휴 기준선 = 약 18~21 ms.** ### 2. 전사 중 `/v1/health` 폴링 결과 (1초 간격, `-m 3`) #### RUN 1 — 콜드 스타트(모델 미로딩) 상태, 영상 `v6oVfFko04A` (오디오 89.9초) `/tmp/t3018/poll.log` 원문: ``` 001 2026-08-25T23:03:51+09:00 OK 200 0.022040 002 2026-08-25T23:03:52+09:00 OK 200 0.020054 003 2026-08-25T23:03:53+09:00 OK 200 0.024127 004 2026-08-25T23:03:54+09:00 FAIL curl_exit=28 (000 3.001985) 005 2026-08-25T23:03:58+09:00 FAIL curl_exit=28 (000 3.002630) 006 2026-08-25T23:04:02+09:00 OK 200 0.784785 007 2026-08-25T23:04:04+09:00 FAIL curl_exit=28 (000 3.002174) 008 2026-08-25T23:04:08+09:00 FAIL curl_exit=28 (000 3.002383) 009 2026-08-25T23:04:12+09:00 FAIL curl_exit=28 (000 3.002150) 010 2026-08-25T23:04:16+09:00 FAIL curl_exit=28 (000 3.002370) 011 2026-08-25T23:04:20+09:00 FAIL curl_exit=28 (000 3.002810) 012 2026-08-25T23:04:24+09:00 FAIL curl_exit=28 (000 3.002039) 013 2026-08-25T23:04:28+09:00 OK 200 1.937484 014 2026-08-25T23:04:31+09:00 OK 200 0.018769 015 2026-08-25T23:04:32+09:00 OK 200 0.052286 016 2026-08-25T23:04:33+09:00 OK 200 0.018151 017 2026-08-25T23:04:34+09:00 OK 200 0.018882 018 2026-08-25T23:04:35+09:00 OK 200 0.019475 019 2026-08-25T23:04:36+09:00 OK 200 0.018826 020 2026-08-25T23:04:37+09:00 OK 200 0.018775 021 2026-08-25T23:04:38+09:00 OK 200 0.019581 022 2026-08-25T23:04:39+09:00 OK 200 0.019066 023 2026-08-25T23:04:40+09:00 OK 200 0.020502 024 2026-08-25T23:04:41+09:00 FAIL curl_exit=28 (000 3.002725) 025 2026-08-25T23:04:45+09:00 FAIL curl_exit=28 (000 3.002340) 026 2026-08-25T23:04:49+09:00 FAIL curl_exit=28 (000 3.001313) 027 2026-08-25T23:04:53+09:00 FAIL curl_exit=28 (000 3.002288) 028 2026-08-25T23:04:57+09:00 FAIL curl_exit=28 (000 3.002368) 029 2026-08-25T23:05:01+09:00 OK 200 2.194734 030 2026-08-25T23:05:05+09:00 OK 200 0.018645 031 2026-08-25T23:05:06+09:00 OK 200 0.018574 032 2026-08-25T23:05:07+09:00 OK 200 0.018770 033 2026-08-25T23:05:08+09:00 OK 200 0.023778 034 2026-08-25T23:05:09+09:00 OK 200 0.018413 ``` `curl_exit=28` = 3초 타임아웃 도달(무응답). RUN 1 요청 결과: ``` REQ_A_SENT_AT=2026-08-25T23:03:51+09:00 REQ_A_DONE_AT=2026-08-25T23:04:30+09:00 wall=38.826336816 curl=200 38.818556 REQ_B_SENT_AT=2026-08-25T23:04:37+09:00 REQ_B_DONE_AT=2026-08-25T23:05:03+09:00 wall=26.256793636 curl=200 26.249975 ``` #### RUN 1 서버 로그와의 위상 대조 (journalctl 발췌) > 인용 규칙: 아래 로그 블록들은 `journalctl --user -u whisper-gpu.service --no-pager -o short-iso` 출력에서 > (1) 공통 접두사 `aidevserver start-whisper-gpu.sh[4102039]:` 와 (2) `GET /v1/health` 접근로그 줄을 제거한 **발췌**다. > 타임스탬프·메시지 본문은 무가공이며, 인용된 11개 타임스탬프 전부를 원본 저널에 대해 grep 존재검증 완료했다. ``` 2026-08-25 23:03:51,501 [INFO] whisper-gpu: yt-dlp 다운로드 시작: video_id=v6oVfFko04A 2026-08-25 23:03:54,098 [INFO] whisper-gpu: yt-dlp 다운로드 완료: video_id=v6oVfFko04A 2026-08-25 23:03:54,120 [INFO] whisper-gpu: 전사 시작: model=large-v3 language=ko file=/tmp/whisper_yt_v6oVfFko04A.webm 2026-08-25 23:03:56,336 [INFO] whisper-gpu: WhisperModel 로딩: size=large-v3 device=cuda compute_type=int8 2026-08-25 23:04:03,360 [INFO] whisper-gpu: WhisperModel 로딩 완료: size=large-v3 2026-08-25 23:04:03,768 [INFO] faster_whisper: Processing audio with duration 01:29.877 2026-08-25 23:04:30,279 [INFO] whisper-gpu: 전사 완료: language=ko duration=89.9s segments=27 ``` | 구간 | 서버 로그 시각 | health 폴링 | 판정 | |---|---|---|---| | yt-dlp 다운로드 (async subprocess) | 23:03:51.501 → 23:03:54.098 | 001~003 **전부 OK ~20ms** | **블로킹 없음** | | 전사 시작 직후 | 23:03:54.120 | 004 (23:03:54) **즉시 타임아웃** | 블로킹 개시 | | 모델 로딩 중 | 23:03:56.336 → 23:04:03.360 | 006 (23:04:02) OK **0.785s** (유휴의 42배) | **부분 블로킹** (모델 파일 I/O 중 GIL 일시 해제로 추정) | | GPU 디코드 (`segments` 소비) | 23:04:03.768 → 23:04:30.279 | 007~012 **6연속 전부 타임아웃** | **완전 블로킹** | | 전사 완료 순간 | 23:04:30.279 | 013 (23:04:28 발사) → **1.937s 후 응답 = 23:04:30.2** | 블로킹 해제 시점과 일치 | ★ 폴링 013 은 23:04:28 에 발사되어 **1.937초 뒤**에야 응답을 받았는데, 그 착지 시각(≈23:04:30.22)이 서버의 `전사 완료` 로그(23:04:30.279)와 일치한다. **전사가 끝나는 그 순간에야 health 가 처리되었다**는 직접 증거다. 두 번째 전사(RUN 1 의 B, `Rve8rNM_J30`)에서도 동일 패턴이 재현되었다: `전사 시작 23:04:40.437` → 폴링 024~028 전부 타임아웃 → `전사 완료 23:05:03.923`, 폴링 029(23:05:01 발사)가 2.195초 뒤 착지(≈23:05:03.2). ### 3. 두 번째 요청의 접수 시점 (원인 A·C 직접 증거) #### 시도 1 (RUN 2, 23:05:51~) — 부분 관측 B 요청이 A 의 **다운로드 구간**에 도달한 케이스. 로그 원문: ``` 2026-08-25 23:05:51,721 yt-dlp 다운로드 시작: video_id=v6oVfFko04A ← A 2026-08-25 23:05:53,773 yt-dlp 다운로드 시작: video_id=Rve8rNM_J30 ← B (B_SENT=23:05:53.736, +37ms 즉시 접수) 2026-08-25 23:05:55,149 전사 시작: model=large-v3 ... v6oVfFko04A ← A 전사 개시(블로킹 시작) 2026-08-25 23:06:22,082 전사 완료: language=ko duration=89.9s segments=27 ← A 완료 2026-08-25 23:06:22,122 yt-dlp 다운로드 완료: video_id=Rve8rNM_J30 ← B 다운로드 "완료" 콜백이 여기서야 처리됨 ``` B 의 yt-dlp 다운로드는 실측상 약 2.4초면 끝난다(23:07:50.755→23:07:53.116). 그런데 B 의 `다운로드 완료` 로그는 **28.3초 뒤**, A 의 `전사 완료` **40ms 후**에 찍혔다. = 서브프로세스는 이미 끝났는데 **await 재개(콜백 처리)가 이벤트 루프 블로킹으로 27초간 지연**된 것. #### 시도 2 (RUN 3, 23:07:20~) — 결정적 관측 B 요청을 **A 의 전사 시작 이후**에 발사하도록 저널 커서를 잡아 재실행. 클라이언트 로그: ``` CURSOR=2026-08-25 23:07:20 A_SENT=2026-08-25T23:07:21.431 A_TRANSCRIBE_START_SEEN=2026-08-25T23:07:23.897 B_SENT=2026-08-25T23:07:27.900 ← A 전사 시작(23:07:23.793) + 4.107초 = 전사 한복판 A_http=200 A_time=29.318749 A_DONE=2026-08-25T23:07:50.757 B_http=200 B_time=48.910377 B_DONE=2026-08-25T23:08:16.817 ``` 서버 로그 원문: ``` 2026-08-25 23:07:21,437 yt-dlp 다운로드 시작: video_id=v6oVfFko04A 2026-08-25 23:07:23,775 yt-dlp 다운로드 완료: video_id=v6oVfFko04A 2026-08-25 23:07:23,793 전사 시작: model=large-v3 language=ko file=/tmp/whisper_yt_v6oVfFko04A.webm 2026-08-25 23:07:24,203 [INFO] faster_whisper: Processing audio with duration 01:29.877 2026-08-25 23:07:50,753 전사 완료: language=ko duration=89.9s segments=27 2026-08-25 23:07:50,755 yt-dlp 다운로드 시작: video_id=Rve8rNM_J30 ← B, 전사 완료 +2ms 2026-08-25 23:07:53,116 yt-dlp 다운로드 완료: video_id=Rve8rNM_J30 2026-08-25 23:07:53,136 전사 시작: model=large-v3 language=ko file=/tmp/whisper_yt_Rve8rNM_J30.webm 2026-08-25 23:08:16,815 전사 완료: language=ko duration=75.2s segments=7 ``` | 항목 | 실측 시각 | |---|---| | B 요청 클라이언트 발사 | 23:07:27.900 | | A 전사 완료 | 23:07:50.753 | | **B 의 yt-dlp 다운로드 시작 로그** | **23:07:50.755** | | B 발사 → B 다운로드 시작 지연 | **22.855초** | | A 전사 완료 → B 다운로드 시작 지연 | **0.002초** | **판별 결과 = (b).** 두 번째 요청은 첫 전사가 **완료된 뒤에야** 처리 시작되었다. B 의 `yt-dlp 다운로드 시작` 은 핸들러 진입 직후, `_gpu_lock` 획득 **이전**의 코드 (`server.py:689`, 락은 `:390`)이다. 따라서 이 지연은 GPU 락에 의한 정상 직렬화가 **아니라**, 요청이 **라우팅조차 되지 못한** 이벤트 루프 블로킹이다. 부수 효과: B 의 클라이언트 체감 시간 48.910초 중 **약 23.5초가 순수 대기**(B 자신의 실작업은 23:07:50.755~23:08:16.815 = 26.06초). ## H1 판정: **참 (TRUE)** 근거 3종 (모두 실측): 1. 전사 구간(`Processing audio` → `전사 완료`) 동안 `/v1/health` 가 **3초 타임아웃으로 100% 무응답**. RUN1-A 6연속, RUN1-B 5연속, RUN3 5연속. 유휴 시 18ms 인 동일 엔드포인트가 응답 불가. 2. 블로킹 해제 시점이 `전사 완료` 로그와 **밀리초 단위로 일치**(폴링 013: 23:04:28 발사 → 1.937s 후 착지 ≈ 전사 완료 23:04:30.279). 3. 전사 중 도착한 두 번째 요청의 **첫 핸들러 로그가 22.855초 지연**되어 A 전사 완료 **2ms 후**에 찍힘. 락 획득 이전 코드이므로 GPU 락 직렬화로는 설명되지 않음. 동시에 **블로킹 구간의 경계도 특정**되었다: - yt-dlp 다운로드(async subprocess) 구간 = **블로킹 없음** (health 20ms 유지) - `get_model_instance()` 모델 로딩 구간 = **부분 블로킹** (health 0.785s, 유휴의 42배) — `server.py:392` 가 executor 밖 동기 호출인 것과 정합. 콜드 스타트마다 약 7.0초(23:03:56.336→23:04:03.360). - `segments` 리스트 컴프리헨션(실 GPU 디코드) 구간 = **완전 블로킹** — 주 원인. ## 4. 정리 확인 ``` === GPU === utilization.gpu [%], memory.used [MiB] 0 %, 1957 MiB === nvidia-smi 프로세스 === pid, used_gpu_memory [MiB] 4102039, 1932 MiB ``` GPU **사용률 0%** 복귀 확인. 잔여 1957MiB 는 whisper-gpu 서버 프로세스(4102039)가 보유한 large-v3 모델로, `unload_timeout_sec=600` 정책상 10분 미사용 시 자동 언로드된다(정상 동작). `/v1/health` 응답: `{"status":"ok", ..., "models":{"small":"unloaded","medium":"unloaded","large-v3":"loaded"}}` `/tmp/whisper_yt_*` 잔여 파일: ``` -rw-rw-r-- 1 jay jay 42154598 2026-08-25 20:43:06.082174489 +0900 /tmp/whisper_yt_EvmWgJ_THDw.webm -rw-rw-r-- 1 jay jay 134296642 2026-08-25 20:43:14.699032061 +0900 /tmp/whisper_yt_YdA_zlA0oUA.webm ``` ★ 이 2개는 **본 측정 이전(20:43)** 부터 존재한 고아 파일이며 내 측정 산출물이 아니다(삭제하지 않고 보존). 본 측정이 만든 6개 파일(`v6oVfFko04A` 3회, `Rve8rNM_J30` 3회)은 서버가 매번 `임시 파일 삭제 완료` 로그와 함께 정상 삭제했다. 즉 **정상 종료 경로의 정리는 동작하나, 비정상 종료(타임아웃/예외) 시 176MB 규모 고아 파일이 남는 별도 문제**가 존재한다 — 오딘 판단 요청. ## 제약 준수 확인 | 금지 항목 | 준수 여부 | 증거 | |---|---|---| | whisper-gpu.service 재시작 금지 | 준수 | `MainPID=4101977`, `ActiveEnterTimestamp=Tue 2026-08-25 20:49:13 KST` 측정 전후 불변 | | insuwiki-youtube-pipeline.timer 기동 금지 | 준수 | `systemctl --user is-active` → `inactive` (측정 전/후 2회 확인) | | server.py 수정 금지 | 준수 | 읽기 전용 접근만(`sed -n`, `grep`). 편집 도구 미사용 | | GPU 장기 점유 금지 | 준수 | 총 전사 6건, 전부 75~90초 오디오. GPU 실사용 누적 약 2분 40초. 545초 영상 `MoJ7s4g9ZaM` **미사용** | | 코드 위치 | 준수 | 측정 스크립트 전량 `/tmp/t3018/`, 보고서만 workspace | ## 미실행 항목 (명시) - 긴 영상 `MoJ7s4g9ZaM`(545초) 재시도 — **미실행**. RUN 1~3 만으로 관측이 충분(타임아웃 16건 확보)하여 불필요한 GPU 점유를 피함. - 수정 후(post-fix) 비교 측정 — **미실행**. 본 보고서는 baseline 전용. - `/v1/transcribe`, `/v1/transcribe-url` 경로 — **미측정**. 동일 `run_transcription` 을 경유하므로 동일 결함이 예상되나 **실측하지 않았다**. ## 원자료 위치 | 파일 | 내용 | |---|---| | `/tmp/t3018/poll.log` | RUN 1 health 폴링 31건 | | `/tmp/t3018/req.log` | RUN 1 전사 요청 송수신 타임스탬프 | | `/tmp/t3018/overlap_poll.log`, `/tmp/t3018/overlap_req.log` | RUN 2 | | `/tmp/t3018/ov2.log` | RUN 3 (결정적 오버랩) | | `journalctl --user -u whisper-gpu.service --since "23:03"` | 서버 원본 로그 |