RCA: Api::V1::AerialPhotosController#update Latency (1049ms)

Overview#

What Happened#

2026-05-27 17:34:59 UTC에 cupixworks-api 서비스의 Api::V1::AerialPhotosController#update 엔드포인트에서 1049ms의 응답 지연이 발생했다. 해당 요청은 aerial_map 452에 대한 약 200건 이상의 연속적인 aerial photo 업데이트 배치 작업 중 하나였으며, HTTP 200으로 정상 응답했으나 latency threshold(500ms)를 초과했다.

Quick Facts#

Timeline#

1. 17:31:35 UTC — AerialMap 452 step function 실행 (invoke_process), preprocessing 시작
2. 17:33:49 UTC — 대량 aerial photo update 배치 요청 시작 (~200건)
3. 17:34:59 UTC — 해당 latency 이벤트 발생 (aerial_photo ID 147693, 1049ms)
4. 17:35:58 UTC — 배치 완료, processing started 알림 발생

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::AerialPhotosController#update",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1049,
  "max_ms": 1049,
  "sample_trace_id": "2031135757626936881"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-05-27T17:34:59.707Z
• 최근 발생: 2026-05-27T17:34:59.707Z
• 영향: BNBuilders 팀(team ID 630)의 aerial map 452 preprocessing 워크플로우에서 개별 API 응답 지연 발생. 사용자 체감 영향은 제한적 — 자동화된 배치 호출(axios/1.7.7)이며 모두 HTTP 200 성공 응답.

Root Cause Summary#

AerialPhotosController#update의 after_commit 콜백에서 Elasticsearch 문서를 동기적으로 업데이트(_update_document)하는 것이 주요 latency 원인이다. Datadog 로그에서 DB 시간은 18.47ms, View 시간은 0.1ms로 측정됐으나 총 응답 시간은 1049ms였다. 나머지 약 1028ms는 Rails after_commit 콜백 내의 Elasticsearch HTTP 요청과 S3 presigned URL 생성에 소요된 것으로 판단된다. 특히 약 200건의 aerial photo가 2분 내에 연속 업데이트되면서 Elasticsearch에 동시 부하가 집중되어 개별 ES 요청 응답 시간이 증가한 것이 직접적 원인이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/aerial_photos_controller.rb:27 — update action
• before_action: app/controllers/api/v1/aerial_photos_controller.rb:60-62 — set_aerial_photo (permission_joins 쿼리)
• Repository update: app/repositories/aerial_photo_repository.rb:15-27 — 파라미터 설정 + save!
• Failure point: app/models/concerns/searchable.rb:55-121 — after_commit 콜백에서 동기 ES 업데이트
• Serialization: app/serializers/aerial_photo_serializer.rb:36-37 — S3 presigned URL 생성

1. Controller update action:

def update
  @model = repository_instance.update(params)
  super  # renders response via render_api
end

2. set_aerial_photo before_action (permission_joins — 11 LEFT JOINs):

def set_aerial_photo
  @model = repository_instance.show(params[:id])
end

이 메서드는 AerialPhotoRepository.permission_joins를 호출하여 11개의 LEFT JOIN을 포함하는 복합 SQL을 실행하지만, 이번 trace에서 DB 시간은 18.47ms로 병목이 아니었다.

3. Searchable _update_document (after_commit 콜백):

def _update_document
  Cupix::Logger.debug('begin - _update_document', class: self.class.name, function: __method__)
  return if @skip_index_document == true

  if (attributes_in_database = __elasticsearch__.instance_variable_get(:@__changed_model_attributes).presence)
    attributes = if respond_to?(:as_indexed_json)
                   # ... attribute transformation logic ...
                   __elasticsearch__.as_indexed_json.select { |k, v| column_names.include?(k.to_s) }
                 end

    unless attributes.empty?
      results = __elasticsearch__.client.update(request.merge({ index: __elasticsearch__.index_name }))
      # ↑ 동기 HTTP 요청 — 응답 대기 중 request cycle 블로킹
    end
  end
end

이 콜백은 after_commit에서 실행되지만, Rails에서 after_commit 콜백은 HTTP 응답 전송 전에 실행된다. 따라서 ES 서버의 응답 시간이 전체 API 응답 시간에 직접 합산된다.

4. S3 presigned URL 생성 (serialization 단계):

def image_source(filename: nil, attachment: true)
  return nil unless self.state_uploaded?

  ver = self.resource.revision
  filename ||= self.resource.name
  download_filename = self.file_extension.present? ? "#{filename}.#{self.file_extension}" : filename

  if attachment
    self.resource.object(ver).presigned_url(:get, expires_in: 3.hours.to_i, ...)
  else
    self.resource.object(ver).presigned_url(:get, expires_in: 1.days.to_i)
  end
