RCA: Api::V1::FieldsController#index latency (36669ms)

Overview#

What Happened#

2026-07-30 21:23 KST Api::V1::FieldsController#index 리소스에서 36.7초 단일 latency trace 가 발생했다. 오류가 아닌 latency 클러스터이며(200 응답), 자동 감지 인시던트 2026-07-30-svc-cupixworks-api--unknown-1 (2026-07-30 20:34 KST 시작, 21:23 KST 해소) 의 다섯 번째이자 마지막 이벤트로 인시던트 종료 시점에 발생했다. 같은 인시던트에는 SitetracksController#check_uploading (77.7s), PointcloudsController#cpc_mesh_upload_url (19s), BadgesController#index (12.4s) 등 서로 다른 4개 리소스의 latency 클러스터가 함께 묶여 있다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-30 20:34:05 KST — 인시던트 첫 클러스터 SitetracksController#check_uploading 77.7s trace 발생 (9855766b), 인시던트 자동 감지 시작.
2. 2026-07-30 20:35:27 KST — 두 번째 클러스터 e758e925 발생.
3. 2026-07-30 21:05~21:23 KST — 서비스 전반 avg request duration 이 baseline (0.30.9s) 에서 2.02.6s 로 상승, 요청 rate 2560 → 80100 req/s.
4. 2026-07-30 21:05:28 KST — PointcloudsController#cpc_mesh_upload_url 19s trace (dfa0ed54).
5. 2026-07-30 21:06:40 KST — BadgesController#index 12.4s trace (1feaf5c5).
6. 2026-07-30 21:23:30 KST — 본 클러스터 FieldsController#index 36.7s trace 발생 (da6d4c75, first_seen == last_seen). 인시던트 자동 해소.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FieldsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 36669,
  "max_ms": 36669,
  "sample_trace_id": "2953304059702542039"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-30 21:23 KST
• 최근 발생: 2026-07-30 21:23 KST

Root Cause Summary#

