RCA: Api::V1::Admin::UsersController#assign_editings 요청 지연 (avg 15.8s, max 20.6s)

Overview#

What Happened#

2026-07-01 10:57~11:00 KST 사이 cupixworks-api (production, us-west-2)에서 POST /api/v1/admin/users/:id/assign_editings 요청 2건이 평균 15.8초, 최대 20.6초의 응답 지연을 보였다. 같은 시간대에 여러 다른 컨트롤러(PanosController, CapturesController, JobsController)에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 502 에러가 대량으로 발생하고 있었으며, assign_editings의 지연은 이 광범위한 MySQL row lock 경합의 부수적 증상이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 10:44 KST — 첫 ActiveRecord::LockWaitTimeout 발생 (PUT /api/v1/panos/90876936/stitched). MySQL row lock 경합 시작.
2. 2026-07-01 10:47 KST — Lock wait timeout이 PanosController, JobsController 등 여러 엔드포인트로 확산.
3. 2026-07-01 10:48 KST — production-us-west-2-20260701T0148Z0 신규 배포 롤아웃.
4. 2026-07-01 10:57:28 KST — 클러스터 first_seen: assign_editings 첫 지연 요청.
5. 2026-07-01 11:00:29 KST — 클러스터 last_seen: 두 번째 지연 요청.
6. 2026-07-01 11:04 KST — 여전히 Mysql2::Error::TimeoutError 발생 (Api::V1::PanosController#stitched).

Error Log#

Datadog Logs

resource_name: Api::V1::Admin::UsersController#assign_editings
service: cupixworks-api
occurrences: 2
avg_ms: 15791
max_ms: 20572
sample_trace_id: 3930104064608961807

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-07-01 10:57 KST
• 최근 발생: 2026-07-01 11:00 KST
• 영향 범위: 편집자 워크플로우의 UX 저하 (요청은 성공하나 응답 15~20초 대기). 동일한 MySQL lock 경합이 다른 endpoint에서 502를 유발하는 광범위 이벤트의 일부.

Root Cause Summary#

assign_editings 자체의 버그가 아니라, us-west-2 프로덕션 MySQL에서 발생 중이던 광범위한 row lock 경합(Mysql2::Error::TimeoutError: Lock wait timeout exceeded)의 부수 증상이다. assign_editings가 실행하는 마지막 단계는 target_editing.update!(editor_id: user_id)로 editings 테이블 row에 UPDATE를 수행하는데, 같은 시간 window에 다른 트랜잭션이 관련 row(또는 gap lock 대상 인덱스)를 잡고 있어 UPDATE가 InnoDB lock wait에서 15~20초 blocking되었다가 성공적으로 커밋되어 200을 반환한 것으로 보인다. 로그 evidence는 (a) 10:44 KST부터 PanosController / CapturesController / JobsController 등 여러 무관한 엔드포인트에서 ActiveRecord::LockWaitTimeout이 대량 발생, (b) 같은 시간대 assign_editings는 실패가 없고 지연만 발생한 것으로, DB 잠금 경합이 서비스 전반에 영향을 주었음을 보여준다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/admin/users_controller.rb (via include EditorableController)
• Controller concern: app/controllers/concerns/editorable_controller.rb:16-29
• Repository dispatch: app/repositories/concerns/editorable_repository.rb:17-68
• Search unassigned: app/repositories/concerns/finalization_repository.rb:25-60 (Elasticsearch)
• Failure point (slow UPDATE): app/repositories/concerns/finalization_repository.rb:62-75 — target_editing.update!(editor_id: user_id)

Controller가 repository_instance.assign_editings(params)를 호출한다.

def assign_editings
  editings = repository_instance.assign_editings(params)

  render_api Renderable.new({
    search_result: editings,
    is_collection: true,
    serializer: EditingSerializer,
    serializer_option: {
      fields: {
        editing: @fields
      }
    }
  })
end

EditorableRepository#assign_editings는 unassigned editings 리스트를 Elasticsearch에서 조회하고, 첫 번째 항목을 EditingRepository#assign_editings(target_user.id, target_editing, ...)로 넘긴다.

unassigned_editings = editing_repo.unassigned_editing_records(states: target_states, editing_type: editing_type, ...)
if unassigned_editings.count.zero?
  Cupix::Logger.info('Unassigned editings are empty', ...)
  return SearchResult.new({ contents: unassigned_editings, ... })
end

target_editing = unassigned_editings.first
assigned_editings = editing_repo.assign_editings(target_user.id, target_editing, editing_type, target_states)
Cupix::Logger.info('The editings are assigned to the editor successfully', ...)

FinalizationRepository#assign_editings는 실제 UPDATE를 수행한다. 로그에서 editing_type: siteinsights 브랜치가 사용된 것이 확인되므로 target_editing.update!(editor_id: user_id) 한 줄이 실질적 write 지점이다.

def assign_editings(user_id, target_editing, editing_type, states)
  if editing_type == 'siteinsights'
    target_editing.update!(editor_id: user_id)
    return [target_editing]
  end

  assigned_editings = unassigned_editing_records(record_id: target_editing.record_id, level_id: target_editing.level_id, editing_type: editing_type, states: states)

  assigned_editings.each do |editing|
    editing.update!(editor_id: user_id)
  end

  assigned_editings
end

기대 동작: update! 는 밀리초 단위에 완료되어 요청 전체가 100~500ms 이내에 응답.

실제 동작: 15~20초 대기 후 성공. InnoDB의 default innodb_lock_wait_timeout=50s 이내에 잠금을 획득하여 timeout 예외를 던지지는 않았지만, 같은 인덱스/row에 대해 다른 트랜잭션이 잠금을 오래 보유하고 있어 blocking. 동일 시간대 다른 엔드포인트에서는 50s를 초과하여 Mysql2::Error::TimeoutError가 발생.

Log Evidence#

Datadog query (재현용):

service:cupixworks-api "editings are assigned"
from: 2026-07-01T01:57:00Z to 2026-07-01T02:01:00Z

성공 로그 (지연 있었으나 200 반환). 두 요청 모두 editing_type: siteinsights, record.id: 134695:

{
  "timestamp": "2026-07-01T02:00:14.394Z",
  "class": "Admin::UserRepository",
  "function": "assign_editings",
  "record": { "id": 134695 },
  "editor": { "id": 47155 },
  "editing": { "count": 1, "ids": [1196559], "editing_type": "siteinsights" },
  "dd.version": "production-us-west-2-20260701T0148Z0-c527a441-cupixworks",
  "message": "The editings are assigned to the editor successfully"
}

같은 window에 발생 중이었던 광범위 lock timeout (다른 엔드포인트):

service:cupixworks-api "Lock wait timeout"
from: 2026-07-01T01:40:00Z to 2026-07-01T02:15:00Z
→ 36+ hits across PanosController, CapturesController, JobsController

대표 502 예시:

{
  "timestamp": "2026-07-01T01:44:14Z",
  "message": "[502] PUT /api/v1/panos/90876936/stitched (Api::V1::PanosController#stitched)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

{
  "timestamp": "2026-07-01T01:47:17Z",
  "message": "[502] PUT /api/v1/jobs/1165311/actions/postprocessor/complete (Api::V1::JobsController#complete_action)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

추가 관측: record.id: 134695 하나에 편집자 20+ 명이 최근 1시간 동안 57회 assign_editings를 호출.

service:cupixworks-api "editings are assigned" @record.id:134695
from: 2026-07-01T01:00:00Z to 2026-07-01T02:05:00Z
→ 57 hits

같은 record에 대한 매우 높은 assignment throughput은 이 지연 발생 시점에 editings 테이블 특정 row 그룹에 대한 잠금 압박이 정점에 있었음을 시사한다 (직접 원인이 아니어도 aggravator).

status-board는 이 클러스터가 활성 인시던트 2026-07-01-svc-cupixworks-api--unknown-1 (시작 01:43 UTC, 클러스터 5개 포함)에 속함을 확인. 즉, 같은 시간대의 다른 4개 클러스터도 동일한 서비스 저하 이벤트의 일부이다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• MySQL 인스턴스 상태 조사: production-us-west-2 MySQL에서 10:40 KST 전후로 장기 실행 트랜잭션이나 lock을 잡고 있던 세션을 확인한다. SHOW ENGINE INNODB STATUS, information_schema.INNODB_TRX, RDS Performance Insights의 blocked/blocking session 뷰가 유용.
• 원인 트랜잭션 식별: Lock timeout 로그의 request timestamp를 기반으로 slow query log 또는 APM에서 동시 실행되던 장기 UPDATE/트랜잭션을 찾는다. 특히 배치 작업(Sidekiq worker, backfill script) 또는 대규모 UPDATE가 있었는지 확인.
• 배포 diff 확인: 20260701T0148Z0-c527a441-cupixworks 배포의 diff에서 새로운 batch UPDATE, 대형 트랜잭션 열기, 또는 hot table(editings, panos, captures, jobs)에 대한 인덱스 변경이 있었는지 확인.
• 이 클러스터는 활성 인시던트 2026-07-01-svc-cupixworks-api--unknown-1의 일부이므로 개별 코드 수정보다 인시던트 대응이 우선.

단기 개선 (1주 이내)#

• FinalizationRepository#assign_editings의 siteinsights 브랜치에 retry 로직 추가 검토: Mysql2::Error::TimeoutError 발생 시 짧은 backoff 후 1~2회 retry. 다만 근본 원인은 아니므로 인시던트 리스크 완화용으로만.
• 편집 할당의 row-level 접근 재설계: 여러 편집자가 동일 record에 대해 assign_editings를 동시에 호출하는 패턴이 존재(record 134695 = 57 hits/1h)한다. Elasticsearch에서 first 항목을 뽑고 UPDATE하는 방식은 race를 유발할 수 있음. SELECT ... FOR UPDATE SKIP LOCKED (Rails 6+ lock("FOR UPDATE SKIP LOCKED")) 또는 큐 기반 assignment로 변경 검토.
• APM 알림 설정: assign_editings p95 latency > 5s 또는 서비스 전체 ActiveRecord::LockWaitTimeout rate > 5/min 시 알림.

장기 개선 (재발 방지)#

• 프로덕션 MySQL의 lock wait / 장기 트랜잭션에 대한 상시 관측(dashboard + on-call alert). 특히 blocked session 수와 innodb history list length.
• Sidekiq 워커 및 API 요청에서 명시적인 statement_timeout 및 트랜잭션 상한 설정.
• 대규모 UPDATE/DELETE는 반드시 배치 크기 상한(예: 500 rows/tx)과 트랜잭션 분리 원칙 강제. 코드 리뷰 체크리스트에 포함.

Monitoring#

Datadog 쿼리 예시 (dashboard timeseries widget용):

avg:trace.rack.request.duration.by_resource{service:cupixworks-api,resource_name:api::v1::admin::userscontroller#assign_editings}

sum:trace.mysql.query.errors{service:cupixworks-api,error_type:activerecord_lockwaittimeout}.as_count()

sum:trace.rack.request.errors{service:cupixworks-api,http.status_code:502}.as_count()

avg:mysql.innodb.row_lock_current_waits{env:production,region:us-west-2}

max:mysql.innodb.row_lock_time_avg{env:production,region:us-west-2}

Risk Assessment#

• Risk level: high — 이 클러스터 자체는 2건이지만, 뿌리 원인인 MySQL row lock 경합은 서비스 전반 502를 유발하는 인시던트임.
• 예상 복잡도: standard (코드 변경보다는 운영/DB 조사 중심). 코드 변경이 필요하다면 트랜잭션 재설계는 non-trivial.