RCA: Api::V1::WorkareasController#index (14.8s outlier)

Overview#

What Happened#

2026-07-03 02:02 KST에 cupixworks-api의 Api::V1::WorkareasController#index 엔드포인트 단일 요청이 14,793ms로 완료되었다 (정상 응답, HTTP 200). 같은 endpoint 의 24시간 max latency 는 두 번째로 큰 값이 3.85s 였고 나머지는 대부분 <1.5s 이므로, 이 요청은 명확한 outlier 이다. 사용자 30566 (cristian.diaz@clarkconstruction.com) 의 /api/v1/reviews/d5yb4d/workareas 요청이며 review 기반 workarea 목록 조회 경로.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-03 02:02:14 KST — 요청 시작 (cluster first_seen, trace 시작 시각)
2. 2026-07-03 02:02:16 KST — UserFactory#update_user_groups! 에서 No custom groups found for user 30566 info 로그
3. 2026-07-03 02:02:28 KST — [200] GET /api/v1/reviews/d5yb4d/workareas 완료 (총 ~14.8s)
4. 2026-07-03 02:02:14 KST 이후 — 후속 요청 정상화, 후속 outlier 없음 (24h 관측)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::WorkareasController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 14793,
  "max_ms": 14793,
  "sample_trace_id": "1195256439043181941"
}

Impact#

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

Root Cause Summary#

이번 이벤트는 systemic 성능 이슈가 아니라 단일 outlier로 판단된다. Api::V1::WorkareasController#index 의 24시간 max 통계에서 문제 요청 하나만 14.8s 였고 두 번째로 큰 값은 3.85s, avg 는 대부분 <1s 였다. 코드 경로 자체 (WorkareaRepository._search → Elasticsearch ::Workarea.search → permission_joins 로 이어지는 대규모 LEFT JOIN 기반 permission 계산) 는 데이터 규모나 캐시 상태에 따라 tail latency 를 발생시킬 잠재적 위험이 있으나, 이 요청 시점 (2026-07-02 17:02 UTC) 근처에서 Elasticsearch/DB timeout, error, warn 이 관측되지 않았고 system.load 도 정상 범위였다. 확인 가능한 증거만으로는 특정 원인 (ES 콜드 캐시, GC pause, DB lock, 네트워크 stall 등) 을 지목할 수 없어 verdict 는 transient tail latency (inconclusive on precise trigger) 이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/workareas_controller.rb:10
• Repository search: app/repositories/base_repository.rb:70
• Elasticsearch query builder: app/repositories/workarea_repository.rb:266 (_search)
• Permission join (heavy SQL): app/repositories/workarea_repository.rb:51 (permission_joins)
• Response 직전 renderer: app/controllers/api/v1/workareas_controller.rb:14-18

controller 진입:

def index
  workarea_query_option = Cupix::QueryOption::Workarea.new(get_query_option, params)
  workareas = repository_instance.search(workarea_query_option)

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

search 는 ES 조회 → DB permission join 을 순차 실행한다:

def search(query_option = nil)
  _search(query_option)

  begin
    if self.review.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review.id, skip_join: _skip_join?)
    elsif self.review_id.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review_id, skip_join: _skip_join?)
    # ...
    end
  rescue Elasticsearch::Transport::Transport::ServerError => e
    raise unless e.message.start_with?('[429]')
    Cupix::Logger.error("Elasticsearch circuit breaker: #{e.message}", ...)
    raise Cupix::Errors::System.new(code: 'SYS20000', reason: 'Elasticsearch circuit breaker triggered (too many requests)')

permission_joins 는 review/facility/workspace/team 각 도메인마다 user/group/system_group permission 을 계산하기 위해 11개의 LEFT JOIN subquery 를 병합하고 workareas 를 join 한다:

