ES /docs

Api::V1::AnnotationsController#update (avg 493359ms, max 493359ms)

RCA: Api::V1::AnnotationsController#update (avg 493359ms, max 493359ms)

Overview#

What Happened#

2026-07-17 14:23:41 KST 무렵, ap-southeast-2 리전의 cupixworks-api 서비스에서 PUT /api/v1/reviews/w7bfdg/annotations/13653 요청 1건이 약 493.4초 동안 실행된 뒤 200 OK로 응답했다. 동일 시간대에 같은 Facility(ID 2947)를 대상으로 하는 PanosController#check_uploading, PanosController#update_meta_by_key, EditingsController#update 요청들이 반복적으로 Mysql2::Error::TimeoutError: Lock wait timeout exceeded / ActiveRecord::Deadlocked 로 실패하고 있어, MySQL row-lock 경합이 원인으로 판단된다.

Quick Facts#

Field Value
cluster_type latency
resource_name Api::V1::AnnotationsController#update
avg_duration_ms 493359
max_duration_ms 493359
sample_trace_id 4435704688727578565
top_frame app/repositories/annotation_repository.rb:23 (@model.save!)
env production
region ap-southeast-2
tenant cupix
facility_id 2947 (from EntityUpdates::Child 로그)

Affected Teams#

Team / Domain Error Count Impact
cupixworks-api (Review/Annotation 편집) 1 slow 200 (this cluster) 클라이언트 요청이 8분 넘게 블록되어 사실상 실패로 인지됨
cupixworks-api (Pano/Editing 업로드) 최소 8 (LockWaitTimeout 7 + Deadlock 1, 14:17-14:40 KST) 502/503 에러로 업로드/편집 실패

Timeline#

  1. 2026-07-17 14:17:57 KST — PUT /api/v1/panos/14851724/check_uploading ActiveRecord::LockWaitTimeout (502) 첫 발생. Facility 2947 관련 다중 요청 경합 시작.
  2. 2026-07-17 14:18:49 / 14:19:45 / 14:20:43 KST — 동일 pano 14851724 에서 LockWaitTimeout 반복.
  3. 2026-07-17 14:23:41 KST — 문제의 PUT /api/v1/reviews/w7bfdg/annotations/13653 요청 시작 (span first_seen).
  4. 2026-07-17 14:24:49 KST — 같은 annotation 13653 에 대한 별도 PUT 200 완료 (동시 편집 정황).
  5. 2026-07-17 14:25:29 ~ 14:26:35 KST — Facility 2947 하위 Annotation 들의 reset_parent_cached_entity_updates 로그 다수 (동시 업데이트 진행 중).
  6. 2026-07-17 14:31:54 KST — 문제 요청 200 OK 로 응답 (span 종료, 493.359s 소요).
  7. 2026-07-17 14:31:57 KST — trace 4435704688727578565 내 Annotation#_update_document, reset_parent_cached_entity_updates, Cupix::EventService.publish_event 후처리 로그.
  8. 2026-07-17 14:34:44 ~ 14:40:03 KST — 같은 window 에서 다른 Pano/Editing 요청에 LockWaitTimeout/Deadlocked 계속 발생.

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::AnnotationsController#update",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 493359,
  "max_ms": 493359,
  "sample_trace_id": "4435704688727578565"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1 (해당 latency cluster) — 단, 같은 window 에 발생한 관련 LockWaitTimeout/Deadlocked 5xx 는 최소 8건 (별도 에러 클러스터)
  • 최초 발생: 2026-07-17 14:23:41 KST
  • 최근 발생: 2026-07-17 14:23:41 KST
  • 클라이언트 관점에서는 요청이 8분 이상 hang 후 늦게 200 을 받으므로 재시도/타임아웃 등 UX 상 실질적 실패로 인식됨.

Root Cause Summary#

