프로필 조회 타임아웃과 듣기 OFF
요청·CPU 재집계와 원인 범위

1날짜별 프로필 요청과 abort율

제공된 ppi-web-prod-202609DD_2000-2200.log 12개를 직접 파싱했습니다. API_AUDIT / api_audit_completed / /api/internal/user-profile/[userId]만 세고, requestId 중복을 확인했습니다(0건). 시작·종료 기록 건수도 날짜별로 일치합니다.

abort율 = aborted 요청 ÷ 전체 완료·중단 요청 × 100. 재시도가 포함된 HTTP 요청 기준이며, 아동 수·입장 수·듣기 OFF 비율이 아닙니다.

457건 모두 20:00·20:30·21:00 경계 이후 74.916초 이내에 발생했습니다. 9/12·19·20은 프로필 요청 자체가 없고, 9/13은 2건 모두 성공했습니다. 9/14 로그는 제공되지 않아 조사에 포함하지 않았습니다.

요청 수가 많아서 실패했는가?

평일 8일 기준 Pearson 상관계수는 요청 수↔abort 건수 0.914, 요청 수↔abort율 0.903입니다. 그러나 실패가 재시도를 만들어 요청 수를 늘리기도 합니다. 9/9(310건·77 abort)와 9/21(323건·152 abort)은 요청 수가 비슷해도 중단은 약 2배 차이 납니다. 상관관계만으로 인과를 확정하지 않습니다. 최초 요청·재시도를 나눠 동시 도착량을 확인해야 합니다.

2운영 Prometheus에서 직접 계산한 CPU

2026-09-22 운영 Grafana의 Prometheus(PBFA97CFB590B2093)에서 job="ppi-web", env="prod", hostname="ppi-web-prod"를 조회했습니다. 각 날짜 20:00:00~22:00:00 KST(양 끝 포함), 평가 간격 15초, 하루 481개씩 총 3,848개 rate[1m] 샘플을 검증했습니다. 15초는 조회 평가 간격이며 원본 수집 주기를 뜻하지 않습니다.

rate(process_cpu_seconds_total{
  job="ppi-web", env="prod", hostname="ppi-web-prod"
}[1m])
# query_range: start=해당 날짜 11:00:00Z, end=13:00:00Z, step=15s
# 날짜별 유효 샘플의 최댓값. 단위는 사용 코어 수.

기본 웹 대시보드는 rate[5m] × 100을 퍼센트로 표시합니다. 위 1분·5분 값은 별도로 집계한 값이므로 서로 혼용하지 않습니다. 이전 이미지와 9/10·11·16·17·18의 값이 다른 이유는 원래 이미지의 정확한 조회 시간·평가 간격이 남아 있지 않아 확정할 수 없습니다.

2 vCPU 서버에서 1.403코어면 부하인가?

사용자가 제공한 호스트 사양은 ppi-web-prod 2 vCPU / 1.8 GiB입니다. 1.403코어는 전체 명목 CPU 용량의 약 70.2%에 해당하는 웹 프로세스 사용량이며, 다른 프로세스를 포함한 호스트 전체 사용률이 아닙니다.

Node.js의 주요 JavaScript 콜백은 하나의 이벤트 루프에서 실행되므로 전체 CPU가 100%에 이르기 전에도 요청 처리가 밀릴 수 있습니다. 반대로 process_cpu_seconds_total은 스레드별 분해가 없어 1.403코어 중 메인 스레드가 얼마를 사용했는지 알 수 없습니다. 메인 1.0 + 보조 0.4코어는 가능한 예시일 뿐 실측 구성이 아닙니다.

CPU 원본 시계열·조회 조건·로그 집계 JSON · 운영 웹 대시보드 · Node.js 공식 이벤트 루프 설명

33초 타임아웃과 웹 duration은 다른 시간

apps/socket/src/utils/profile-client.ts는 시도마다 AbortSignal.timeout(3000)을 적용하고 실패 시 즉시 1회 재시도합니다. 두 번 모두 타임아웃이면 통상 약 6초 뒤 실패 경로로 진행하지만, 타이머 실행 지연 등이 있어 정확한 전체 대기 시간은 별도 실측이 필요합니다. response.json()도 같은 try 안에서 실행됩니다.

apps/web/server.js는 요청 콜백 안에서 타이머를 시작하고, apps/web/api-audit.js는 응답 완료 전 close를 aborted로 분류합니다. aborted는 3초 타임아웃의 동의어가 아닙니다. 연결 종료 원인은 소켓 로그와 매칭해야 합니다.

