RCA: Api::V1::UsersController#update latency spike (12861ms)

Overview#

관리자가 사용자 하나를 비활성 처리하는 PUT /api/v1/users/36575 요청이 12861 ms 걸렸다. 이 요청 시간의 거의 전부인 12098 ms 는 단일 SQL DELETE FROM sessions WHERE sessions.user_id = ? 한 문장에서 소비됐다. 이 DELETE 는 user 를 inactive 상태로 전이할 때 Statable::User state machine 이 동기적으로 실행하는 세션 정리다. sessions.user_id 에는 인덱스가 있어 쿼리 계획 자체는 정상이며, 지연은 같은 배포 창(deploy production-us-west-2-20260806t0615z0)에서 발생한 광범위한 InnoDB lock 경합 때문이다. 같은 분에 다른 엔드포인트에서 Lock wait timeout exceeded 와 Deadlock 이 다수 관측된다.

What Happened#

2026-08-06 16:21 KST, cupixworks-api 에서 Api::V1::UsersController#update 요청 한 건이 12861 ms 로 느리게 처리됐다(HTTP 200 성공). 지연의 원인은 user 비활성 전이 시 실행되는 DELETE FROM sessions WHERE sessions.user_id = ? 가 InnoDB row lock 을 12 초간 기다린 것이다. 배포 직후 DB primary 의 lock 경합 창에 국한된 단발 outlier 다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-08-06 14:42 KST — 05:42:15Z, svc:cupixworks-api::unknown 인시던트 시작(배포 창 서비스 저하 burst).
2. 2026-08-06 15:15 KST — 06:15Z 배포 production-us-west-2-20260806t0615z0 반영.
3. 2026-08-06 15:46 KST — 같은 primary 에서 PanosController#update_meta_by_key 다수 [502] Lock wait timeout exceeded 관측.
4. 2026-08-06 16:21 KST — 07:21:05Z, PUT /api/v1/users/36575 (UsersController#update) 12861 ms, 세션 DELETE 12098 ms. 이 클러스터의 유일 발생.
5. 2026-08-06 16:29 KST — EditingsController#update [503] ActiveRecord::Deadlocked 관측(동일 경합 창).

Error Log#

이 클러스터는 예외가 아니라 latency 클러스터다. 대표 span 은 아래와 같다.

Datadog Logs

{
  "resource_name": "Api::V1::UsersController#update",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 12861,
  "max_ms": 12861,
  "sample_trace_id": "4513560000868804017"
}

Impact#

• Service: cupixworks-api
• Team: cupix
• 발생 횟수: 1
• 최초 발생: 2026-08-06 16:21 KST
• 최근 발생: 2026-08-06 16:21 KST

Root Cause Summary#

관리자가 admin.cupix.works 에서 user 36575 를 비활성 처리하는 PUT /api/v1/users/36575 요청을 보냈다. UserRepository#update 의 @model.save! 가 user state 를 inactive 로 전이시키고, Statable::User state machine 의 after_transition any => :inactive 콜백이 요청 스레드 안에서 동기적으로 user.sessions.delete_all (DELETE FROM sessions WHERE sessions.user_id = ?) 을 실행한다. sessions.user_id 에는 index_sessions_on_user_id 인덱스가 있어 쿼리 계획은 정상이지만, 이 DELETE 가 InnoDB row/gap lock 을 획득하려고 12098 ms 대기했다. 대기의 근본 원인은 이 코드가 아니라 같은 배포 창(production-us-west-2-20260806t0615z0)에 primary DB 에서 벌어진 광범위한 lock 경합이다. 같은 분 다른 엔드포인트에서 Lock wait timeout exceeded, Deadlock 이 다수 관측된다. 요청은 결국 200 으로 성공했다. 따라서 endpoint 코드 결함이 아닌 transient DB 경합에 따른 단발 지연이다. 다만 세션 정리를 요청 경로에서 동기 실행하는 구조는 경합 시 요청 스레드를 길게 점유하는 resilience gap 이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/users_controller.rb:42

def update
  @model = repository_instance.update(params.permit!)

  super
end

• Repository update: app/repositories/user_repository.rb:123-139 의 @model.save! 가 state 변경을 커밋한다.

def update(params = {})
  super

  set_parameters(params)

  begin
    @model.save!

    if params[:password].present? && params[:new_password] && params[:new_password_confirm]
      Cupix::Mailer::UserMailer.password_changed(@model)
    end
  rescue StandardError => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
  end

  @model
end

• Failure(지연) point: app/models/concerns/statable/user.rb:38-40 — user 가 inactive 로 전이되면 콜백이 요청 스레드에서 세션을 동기 삭제한다.

after_transition any => :inactive do |user, transition|
  user.sessions.delete_all
end

• 연관 정의: app/models/user.rb:54 — has_many :sessions, dependent: :delete_all. 콜백의 sessions.delete_all 이 DELETE FROM sessions WHERE sessions.user_id = ? 를 발행한다.

has_many :sessions, dependent: :delete_all

• 인덱스 존재 확인: db/schema.rb:3942 — user_id 는 인덱싱돼 있어 full scan 이 아니다. 즉 지연은 쿼리 계획이 아니라 lock 대기다.

t.integer "user_id"
t.datetime "user_updated_at", precision: nil
t.index ["credential_id"], name: "index_sessions_on_credential_id"
t.index ["expires_at"], name: "index_sessions_on_expires_at"
t.index ["grant_type"], name: "index_sessions_on_grant_type"
t.index ["state"], name: "index_sessions_on_state"
t.index ["token"], name: "index_sessions_on_token"
t.index ["user_id"], name: "index_sessions_on_user_id"

기대 동작: sessions.user_id 인덱스로 해당 user 세션만 짧게 삭제하고 요청이 수백 ms 내 완료된다(정상 시 p50 = 676 ms).

실제 동작: DELETE 가 InnoDB lock 을 획득하려고 12098 ms 대기한 뒤 완료됐고, 요청 전체가 12861 ms 가 됐다.

Log Evidence#

트레이스 분해 쿼리(재현용):

trace_id:4513560000868804017

대표 트레이스의 가장 느린 span 은 단일 mysql2 쿼리다. span attribute 원문:

{
  "base_service": "cupixworks-api",
  "component": "mysql2",
  "db": {
    "instance": "tesla_production",
    "statement": "DELETE FROM sessions WHERE sessions . user_id = ?",
    "system": "mysql"
  },
  "duration": 12098083598,
  "env": "production",
  "operation": "query",
  "peer": { "db": { "name": "tesla_production", "system": "mysql" }, "hostname": "db-tesla.cupix.internal" },
  "version": "production-us-west-2-20260806t0615z0-5d437c17-cupixworks"
}

루트 rack span 은 12861 ms 이며 요청은 성공했다:

{
  "method": "PUT",
  "route": "/api/v1/users/:id",
  "url_details": { "path": "/api/v1/users/36575" },
  "base_url": "http://admin.cupix.works",
  "status_code": "200",
  "response": { "headers": { "x-request-id": "62088a75-adb0-4dc7-840c-06bbec5c5247" } }
}

같은 요청의 request 로그(쿼리 service:cupixworks-api "users/36575"):

2026-08-06 16:21:18  info  [200] PUT /api/v1/users/36575 (Api::V1::UsersController#update)

같은 경합 창의 DB lock 증거(쿼리 service:cupixworks-api ("Lock wait timeout" OR "Deadlock")):

{
  "timestamp": "2026-08-06 15:46:43",
  "message": "[502] PUT /api/v1/panos/11015076/meta/blurriness (Api::V1::PanosController#update_meta_by_key)",
  "error": { "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction", "class": "ActiveRecord::LockWaitTimeout" }
}
{
  "timestamp": "2026-08-06 16:29:23",
  "message": "[503] PATCH /api/v1/editings/1344125 (Api::V1::EditingsController#update)",
  "error": { "message": "Mysql2::Error: Deadlock found when trying to get lock; try restarting transaction", "class": "ActiveRecord::Deadlocked" }
}

Latency 분포(쿼리 service:cupixworks-api resource_name:"Api::V1::UsersController#update", now-14d, 170 spans):

p50=676 p90=1349 p95=1569 p99=12832 max=12861 min=2 ms
>2000ms: 4 / 170
12861ms  host i-0624c7093702339fd
12832ms  host i-0624c7093702339fd   (동일 요청의 action_pack span)
3468ms   host i-06ff6863ff3e53ea0
3454ms   host i-06ff6863ff3e53ea0

170 건 중 baseline 은 676 ms 이며 2000 ms 초과는 4 건뿐이다. 12.8 초 쌍은 이 트레이스 하나의 rack + action_pack span 이다. endpoint 는 평상시 정상이고 이 발생만 outlier 다.

Hypotheses Considered#

Fix Recommendation#

이 발생은 배포 창 DB 경합에 따른 단발 latency outlier 이며 endpoint 코드 결함이 아니다. 코드 변경 없이 인시던트 모니터링으로 충분하다. 다만 세션 정리를 요청 경로에서 동기 실행하는 구조는 경합 시 요청을 길게 점유하므로 선택적 개선 여지가 있다.

즉시 조치 (Critical)#

• 코드 수정 불필요. svc:cupixworks-api::unknown (2026-08-06-svc-cupixworks-api--unknown-1) 인시던트가 해소되었는지 확인하고, 이 클러스터를 해당 인시던트에 귀속시킨다. 상태는 <DOCS_SITE_URL>/status 에서 확인한다.

단기 개선 (1주 이내)#

• app/models/concerns/statable/user.rb:39 의 user.sessions.delete_all 를 요청 경로에서 분리하는 것을 검토한다. 세션 무효화는 사용자 응답을 블록할 필요가 없으므로 background worker(예: Sidekiq)로 async 실행하면 비활성 처리 요청이 DB 경합에 걸려도 admin 응답 지연이 없다. 단, 보안상 즉시 무효화가 필요하면 async 지연 시간을 짧게 잡는다.

장기 개선 (재발 방지)#

• 배포 창 lock 경합 자체가 별도 트랙이다(EditingsController#update deadlock, PanosController#update_meta_by_key lock wait 는 기존 에피소드로 추적 중). primary DB 의 배포 시점 경합을 줄이는 방향(배포 중 무거운 write 워크로드 스로틀, 커넥션/트랜잭션 범위 축소)을 인프라 트랙에서 검토한다.

Monitoring#

UsersController#update 요청 처리 시간 추세(APM latency metric):

avg:trace.rack.request{service:cupixworks-api,resource_name:api::v1::userscontroller#update}

배포 창 DB lock 경합 재발 추적(요청 로그, lock wait / deadlock 을 표면화하는 502/503):

service:cupixworks-api ("Lock wait timeout exceeded" OR "Deadlock found when trying to get lock")

세션 정리 경로가 표면화하는 500 (UsersController#update 실패):

service:cupixworks-api "Api::V1::UsersController#update" @http.status_code:[500 TO 599]

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (코드 변경 시 async 전환은 standard)