RCA: Api::V1::PointcloudsController#update latency (avg 10319ms)

Overview#

What Happened#

2026-07-03 17:45 KST 경 cupixworks-api 의 Api::V1::PointcloudsController#update 엔드포인트가 단일 요청에서 10.3초의 응답 지연을 기록했다. cupix-agent가 team gilbaneco 소속 사용자 세션으로 다수의 pointcloud 를 일괄 PUT 하는 과정에서 발생했고, 같은 시간대에 다른 pointcloud 업데이트도 5–10초대의 지연을 보였다. 동일 시간창(17:08–18:45 KST)에 captures/724243 에서 ActiveRecord::LockWaitTimeout 502가 반복 발생해 DB row lock 경쟁이 배경 요인으로 확인된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-03 17:08 KST — cupixworks-api 서비스 저하 인시던트 2026-07-03-svc-cupixworks-api--unknown-1 최초 이벤트 (status-board)
2. 2026-07-03 17:45 KST — 본 클러스터 대표 트레이스 (10319ms) 기록
3. 2026-07-03 17:52–17:57 KST — PUT /api/v1/captures/724243 에서 ActiveRecord::LockWaitTimeout 반복 발생 (502)
4. 2026-07-03 18:09 KST — 동일 엔드포인트 응답 시간이 200–400ms 대로 정상화
5. 2026-07-03 18:45 KST — 서비스 저하 인시던트 resolved

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PointcloudsController#update",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10319,
  "max_ms": 10319,
  "sample_trace_id": "4518289087558453390"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (본 클러스터), 인접 20+건이 5–10s 지연으로 관측
• 최초 발생: 2026-07-03 17:45 KST
• 최근 발생: 2026-07-03 17:45 KST

Root Cause Summary#

PointcloudsController#update 는 PointcloudRepository#update 에서 @model.save! 를 호출하고, Pointcloud 모델에는 after_commit 단계에서 실행되는 두 개의 동기 Elasticsearch 쓰기 (Searchable#_update_document 와 EntityIndexable#_entity_update_document) 및 다수의 counter_culture / Notifiable 콜백이 걸려 있다. 문제의 시간창에는 (1) 상위 captures/724243 row lock 경쟁으로 인해 관련 pointcloud 업데이트가 DB 대기 (db: 1220.61ms)에서 지연되고, (2) 저장 이후 after_commit 이 동기적으로 실행하는 ES index 쓰기 (reindex 중이면 primary + tmp_index 이중 쓰기) 가 나머지 ~9초를 차지했다. 즉 순간적으로 DB row lock hotspot + ES 부하가 겹치면서 Pointcloud save 경로 전체가 지연되었고, cupix-agent 가 같은 세션에서 연속으로 다수의 pointcloud 를 PUT 하고 있어 하나의 슬로우 요청이 다른 요청들의 백프레셔를 유발했다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/pointclouds_controller.rb:34 — PointcloudsController#update
• Repository: app/repositories/pointcloud_repository.rb:19 — PointcloudRepository#update
• Failure point (지연): app/repositories/pointcloud_repository.rb:25 — @model.save!

Controller entry:

def update
  @model = repository_instance.update(params)

  super
end

Repository update 는 BaseRepository#update 로 권한/params 세팅 후 @model.save! 를 호출한다:

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

Pointcloud 모델은 다수의 concern 을 include 하며, 그 중 Searchable(via Searchable::Pointcloud) 과 EntityIndexable 이 각각 after_commit on: [:update] 로 동기 ES 쓰기를 수행한다:

include RecordEntity::Pointcloud
include EntityIndexable
include Permissionable::Pointcloud
# ... (약 40개 concern)
include Searchable::Pointcloud

Searchable#_update_document 는 매 update 후 ES client.update 를 호출하고, zero-downtime reindex 진행 중이면 tmp_index 로 이중 쓰기한다:

after_commit on: [:update] do
  _update_document
