RCA: Api::V1::MeasurementsController#index — 15.2s Latency Outlier

Overview#

What Happened#

2026-07-02 10:05 KST, cupixworks-api production (us-west-2) 에서 단일 GET /api/v1/reviews/q1vykf/measurements 요청이 15,179ms (DB 4,463ms + serialization 3,601ms + view 0.11ms + 나머지 오버헤드) 걸린 뒤 HTTP 200 으로 종료되었다. 응답 페이로드는 total_entries: 4 로 매우 작으며, 동일 endpoint 의 평상시 평균은 60–120ms 수준이다. 24시간 내 다른 slow request 발생은 없고, 동일 pod 에서 같은 시간대에 Pano#set_parameters / EventService#publish_event 대량 처리가 함께 관측된 pod-level 순간 포화로 판단된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-02 10:05:10 KST — Request 시작. UserFactory#update_user_groups! 로그 관측 ("No custom groups found for user 46446, takamatsu.hayato.z@takenaka.co.jp").
2. 2026-07-02 10:05:10–10:05:24 KST — 동일 host (ip-10-1-144-228) 에서 Pano#set_parameters, Pano#set_world_transformation_from_meta, Cupix::EventService#publish_event 로그가 지속적으로 발생 (수 초 동안 동시 요청 처리 중).
3. 2026-07-02 10:05:24.400 KST — Request 200 응답. duration 15179ms, DB 4463ms, serialization 3601ms 기록.
4. 2026-07-02 10:05:07 KST — error-sweeper collector 가 latency cluster 로 감지 (cluster_type: latency, avg_duration_ms: 15203).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::MeasurementsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 15203,
  "max_ms": 15203,
  "sample_trace_id": "3863876165434743336"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-02 10:05 KST
• 최근 발생: 2026-07-02 10:05 KST

Root Cause Summary#

