Api::V1::PhaseMetricsController#index (avg 6430ms, max 6430ms)

RCA: PhaseMetricsController#index Slow Response (6430ms)

Overview#

What Happened#

2026-06-04 12:56 KST, cupixworks-api 서비스의 Api::V1::PhaseMetricsController#index 엔드포인트에서 단일 요청이 6430ms 소요되었다. 전체 응답 시간의 79%인 5017ms가 데이터베이스에서 소비되었으며, 결과는 0건(empty)이었다.

Quick Facts#

Field	Value
resource_name	`Api::V1::PhaseMetricsController#index`
top_frame	`app/repositories/base_repository.rb:81`
env	production, us-west-2
duration	6430ms (db: 5017ms, view: 0.12ms)
HTTP status	200

Affected Teams#

Team / Domain	Error Count	Impact
accoes (team ID 816)	1	단일 사용자(lamaya@accoes.com)의 PhaseMetrics 조회 응답 지연

Timeline#

2026-06-04 12:56 KST — PhaseMetricsController#index 요청 수신 (facility_key=533wrh, user=42996)
2026-06-04 12:56 KST — Elasticsearch 검색 완료 후 permission_joins SQL 실행, DB 5017ms 소비
2026-06-04 12:56 KST — 0건 결과 응답 (200 OK, total 6430ms)
2026-06-04 12:56 KST — 동일 사용자/파라미터의 후속 요청들은 15-28ms로 정상 완료

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::PhaseMetricsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 6430,
  "max_ms": 6430,
  "sample_trace_id": "1467597885058481757"
}

Impact#

Service: cupixworks-api
발생 횟수: 1
최초 발생: 2026-06-04 12:56 KST
최근 발생: 2026-06-04 12:56 KST

Root Cause Summary#

PhaseMetricsController#index는 Elasticsearch 검색 후 결과 레코드에 대해 11개의 LEFT JOIN 서브쿼리로 구성된 permission_joins를 실행한다. 이번 요청에서 DB 실행 시간이 5017ms(전체의 79%)를 차지했으며, 이는 MySQL의 일시적 부하(cold cache, lock contention, 또는 query plan 비효율)로 인해 permission_joins의 복잡한 다중 LEFT JOIN 쿼리가 비정상적으로 느리게 실행된 것으로 판단된다. 동일한 파라미터의 후속 요청들은 2-6ms DB 시간으로 정상 완료되어, 지속적 문제가 아닌 일시적 DB 성능 저하임을 확인했다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/phase_metrics_controller.rb:7
Elasticsearch 검색: app/repositories/phase_metric_repository.rb:291
Permission joins 적용: app/repositories/base_repository.rb:81
Failure point: app/repositories/phase_metric_repository.rb:73 (permission_joins SQL)

1. Controller에서 search 호출:

app/controllers/api/v1/phase_metrics_controller.rb:7-15ruby

def index
  phase_metric_query_option = Cupix::QueryOption::PhaseMetric.new(get_query_option, params)
  phase_metrics = repository_instance.search(phase_metric_query_option)

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

2. BaseRepository에서 Elasticsearch 검색 후 permission_joins 실행:

app/repositories/base_repository.rb:70-82ruby

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?)
    elsif self.capture.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, capture_id: self.capture.id, skip_join: _skip_join?)
    else # = self.review_id.nil?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end

3. PhaseMetricRepository의 Elasticsearch 검색:

app/repositories/phase_metric_repository.rb:264-298ruby

def _search(query_option = nil)
  set_query_option(query_option)

  raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'facility_key is required') if self.query_option.facility_key.blank?

  self.query_option.query[:bool][:must] << {
    term: {
      "facility.key": self.query_option.facility_key
    }
  }

  response = ::PhaseMetric.search(
    self.query_option.serializable_hash
  ).paginate(
    per_page: self.query_option.per_page,
    page: self.query_option.page
  )

  set_response(response)
end

4. Permission joins — 11개 LEFT JOIN 서브쿼리:

app/repositories/phase_metric_repository.rb:73-246ruby