end
# ...
unless attributes.empty?
  begin
    request = {
      id: __elasticsearch__.id,
      body: { doc: attributes },
      retry_on_conflict: 5
    }
    request.merge!(type: __elasticsearch__.document_type) if __elasticsearch__.document_type

    results = __elasticsearch__.client.update(request.merge({ index: __elasticsearch__.index_name }))
    Cupix::Logger.debug(results.to_json, class: self.class.name, function: __method__)

    # NOTE: dual write to tmp_index while reindexing
    if (tmp_index = self.class.fetch_tmp_index_name)
      __elasticsearch__.client.update(request.merge(index: tmp_index))
    end

EntityIndexable#_entity_update_document 는 별도의 entity index 에 또 한 번 동기 쓰기한다:

included do
  after_commit :_entity_index_document, on: [:create]
  after_commit :_entity_update_document, on: [:update]
  after_commit :_entity_delete_document, on: [:destroy]
end
# ...
def _entity_update_document
  return if @skip_index_document == true

  Elasticsearch::Model.client.index(
    index: self.class.entity_index_name,
    id: entity_document_id,
    body: as_entity_indexed_json
  )
rescue StandardError => e
  Cupix::Logger.error("Entity update error - #{e.message}", class: self.class.name, function: __method__)
end

기대 동작: save! + 콜백 합쳐 수백 ms 이내 종료. 실제 동작: DB row 대기 1220ms + ES 이중 쓰기 · entity index 쓰기 · counter_culture 등 콜백이 합쳐져 총 10308ms 소요.

Log Evidence#

Datadog query:

service:cupixworks-api "PointcloudsController#update" @duration:>10000

시간 범위 2026-07-03T08:44:00Z – 2026-07-03T08:47:00Z 에서 확인한 슬로우 요청 원문 (KST 17:45):

{
  "@timestamp": "2026-07-03T08:45:49.675Z",
  "duration": 10308.74,
  "db": 1220.61,
  "controller": "Api::V1::PointcloudsController",
  "action": "update",
  "http": { "url_details": { "path": "/api/v1/pointclouds/1192265" }, "status_code": 200, "method": "PUT" },
  "params": { "id": "1192265", "fields": ["id", "name", "state", "resource_state", "potree_state", "octree_state", "cpc_mesh_state", "..."] },
  "user_agent": "cupix-agent",
  "team": { "domain": "gilbaneco", "id": 780 },
  "user": { "id": 40509, "email": "esimpson@gilbaneco.com" },
  "request_id": "a8c28c13-0356-4ad4-bcdb-0935ccd1b9a5"
}

duration: 10308.74, db: 1220.61 → wall time 의 ~88% 가 DB 외 구간 (ES 콜백 + Rails 처리). 같은 요청 계열에서 duration: 5448.98, db: 1052.53 인 요청도 관측 (1192263 @08:45:59.693Z) — DB 대기 + 콜백이 반복적으로 큰 비중을 차지.

주변 lock 경쟁 증거 (동일 인시던트 시간창):

service:cupixworks-api ("Lock wait timeout" OR "Deadlock" OR "Timeout::Error" OR "PG::")