end

Serializer에서 download_url과 thumbnail 속성에 대해 각각 S3 presigned URL을 생성한다. 그러나 이번 요청에서 fields: [id, key]만 요청했으므로 이 속성들은 직렬화되지 않았을 가능성이 높다.

5. Session touch (조건부 추가 DB write + ES index):

def session
  return nil if @session.nil?

  if @session.user_updated_at.nil? ||
     @session.team_updated_at.nil? ||
     @session.user_updated_at.to_i < @current_user.try(:updated_at).to_i ||
     @session.team_updated_at.to_i < @current_team.try(:updated_at).to_i ||
     @session.created_at > 2.second.ago ||
     @session.show_option == true

    @session.touch_updated_at
    SessionSerializer.new(@session).serializable_hash[:data][:attributes]
  end
end

touch_updated_at는 Session 모델을 save하며, Session도 Searchable을 include하면 추가 ES 인덱싱이 발생할 수 있다.

Log Evidence#

Datadog에서 확인한 trace 정보:

service:cupixworks-api resource_name:"Api::V1::AerialPhotosController#update" env:production @duration:>500ms

{
  "timestamp": "2026-05-27T17:35:02.024Z",
  "status": "info",
  "message": "[200] PUT /api/v1/aerial_maps/452/aerial_photos/147693 (Api::V1::AerialPhotosController#update)",
  "duration_ms": 1046.72,
  "db_ms": 18.47,
  "view_ms": 0.1,
  "serialization_ms": 0,
  "controller": "Api::V1::AerialPhotosController",
  "action": "update",
  "params": { "id": "147693", "key": "452", "fields": ["id", "key"] },
  "user": "nick.gass@bnbuilders.com",
  "team": "BNBuilders (630)",
  "user_agent": "axios/1.7.7",
  "request_id": "583050d8-d00e-4906-8b4c-d78a5367d36e"
}

배치 컨텍스트 — 동일 시간대 관련 로그:

service:cupixworks-api "AerialMap 452"

2026-05-27T17:31:35Z — "Aerial map step function executed on AerialMap 452" (invoke_process)
2026-05-27T17:31:35Z — Preprocessing started notification (AerialMap 452)
2026-05-27T17:33:49Z — Batch PUT requests start (~200 aerial_photos)
2026-05-27T17:35:58Z — Processing started notification (AerialMap 452)

핵심 관찰: DB 18.47ms + View 0.1ms = 18.57ms vs Total 1046.72ms. 차이 ~1028ms는 Rails 미들웨어/콜백/외부 I/O에서 소요. after_commit의 ES 동기 호출이 유일한 외부 네트워크 I/O (fields: [id, key]이므로 S3 URL 생성은 스킵됨).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/searchable.rb:16-18의 after_commit on: [:update] 콜백을 비동기로 전환
• 현재 _update_document는 ES HTTP 요청을 request cycle 내에서 동기 실행하므로, 이를 Sidekiq worker로 위임하면 API 응답 시간에서 ES latency를 제거할 수 있다
• 변경 대상: app/models/concerns/searchable.rb:16-18

단기 개선 (1주 이내)#

• 배치 업데이트 시나리오에서 ES 인덱싱을 bulk 방식으로 통합 — 200건의 개별 ES update 대신 batch가 완료된 후 BulkIndexWorker로 한 번에 처리
• AerialPhotosController#update에서 batch 패턴(동일 aerial_map의 다수 photo 연속 업데이트) 감지 시 skip_index_document!를 활용하고, 배치 완료 후 bulk reindex 실행

장기 개선 (재발 방지)#

• Searchable 모듈의 after_commit ES 인덱싱을 전체적으로 비동기 이벤트 기반 아키텍처로 전환 (예: ActiveJob + dedicated ES indexing queue)
• Aerial photo preprocessing 워크플로우에서 step function이 대량 API 호출 대신 내부 batch update + 단일 bulk index를 사용하도록 리팩터링

Monitoring#

• Elasticsearch _update_document 호출 시간을 측정하는 custom metric 추가
• 배치 업데이트 감지를 위한 Datadog 쿼리:

service:cupixworks-api resource_name:"Api::V1::AerialPhotosController#update" @duration:>500ms

• ES 응답 시간 모니터링:

service:cupixworks-api "TimeoutError" OR "ElasticsearchError" class:AerialPhoto function:_update_document

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 이 latency는 단발성 이벤트(1건)이며, 배치 업데이트라는 특수 상황에서 발생했다. 사용자 체감 영향은 없으나(자동화 클라이언트), 대규모 aerial map 업로드 시 반복 가능성이 있다.