RCA: Api::V1::ClustersController#create Latency (avg 1866ms, max 2358ms)

Overview#

What Happened#

2026-05-26 08:2208:24(UTC) 사이에 Api::V1::ClustersController#create 엔드포인트에서 2건의 요청이 평균 1866ms, 최대 2358ms의 비정상적 지연을 보였다. 정상 기준(80135ms) 대비 1530배 느린 응답이다. 두 건 모두 DB 시간이 전체의 8995%를 차지했으며, 동일 capture에 대해 postprocessor 완료 워크플로우가 동시에 실행 중이었다.

Quick Facts#

Timeline#

1. 2026-05-26T08:22:05Z — 첫 번째 느린 요청 발생 (capture_id=702529, 2355ms, DB 2099ms)
2. 2026-05-26T08:24:33Z — 두 번째 느린 요청 발생 (capture_id=695076, 1372ms, DB 1303ms)
3. 2026-05-27 — Error Sweeper 감지 및 RCA 수행

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ClustersController#create",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 1866,
  "max_ms": 2358,
  "sample_trace_id": "6106666673141557374"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-05-26T08:22:05.576Z
• 최근 발생: 2026-05-26T08:24:33.254Z
• 영향 받은 사용자: 2명 (tanseisha 팀: m-takata@tanseisha.co.jp, siteline 팀: daniel.lovik@truebeck.com)
• 사용자 체감: Cluster 생성 API 응답이 ~2초 지연. cupix-agent가 호출한 요청으로, 에이전트 파이프라인의 후속 처리가 대기함.

Root Cause Summary#

Postprocessor 완료 워크플로우가 동일 capture에 대해 대량의 동시 쓰기(state transition, reset_parent_cached_entity_updates, entity update 등)를 수행하는 도중에 ClustersController#create가 실행되면서 row-level lock contention이 발생했다. Cluster 생성 과정에서 counter_culture 콜백이 captures 테이블의 clusters_count를 UPDATE하는데, 동시에 postprocessor가 같은 capture row를 반복적으로 UPDATE하고 있어 lock 대기 시간이 DB time의 89~95%를 차지하게 되었다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/clusters_controller.rb:24
• Factory: app/factories/cluster_factory.rb:5-33
• Base save: app/factories/base_factory.rb:124 (@model.save!)
• Counter culture: app/models/cluster.rb:40-42
• Ancestry validation: app/models/concerns/ancestryable/cluster.rb:11-17
• Elasticsearch indexing: app/models/concerns/searchable.rb:12-22

Controller:

def create
  @model = factory_instance.create!(params)
  super
end

Factory — Capture 조회 및 Cluster 생성:

def create!(params)
  # ...
  capture = CaptureRepository.new(...).show(params[:capture_id])  # DB query 1
  # ... build model ...
  parent_cluster = ClusterRepository.new(...).show(params[:cluster_id])  # DB query 2 (optional)
  self.model.update_attribute(:parent, parent_cluster)  # DB query 3 — SEPARATE UPDATE after INSERT
end

Counter Culture — capture의 clusters_count를 개별 UPDATE:

counter_culture :capture,
                column_name: proc { |model| model.untrashed? ? 'clusters_count' : nil }

이 콜백은 save! 이후에 captures 테이블에 대한 별도 UPDATE clusters_count = clusters_count + 1 SQL을 실행한다. Postprocessor가 동일 capture row를 점유하고 있으면 이 UPDATE가 lock을 대기하게 된다.

Ancestry 검증 — 추가 쿼리:

before_save :update_cluster_kind
before_save :update_cluster_ancestry
validate :check_ancestry
validate :validate_cluster_kind
validate :validate_cluster_ancestry

check_ancestry 내에서 children.size, ancestors.size, descendants.size를 호출하여 추가 COUNT 쿼리를 발생시킨다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api @duration:>500 "ClustersController#create"

service:cupixworks-api trace_id:6106666673141557374

service:cupixworks-api trace_id:7043480453219843657

느린 요청 1 (2355ms, capture_id=702529):

Timestamp: 2026-05-26T08:22:08.336Z
Duration:  2355.24 ms (total)
DB time:   2099.40 ms (89% of total)
View:      0.15 ms
Host:      ip-10-1-80-134.us-west-2.compute.internal
User:      m-takata@tanseisha.co.jp (team: tanseisha, id: 745)
Params:    name="Unrefined Cluster", capture_id=702529
User Agent: cupix-agent
Request ID: 826bb92b-8544-4cab-936f-db2b7de61340

느린 요청 2 (1372ms, capture_id=695076):

Timestamp: 2026-05-26T08:24:36.275Z
Duration:  1371.79 ms (total)
DB time:   1303.03 ms (95% of total)
View:      0.10 ms
Host:      ip-10-1-144-228.us-west-2.compute.internal
User:      daniel.lovik@truebeck.com (team: siteline, id: 1012)
Params:    name="Unrefined Cluster", capture_id=695076
User Agent: cupix-agent
Request ID: 9c228ab8-5b88-43ed-bf21-5b98f98ebc7c

동일 trace에서 확인된 동시 작업 (postprocessor):

# trace_id:7043480453219843657 — capture 702529
- 다수의 reset_parent_cached_entity_updates 호출 (Facility 13482)
- NotFound - attributes_in_database 경고 (Capture._update_document, Record._update_document)
- [400] Invalid state: uploaded — check_process_output_uploading
- Duplicate kind: alignments_all / alignments_sampled 에러

# trace_id:6106666673141557374 — capture 695076
- 다수의 reset_parent_cached_entity_updates 호출 (Facility 13989) — 초당 10회 이상
- NotFound - attributes_in_database 경고
- State transitions: done -> finalizing -> done -> stopping -> stopped

정상 요청과의 비교:

정상 요청의 DB time은 2025ms로, 문제 요청(13032099ms)과 50~100배 차이가 난다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

없음. 이 현상은 간헐적 lock contention으로 서비스 장애를 유발하지는 않으며, 발생 빈도가 낮다 (2건).

단기 개선 (1주 이내)#

1. update_attribute(:parent, ...) 제거 — app/factories/cluster_factory.rb:29

   • parent relationship을 save! 전에 설정하여 INSERT 1회로 통합. 별도 UPDATE SQL이 capture row lock을 추가로 점유하는 시간을 제거.

2. counter_culture를 비동기로 전환 검토 — app/models/cluster.rb:40-42

   • clusters_count 업데이트를 after_commit + background job으로 처리하면 API 응답 시간에서 lock 대기를 분리할 수 있음.

장기 개선 (재발 방지)#

1. Postprocessor 완료 워크플로우의 write 최적화

   • reset_parent_cached_entity_updates가 동일 facility/capture에 대해 초당 10회 이상 호출되는 패턴을 debounce 또는 batch로 통합하여 lock 보유 시간을 줄임.

2. Advisory lock 또는 retry 패턴 도입

   • Cluster 생성 시 capture row lock 획득에 실패하면 짧은 retry로 대응. 또는 SELECT FOR UPDATE NOWAIT + exponential backoff 적용.

Monitoring#

• Counter 메트릭 추가: ClustersController#create의 DB time > 500ms 발생 시 알림
• Datadog 쿼리:

service:cupixworks-api resource_name:"Api::V1::ClustersController#create" @duration:>500

• Lock wait 모니터링: RDS Performance Insights에서 captures 테이블의 row lock wait 증가 추적

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 발생 빈도가 낮고(2건/일) 사용자 체감 영향이 제한적이나, postprocessor 부하가 높은 시간대에 반복될 수 있음.