원인은 MySQL row-lock 경합이다. 동일 Facility(ID 2947) 하위의 Pano/Annotation/Editing 리소스에 대해 클라이언트가 짧은 시간 안에 다수의 update 요청을 병렬로 보냈고, 그중 한 트랜잭션이 오랫동안 관련 row 를 hold 하면서 AnnotationsController#update 의 @model.save! 가 innodb_lock_wait_timeout 이 만료되기 전까지 대기했다. Datadog 에는 14:17-14:40 KST 사이에 같은 Facility 를 대상으로 하는 PanosController#check_uploading, update_meta_by_key, check_mask_uploading, mask_upload_url, EditingsController#update 요청들이 ActiveRecord::LockWaitTimeout / ActiveRecord::Deadlocked 로 반복 실패한 로그가 남아 있으며, 이는 동일 InnoDB row/gap lock 경합의 흔적이다. 문제의 요청 자체는 결국 lock 을 획득해 200 을 반환했지만, 대기 시간이 493 초에 달했다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/api/v1/annotations_controller.rb:33 — AnnotationsController#update
  • Repository update: app/repositories/annotation_repository.rb:17-29 — AnnotationRepository#update
  • Actual write: app/repositories/annotation_repository.rb:23 — @model.save!
  • After-commit hooks: app/models/concerns/searchable.rb:16-18 (_update_document), app/models/concerns/entity_updates/child.rb:8-9 (reset_parent_cached_entity_updates)
app/controllers/api/v1/annotations_controller.rb:33-37ruby
def update
  @model = repository_instance.update(params)

  super
end
app/repositories/annotation_repository.rb:17-29ruby
def update(params = {})
  super

  set_parameters(params)

  begin
    @model.save!
  rescue StandardError => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
  end

  @model
end

@model.save! 는 BEGIN → UPDATE annotations WHERE id = 13653 → after_commit (Elasticsearch update + Facility 캐시 무효화 + Kinesis event publish) 를 실행한다. 이 트랜잭션이 다른 세션이 소유한 InnoDB row/index lock 을 기다리는 동안 Rails 스레드는 블록된다. innodb_lock_wait_timeout (기본 50s) 이 넘어야 예외가 발생하는데, 493 초 동안 대기했다는 것은 다음 중 하나로 해석된다:

  1. innodb_lock_wait_timeout 이 튜닝되어 매우 크게 설정됨.
  2. 대기가 여러 차례 부분적으로 해소·재획득되었고, 최종적으로 lock 을 얻어 성공.
  3. 트랜잭션 자체는 짧지만 앞선 트랜잭션 완료 대기가 누적됨.

Failure point (지연 지점): app/repositories/annotation_repository.rb:23 @model.save! — MySQL UPDATE 가 다른 트랜잭션이 걸어둔 lock 을 대기.

기대 동작: Annotation#update 는 수백 ms 내에 완료되어야 함 (동일 endpoint 의 다른 인접 요청들은 14:22:53 / 14:23:37 등에서 정상 응답).

실제 동작: 동일 Facility 를 대상으로 하는 다중 클라이언트 요청 혼잡 상황에서 lock 경합이 발생, 특정 요청이 493 초 동안 hang.

Log Evidence#

Datadog 쿼리 1 — 트레이스 세부 로그 (실제 사용):

text
service:cupixworks-api trace_id:4435704688727578565

시간 범위 2026-07-17T04:00:00Z ~ 06:30:00Z 에서 반환된 4 개 로그 (모두 span 종료 시점 근처):

json
{ "timestamp": "2026-07-17 14:31:57 KST", "status": "info", "message": "Fallback to full index (attributes_in_database unavailable)", "class": "Annotation", "function": "_update_document" }
json
{ "timestamp": "2026-07-17 14:31:57 KST", "status": "info", "message": "reset Facility (ID: 2947) cached entity updates", "class": "Annotation", "function": "reset_parent_cached_entity_updates" }
json
{ "timestamp": "2026-07-17 14:31:57 KST", "status": "info", "message": "Published event - failed_record_count: 0 / 1", "class": "Cupix::EventService", "function": "publish_event" }
json
{ "timestamp": "2026-07-17 14:31:54 KST", "status": "info", "message": "[200] PUT /api/v1/reviews/w7bfdg/annotations/13653 (Api::V1::AnnotationsController#update)" }

_update_document/reset_parent_cached_entity_updates/publish_event 로그가 응답 직후 3초 안에 모두 찍혔다는 것은 after-commit 후처리 자체는 초 단위로 수행됐음을 의미한다. 즉, 493 초의 대부분은 @model.save! 이전 또는 내부 (MySQL wait) 에서 소비되었고 ES/Kinesis/Rails.cache 자체는 병목이 아니다.

