Api::V1::ReferencesController#create (avg 1080ms, max 1080ms)
RCA: Api::V1::ReferencesController#create Latency (1080ms)
Overview#
What Happened#
2026-05-26 07:16:49 UTC에 cupixworks-api 서비스의 Api::V1::ReferencesController#create 엔드포인트가 1080ms로 응답하여 500ms latency threshold를 초과했다. ap-southeast-2 리전에서 단일 발생이며 HTTP 200으로 정상 응답했으나 응답 시간이 비정상적으로 길었다.
Quick Facts#
| Field | Value |
|---|---|
| resource_name | Api::V1::ReferencesController#create |
| top_frame | app/factories/reference_factory.rb:5 |
| env | production, ap-southeast-2 |
| duration | 1080ms |
Timeline#
- 2026-05-26T07:16:49Z — ReferencesController#create 요청 수신 (trace_id: 1246722744291408576)
- 2026-05-26T07:16:50Z — EventService.publish_event 완료 (Kinesis put_records)
- 2026-05-26T07:16:52Z — HTTP 200 응답 반환 (총 ~1080ms)
- 2026-05-27 — Error Sweeper 자동 감지 및 RCA 시작
Error Log#
json
{
"resource_name": "Api::V1::ReferencesController#create",
"service": "cupixworks-api",
"occurrences": 1,
"avg_ms": 1080,
"max_ms": 1080,
"sample_trace_id": "1246722744291408576"
}
Impact#
- Service:
cupixworks-api - 발생 횟수: 1
- 최초 발생: 2026-05-26T07:16:49.842Z
- 최근 발생: 2026-05-26T07:16:49.842Z
Root Cause Summary#
ReferencesController#create 요청 시 ReferenceFactory#create!에서 Reference 모델 저장 후 add_reference_sources를 호출한다. 이 과정에서 각 ReferenceSource 레코드 생성 시마다 after_commit 콜백이 트리거되어 (1) write_cache → update_reference_sources → Elasticsearch 재인덱싱, (2) Eventable 이벤트 생성 + Kinesis publish가 동기적으로 실행된다. 단일 요청 내에서 Reference 저장(ES index) + ReferenceSource 생성(각각 ES re-index + Kinesis put) + 이벤트 publish가 순차적으로 수행되어 누적 latency가 1080ms에 달한 것이다.
Technical Analysis#
Code Path#
- Entry point:
app/controllers/api/v1/references_controller.rb:20 - Factory 호출:
app/factories/reference_factory.rb:5 - Model save + ES index:
app/models/concerns/searchable.rb:34-53 - Reference source 생성:
app/repositories/reference_repository.rb:27-93 - Source 생성 후 캐시+ES 갱신:
app/models/concerns/cachable/property/reference_sources.rb:15-25 - 이벤트 publish:
lib/cupix/event_service.rb:21-54
1. Controller → Factory 호출
app/controllers/api/v1/references_controller.rb:20-24ruby
def create
@model = factory_instance.create!(params)
super
end
2. Factory에서 Reference 저장 + Source 추가
app/factories/reference_factory.rb:5-41ruby
def create!(params = {})
self.model = ::Reference.new
if params[:capture_id].present?
capture = CaptureRepository.new(current_user: self.current_user).show(params[:capture_id])
@parent = capture.facility
elsif params[:facility_key].present?
@parent = FacilityRepository.new(current_user: self.current_user).show(params[:facility_key])
end
self.model.facility = self.parent
super # BaseFactory#create! → model.save! → after_commit → _index_document (ES)
reference_repository = ReferenceRepository.new(model: self.model)
if params[:capture_ids].present? || params[:pano_ids].present? || ...
reference_repository.add_reference_sources(...) # 각 source마다 개별 create
end
if params[:capture_id].present?
reference_repository.add_reference_sources(capture_ids: [params[:capture_id]])
end
self.model
end
3. add_reference_sources — N+1 ES index 패턴
app/repositories/reference_repository.rb:27-37ruby
def add_reference_sources(opts = {})
unless opts[:pano_ids].blank?
panos = PanoRepository.where(id: opts[:pano_ids])
panos.each do |pano|
next if @model.reference_sources.where(reference_sourcable: pano).exists?
result = @model.reference_sources.create(reference_sourcable: pano)
# ↑ 각 create마다 after_commit 트리거
end
end
# capture_ids, pointcloud_ids, mesh_ids 등 동일 패턴 반복
end
4. ReferenceSource after_commit → 부모 Reference ES 재인덱싱
app/models/concerns/cachable/property/reference_sources.rb:15-25ruby
def update_reference_sources
_cache_key = cache_key('ReferenceSources', id)
_cache_value = serialized_reference_sources_json # 6개 타입별 DB 조회
if _cache_value.present?
Rails.cache.write(_cache_key, _cache_value, expires_in: self.class.cache_expires_in)
self._index_document if respond_to?(:_index_document) # ES HTTP 요청
end
end
5. Elasticsearch 동기 인덱싱
app/models/concerns/searchable.rb:34-53ruby
after_commit on: [:create] do
_index_document
end
def _index_document
return if @skip_index_document == true
indexed_json = __elasticsearch__.as_indexed_json
results = __elasticsearch__.client.index(...) # 동기 HTTP → ES
if (tmp_index = self.class.fetch_tmp_index_name)
__elasticsearch__.client.index(...) # dual-write 시 추가 HTTP
end
end
6. Kinesis 이벤트 발행
lib/cupix/event_service.rb:21-44ruby
def self.publish_event(events = [])
# ...
response = Cupix::Aws::Kinesis.put_records!({
stream_name: stream_name, records: records
}) # 동기 AWS Kinesis API 호출
end
Log Evidence#
Trace ID 1246722744291408576에 대한 로그:
text
Datadog query: trace_id:1246722744291408576
Time: 2026-05-26T06:00:00Z ~ 2026-05-26T08:30:00Z
text
2026-05-26 16:16:50 KST [info] Published event - failed_record_count: 0 / 1
class: Cupix::EventService, function: publish_event
2026-05-26 16:16:52 KST [info] [200] POST /api/v1/references (Api::V1::ReferencesController#create)
요청 시작(16:16:50 이전)부터 응답(16:16:52)까지 약 2초간 요청이 진행되었으며, EventService.publish_event가 중간에 실행된 것이 확인된다. 실제 APM에서 측정된 duration은 1080ms이다.
동일 시간대 다른 ReferencesController#create 요청들은 정상 속도로 처리됨:
text
Datadog query: service:cupixworks-api "ReferencesController#create"
Time: 2026-05-26T07:28:00Z ~ 2026-05-26T07:30:00Z
2026-05-26 16:29:37 KST [info] [200] POST /api/v1/references (Api::V1::ReferencesController#create)
2026-05-26 16:29:37 KST [info] [200] POST /api/v1/references (Api::V1::ReferencesController#create)
2026-05-26 16:29:36 KST [info] [200] POST /api/v1/references (Api::V1::ReferencesController#create)
다수의 create 요청이 동시에 들어오는 패턴이 관찰되어 batch 생성 시나리오로 추정된다.
Hypotheses Considered#
| # | Hypothesis | Evidence for | Evidence against | Verdict |
|---|---|---|---|---|
| H1 | ReferenceSource 개별 생성 시 after_commit 콜백(ES re-index + cache)이 반복 실행되어 누적 latency 발생 | 코드에서 각 source create마다 _index_document 호출 확인 (reference_sources.rb:21). trace 로그에서 요청이 ~1초 이상 소요. 동시간대 다수 create 요청 패턴 관찰. |
단일 source 추가만 있었다면 1회 호출에 그칠 수 있음 | Confirmed |
| H2 | Kinesis put_records 호출 시 네트워크 latency로 인한 지연 (ap-southeast-2 → Kinesis endpoint) | trace에서 publish_event 로그가 요청 중간에 확인됨. ap-southeast-2 리전은 물리적으로 AWS 서비스 간 latency가 상대적으로 높음 |
Kinesis put_records는 일반적으로 <100ms, failed_record_count=0으로 정상 처리 | Inconclusive |
| H3 | 복잡한 permission_joins SQL 쿼리로 인한 DB latency | permission_joins 메서드에 10개 LEFT JOIN 포함 (reference_repository.rb:135-293) |
permission_joins는 show/search 시에만 사용되고, factory의 CaptureRepository.show에서 호출될 수 있으나 단일 레코드 조회이므로 과도한 지연은 아님 |
Rejected |
| H4 | Elasticsearch dual-write (tmp_index) 로 인한 추가 latency | searchable.rb:47-49에서 tmp_index 존재 시 추가 index 호출 |
reindexing이 진행 중이었는지 확인 불가 — 로그에 직접적 증거 없음 | Inconclusive |
Fix Recommendation#
즉시 조치 (Critical)#
app/repositories/reference_repository.rb:27-93—add_reference_sources메서드에서 개별create를 bulk insert로 변경하거나,skip_index_document플래그를 사용하여 중간 ES 인덱싱을 억제하고 마지막에 1회만_index_document를 호출하도록 변경
단기 개선 (1주 이내)#
ReferenceSource모델의after_commit → write_cache → update_reference_sources → _index_document체인을 비동기화.BulkIndexWorker를 활용하여 reference source 변경 시 ES 재인덱싱을 Sidekiq으로 위임Cupix::EventService.publish_event호출을after_commit콜백 내에서 비동기 worker로 전환
장기 개선 (재발 방지)#
- Reference + ReferenceSource 생성을 단일 트랜잭션 + 단일 ES bulk index 패턴으로 리팩터링
- Elasticsearch 인덱싱을 요청 사이클 밖(background job)으로 완전 분리하여 API 응답 시간에서 ES latency를 제거
serialized_reference_sources_json의 6개 타입별 개별 쿼리를 단일 쿼리로 최적화
Monitoring#
ReferencesController#createp95/p99 latency 모니터링 추가- Datadog APM 쿼리:
text
avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::referencescontroller_create} by {region}
- ES 인덱싱 소요시간 메트릭:
text
avg:elasticsearch.indexing.index.time{service:cupixworks-api}
Risk Assessment#
- Risk level: low
- 예상 복잡도: standard