이 클러스터는 개별 코드 결함이 아니라, 해소된 서비스 전반 성능 저하 인시던트(2026-07-30-svc-cupixworks-api--unknown-1) 의 마지막 이벤트로 발생한 단발성 slow trace 다. FieldsController#index 경로는 fieldable(annotation / asset_instance / work_order) 를 lookup 한 뒤 FieldRepository#search → form_values → (hierarchical 또는 legacy) form field join → paginate 를 수행하는 read/mixed I/O 경로다. 정상 baseline 은 sub-second 수준이며, 이 요청 하나가 36.7s 로 튀는 것은 코드 자체보다 서비스 전반의 request-handling 포화(avg duration 35x, 요청 rate 23x) 상태에서 (a) Rack request queue / 스레드 대기, (b) MySQL 커넥션 pool 대기 또는 join-heavy 쿼리 지연, (c) N+1 (prepare_fields_from_legacy_form_fields 의 _fields.each ... fieldable.fields.create 루프) 중 하나 또는 조합으로 늘어난 것으로 판단된다. 다만 이 클러스터의 개별 trace flame graph 로 어느 span 이 시간을 소비했는지 직접 확인하지는 못했으므로 개별 요인 비중은 uncertain — needs verification. 근본 원인은 fields 코드 자체가 아니며, 상위 인시던트의 원인(현재 root_cause_types: [unknown] 으로 미분류) 이 규명되어야 이 클러스터도 재발 방지된다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/fields_controller.rb:10-19 — Api::V1::FieldsController#index
• Repository: app/repositories/field_repository.rb:308-348 — FieldRepository#search
• Fieldable lookup (I/O #1): app/repositories/field_repository.rb:317-328 — annotation / asset_instance / work_order 를 다른 repository 로 조회
• Form field join (I/O #2, N+1 후보): app/repositories/field_repository.rb:415-442 — prepare_fields_from_legacy_form_fields
• Hierarchical branch (I/O #2', insert 포함): app/repositories/field_repository.rb:364-413 — prepare_fields_from_hierarchical_form_fields

def index
  field_query_option = Cupix::QueryOption::Field.new(get_query_option, params)
  fields = repository_instance.search(field_query_option)

  render_api Renderable.new({
    search_result: fields,
    is_collection: true,
    serializer_option: @serializer_option
  })
end

FieldRepository#search 는 fieldable 종류에 따라 다른 repository 로 위임한다. 파라미터가 없으면 Cupix::Errors::Parameter 로 즉시 실패(latency 원인 아님) — 이 요청은 파라미터가 유효했다는 뜻이므로 fieldable lookup 은 실행됐다.

def search(query_option = nil)
  set_query_option(query_option)
  review_id = -1

  if self.query_option.review_key.present?
    review = ReviewRepository.new(current_user: self.current_user).show(self.query_option.review_key)
    review_id = review.id
  end

  fieldable = if self.query_option.annotation_id.present?
                AnnotationRepository.new(current_user: current_user)
                                    .show(self.query_option.annotation_id, review_id: review_id)
              elsif self.query_option.asset_instance_id.present?
                AssetInstanceRepository.new(current_user: current_user)
                                       .show(self.query_option.asset_instance_id)
              elsif self.query_option.work_order_id.present?
                WorkOrderRepository.new(current_user: current_user)
                                   .show(self.query_option.work_order_id)
              else
                raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'No fieldable_id(annotation or asset_instance or work_order) provided')
              end

  fields = form_values(fieldable).paginate(per_page: self.query_option.per_page, page: self.query_option.page).order('row_order ASC')

Legacy 경로는 매 field 마다 fieldable.fields.create 를 호출할 수 있는 N+1 write 루프를 포함한다 — 부하 창구에서는 이 write 반복이 커넥션 pool 을 점유하며 latency 증폭 요인이 될 수 있다.

def prepare_fields_from_legacy_form_fields(fieldable)
  fieldable_class = fieldable.class.name
  fieldable_id = fieldable.id

  _fields = fieldable.form_fields.joins("
  LEFT OUTER JOIN fields ON (
    fields.form_field_id = form_fields.id
    AND fields.fieldable_id = #{ApplicationRecord.sanitize_sql(fieldable_id)}
    AND fields.fieldable_type = '#{fieldable_class}'
  )").select("
    fields.*, fields.id AS id, fields.uuid AS uuid, form_fields.kind AS form_field_kind, ...
  ")

  refresh = false
  _fields.each do |field|
    if field.id.blank?
      res = fieldable.fields.create(form_field_id: field.form_field_id)
      refresh = true
    end
  end

  if refresh
    Cupix::Logger.info("Create fields for #{fieldable_class} #{fieldable_id}", class: self.class.name, function: __method__)
    _fields.reload
  else
    _fields
  end
end

Hierarchical 경로도 트랜잭션 안에서 Field.insert_all + BulkSavePartialJsonToFileWorker.perform_async 를 수행 — sidekiq 인큐잉 대기가 포함될 수 있다.

ActiveRecord::Base.transaction do
  ::Field.insert_all(insert_data)

  inserted_ids = ::Field.where(hierarchical_form_field_id: hierarchical_form_field_ids, fieldable_id: fieldable.id, fieldable_type: fieldable.class.name).pluck(:id)
  BulkSavePartialJsonToFileWorker.perform_async('Field', inserted_ids, { operation: '(created)', all_data: true }.to_json) if inserted_ids.present?

  Cupix::Logger.info("Created #{insert_data.size} fields from hierarchical form fields for #{fieldable.class.name} #{fieldable.id}", class: self.class.name, function: __method__)
end

기대 동작: FieldsController#index 는 fieldable 이 이미 존재하고 field 가 이미 생성된 정상 케이스에서 baseline 수백 ms 이내 응답. 실제 동작: 인시던트 해소 시점에 단일 요청이 36.7s. 같은 창구에서 서비스 전반 avg duration 35x 상승, 요청 rate 23x 상승 — fields 만의 문제가 아니라 서비스 전반 포화 상태가 이 요청에 겹친 것으로 보임.

Log Evidence#

같은 시각 FieldsController#index 요청 상태 (모두 200):

Datadog query:

service:cupixworks-api "FieldsController#index"

인시던트 창구 및 인접 시각(20:34~21:27 KST) 안의 FieldsController#index 호출 예시 (모두 성공):

2026-07-30 21:15:17  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:15:17  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:15:17  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:15:18  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:15:19  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:21:22  [200] GET /api/v1/reviews/ubdy79/annotations/8462/fields (Api::V1::FieldsController#index)
2026-07-30 21:21:32  [200] GET /api/v1/reviews/ubdy79/annotations/8462/fields (Api::V1::FieldsController#index)
2026-07-30 21:23:04  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:23:04  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:23:06  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:23:08  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:23:12  [200] GET /api/v1/fields (Api::V1::FieldsController#index)  (x4)
2026-07-30 21:23:14  [200] GET /api/v1/fields (Api::V1::FieldsController#index)
2026-07-30 21:23:18  [200] GET /api/v1/fields (Api::V1::FieldsController#index)  (x5)
2026-07-30 21:24:08  [200] GET /api/v1/fields (Api::V1::FieldsController#index)  (x6)
2026-07-30 21:27:17  [200] GET /api/v1/reviews/ubdy79/annotations/8461/fields
2026-07-30 21:27:18  [200] GET /api/v1/reviews/ubdy79/annotations/8461/fields

응답 코드는 모두 200 — 오류 없이 latency 만 튐. cluster_type=latency 와 일치. first_seen 시각(12:23:30Z = 21:23:30 KST) 을 앞뒤로 /api/v1/fields 요청이 초당 수 건씩 몰려 있고(21:23:04~21:24:08 사이 20+ 회 관찰), 이 burst 안의 특정 한 건이 36.7s trace 로 관측됨.

서비스 전반 avg request duration & 요청 rate (동 인시던트 공유 근거, 9855766b RCA 에서 도출):

Datadog query:

avg:trace.rack.request.duration{service:cupixworks-api}

sum:trace.rack.request.hits{service:cupixworks-api}.as_rate()

Baseline (19:0020:30 KST) 0.30.9s → 인시던트 창구(20:3421:23 KST) 2.02.6s. 요청 rate baseline 2560 req/s → 인시던트 창구 60100 req/s (peak 101). 인시던트 해소 시각(21:23:30 KST) 이 본 클러스터 first_seen 과 정확히 일치.

Resource 별 duration metric (api::v1::fieldscontroller#index 태그):

Datadog query:

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::fieldscontroller#index}

이 태그로 timeseries 조회를 시도했으나 결과 비어 있음 — resource_name tag 표기 규칙이 소문자로 정확히 일치하지 않을 가능성. Uncertain — needs verification (Datadog APM UI 에서 trace 2953304059702542039 의 flame graph 확인 필요).

Status board 컨텍스트:

$ bun run cli/incident-board.ts for-cluster da6d4c75-28f5-4ac7-a8a1-721df2ead8c3

{
  "scope": "svc:cupixworks-api::unknown",
  "active": null,
  "recent": [{
    "id": "2026-07-30-svc-cupixworks-api--unknown-1",
    "title": "cupixworks-api service degraded",
    "status": "resolved",
    "started_at": "2026-07-30T11:34:05.124Z",
    "resolved_at": "2026-07-30T12:23:30.350Z",
    "cluster_ids": [
      "9855766b-3975-47ac-9d01-4984a543fba9",
      "e758e925-3b09-4acf-bb97-4468f619239e",
      "dfa0ed54-7545-4c81-8023-e7def3db3669",
      "1feaf5c5-af3f-4902-96a8-537a72bd4d9e",
      "da6d4c75-28f5-4ac7-a8a1-721df2ead8c3"
    ]
  }]
}

본 클러스터가 인시던트의 마지막 이벤트(resolved_at == first_seen)이며, 5개 latency 클러스터가 ~50분 창구에 몰려 발생 후 자동 해소됨.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 단일 이벤트이며 이미 해소된 상위 인시던트(2026-07-30-svc-cupixworks-api--unknown-1) 의 마지막 클러스터이므로, 이 클러스터 단독으로 즉시 코드 수정은 불필요.
• 재발 감지를 위해 status board 및 아래 Monitoring 섹션 쿼리로 관찰 계속.

단기 개선 (1주 이내)#

• trace_id:2953304059702542039 의 APM flame graph 를 확인해 36.7s 가 어느 span (rack queue / db.query permission_joins / db.write fields.create / sidekiq.perform_async / 기타) 에 분포되어 있는지 규명. Datadog APM trace 링크가 클러스터 상단 URL 에 그대로 존재.
• 같은 창구에 묶인 다른 4개 latency 클러스터(9855766b, e758e925, dfa0ed54, 1feaf5c5) 의 span 분포와 교차 비교해 공통 병목을 특정. 4개 리소스가 서로 다른 backing store 를 쓰므로 공통 span 이 rack queue / 스레드 대기라면 인프라 튜닝 방향, 특정 리소스만 심하면 endpoint 최적화 방향.
• prepare_fields_from_legacy_form_fields 의 write 루프(app/repositories/field_repository.rb:429-434) 를 insert_all 배치로 전환하는 리팩터를 별도 이슈로 검토 — 본 인시던트의 primary cause 는 아니지만 부하 창구에서 latency 증폭 요인이 될 수 있음.

장기 개선 (재발 방지)#

• 서비스 전반의 부하 급증 시 자동 감지·알림을 강화. 현재 svc:*::unknown 스코프로만 자동 그룹핑되어 root_cause 가 미분류 (root_cause_types: [unknown]). request rate + duration 상관 알림을 별도로 구성해 부하 급증 시나리오를 별도 스코프로 분리.
• Puma / 컨테이너 동시성 metric (worker/thread busy, queued requests) 을 Datadog 로 노출해 다음 유사 인시던트에서 request queue 병목을 즉시 확인 가능하도록 계측.
• Read-heavy endpoint (FieldsController#index, BadgesController#index 등) 에 대해 짧은 서버 timeout 을 설정해 클라이언트 재시도가 서버 자원을 오래 점유하지 않도록 유도. 현재 36.7s 응답을 그대로 반환한 것은 서버 timeout 이 여유로움을 시사 (uncertain — Puma 설정 미확인).

Monitoring#

Datadog 쿼리 예시:

avg:trace.rack.request.duration{service:cupixworks-api}

sum:trace.rack.request.hits{service:cupixworks-api}.as_rate()

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::fieldscontroller#index}

avg:trace.mysql.query.duration{service:cupixworks-api}

각 쿼리 모두 timeseries widget 에 그대로 삽입 가능. count by(...) / | stats 같은 monitor-only 문법은 사용하지 않음.

Risk Assessment#

• Risk level: low — 단일 latency 이벤트, 이미 해소, 오류 아님 (200 응답).
• 예상 복잡도: trivial (이 클러스터 단독 관점). 상위 인시던트 원인 규명은 별도로 추적 필요.