Api::V1::AssetsController#create (avg 4597ms, max 4597ms)
RCA: Api::V1::AssetsController#create Latency (4597ms)
Overview#
What Happened#
2026-06-04 07:16 KST에 cupixworks-api 서비스의 Api::V1::AssetsController#create 엔드포인트에서 단일 요청이 4597ms로 처리되었다. 동일 시간대에 같은 호스트(ip-10-1-19-190)에서 3건의 극심한 지연(41076599ms)이 관측되었으며, 다른 호스트에서는 정상(80135ms)으로 처리되었다.
Quick Facts#
| Field | Value |
|---|---|
| resource_name | Api::V1::AssetsController#create |
| top_frame | app/controllers/api/v1/assets_controller.rb:28 |
| env | production, us-west-2 |
| avg_duration | 4597ms |
| affected_host | ip-10-1-19-190.us-west-2.compute.internal |
Affected Teams#
| Team / Domain | Error Count | Impact |
|---|---|---|
| enbridge (team_id: 1088) | 3 | Asset 업로드 응답 지연 (4~6초), 클라이언트 UX 저하 |
Timeline#
- 2026-06-04 07:16:28 KST — 첫 번째 느린 요청 감지 (6599ms, 파일: 26.mp4, capture_id: 707452)
- 2026-06-04 07:16:42 KST — 클러스터 대표 span 기록 (4597ms)
- 2026-06-04 07:16:48 KST — 두 번째 느린 요청 (4571ms, 파일: 27.jpg, capture_id: 707452)
- 2026-06-04 07:16:59 KST — 세 번째 느린 요청 (4107ms, 파일: 3.mp4, capture_id: 707510)
- 2026-06-04 07:17:14 KST — 다른 호스트에서 정상 응답 확인 (98ms)
Error Log#
text
{
"resource_name": "Api::V1::AssetsController#create",
"service": "cupixworks-api",
"occurrences": 1,
"avg_ms": 4597,
"max_ms": 4597,
"sample_trace_id": "1285544296985924367"
}
Impact#
- Service:
cupixworks-api - 발생 횟수: 1 (동일 시간대 유사 사례 3건)
- 최초 발생: 2026-06-04 07:16 KST
- 최근 발생: 2026-06-04 07:16 KST
Root Cause Summary#
AssetsController#create 요청이 4597ms 지연된 원인은 after_commit 콜백에서 수행되는 동기적 Elasticsearch 인덱싱이 핵심 병목이다. Asset 생성 시 Searchable#_index_document, EntityIndexable#_entity_index_document가 각각 동기 HTTP 호출로 Elasticsearch에 문서를 인덱싱하며, after_create 콜백에서 생성된 Resource 모델도 동일한 동기 인덱싱을 수행하여 총 35회의 동기 ES 호출이 발생한다. DB 시간은 423507ms로 정상 범위(29~44ms) 대비 10배 높았으나, 나머지 ~4000ms는 애플리케이션 코드(주로 ES 인덱싱 + ancestry 해석)에서 소비되었다. 이 현상이 특정 호스트(ip-10-1-19-190)에 집중된 점으로 보아, 해당 호스트에서 Elasticsearch 클러스터로의 네트워크 지연 또는 ES 노드 부하가 겹쳤을 가능성이 높다.
Technical Analysis#
Code Path#
- Entry point:
app/controllers/api/v1/assets_controller.rb:28
app/controllers/api/v1/assets_controller.rb:27-31ruby
def create
@model = factory_instance.create!(params)
super
end
- Factory:
AssetFactory#create!가 Capture를 조회하고BaseFactory#create!를 호출하여model.save!실행
app/factories/asset_factory.rb:5-34ruby
def create!(params = {})
_required_params = %i[name asset_type]
_required_params.each do |param|
raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: "#{param} is required") if params[param].nil?
end
self.model = ::Asset.new
_assetable =
if params[:capture_id].present?
CaptureRepository.new(
current_user: current_user,
review: @review
).show(params[:capture_id])
# ...
end
model.assetable = _assetable
model.facility = _assetable.facility
super
end
- after_create 콜백: Asset 저장 후 Resource를 추가 생성 (트랜잭션 내)
app/models/concerns/resourcable/asset.rb:8-16ruby
after_create :after_asset_create
def after_asset_create
create_asset_resource
end
def create_asset_resource
ResourceFactory.new(current_user: user, current_team: self.team).create!({ resourcable: self, name: name })
end
- Failure point (병목):
after_commit에서 동기적 Elasticsearch 인덱싱
app/models/concerns/searchable.rb:34-53ruby
def _index_document
return if @skip_index_document == true
indexed_json = __elasticsearch__.as_indexed_json
base_request = {
id: __elasticsearch__.id,
body: indexed_json
}
results = __elasticsearch__.client.index(base_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.index(base_request.merge(index: tmp_index))
end
rescue StandardError => e
Cupix::Logger.error("Index error - #{e.message}", class: self.class.name, function: __method__)
BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end
app/models/concerns/entity_indexable.rb:160-170ruby
def _entity_index_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 index error - #{e.message}", class: self.class.name, function: __method__)
end
- ancestry 해석:
_entity_ancestry가 각 ancestor별 개별 DB 조회 실행
app/models/concerns/entity_indexable.rb:108-120ruby
def _entity_ancestry(cache = nil)
h = {}
_add_ancestor(h, :team, :team_id, cache)
_add_ancestor(h, :workspace, :workspace_id, cache)
_add_facility_ancestor(h, cache)
_add_ancestor(h, :record, :record_id, cache)
_add_ancestor(h, :capture, :capture_id, cache)
_add_ancestor(h, :level, :level_id, cache)
_add_ancestor(h, :bim, :bim_id, cache)
_add_ancestor(h, :review, :review_id, cache)
_add_ancestor(h, :annotation_layer, :annotation_layer_id, cache)
h
end
기대 동작: Asset 생성 후 빠르게 HTTP 200 응답 반환 (< 200ms)
실제 동작: 동기적 ES 인덱싱 + ancestry DB 조회가 after_commit 내에서 블로킹되어 4597ms 소요
Log Evidence#
Datadog 쿼리:
text
service:cupixworks-api (AssetsController OR asset) @http.method:POST
핵심 로그 (동일 시간대 느린 요청들):
json
{
"timestamp": "2026-06-03T22:16:28.931Z",
"resource_name": "Api::V1::AssetsController#create",
"duration_ms": 6598.96,
"db_duration_ms": 507.46,
"host": "ip-10-1-19-190.us-west-2.compute.internal",
"user": "Ryan Vaughan",
"team": "enbridge",
"file": "26.mp4",
"capture_id": 707452
}
json
{
"timestamp": "2026-06-03T22:16:48.999Z",
"resource_name": "Api::V1::AssetsController#create",
"duration_ms": 4571.03,
"db_duration_ms": 423.35,
"host": "ip-10-1-19-190.us-west-2.compute.internal",
"user": "Ryan Vaughan",
"team": "enbridge",
"file": "27.jpg",
"capture_id": 707452
}
동일 시간대 다른 호스트의 정상 응답:
json
{
"timestamp": "2026-06-03T22:16:32.969Z",
"resource_name": "Api::V1::AssetsController#create",
"duration_ms": 135.79,
"db_duration_ms": 44.87,
"host": "ip-10-1-80-134.us-west-2.compute.internal",
"user": "Mark Wilson",
"team": "enbridge",
"file": "26.jpg",
"capture_id": 707510
}
핵심 관측:
- DB 시간(423
507ms)은 전체 응답(45716599ms)의 약 8~10%에 불과 - 나머지
40006000ms는 애플리케이션 레벨 (ES 인덱싱 + ancestry 해석)에서 소비 - 정상 호스트 대비 DB 시간도 10배 높아 해당 호스트의 전반적 부하 확인
Hypotheses Considered#
| # | Hypothesis | Evidence for | Evidence against | Verdict |
|---|---|---|---|---|
| H1 | 동기적 Elasticsearch 인덱싱이 응답 시간을 블로킹 | searchable.rb:43, entity_indexable.rb:163에서 동기 HTTP 호출 확인. DB 시간(507ms) 대비 전체(6599ms) 차이 ~6000ms가 ES+ancestry에 해당. 특정 호스트에 집중 |
에러 로그 없음 (ES 호출 실패 시에만 로깅) | Confirmed |
| H2 | 대용량 파일 업로드로 인한 네트워크 대역폭 경합 | mp4 파일(26.mp4, 3.mp4) 포함. 같은 호스트에서 연속 요청 | AssetsController#create는 presigned URL 발급만 하며 실제 파일 전송은 클라이언트→S3 직접 업로드. jpg(27.jpg)도 동일하게 느림 | Rejected |
| H3 | DB 커넥션 풀 고갈 또는 DB 부하 | DB 시간 423 |
DB 시간은 전체 latency의 10% 미만. 주 병목은 DB 외부. 다른 호스트는 정상 DB 시간 | Rejected |
| H4 | 특정 호스트의 Elasticsearch 연결 지연 (네트워크 또는 ES 노드 부하) | 3건 모두 동일 호스트(ip-10-1-19-190). 다른 호스트는 정상. DB 시간도 해당 호스트에서만 상승 |
호스트 레벨 메트릭 미확인 (uncertain) | Confirmed (보조 원인) |
Fix Recommendation#
즉시 조치 (Critical)#
app/models/concerns/searchable.rb:34-53—_index_document를 비동기로 전환하여after_commit콜백에서 Sidekiq worker로 위임. 현재 에러 시에만BulkIndexWorker.perform_async를 호출하는데, 정상 경로에서도 비동기 인덱싱을 기본으로 사용해야 한다.app/models/concerns/entity_indexable.rb:160-170—_entity_index_document도 동일하게 비동기 worker로 전환.
단기 개선 (1주 이내)#
_entity_ancestry메서드(entity_indexable.rb:108-120)에서 각 ancestor별 개별 DB 쿼리를 batch 조회 또는 캐시 활용으로 변경. 현재 cache 파라미터가 존재하지만after_commit경로에서는 nil로 전달되어 매번 DB 직접 조회.Resourcable::Asset#after_asset_create에서 Resource 생성을 별도 트랜잭션 또는 비동기로 분리하여 Asset 생성 트랜잭션의 lock 시간 단축.
장기 개선 (재발 방지)#
- Elasticsearch 인덱싱을 전면적으로 이벤트 기반 비동기 파이프라인으로 전환 (예: Sidekiq worker + bulk indexing 주기적 실행).
after_commit콜백에서 동기 외부 호출을 금지하는 lint rule 또는 코드 리뷰 체크리스트 도입.- 호스트별 ES 연결 latency를 모니터링하여 특정 노드의 네트워크 이슈 조기 감지.
Monitoring#
- ES 인덱싱 latency per host 추가 모니터링:
text
avg:trace.elasticsearch.query.duration{service:cupixworks-api} by {host}
- AssetsController#create p95 latency 알림:
text
p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::assetscontroller#create} > 2000
after_commit콜백 실행 시간을 custom metric으로 계측하여 인덱싱 병목 가시화
Risk Assessment#
- Risk level: medium
- 예상 복잡도: standard — 비동기 전환은 기존
BulkIndexWorker인프라를 활용할 수 있으나, 인덱싱 지연에 따른 eventual consistency 영향도 검증 필요