Datadog 쿼리 2 — 동일 window Lock/Deadlock:

text
service:cupixworks-api ("Lock wait timeout" OR "LockWaitTimeout" OR "deadlock")

시간 범위 2026-07-17T04:30:00Z ~ 06:00:00Z 에서 10 건 반환:

json
{ "timestamp": "2026-07-17 14:17:57 KST", "message": "[502] PUT /api/v1/panos/14851724/check_uploading", "error": { "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction", "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:18:49 KST", "message": "[502] PUT /api/v1/panos/14851724/check_uploading", "error": { "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:19:45 KST", "message": "[502] PUT /api/v1/panos/14851724/check_uploading", "error": { "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:20:43 KST", "message": "[502] PUT /api/v1/panos/14851724/check_uploading", "error": { "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:34:44 KST", "message": "[502] PUT /api/v1/panos/14851968/check_mask_uploading", "error": { "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:34:44 KST", "message": "[502] POST /api/v1/panos/14851969/mask_upload_url", "error": { "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:36:04 KST", "message": "[502] PUT /api/v1/panos/14851967/meta/blurriness", "error": { "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:36:54 KST", "message": "[502] PUT /api/v1/panos/14851967/meta/blurriness", "error": { "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:37:46 KST", "message": "[502] PUT /api/v1/panos/14851967/meta/blurriness", "error": { "class": "ActiveRecord::LockWaitTimeout" } }
{ "timestamp": "2026-07-17 14:40:03 KST", "message": "[503] PATCH /api/v1/editings/4919 (Api::V1::EditingsController#update)", "error": { "class": "ActiveRecord::Deadlocked" } }

문제 요청의 first_seen(14:23:41) 과 last_seen(14:31:54) 이 정확히 이 lock-contention window 안에 있다.

Datadog 쿼리 3 — Facility 2947 관련 활동:

text
service:cupixworks-api "facility" "2947"

14:25:29 ~ 14:31:57 KST 사이에 Annotation 여러 건이 reset Facility (ID: 2947) cached entity updates 로그를 남김 (Facility 2947 아래 여러 Annotation 이 동시에 편집되고 있었음).

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 MySQL row-lock 경합으로 @model.save! 가 대기 같은 window 에서 LockWaitTimeout 7건 + Deadlocked 1건, 모두 같은 Facility 2947 소속 리소스; trace 로그가 응답 직후 3초 안에 몰려 있어 대기 구간이 save 전/내부임을 시사 문제 요청 자체의 스택에서 명시적 LockWaitTimeout 예외 로그는 없음 (요청이 결국 lock 을 얻어 200) Confirmed
H2 Elasticsearch _update_document 가 느려서 지연 _update_document 로그 존재 after_commit 로그(_update_document, reset_parent_cached_entity_updates, publish_event) 3건이 200 응답 후 3초 이내에 모두 찍힘 → ES/Kinesis 는 병목 아님 Rejected
H3 Kinesis publish_event timeout 재시도 코드상 RestClient::Exception 시 raise, event_service 에 log 존재 Published event - failed_record_count: 0 / 1 정상 응답 로그 존재, 실패/재시도 로그 없음 Rejected
H4 외부 의존성 outage (dep:*) 상태 보드 조회로 확인 status-board 결과: scope=svc:cupixworks-api::unknown, active=null. dep:* 인시던트 없음 Rejected
H5 배포/코드 회귀 — 인접 시각에 동일 endpoint 의 정상 응답 다수 (14:22:53, 14:23:37 등) → 코드/배포 자체 이슈면 endpoint 전체가 실패했어야 함 Rejected
H6 EntityUpdates::Child#reset_parent_cached_entity_updates 의 ObjectSpace.each_object(Class) 부하 매 after_update 마다 호출됨 493s 지연에 비해 규모가 맞지 않고, 후처리 로그가 3초 안에 완료됨 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  • 운영 조치: 이번 사례처럼 특정 Facility 에 동시 편집이 몰릴 때의 lock 경합은 코드 변경 없이도 클라이언트 재시도 완화(백오프) 및 트래픽 관측만으로 완충 가능. 관련 다른 클러스터(ActiveRecord::LockWaitTimeout / ActiveRecord::Deadlocked 발생) 를 우선 조사할 것.
  • 코드 조치 후보: app/repositories/annotation_repository.rb:22-26 의 rescue StandardError => e 는 lock 대기/deadlock 예외도 그대로 Cupix::Errors::Parameter(ARG10001, Invalid argument) 로 감싸버려 원인 진단을 어렵게 한다. ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked 는 각각 별도 rescue 로 분기해 원본 클래스 그대로 로깅/재발생하도록 방향 잡을 것.

단기 개선 (1주 이내)#

  • APM 트레이스 상세 분석: sample_trace_id 4435704688727578565 를 APM 에서 열어 mysql.query span 별 duration 확인. 어느 SQL 이 실제로 대기했는지 (annotations UPDATE 인지, 관련 join/callback 쿼리인지) 파악 후 해당 쿼리 최적화 여부 판단.
  • 동일 Facility 동시 편집 감지: 동일 facility_id 에 대한 concurrent PUT 카운트를 메트릭화하고, 임계치 초과 시 알림. Sidekiq/rate-limit 계층에서 조율 대상.
  • Statement timeout 도입: MySQL 세션에 SET SESSION MAX_EXECUTION_TIME=60000 유사 가드를 도입 검토. 100 초 이상 hang 하는 API 트랜잭션이 클라이언트/앱 리소스를 계속 점유하는 것을 방지.
  • rescue StandardError 세분화: annotation_repository.rb:24 의 catch-all 을 ActiveRecord::LockWaitTimeout / ActiveRecord::Deadlocked 분리 rescue 로 좁혀 원인이 masking 되지 않도록 (memory 규칙 참고: rescue 를 좁힐 때 sibling 메서드와 스펙 동기화).

장기 개선 (재발 방지)#

  • Facility-scoped write concurrency 정책: 같은 Facility 하위 Pano/Annotation/Editing 대량 편집 시 backend-side lock 조율 (advisory lock 또는 Sidekiq 직렬화 큐) 을 도입. FE 는 optimistic UI 로 최소화하되 서버에서 순서 보장.
  • After-commit 콜백 재검토: EntityUpdates::Child#reset_parent_cached_entity_updates 의 ObjectSpace.each_object(Class) 스캔은 콜백마다 반복 실행되므로 memoize 검토. 이번 사건의 주 원인은 아니지만 write 경로 지연 증가 요인.
  • Long-request alerting: p99 > 60s, avg > 30s 를 넘는 endpoint 에 대해 Datadog Monitor 를 설정해 개별 slow trace 를 즉시 파악.

Monitoring#

추가/유지할 Datadog 쿼리 (dashboard timeseries widget 기준):

  • AnnotationsController#update p95 latency:
text
p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::annotationscontroller#update}
  • MySQL lock timeout / deadlock 발생률 (log-based metric):
text
sum:logs.hits{service:cupixworks-api,@error.class:activerecord::lockwaittimeout}.as_count()
text
sum:logs.hits{service:cupixworks-api,@error.class:activerecord::deadlocked}.as_count()
  • Facility 편집 write 요청 rate (같은 facility 에 대한 편집 집중도 파악):
text
sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::annotationscontroller#update}.as_rate()
  • Rails DB spans p95 (MySQL 병목 관측):
text
p95:trace.mysql.query.duration{service:cupixworks-api}

알림 정책 후보 (Monitor 별도 정의):

  • AnnotationsController#update p95 > 30s 5분 연속.
  • service:cupixworks-api @error.class:ActiveRecord::LockWaitTimeout 5 분에 3건 이상.

Risk Assessment#

  • Risk level: medium — 개별 요청 hang 은 UX 상 심각하지만 발생 빈도가 낮고 (14일 검색 시 493s 급 slow update 는 이 1건), 관련 5xx 는 이미 별도 클러스터로 트래킹 중.
  • 예상 복잡도: standard — 우선순위는 (1) rescue StandardError 를 좁혀 원인 로깅 개선, (2) APM 트레이스 분석 후 lock 을 유발하는 실제 SQL 확인, (3) 필요 시 서버측 concurrency 제어 추가.