9/21 사용자 식별자 끝자리 …b744ee는 20:00:13.399에 11.948ms 후 중단, 20:00:17.558에 120.519ms 후 중단됐으며 20:01:48.234에는 6.408ms로 성공했습니다. 파일의 426·622·5161행입니다. 짧은 웹 duration은 “총 12ms만 기다렸다” 또는 “DB가 빨랐다”를 증명하지 않습니다.

4확인된 경로와 남은 원인 범위

아동 입장 (GUEST_REQUEST_ENTRY)
  → getUserProfile: 시도당 3초 제한 + 실패 시 1회 재시도
  → 최종 조회 실패: isVoiceUser=false 유지
  → 일반 수업의 초기 listeningIntent=false로 초기화 시도
  → 듣기 OFF로 시작할 수 있음
  ※ 테스트 모드와 이미 존재하는 durable snapshot은 별도 상태 조건

제공된 웹 로그에는 프로필 API의 4xx·5xx 및 사용자 조회 오류가 관측되지 않았습니다. 이는 DB 지연을 기각하는 증거가 아닙니다. CPU와 abort의 인과를 검증하려면 날짜별 최대값 비교를 넘어 동일한 수초 구간의 시각 정렬이 필요합니다.

5이전 조사 보존 — 이번에 재검증하지 않은 근거

09/22 문서는 소켓·ALB·호스트 지표까지 조회했다고 기록했습니다. 해당 원본·매칭 산출물을 이번 검증 자료로 확보하지 못했으므로 거짓으로 단정하지도, 새로 확인된 사실로 재인용하지도 않습니다. 아래 세부 내용은 이전 조사 기록이며 현재 결론은 위 §4를 따릅니다.

• 소켓 타임아웃−3초를 발신 시각으로 간주한 매칭: 9/21 88건(p50 4.75초·최대 8.08초), 9/10 18건, 9/17 50건. 발신 직접 계측이 아닌 역산 추정이며 재시도 식별·타이머 지연·호스트 시계 정렬을 재검증해야 합니다.
• 9/17 사례의 초기 OFF, 후속 조회 성공, 기존 snapshot 유지, 진행자 수동 ON 및 소켓 fallback 방 수(9/21 41개·9/10 5개)는 원본 소켓·브라우저 로그 재대조가 필요합니다.
• 이벤트 루프 p99 0.18~0.21초, ALB 전건 ≤25ms, socket CPU 0.15~0.23코어, listen overflow 0, 시계 차이 p50 18ms는 이전 측정 주장입니다. 값만으로 각 대기 원인을 모두 기각할 수는 없습니다.
• 요청당 CPU 32.3ms·포화 29 req/s 회귀와 getResources Scan 약 292회는 산출물·프로파일을 재검증해야 합니다. 요청 경과시간 합계는 CPU 실행시간 합계가 아닙니다.

수업 시작 정각 버스트 (아동·진행자 동시 입장)
  → ppi-web 프로세스 CPU 1.0코어 초과 → 메인 스레드 포화 가설 (미확정)
  → 요청이 Node 'request' 이벤트까지 도달하는 데 4~8초 대기 (핸들러 실행은 20ms)
      │
21:00:19.084  소켓 → web  프로필 조회 1차 발신
21:00:22.084  3초 타임아웃      (web 진입은 21:00:23.654 = +4.57초, 이미 끊긴 뒤)
21:00:22.084  2차 발신
21:00:25.084  2차도 타임아웃  → isVoiceUser=false 폴백
21:00:25.088  Room defaults reset   isMicrophoneEnabled=false
21:00:25.093  스냅샷 하이드레이트   revision=0  listeningIntent=false
21:00:25.099  아동 브라우저: Agent listening disabled (voice-control-startup-pending)
      │ 고착
21:01:51.030  프로필 재조회 성공  isVoiceUser=true   ← 실제로는 음성 아동
21:01:51.035  그러나 스냅샷은 여전히 revision=0 / listeningIntent=false
              (initializeVoiceControlSnapshot 이 EXISTS==0 일 때만 쓰기 때문)
21:03:26.780  진행자 수동 듣기 ON  → revision 0→1
              듣기 OFF 지속 3분 01초

20:00:10  n=11  중앙 5.63s
20:00:20  n=38  중앙 4.19s
20:00:30  n=14  중앙 7.41s   ← 최대 8.08초, 백로그 정점
20:00:50  n=11  중앙 4.41s
20:01:10  n= 4  중앙 3.12s   ← 해소되며 3초 근처로 복귀

