ES /docs

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#

  1. 2026-05-26T04:13:07Z — 최초 느린 요청 감지 (ap-southeast-2, eu-central-1, us-west-2)
  2. 2026-05-26T05:10:39Z — facility umphr6 사용자가 page 1~147 순차 pagination 시작 (per_page=300)
  3. 2026-05-26T05:35:10Z — 마지막 느린 요청 기록
  4. 2026-05-26 — error-sweeper가 latency cluster로 감지

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::ElementRecordsController#index",
  "service": "cupixworks-api",
  "occurrences": 3,
  "avg_ms": 2499,
  "max_ms": 2722,
  "sample_trace_id": "5482070185489755310"
}

Impact#

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)
app/controllers/api/v1/element_records_controller.rb:4-8ruby
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!를 동기적으로 호출하고 그 결과를 그대로 렌더링한다.

app/services/cupix/siteinsights_service.rb:100-130ruby
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을 결정한다.

lib/cupix/http_client.rb:12-24ruby
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.getopen_timeout, read_timeout 파라미터가 전달되지 않아 RestClient 기본값(60초)이 적용된다. 하류 서비스가 느리더라도 60초까지 대기한다.

lib/cupix/siteinsights.rb:4-33ruby
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에서 사용한 쿼리:

text
service:cupixworks-api resource_name:"Api::V1::ElementRecordsController#index" @duration:>2000ms

주요 로그 항목 (facility umphr6, user fredmond@pcl.com):

json
{
  "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"
}
json
{
  "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 케이스:

json
{
  "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 212ms vs total duration 2,00012,555ms. 3개 리전 동시 발생. page 140+ 에서 지연 극대화. 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:15RestClient.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#

추가할 메트릭/알림:

text
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