단일 outlier 요청이다. GET /api/v1/reviews/q1vykf/measurements 는 total_entries: 4 로 데이터 규모가 작음에도 DB 시간이 4.4s, serialization 이 3.6s 로 튀었고, 나머지 ~7s 는 로그에 상세가 남지 않은 애플리케이션 처리 시간이다. 같은 host 에서 동시간대에 Pano meta 업데이트와 EventService publish 가 대량으로 진행 중이었던 정황으로 볼 때, 원인은 endpoint 자체의 로직 결함보다는 pod-level 순간 리소스 경합 (DB connection pool / CPU / GC pause) 로 인한 tail latency 발생으로 판단된다. 다만 이 endpoint 의 코드 경로에는 permission_joins 가 10+ 개의 LEFT JOIN 을 수행하고, before_action :set_review 와 _search 내 ReviewRepository.show 가 review 조회를 중복 실행하는 등 tail-latency 를 키우는 구조적 요인이 존재한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/measurements_controller.rb:14 (#index)
• before_action :set_review — parameter_required.rb:27 에서 review_key 로 review 를 조회.
• #index 는 Cupix::QueryOption::Measurement 를 만든 뒤 repository_instance.search(...) 호출.
• MeasurementRepository#_search — measurement_repository.rb:264. review_key 로 다시 ReviewRepository.show 를 수행하고 Elasticsearch 쿼리 실행.
• BaseRepository#search — base_repository.rb:70. Elasticsearch 결과의 records 에 대해 permission_joins 를 적용 (10+ LEFT JOIN 을 포함한 raw SQL, measurement_repository.rb:83-247).
• 이후 Renderable 를 통해 MeasurementSerializer (20 필드, Team/Workspace/Facility/Storage/Cyclable/Filesize/Resourcable concern 포함) 로 직렬화.
• Failure point: 특정 라인 실패가 아니라 아래 구간 전반의 tail-latency:
  • DB: permission_joins 다중 LEFT JOIN
  • Serialization: 20 필드 × concern chain
  • 중복 ReviewRepository.show (before_action + _search)

주요 코드:

before_action :set_review, if: :require_review?
before_action :set_aerial_map_for_measurement, if: :require_aerial_map?
before_action :set_measurement, except: %i[index create bulk_trash]

include MultipleResourcableController
include MetableController

def index
  measurement_query_option = Cupix::QueryOption::Measurement.new(get_query_option, params)
  measurements = repository_instance.search(measurement_query_option)

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

def _search(query_option = nil)
  set_query_option(query_option)

  review = nil

  if @aerial_map.present?
    # ...
  else
    raise Cupix::Errors::Parameter.new(...) if self.query_option.review_key.blank?

    review = ReviewRepository.new(current_user: self.current_user).show(self.query_option.review_key)
    raise Cupix::Errors::NotFound.new(...) if review.blank?

    facility = review.facility
    self.query_option.query[:bool][:must] << { term: { "facility.id": facility.id } }
    # ...
  end
  # ...
  response = ::Measurement.search(self.query_option.serializable_hash).paginate(
    per_page: self.query_option.per_page,
    page: self.query_option.page
  )

  set_review_id(review&.id)
  set_response(response)
end

record.joins("
  LEFT JOIN ( SELECT reviews.id AS review_id, 2 AS permission
              FROM reviews
              where reviews.public_access_enabled_at IS NOT NULL
                AND reviews.id = #{sanitized_review_id} ) AS review_public_permissions
    ON review_public_permissions.review_id = #{sanitized_review_id}
  LEFT JOIN ( SELECT review_id, permission FROM review_permissions ... ) AS review_user_permissions ...
  LEFT JOIN ( SELECT review_id, permission FROM review_permissions LEFT JOIN grouped_users ... ) AS review_group_permissions ...
  LEFT JOIN ( SELECT facility_id, permission FROM facility_permissions ... ) AS facility_user_permissions ...
  LEFT JOIN ( SELECT facility_id, permission FROM facility_permissions LEFT JOIN grouped_users ... ) AS facility_group_permissions ...
  LEFT JOIN ( ... ) AS facility_system_group_permissions ...
  LEFT JOIN ( ... ) AS workspace_user_permissions ...
  LEFT JOIN ( ... ) AS workspace_group_permissions ...
  LEFT JOIN ( ... ) AS team_user_permissions ...
  LEFT JOIN ( ... ) AS team_group_permissions ...
  LEFT JOIN ( ... ) AS team_system_group_permissions ...
").group('id').select(_select).where("...")

기대 동작: total_entries: 4 정도의 작은 collection 은 60–120ms 내에 응답해야 함 (같은 endpoint 의 정상 baseline). 실제 동작: 이 요청만 15,179ms 소요. db=4463ms, serialization=3601ms, 나머지 ~7s 는 request lifecycle (permission_joins post-processing, ActiveRecord instantiation, before_action, Renderable, response 직렬화) 전반에 분산된 것으로 추정.

Log Evidence#

Datadog 쿼리 (trace_id 로 요청 원문 조회):

service:cupixworks-api trace_id:3863876165434743336

Request completion 로그 (핵심 timing attributes 포함):

{
  "@timestamp": "2026-07-02T01:05:24.400Z",
  "message": "[200] GET /api/v1/reviews/q1vykf/measurements (Api::V1::MeasurementsController#index)",
  "duration": 15179.07,
  "db": 4463.21,
  "view": 0.11,
  "serialization": { "duration": 3601 },
  "pagination": { "per_page": 100, "total_pages": 1, "total_entries": 4, "current_page": 1 },
  "http": { "status_code": 200, "method": "GET", "url_details": { "path": "/api/v1/reviews/q1vykf/measurements" } },
  "controller": "Api::V1::MeasurementsController",
  "action": "index",
  "host": { "name": "ip-10-1-144-228.us-west-2.compute.internal" },
  "team": { "id": 1192, "domain": "umedafm" },
  "user": { "id": 46446 },
  "tenant": "cupix",
  "params": { "review_key": "q1vykf", "per_page": "100", "page": "1", "fields": ["id","name","created_at","updated_at","meta","value","measurement_type","user","team","workspace","facility","review","record","level","state","cycle_state","cycle_state_updated_at","cycle_state_updated_by","aerial_map_id","storage"] },
  "request_id": "93973d8b-d59a-4268-9579-428f2c1fd314"
}

Endpoint 의 최근 3시간 평균 latency 시리즈 (한 지점만 3.56s 로 튀고 나머지는 60–120ms):

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

값 (일부, 초 단위):

... 0.070, 0.055, 0.116, 3.563, 1.406, 0.074, 0.125, 0.084, ...

24시간 내 같은 endpoint 의 slow request 수 (@duration:>10000 ms):

service:cupixworks-api "MeasurementsController#index" @duration:>10000

결과: 1건 (당해 요청만).

동시간대 같은 host (ip-10-1-144-228.us-west-2.compute.internal) 활동:

service:cupixworks-api @host.name:"ip-10-1-144-228.us-west-2.compute.internal"
(2026-07-02T01:04:50Z ~ 01:05:30Z)

40초 창에 Pano#set_parameters, Pano#set_world_transformation_from_meta, Cupix::EventService#publish_event 로그가 수십 건 관측 — 같은 pod 에서 대용량 meta 갱신 요청과 병렬 처리 중이었다는 증거.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

없음. 단일 outlier 이며 응답은 정상 (200) 반환되었다. 재발 감시만 필요. 만약 유사 outlier 가 24시간 내 다시 발생하면 즉시 escalation.

단기 개선 (1주 이내)#

1. 중복 ReviewRepository.show 제거 — app/repositories/measurement_repository.rb:281 에서 _search 가 review_key 로 review 를 다시 조회하는데, controller 는 이미 before_action :set_review (app/controllers/concerns/parameter_required.rb:27) 로 @review 를 로드한다. _search 가 controller 에서 로드된 review 를 그대로 사용하도록 리팩터. 절감은 크지 않지만 tail latency 시 배수 효과가 큼.
2. Kibana debug 로그로 이 요청 재확인 — Watch (Kibana) 의 debug/silly 로그에서 request_id=93973d8b-d59a-4268-9579-428f2c1fd314 를 조회해 실제 병목 구간 (permission_joins SQL 시간, ActiveRecord instantiation, before_action 등) 을 세분화. 본 RCA 에서는 debug 로그를 아직 확인하지 않음 — verify 필요.
3. APM latency 알림 임계 재점검 — 이 endpoint 의 정상 latency 가 100ms 미만인데, 15s 짜리 outlier 가 자동 감지되었다는 것은 좋은 신호. 다만 p95 기반 이상감지 (예: > 500ms for 5m) 를 추가하면 조기 인지 가능.

장기 개선 (재발 방지)#

1. permission_joins 리팩터 방향 검토 — 10+ 개의 LEFT JOIN + GROUP BY id + GREATEST(...) where 절 (app/repositories/measurement_repository.rb:83-247) 은 record 수가 적을 때도 상수 오버헤드가 크다. 권한 계산을 별도 캐시 또는 재사용 가능한 CTE 로 옮기는 방안 검토.
2. Serializer concern chain 프로파일링 — MeasurementSerializer 는 TeamAttribute, WorkspaceAttribute, FacilityAttribute, StorageAttribute, CyclableAttribute, FilesizeAttribute, ResourcableAttribute 를 include. concern 별 실행 시간을 측정해 N+1 이나 무거운 lookup 여부 확인.
3. 동일 pod 리소스 격리 — Rails 요청과 Pano#set_parameters / EventService#publish_event 같은 대용량 async-like 작업이 같은 pod 에서 경합하는 구조라면, 우선순위 요청과 heavy write 를 분리하는 배포 토폴로지 검토 (별도 replica set 등).

Monitoring#

• Endpoint tail latency 감시 — p95 가 500ms 를 넘는지 5분 창에서 감지.

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::measurementscontroller_index}

• 동일 endpoint slow request count — duration 10s 초과 요청 발생 시 알림.

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::measurementscontroller_index,duration:>10000}.as_count()

• DB time 비율 이상 감지 — 정상 대비 DB time 급증.

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

• Host-level 경합 확인 — CPU 스파이크 상관 관찰.

avg:system.cpu.user{service:cupixworks-api} by {host}

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (즉시 조치 없음, 단기 개선은 중복 review 조회 제거 수준)