MaskableRepository — InnoDB row lock contention on concurrent pano updates
RCA: PanosController#mask_upload_url Latency (1815ms)
Overview#
What Happened#
2026-05-27 11:44:09 UTC에 cupixworks-api 서비스의 Api::V1::PanosController#mask_upload_url 엔드포인트에서 1815ms의 응답 지연이 발생했다. cupix-agent 클라이언트가 12개 이상의 pano mask upload URL 요청을 동시에 전송하는 burst 패턴에서, 첫 번째 배치(~11:44:10)는 정상(100-350ms)이었으나 두 번째 배치(~11:44:12)에서 1700-3200ms로 급증했다.
Quick Facts#
| Field | Value |
|---|---|
| resource_name | Api::V1::PanosController#mask_upload_url |
| top_frame | app/controllers/concerns/maskable_controller.rb:28 |
| env | production, us-west-2 |
| deploy | production-us-west-2-20260527t0524z0-650f3601-cupixworks |
Timeline#
- 2026-05-27T11:44:10Z — 첫 번째 배치 요청 도착 (7개, pano 86026458-86026469), 정상 응답 (100-350ms)
- 2026-05-27T11:44:12Z — 두 번째 배치 요청 도착 (5개), 지연 응답 (1700-3200ms)
- 2026-05-27T11:44:12.817Z — 대표 trace (ID: 1047593615445870707, pano 86026468) 1813ms 응답
- 2026-05-27T11:48:20Z — 동일 사용자의 후속 요청에서도 2065ms 지연 재현
Error Log#
{
"resource_name": "Api::V1::PanosController#mask_upload_url",
"service": "cupixworks-api",
"occurrences": 1,
"avg_ms": 1815,
"max_ms": 1815,
"sample_trace_id": "1047593615445870707"
}
Impact#
- Service:
cupixworks-api - 발생 횟수: 1 (클러스터 기준, 실제 동시간대 5건 이상)
- 최초 발생: 2026-05-27T11:44:09.407Z
- 최근 발생: 2026-05-27T11:44:09.407Z
- 영향 사용자: findorff 팀 (user_id: 38891, cupix-agent 사용)
- 기능 영향: mask upload URL 생성 지연으로 cupix-agent의 mask 업로드 워크플로우 지연. HTTP 200 정상 응답했으므로 데이터 손실 없음.
Root Cause Summary#
cupix-agent가 12개 이상의 mask_upload_url 요청을 동시에 전송하면서 DB row lock contention이 발생했다. mask_upload_url 엔드포인트는 find_or_create_mask (SELECT + 잠재적 INSERT) → mask.uploading (UPDATE) → @model.uploading_mask_state! (UPDATE)으로 최대 3개의 write operation을 수행한다. 동일 pano의 mask 테이블과 pano 모델의 state 컬럼에 대한 동시 쓰기가 row-level lock 대기를 유발하며, 첫 배치가 lock을 점유하는 동안 두 번째 배치가 대기하면서 1700-3200ms로 지연되었다. DB time 자체는 82ms로 낮지만, 이는 lock 획득 후의 실제 쿼리 시간만 측정한 것이고 lock 대기 시간은 포함되지 않는다.
Technical Analysis#
Code Path#
- Entry point:
app/controllers/concerns/maskable_controller.rb:16 - before_action
set_pano: pano를 DB에서 로드 (permission joins + Pundit 인가) - Line 27-28:
repository_instance.mask_upload_url(_mask_type)호출 - Repository:
app/repositories/concerns/maskable_repository.rb:51-62 - Model:
app/models/concerns/maskable.rb:42-57—find_or_create_mask - Serializer:
app/serializers/mask_serializer.rb:13-19— S3 presigned URL 생성 트리거 - S3 URL:
app/models/concerns/storagable/mask.rb:37-44
1. Controller action (entry point)
def mask_upload_url
if params[:review_key].present?
review_repository_instance = ReviewRepository.new(current_user: current_user)
review = review_repository_instance.show(params[:review_key])
pano = PanoRepository.new(current_user: current_user, review: review).show(params[:id])
if !review_repository_instance._capture_ids.include?(pano.capture_id) || !review_repository_instance._level_ids.include?(pano.level_id)
raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: 'Pano not found with review', review: { key: params[:review_key] }, pano: { id: params[:id] })
end
end
_mask_type = params[:mask_type].presence || 'custom'
mask = repository_instance.mask_upload_url(_mask_type)
render_api Renderable.new({
contents: mask,
serializer: MaskSerializer
})
end
2. Repository — DB write operations (contention point)
def mask_upload_url(mask_type)
_mask_type = mask_type.presence || 'custom'
mask = @model.find_or_create_mask(_mask_type) # SELECT + potential INSERT
if %i[missing created uploaded].include?(mask.state_name)
mask.uploading # UPDATE masks SET state = 'uploading'
end
@model.uploading_mask_state! # UPDATE panos SET mask_state = 'uploading'
mask
end
기대 동작: 각 요청이 독립적인 pano에 대해 mask를 생성/갱신하므로 병렬 처리 가능해야 함.
실제 동작: 동시 요청 시 masks 테이블의 INSERT와 panos 테이블의 UPDATE가 겹치면서 DB connection pool 경합 및 row lock 대기 발생.
3. find_or_create_mask — 비원자적 패턴
def find_or_create_mask(mask_type = CUSTOM_TYPE)
mask = masks.find_by_mask_type(mask_type)
if mask.nil?
mask = ::Mask.new
mask.maskable_id = id
mask.maskable_type = self.class.name
mask.mask_type = mask_type
mask.team_id = self.team_id
mask.save! # INSERT — row lock on masks table
end
mask
end
4. S3 presigned URL 생성
def mask_upload_url(params = {})
_mask_revision = params[:mask_revision].presence || mask_upload_revision
mask_object(mask_type: params[:mask_type], mask_revision: _mask_revision).presigned_url(
:put,
bucket: hosting_bucket_name,
expires_in: $AWS[:s3][:put_presigned_url_expires_in].to_i,
acl: 'bucket-owner-full-control'
)
end
S3 presigned URL 생성은 일반적으로 로컬 암호화 연산이지만, AWS credential이 만료되어 instance metadata 또는 STS에서 갱신이 필요한 경우 추가 네트워크 지연이 발생할 수 있다.
Log Evidence#
Datadog에서 사용한 쿼리:
service:cupixworks-api resource_name:"Api::V1::PanosController#mask_upload_url" env:production @duration:>500ms
대표 trace (ID: 1047593615445870707)의 로그:
2026-05-27T11:44:12.817Z [200] POST /api/v1/panos/86026468/mask_upload_url (Api::V1::PanosController#mask_upload_url)
duration: 1813.35ms, db_time: 82.43ms
host: ip-10-1-144-228
user_id: 38891, team: findorff, session: 455ad67ca73a66bdb602d3bb3fc0f90a5cdec03d
동시간대 관련 로그:
2026-05-27T11:44:10.595Z Published event - failed_record_count: 0 / 1 (class: Cupix::EventService)
2026-05-27T11:44:10.595Z world_transformation set as [...] (class: Pano, function: set_world_transformation_from_meta)
2026-05-27T11:44:10.595Z Set a storage on Mask using default storage on uswe2 (class: Mask, function: set_storage)
지연 패턴 비교:
# 첫 번째 배치 (~11:44:10) - 정상
pano 86026461: 354ms (db: 61ms)
pano 86026460: 198ms (db: 77ms)
pano 86026458: 136ms (db: 30ms)
pano 86026459: 103ms (db: 19ms)
# 두 번째 배치 (~11:44:12) - 지연
pano 86026465: 3204ms (db: 118ms)
pano 86026466: 1782ms (db: 81ms)
pano 86026468: 1813ms (db: 82ms) ← 대표 trace
pano 86026467: 1776ms (db: 30ms)
pano 86026463: 1760ms (db: 25ms)
핵심 관찰: DB time(25-118ms)과 total duration(1700-3200ms) 간 큰 격차는 lock 대기 또는 connection pool 대기 시간이 Rails 계측에서 DB time으로 측정되지 않음을 의미한다.
Hypotheses Considered#
| # | Hypothesis | Evidence for | Evidence against | Verdict |
|---|---|---|---|---|
| H1 | DB row lock contention from concurrent mask state updates | 동시 12개 요청 burst; 첫 배치 정상, 두 번째 배치 지연; total duration >> db_time (lock 대기 미계측); repository에서 3개 write operation 순차 수행 | 각 pano가 별도 row이므로 pano 간 직접적 row lock은 없어야 함 — 그러나 masks 테이블 INSERT와 connection pool 경합은 발생 가능 | Confirmed |
| H2 | AWS S3 credential refresh latency | presigned URL 생성 시 credential 만료 시 STS 호출 필요; 배포 직후(05:24Z) 새 인스턴스에서 첫 credential fetch 가능 | credential refresh는 한 번만 발생하고 캐시됨, 같은 호스트의 첫 배치는 정상 응답 | Rejected |
| H3 | Application server request queueing (Puma thread exhaustion) | 3개 서버(ip-10-1-80-134, ip-10-1-144-228, ip-10-1-19-190)에 분산됨에도 모두 지연; burst 요청이 available thread를 모두 점유 가능 | 3개 서버 모두 동시에 thread 고갈은 12개 요청으로는 불가능 (일반적으로 Puma는 16-32 thread) | Rejected |
| H4 | DB connection pool exhaustion under concurrent write load | 동시 12개 요청이 각각 3개 DB operation 수행 = 최대 36개 concurrent DB connection 필요; pool size 초과 시 대기 발생; db_time에 pool 대기는 미포함 | connection pool size 미확인 — uncertain | Likely contributing |
Fix Recommendation#
즉시 조치 (Critical)#
- 해당 없음 — HTTP 200 정상 응답했으며 기능적 장애가 아닌 latency 이슈. 즉시 조치 불필요.
단기 개선 (1주 이내)#
app/repositories/concerns/maskable_repository.rb:51-62:find_or_create_mask와 state transition을 하나의 DB transaction으로 묶어 lock 점유 시간 최소화.find_or_create_by패턴 사용으로 race condition 방지.app/models/concerns/maskable.rb:42-57:find_or_create_mask에서find_or_create_by!를 사용하여 SELECT → INSERT 간의 race condition 제거.cupix-agent측에서 동시 요청 수를 제한하는 rate limiting 또는 request batching 적용 검토.
장기 개선 (재발 방지)#
mask_upload_url엔드포인트에 bulk API 제공: 하나의 요청으로 여러 pano의 mask upload URL을 동시에 생성할 수 있도록 하여 N개의 HTTP 요청을 1개로 줄임.- DB connection pool size 모니터링 및 적정 수준 확인. concurrent write 부하에 맞게 pool size 조정.
Monitoring#
mask_upload_url엔드포인트 p95/p99 latency 알림 추가:
avg(last_5m):trace.rack.request.duration{service:cupixworks-api, resource_name:api::v1::panoscontroller#mask_upload_url} > 1000
- DB connection pool 사용률 메트릭 추가 (ActiveRecord pool checkout wait time)
cupix-agentburst 패턴 감지를 위한 request rate 모니터링
Risk Assessment#
- Risk level: low
- 예상 복잡도: standard
- 사유: 기능 장애 없이 latency만 증가하는 이슈. HTTP 200 정상 응답하며 데이터 손실 없음. 특정 클라이언트(cupix-agent)의 burst 패턴에서만 재현되며, 일반 사용자에게는 영향 없음.