ElementRecordsController missing HTTP timeout — Siteinsights API delay amplification
RCA: ElementRecordsController#index Latency (avg 2499ms, max 2722ms)
Overview#
What Happened#
2026-05-26 04:13~05:35 UTC 사이에 Api::V1::ElementRecordsController#index 엔드포인트에서 평균 2499ms, 최대 2722ms의 응답 지연이 ap-southeast-2, us-west-2, eu-central-1 3개 리전에서 발생했다. 이 컨트롤러는 외부 SiteInsights API Gateway/Lambda 서비스에 동기 HTTP 프록시 호출을 수행하며, 하류 서비스의 응답 지연이 Rails 요청 전체 지연으로 전파되었다.
Quick Facts#
| Field | Value |
|---|---|
| resource_name | Api::V1::ElementRecordsController#index |
| top_frame | app/services/cupix/siteinsights_service.rb:118 |
| runtime | Ruby on Rails (cupixworks-api) |
| env | production (ap-southeast-2, us-west-2, eu-central-1) |
Timeline#
- 2026-05-26T04:13:07Z — 최초 느린 요청 감지 (ap-southeast-2, eu-central-1, us-west-2)
- 2026-05-26T05:10:39Z — facility
umphr6사용자가 page 1~147 순차 pagination 시작 (per_page=300) - 2026-05-26T05:35:10Z — 마지막 느린 요청 기록
- 2026-05-26 — error-sweeper가 latency cluster로 감지
Error Log#
{
"resource_name": "Api::V1::ElementRecordsController#index",
"service": "cupixworks-api",
"occurrences": 3,
"avg_ms": 2499,
"max_ms": 2722,
"sample_trace_id": "5482070185489755310"
}
Impact#
- Service:
cupixworks-api - 발생 횟수: 3 (cluster threshold, 실제 98+ slow requests in window)
- 최초 발생: 2026-05-26T04:13:07.916Z
- 최근 발생: 2026-05-26T05:35:10.286Z
- 영향 범위: 다수 고객 (fredmond@pcl.com facility
umphr6, integration@cupix.com, pip@pacedg.com.au, djarman@walkcon.com 등)
Root Cause Summary#
ElementRecordsController#index는 자체 DB 쿼리 없이 외부 SiteInsights API Gateway(Lambda-backed)에 동기 HTTP GET을 수행하는 thin proxy이다. Datadog 로그에서 DB 시간은 212ms로 무시할 수준이나, 전체 요청 duration이 2,00012,555ms에 달하는 것은 하류 Lambda 서비스의 응답 지연(cold start + 대용량 데이터 처리)이 원인이다. 특히 facility umphr6는 44,000건 이상의 element record를 per_page=300으로 147페이지까지 순차 pagination하여 Lambda의 반복 호출 부하를 유발했다. Cupix::HttpClient에 명시적 timeout 설정이 없어 RestClient 기본값(60s)이 적용되며, 느린 Lambda 응답을 무한정 대기하는 구조이다.
Technical Analysis#
Code Path#
- Entry point:
app/controllers/api/v1/element_records_controller.rb:4 - Service call:
app/services/cupix/siteinsights_service.rb:118 - HTTP client:
lib/cupix/http_client.rb:15 - Downstream: AWS API Gateway → Lambda (
Cupix::Siteinsights.service_url)
def index
si_query_option = Cupix::QueryOption::Siteinsights.new(get_query_option, params)
element_records = Cupix::SiteinsightsService.get_element_records!(si_query_option, fields: @fields, current_user: @current_user, current_team: @current_team)
render_json 200, element_records
end
컨트롤러는 query option을 구성한 후 SiteinsightsService.get_element_records!를 동기적으로 호출하고 그 결과를 그대로 렌더링한다.
def get_element_records!(query_option, fields: '', current_user: nil, current_team: nil)
raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'facility_key is required') if query_option.facility_key.blank?
begin
params = {
facility_key: query_option.facility_key
}
params[:vendor_ids] = query_option.vendor_ids.join(',') if query_option.vendor_ids.present?
params[:category_ids] = query_option.category_ids.join(',') if query_option.category_ids.present?
params[:phase_ids] = query_option.phase_ids.join(',') if query_option.phase_ids.present?
params[:workarea_ids] = query_option.workarea_ids.join(',') if query_option.workarea_ids.present?
params[:level_ids] = query_option.level_ids.join(',') if query_option.level_ids.present?
params[:versioned_at] = query_option.versioned_at.to_i if query_option.versioned_at.present?
params[:per_page] = query_option.per_page if query_option.per_page.present?
params[:page] = query_option.page if query_option.page.present?
params[:completed_until] = query_option.completed_until if query_option.completed_until.present?
params[:fields] = fields if fields.present?
response = Cupix::HttpClient.get("#{Cupix::Siteinsights.service_url}/element_records?#{params.to_param}")
JSON.parse(response.body)['result']
rescue RestClient::Exception => e
# ...error handling...
end
end
핵심은 line 118: Cupix::HttpClient.get으로 외부 API Gateway에 동기 GET 요청을 보낸다. 이 호출의 응답 시간이 곧 전체 요청 duration을 결정한다.
def self.get(url, headers = {}, retries: MAX_RETRIES)
attempt = 0
begin
RestClient.get(url, headers)
rescue RestClient::Exception => e
if RETRIABLE_STATUS_CODES.include?(e.http_code) && attempt < retries
attempt += 1
sleep((2**(attempt - 1)) + rand(0.0..0.5))
retry
end
raise
end
end
RestClient.get에 open_timeout, read_timeout 파라미터가 전달되지 않아 RestClient 기본값(60초)이 적용된다. 하류 서비스가 느리더라도 60초까지 대기한다.
def service_url
case Cupix::Tesla.tenant
when 'cupix'
case Rails.env
when 'production'
case Cupix::Tesla.region_code
when 'euce1'
'https://4img1siwbf.execute-api.eu-central-1.amazonaws.com/api'
when 'apse2'
'https://5ufrbwf306.execute-api.ap-southeast-2.amazonaws.com/api'
else
'https://6hdi0xzqqk.execute-api.us-west-2.amazonaws.com/api'
end
end
end
end
3개 리전(us-west-2, eu-central-1, ap-southeast-2) 모두 개별 API Gateway endpoint를 가지며, 모든 리전에서 동시에 지연이 발생한 것은 Lambda 서비스 자체의 처리 성능 문제를 시사한다.
Log Evidence#
Datadog에서 사용한 쿼리:
service:cupixworks-api resource_name:"Api::V1::ElementRecordsController#index" @duration:>2000ms
주요 로그 항목 (facility umphr6, user fredmond@pcl.com):
{
"resource_name": "Api::V1::ElementRecordsController#index",
"duration_ms": 8436,
"db_time_ms": 2.15,
"view_time_ms": 12.4,
"params": {"facility_key": "umphr6", "per_page": "300", "page": "140", "fields": "bim,element,task,texture,revisioned_keys,..."},
"region": "us-west-2",
"host": "ip-10-1-144-228"
}
{
"resource_name": "Api::V1::ElementRecordsController#index",
"duration_ms": 12555,
"db_time_ms": 5.37,
"view_time_ms": 126.0,
"params": {"facility_key": "umphr6", "per_page": "300", "page": "147"},
"region": "us-west-2"
}
다른 facility의 borderline 케이스:
{
"resource_name": "Api::V1::ElementRecordsController#index",
"duration_ms": 2710,
"db_time_ms": 12.36,
"params": {"facility_key": "uge5bm", "per_page": "300", "page": "1"},
"region": "ap-southeast-2",
"user": "pip@pacedg.com.au"
}
핵심 패턴:
- DB time은 항상 2~12ms로 매우 낮음
- Duration의 99%는 외부 HTTP 호출 대기 시간
- 높은 페이지 번호(140+)에서 지연이 극대화 — OFFSET 기반 pagination에 의한 Lambda 측 성능 저하
Hypotheses Considered#
| # | Hypothesis | Evidence for | Evidence against | Verdict |
|---|---|---|---|---|
| H1 | 하류 SiteInsights Lambda의 응답 지연 (cold start + 대용량 OFFSET pagination 처리) | DB time 2 |
— | Confirmed |
| H2 | Rails 측 N+1 쿼리 또는 DB 병목 | 일반적인 Rails latency 원인 | ElementRecord는 로컬 모델 없음. DB time 2~12ms. 컨트롤러에 ActiveRecord 쿼리 없음. | Rejected |
| H3 | HttpClient retry backoff에 의한 누적 지연 | retry 시 1~4.5초 sleep 가능 (http_client.rb:19) | 로그에 에러/retry 흔적 없음. 모든 요청 200 반환. retry는 429/502/503/504에만 트리거됨. | Rejected |
| H4 | JSON 파싱/직렬화 병목 | 대용량 response body (300 records × 17 fields) | view_time 12~126ms로 전체 duration 대비 미미. JSON.parse는 수십 ms 수준. | Rejected |
Fix Recommendation#
즉시 조치 (Critical)#
lib/cupix/http_client.rb:15—RestClient.get에 명시적open_timeout(5초),read_timeout(10초) 파라미터 추가. 하류 서비스가 10초 이상 응답하지 않으면 빠르게 실패시켜 Rails 스레드 점유를 방지한다.- 로그에 하류 서비스 응답 시간을 기록하여 지연 패턴을 모니터링할 수 있도록 한다.
단기 개선 (1주 이내)#
- SiteInsights Lambda 서비스에 provisioned concurrency 설정을 검토하여 cold start 지연을 제거한다.
per_page최대값을 300에서 100으로 축소하거나, 대용량 facility에 대해 cursor-based pagination으로 전환하여 OFFSET 기반 깊은 페이지 조회의 성능 저하를 방지한다.- 동일 facility의 반복 요청에 대해 Redis 캐싱(TTL 30~60초)을 적용한다.
장기 개선 (재발 방지)#
- SiteInsights Lambda의 pagination을 OFFSET에서 cursor/keyset-based pagination으로 마이그레이션하여 깊은 페이지에서도 일정한 성능을 보장한다.
- API Gateway에 response caching 레이어를 추가한다.
- Circuit breaker 패턴을
HttpClient에 도입하여 하류 서비스가 지속적으로 느릴 때 빠르게 실패하고 fallback을 제공한다.
Monitoring#
추가할 메트릭/알림:
service:cupixworks-api resource_name:"Api::V1::ElementRecordsController#index" @duration:>3000ms
- P95/P99 latency를 APM 대시보드에 추가하고, 3초 초과 시 Slack 알림 설정
- 하류 SiteInsights Lambda의 CloudWatch Duration 메트릭을 모니터링 (p95 > 2초 시 알림)
per_page=300+page > 50조합의 요청 빈도를 추적하여 대용량 pagination 패턴을 감지
Risk Assessment#
- Risk level: medium
- 예상 복잡도: standard