record.joins("
  LEFT JOIN ( SELECT reviews.id AS review_id, 2 AS permission FROM reviews
              WHERE reviews.published_at IS NOT NULL AND reviews.id = #{sanitized_review_id} ) AS review_public_permissions ...
  LEFT JOIN ( SELECT review_id, permission FROM review_permissions
              WHERE ... AND review_permissions.review_id = #{sanitized_review_id} ) AS review_user_permissions ...
  LEFT JOIN ( SELECT review_id, permission FROM review_permissions
                LEFT JOIN grouped_users ON grouped_users.group_id = review_permissions.accessor_id ... ) AS review_group_permissions ...
  LEFT JOIN ( SELECT facility_id, permission FROM facility_permissions ... ) AS facility_user_permissions ...
  # ... facility_group, facility_system_group, workspace_user, workspace_group,
  #     team_user, team_group, team_system_group 까지 총 11개 LEFT JOIN ...
").group('id').select(_select).where(" GREATEST(...) > 0 OR GREATEST(...) > 1 ")

기대 동작: 단일 요청은 sub-second 이내 완료 (24h 관측 대부분 <300ms avg). 실제 동작: 이 요청만 14.8s 소요. 다른 outlier 는 3.85s 로 크게 낮다. 코드 자체가 매 요청마다 실행하는 경로이므로, 코드 결함이라기보다는 런타임 환경 요인 (ES 응답 지연 / MySQL 실행 계획 재컴파일 / 잠깐의 lock contention / GC pause 등) 에 의해 이 한 트레이스가 튄 것으로 해석된다. Datadog 에는 span-level breakdown 이 있으나 error-sweeper 가 trace 세부를 수집하지 않아 어느 구간이 늦었는지 로그로 확정할 수 없음 — uncertain -- needs verification via APM span waterfall.

Log Evidence#

Query used:

service:cupixworks-api trace_id:1195256439043181941

Result — request start/end (KST 로 변환):

{
  "timestamp": "2026-07-03 02:02:28",
  "status": "info",
  "message": "[200] GET /api/v1/reviews/d5yb4d/workareas (Api::V1::WorkareasController#index)"
}

{
  "timestamp": "2026-07-03 02:02:16",
  "status": "info",
  "message": "No custom groups found for user 30566, cristian.diaz@clarkconstruction.com",
  "class": "UserFactory",
  "function": "update_user_groups!"
}

update_user_groups! info 로그가 요청 시작 ~2초 후 남았고, 이 사용자에게서 같은 로그가 20분 창에 20건 이상 반복 관측된다 (하단 참고). 다만 이 함수는 debug 성 info 로그만 남기고 실제 group 갱신은 하지 않는 short-circuit path 이므로 (custom_groups.nil? 인 경우 즉시 return) 이 함수 자체가 14초를 소모할 만한 지점은 아니다. 그럼에도 이 로그가 요청 중반부에 남았다는 사실은 요청이 auth 검증 이후 단계에서 대기하고 있었음을 시사한다.

같은 사용자의 반복 auth-path 로그 (샘플):

2026-07-03 02:08:16 -> No custom groups found for user 30566, cristian.diaz@clarkconstruction.com
2026-07-03 02:08:18 -> No custom groups found for user 30566, ...
2026-07-03 02:08:27 -> No custom groups found for user 30566, ...
2026-07-03 02:08:27 -> No custom groups found for user 30566, ...
2026-07-03 02:08:27 -> No custom groups found for user 30566, ...
2026-07-03 02:08:28 -> No custom groups found for user 30566, ...
2026-07-03 02:08:29 -> No custom groups found for user 30566, ...

update_user_info 는 groups_synced_at 이 GROUPS_SYNC_INTERVAL = 5.minutes 이내면 group 조회를 건너뛰도록 되어있으나, sync path 에서는 매번 호출된다:

GROUPS_SYNC_INTERVAL = 5.minutes

def update_user_info(user, user_response, async_update: false)
  if async_update
    if user.groups_synced_at.nil? || user.groups_synced_at < GROUPS_SYNC_INTERVAL.ago
      UpdateUserGroupsWorker.perform_async(user.id, user_response.groups, user_response.given_name, user_response.family_name)
    end
  else
    user.firstname = user_response.given_name if user_response.given_name.present?
    user.lastname = user_response.family_name if user_response.family_name.present?

    user_factory = ::UserFactory.new
    user_factory.update_user_groups!(user, user_response)
    user.update_column(:groups_synced_at, Time.current)
  end
end

문제 요청 근처 (2026-07-02 16:55–17:10 UTC) 창에서 확인한 관찰:

• service:cupixworks-api status:error — 0건
• service:cupixworks-api status:warn — NotFound - attributes_in_database (ES sync 관련 무해 warn) 만 관측, 문제 트레이스와 무관
• service:cupixworks-api ("timeout" OR "slow" OR "deadlock" OR "Elasticsearch" OR "Faraday") — 0건
• system.load.1{service:cupixworks-api} 1시간 최대 1.63 — 정상 부하 범위

24시간 max latency 분포 (max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::workareascontroller_index}, 10분 bucket):

2026-07-02 17:00 UTC -> 3.85 s
2026-07-01 22:05 UTC -> 1.639 s
2026-07-01 22:20 UTC -> 1.506 s
2026-07-02 16:30 UTC -> 1.434 s
2026-07-02 16:55 UTC -> 1.32 s
2026-07-01 23:00 UTC -> 1.249 s
...

1분 bucket 으로 좁히면 문제 트레이스가 명확히 spike 로 잡힘:

2026-07-02 17:02 UTC -> 14.793 s   <-- 이 요청
2026-07-02 16:58 UTC -> 1.32 s
2026-07-02 16:56 UTC -> 1.334 s
2026-07-02 16:32 UTC -> 2.207 s
2026-07-02 16:02 UTC -> 2.419 s

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 없음. 재현되지 않은 단발 outlier 이고 200 OK 로 완료됨. 코드 변경 불필요.
• 다만 사후 확인이 필요하면 trace 1195256439043181941 를 Datadog APM 에서 열어 span waterfall 로 ES 응답 시간 vs SQL 실행 시간 vs 애플리케이션 CPU 시간을 breakdown 하여 어느 구간이 지연되었는지 특정한다 (Root Cause Summary 의 uncertain 항목 해소용).

단기 개선 (1주 이내)#

• Api::V1::WorkareasController#index 및 WorkareaRepository.permission_joins 에 span 태그 를 추가하여 SQL 구간 시간 (permission_joins), ES 구간 시간 (Workarea.search) 을 각각 측정 가능하게 한다. 다음 재발 시 어느 구간이 원인인지 즉시 판별할 수 있다. 방향: Datadog::Tracing.trace('workarea.permission_joins') 블록 감싸기.
• lib/cupix/auth/verification.rb:294 의 update_user_info 를 검토: 이 사용자의 update_user_groups! 로그가 초당 여러 번 발생하는 것은 async path 가 아니라 sync path 로 매 요청 auth 마다 재실행됨을 시사. groups_synced_at 캐싱이 sync path 에도 동일하게 적용되도록 조정하는 것을 검토 (문제 트레이스의 직접 원인은 아니지만 요청 CPU 비용 감소에 도움).

장기 개선 (재발 방지)#

• permission_joins 의 11개 LEFT JOIN 구조는 permission 규모가 커질수록 tail latency 위험이 증가한다. 조회 결과에 대해서만 permission 을 사후 계산하도록 batch 방식 리팩터 (예: 페이지네이션된 workarea id 집합에 대해 IN 절 기반 permission 조회) 를 중장기 로드맵으로 검토. 단발 이벤트만으로 우선순위 상향은 권장하지 않음.
• Datadog latency SLO / 알림 추가: Api::V1::WorkareasController#index 의 p95/p99 를 monitor 하여 systemic 저하로 진화하는 경우 조기 감지.

Monitoring#

추적 및 재발 감지용 Datadog timeseries 쿼리. 각 쿼리는 release dashboard timeseries widget 에 그대로 삽입 가능하다 (monitor-only 문법 미사용).

• p95 latency 추이:

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

• p99 latency 추이:

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::workareascontroller_index}

• 초당 요청 수 (부하 상관 파악용):

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

• 5xx / 오류 비율:

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::workareascontroller_index}.as_rate()

• Elasticsearch client 평균 응답 시간 (동일 서비스 스코프):

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

• DB 평균 응답 시간 (permission_joins 지연 감지):

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

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (관찰/모니터링 추가만 권장, 코드 로직 변경 없음)