{
  "@timestamp": "2026-07-03T08:57:47.969Z",
  "message": "[502] PUT /api/v1/captures/724243 (Api::V1::CapturesController#update)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

동일 시간창의 ES 관련 warn 다수 (Pano/Team/Workspace/ElementTrace 등 여러 모델 공통):

service:cupixworks-api status:warn

{ "@timestamp": "2026-07-03T08:46:59.495Z", "message": "NotFound - attributes_in_database", "class": "Pano", "function": "_update_document" }
{ "@timestamp": "2026-07-03T08:46:56.089Z", "message": "NotFound - attributes_in_database", "class": "Team", "function": "_update_document" }
{ "@timestamp": "2026-07-03T08:46:56.089Z", "message": "NotFound - attributes_in_database", "class": "Workspace", "function": "_update_document" }

이 warn 은 app/models/concerns/searchable.rb:108 에서 발생하며 @__changed_model_attributes 가 비어 있는 상태의 save 를 뜻한다. 여러 모델에서 동시에 관측되는 것은 인시던트 시간창 전반에 걸쳐 트래픽/콜백 부하가 걸렸음을 방증한다.

Status-board 관측 (동일 서비스 · 동일 시간창):

{
  "id": "2026-07-03-svc-cupixworks-api--unknown-1",
  "scope": "svc:cupixworks-api::unknown",
  "status": "resolved",
  "started_at": "2026-07-03T08:08:35.753Z",
  "resolved_at": "2026-07-03T09:45:16.160Z",
  "cluster_ids": ["...", "499956b5-... (본 클러스터가 이 인시던트 시간창에 포함)"]
}

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도 코드 변경 없이 단기적으로는 인시던트 시간창이 이미 해소됨. 향후 재발 대비를 위해 다음 지점을 확인:
  • app/models/concerns/searchable.rb:16-18 및 app/models/concerns/entity_indexable.rb:41-44 — 두 곳 모두 update 시 동기 ES 쓰기. 특히 Pointcloud 처럼 agent 가 짧은 시간에 수십 건씩 PUT 하는 모델은 콜백을 after_commit_async (Sidekiq) 로 옮기는 것이 안전.
• captures/724243 관련 row lock 경쟁: Api::V1::CapturesController#update 의 트랜잭션 범위와 그 하위에서 걸리는 pointclouds 관련 update 를 검토. 캡처 update 트랜잭션이 pointcloud row 를 잠그거나, 반대로 pointcloud update 가 capture row 를 잠그는 경로가 있는지 app/repositories/capture_repository.rb, app/models/concerns/*/capture.rb 를 확인.

단기 개선 (1주 이내)#

• ES index 쓰기 비동기화: Searchable#_update_document 와 EntityIndexable#_entity_update_document 를 Sidekiq worker (BulkIndexWorker 이미 존재) 로 옮기고, request path 에서는 큐잉만 수행. 이미 rescue 경로에서는 BulkIndexWorker.perform_async 를 사용 중 (app/models/concerns/searchable.rb:52,114,117,120) 이므로 이를 정상 경로에도 적용.
• APM 계측 추가: PointcloudsController#update 및 save! after_commit 구간을 별도 Datadog::Tracing.trace 로 감싸 DB / ES / 기타 콜백 시간을 분리 계측.
• API 사이드 rate-limit / batch API: cupix-agent 가 반복 PUT 하는 필드 패턴 (state, resource_state, potree_state, octree_state, cpc_mesh_state, voxel_state) 은 bulk update endpoint 로 통합 검토. 매 pointcloud 마다 save! + ES 이중 쓰기가 반복되는 구조 자체가 지연의 근본 원인.

장기 개선 (재발 방지)#

• Pointcloud 모델의 concern 수 (40+) 와 각 concern 에서 걸리는 콜백 총량을 검토하여 필요 없는 동기 콜백을 정리.
• Zero-downtime reindex 진행 중 dual-write 부하를 완화하기 위한 write-through 캐시 또는 async fan-out 도입.
• Capture ↔ Pointcloud 간 lock hotspot 을 방지하도록 transaction boundary 분리 (예: pointcloud batch update 시 capture 를 잠그지 않는 flow).

Monitoring#

• 추가할 메트릭/알림:
  • PointcloudsController#update 의 p95/p99 latency 알림 (임계 1500ms)
  • Pointcloud after_commit ES index 쓰기 지연 커스텀 span
  • MySQL row lock wait 지속 시간 지표

Datadog 쿼리 예시:

avg:trace.rack.request.duration.by_http_status{service:cupixworks-api,resource_name:api::v1::pointcloudscontroller#update,env:production}.rollup(avg,60)

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::pointcloudscontroller#update,env:production}.rollup(avg,60)

sum:mysql.innodb.row_lock_time{service:cupixworks-api,env:production}.as_rate()

Risk Assessment#

• Risk level: medium — 단일 트레이스는 1건이지만 같은 시간창에 다수의 5–10s 지연 요청이 관측되었고, agent 업로드 파이프라인 사용자 체감 영향이 있음
• 예상 복잡도: standard — after_commit 콜백 비동기화는 기존 BulkIndexWorker 재사용 가능하지만 dual-write 시나리오와 회귀 리스크 검토 필요