GET /api/guest-data  (아동 입장 시 1회)
 ├ collectActivityResourceFileNames()  → getResources()  ← 전체 Scan ①  resource.service.ts:101
 └ collectAmbientNoiseImageFileNames() → getResources()  ← 전체 Scan ②  resource.service.ts:134

db-queries.ts:1838-1854
  const params = { TableName: `${prefix}-${stage}` };        // 키 조건 없음
  await paginateDynamoDBCommand<Resource>(ScanCommand, params);
  return resources.sort((a,b) => b.createdAt - a.createdAt); // 전건 JS 정렬
  → 캐시 없음 (unstable_cache / Redis / 메모이제이션 모두 0건)

6다음 검증과 수정 방향

1. 9/21 20:00~20:02의 소켓 로그에서 입장·1차 실패·최종 fallback을 사용자와 시도별로 매칭합니다. 기존 자료로 불충분하면 fetch 시작·종료 monotonic elapsed 및 상관 ID를 계측합니다.
2. 동일 시각의 웹 이벤트 루프 지연·이용률, 스레드별 CPU, 호스트 CPU·throttling과 ALB 구간 지연을 대조합니다. 기본 대시보드의 rate(nodejs_eventloop_lag_seconds[5m])는 지연 gauge 자체와 다르므로 원본 gauge·분위수와 산식을 확인합니다.
3. 조회 실패를 음성수업 OFF와 구분하는 상태 처리를 검토합니다. 기존 캐시·최근 정상 프로필 사용, 재확인 및 안내 여부를 제품 정책으로 결정해야 합니다.
4. 나중에 프로필 조회가 성공했을 때 자동 복구하려면, 진행자의 명시적 OFF와 최신 revision·재접속 세대를 보존해야 합니다. EXISTS==0 조건을 단순 제거해 사용자의 조작을 덮어쓰면 안 됩니다.
5. 리소스 Scan 캐시·중복 조회 제거·확장은 CPU 프로파일과 데이터 변경 정책을 확인한 뒤 결정합니다. 타임아웃 연장만으로 해결된다고 가정하지 않습니다.

7수정 방안 — 입장 몰림 완화

백로그: 수업 입장 몰림 시 ppi-web CPU 포화 완화 · 코드 기준 develop 64c71f7b · 2026-09-23 제안 · 1차 묶음 구현 완료(PR #1135, b28aa399, 배포 전)

원인이 메인 스레드 포화로 확정되지 않았으므로, 조치를 원인과 무관하게 유효한 것과 부하 가설에 의존하는 것으로 나눕니다. 프로필 요청만 몰리는 것이 아니라, 같은 시점에 guest-data와 리소스 URL 발급 요청도 몰립니다.

정각 입장
  ├ GET /api/guest-data ─┬ collectActivityResourceFileNames → getResources()   전체 Scan + 정렬
  │                     └ collectAmbientNoiseImageFileNames → getResources()   전체 Scan 한 번 더
  │                        + 스텝 리소스마다 allResources.filter(정규식)
  ├ useResourceCache → POST /api/resources/urls → getResources()  또 Scan
  │     ※ 캐시에 있는 파일도 updatedAt 비교용으로 매번 전체 목록 URL을 다시 발급받음
  ├ session-logs · lesson-logs/upload-url  (건당 가볍지만 요청 수 많음)
  └ socket → web /api/internal/user-profile  (시도당 3초, 캐시 TTL 30초)
        → 같은 web 프로세스에서 위 요청들과 경합 → 실패하면 isVoiceUser=false

8검증 방법과 관련 문서

• 웹 로그 12개 JSON 파싱, requestId 중복 검사, 날짜별 시작·종료 건수 일치, 별도 문자열 검색의 aborted 건수 교차 확인. 9/16의 비JSON 스택 후속 1행은 API 집계와 무관합니다.
• CPU rate[1m] 시계열은 하루 481점·15초 간격·유효 숫자·단일 웹 prod 시리즈를 확인하고, 저장한 JSON에서 최대값·시각을 다시 계산했습니다. rate[5m]은 비교용 요약을 함께 보존했습니다.
• CPU 원본 조회일 2026-09-22, 문서 갱신일 2026-09-23. 코드 확인 기준 PPI 812a26eb4a6939414e9f8fceab840e190abd68c2. 이 SHA는 현재 코드 기준이며 사건 당시 배포 SHA로 확인된 것은 아닙니다.