def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  # ... 11개 LEFT JOIN (review, facility, workspace, team 각 user/group/system)
  record.joins("
    LEFT JOIN (...) AS review_public_permissions ...
    LEFT JOIN (...) AS review_user_permissions ...
    LEFT JOIN (...) AS review_group_permissions ...
    LEFT JOIN (...) AS facility_user_permissions ...
    LEFT JOIN (...) 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("GREATEST(...) > 1")
end

실행 흐름:

Elasticsearch에서 facility.key=533wrh로 검색 → 결과 0건
결과가 0건이더라도 response.records는 ActiveRecord relation을 반환
이 relation에 default_joins + permission_joins가 체이닝됨
최종 SQL이 MySQL에 전달되어 실행됨
정상적으로는 0건에 대한 쿼리가 즉시 반환되어야 하나, 이번 요청에서 5017ms 소요

기대 동작: 0건 결과에 대한 permission_joins는 빈 ID 목록(WHERE id IN ())이므로 즉시(< 10ms) 완료되어야 함.

실제 동작: 5017ms 소요. 동일 조건의 후속 요청은 2-6ms로 정상 → MySQL의 일시적 성능 저하 (cold buffer pool, table lock, 또는 쿼리 플래너의 비효율적 plan 선택).

Log Evidence#

Datadog 로그 검색 쿼리:

text

service:cupixworks-api @http.url_details.path:*phase_metrics* env:production
Time: 2026-06-04T02:56:00Z ~ 2026-06-04T04:56:00Z

Slow request (6430ms):

json

{
  "timestamp": "2026-06-04T03:56:22.635Z",
  "resource": "Api::V1::PhaseMetricsController#index",
  "duration_ms": 6328.68,
  "db_ms": 5017.03,
  "view_ms": 0.12,
  "status": 200,
  "host": "ip-10-1-144-228.us-west-2.compute.internal",
  "params": "per_page=100, page=1, fields=[id,phase,metric,formula], facility_key=533wrh",
  "user": "lamaya@accoes.com (ID: 42996)",
  "team": "accoes (ID: 816)",
  "pagination": "total_entries=0, total_pages=1"
}

동일 파라미터의 정상 요청 (같은 시간대):

text

- 15.46ms (db: 4.51ms)
- 18.66ms (db: 4.46ms)
- 20.06ms (db: 5.13ms)
- 18.17ms (db: 6.62ms)
- 28ms (db: 2.52ms)
- 12.12ms (db: 2.42ms)

동일 사용자, 동일 파라미터의 요청들이 15-28ms로 정상 완료됨. 단 하나의 요청만 6430ms로 비정상.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	MySQL 일시적 부하 (cold cache/lock contention)로 permission_joins 쿼리 지연	db=5017ms로 전체 시간의 79% 차지. 동일 조건 후속 요청은 2-6ms로 정상. 단일 발생.	동시간대 다른 에러/경고 로그 없음	Confirmed
H2	Elasticsearch 검색 자체의 지연	ES 검색이 느렸다면 전체 duration에서 db 외 시간이 클 것	6328ms 중 db=5017ms, view=0.12ms → ES + Rails 오버헤드는 ~1300ms 수준이나 이것도 높은 편. 그러나 후속 요청에서 ES도 정상	Rejected
H3	대량 레코드에 대한 N+1 쿼리 또는 serialization 지연	serializer에 respond_to? 패턴으로 N+1 가능성 존재	total_entries=0이므로 serialization 대상 레코드 없음. view=0.12ms로 serialization 비용 0	Rejected
H4	Permission joins의 구조적 성능 문제 (11개 LEFT JOIN)	복잡한 쿼리 구조가 잠재적 성능 리스크. 특정 조건에서 MySQL optimizer가 비효율적 plan 선택 가능	동일 쿼리가 평소 2-6ms로 완료됨 → 구조적 문제라기보다 일시적 현상	Inconclusive

Fix Recommendation#

즉시 조치 (Critical)#

없음. 단일 발생이며 후속 요청은 정상 완료되었으므로 긴급 수정 불필요.

단기 개선 (1주 이내)#

Slow query 모니터링 추가: PhaseMetricsController#index에 대해 DB 시간이 1000ms를 초과하는 경우를 추적하는 Datadog 모니터 설정. 반복 발생 여부를 먼저 확인한 후 코드 변경 결정.
Permission joins 캐싱 검토: app/repositories/phase_metric_repository.rb:73 — Elasticsearch 결과가 0건일 때 permission_joins를 건너뛰는 early return 로직 추가 검토. 0건에 대해 불필요한 SQL 실행을 방지.

장기 개선 (재발 방지)#

Permission joins 리팩토링: 11개 LEFT JOIN을 단일 쿼리로 실행하는 현재 구조는 MySQL optimizer에 의존적이며 데이터 증가 시 성능 저하 리스크가 있음. 권한 정보를 별도 캐시 레이어(Redis)로 분리하거나, 각 permission을 개별 쿼리로 분리 후 application level에서 합산하는 방식 검토.
Empty result early return: base_repository.rb:70-82에서 response.records가 비어있을 때 permission_joins를 skip하는 guard clause 추가.

Monitoring#

Datadog APM Monitor: PhaseMetricsController#index에 대해 p99 latency > 3000ms 알림 설정
Datadog Query:

text

service:cupixworks-api resource_name:"Api::V1::PhaseMetricsController#index" @duration:>3000000000

DB Duration Monitor: db 메트릭이 2000ms를 초과하는 요청 추적

Risk Assessment#

Risk level: low
예상 복잡도: trivial (early return 추가) ~ standard (permission joins 리팩토링)