ES /docs

Api::V1::LevelsController#show (avg 4818ms, max 4818ms)

RCA: Api::V1::LevelsController#show Latency Spike (4818ms)

Overview#

What Happened#

2026-06-06 05:32 KST에 cupixworks-api 서비스의 Api::V1::LevelsController#show 엔드포인트에서 단일 요청이 4818ms의 응답 시간을 기록했다. 정상 응답 시간(30-80ms) 대비 약 60-160배 느린 성능 저하가 발생했으며, APM 메트릭 분석 결과 해당 시점을 전후로 약 30분간 전반적인 latency 상승이 관찰되었다.

Quick Facts#

Field Value
resource_name Api::V1::LevelsController#show
avg_duration 4818ms
max_duration 4818ms
sample_trace_id 6172692582349211334
env production, us-west-2

Timeline#

  1. 2026-06-06 05:32 KSTLevelsController#show 요청 4818ms 응답 (정상 대비 ~60x 느림)
  2. 2026-06-06 05:32-05:35 KST — 동일 trace_id에서 capture 709116 처리 작업 다수 진행 중
  3. 2026-06-06 05:34-05:40 KST — worker에서 S3 connection timeout, voxel-service 503 에러 다수 발생
  4. 2026-06-06 ~05:45 KST — latency 정상 수준으로 회복

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::LevelsController#show",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 4818,
  "max_ms": 4818,
  "sample_trace_id": "6172692582349211334"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1
  • 최초 발생: 2026-06-06 05:32 KST
  • 최근 발생: 2026-06-06 05:32 KST

Root Cause Summary#

LevelsController#show 요청은 BaseRepository.showLevelRepository.permission_joins를 통해 11개의 LEFT JOIN을 포함하는 대규모 permission 검증 SQL 쿼리를 실행한다. 이 쿼리가 4818ms 동안 응답하지 못한 원인은 동일 시간대에 발생한 capture 처리 burst(capture 709116 등)로 인한 데이터베이스 contention이다. worker들이 동시에 facility_permissions, level_permissions 등의 테이블에 대한 읽기/쓰기 작업을 수행하면서, 11개 LEFT JOIN 쿼리의 실행 계획이 정상보다 크게 지연되었다. APM 메트릭으로 해당 시간대에 30분간 전체 LevelsController#show 평균 latency가 100ms-1060ms로 상승한 것이 확인된다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/api/v1/levels_controller.rb:38before_action :set_level
app/controllers/api/v1/levels_controller.rb:38-39ruby
def set_level
  @model = repository_instance.show(params[:id])
end
  • BaseRepository#show instance method 호출: app/repositories/base_repository.rb:121
app/repositories/base_repository.rb:121-128ruby
def show(id, visibility: Cyclable.visibility[:UNTRASHED], review_id: nil, capture_id: nil, skip_permission: false)
  _review_id = if review_id.present?
                 review_id
               elsif self.review.present?
                 self.review.id
               end

  @model = self.class.show(id, current_user: @current_user, visibility: visibility, review_id: _review_id, capture_id: capture_id, skip_permission: skip_permission)
end
  • BaseRepository.show class method: app/repositories/base_repository.rb:306-343 — current_user가 있으므로 permission_joins 분기 진입
app/repositories/base_repository.rb:335-337ruby
elsif current_user.present?
  permission_joins(default_joins(current_class), current_user).where(attrs)
else
  • Failure point (bottleneck): app/repositories/level_repository.rb:105-305LevelRepository.permission_joins

이 메서드는 단일 SQL 쿼리에서 11개의 LEFT JOIN subquery를 생성하여 level_permissions, facility_permissions, workspace_permissions, team_permissions, review_permissions, grouped_users 테이블을 모두 조인한다:

app/repositories/level_repository.rb:105-138ruby
def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  if select.present?
    _select = ApplicationRecord.sanitize_sql(select)
  else
    _select = "levels.*,
    MAX(review_user_permissions.permission) AS review_user_permission,
    MAX(review_group_permissions.permission) AS review_group_permission,
    MAX(review_public_permissions.permission) AS review_public_permission,
    MAX(level_user_permissions.permission) AS level_user_permission,
    MAX(level_group_permissions.permission) AS level_group_permission,
    MAX(facility_user_permissions.permission) AS facility_user_permission,
    MAX(facility_group_permissions.permission) AS facility_group_permission,
    MAX(facility_system_group_permissions.permission) AS facility_system_group_permission,
    MAX(workspace_user_permissions.permission) AS workspace_user_permission,
    MAX(workspace_group_permissions.permission) AS workspace_group_permission,
    MAX(team_user_permissions.permission) AS team_user_permission,
    MAX(team_group_permissions.permission) AS team_group_permission,
    MAX(team_system_group_permissions.permission) AS team_system_group_permission,
    MAX(GREATEST(
      IFNULL(level_user_permissions.permission, 0),
      ...
    )) AS applied_permission"
  end
  # ... 11 LEFT JOIN subqueries follow
end
  • Serialization: app/controllers/api/v1/api_controller.rb:72-77LevelSerializer를 통해 _user, _team, _workspace, _facility 등 cached association을 Redis에서 fetch
app/controllers/api/v1/api_controller.rb:72-77ruby
def show
  render_api Renderable.new({
    contents: @model,
    serializer_option: @serializer_option
  })
end

Log Evidence#

Datadog APM 메트릭 쿼리:

text
avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#show}

정상 시간대 평균 응답 시간 (초):

text
0.035, 0.032, 0.026, 0.024, 0.035, 0.041, 0.030, 0.043, 0.053, 0.074

Latency 상승 구간 (초, 약 2026-06-06 04:50-05:40 KST):

text
0.128, 0.197, 0.068, 0.299, 0.377, 0.098, 0.111, 0.112, 0.287, 0.324, 0.226, 0.181, 0.774, 0.087, 0.192, 0.337, 0.429, 0.607, 0.232, 0.592, 0.198, 0.207, 0.159, 0.094, 0.076, 0.028, 1.060, 0.693, 0.795

동시 발생한 worker 에러 (05:34-05:40 KST):

text
service:cupixworks-worker status:error
json
{
  "timestamp": "2026-06-06 05:39:52",
  "status": "error",
  "message": "failed to calculate captured size for Facility ID: 10757, error: failed to get captured area - error: 503 Service Unavailable",
  "class": "Facility",
  "function": "calculate_captured_size"
}
json
{
  "timestamp": "2026-06-06 05:36:22",
  "status": "error",
  "message": "flush_geo_coordinate - error - message: Failed to open TCP connection to s3.me-south-1.amazonaws.com:443 (execution expired)",
  "class": "Record",
  "function": "flush_geo_coordinate"
}

동일 trace_id에서 capture 처리 활동 (trace_id: 6172692582349211334):

text
service:cupixworks-api trace_id:6172692582349211334
json
{
  "timestamp": "2026-06-06 05:35:11",
  "message": "skatmaster is invoked for capture 709116. job id: 1108448",
  "class": "Capture",
  "function": "run_skat_master"
}
json
{
  "timestamp": "2026-06-06 05:32:36",
  "message": "[200] PUT /api/v1/captures/709116 (Api::V1::CapturesController#update)"
}

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 DB contention: 11 LEFT JOIN permission 쿼리가 동시 worker write 작업과 lock 경합 APM 메트릭에서 30분간 전체 latency 상승 패턴 확인; 동일 시간대 capture 처리 burst (trace_id 로그), worker에서 facility 관련 operation 다수 실행; permission 테이블은 workers와 API가 공유하는 테이블 명시적인 deadlock/lock wait 로그 미발견 (info 레벨만 기록됨) Confirmed
H2 Redis cache miss로 인한 serialization 지연 LevelSerializer가 _user, _team, _facility 등 cached association을 Redis에서 fetch (cachable.rb:58-70); cache miss 시 DB fallback 단일 레코드 serialization은 일반적으로 수 ms 소요; 30분간 지속된 latency 상승 패턴은 serialization 이슈로 설명 불가 Rejected
H3 네트워크 지연 (S3/외부 서비스) 동일 시간대 S3 me-south-1 connection timeout 다수 발생 LevelsController#show는 S3나 외부 서비스를 직접 호출하지 않음; 외부 서비스 이슈는 worker에만 영향 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  • 현재 단일 발생(occurrence: 1)이며 자동 회복되었으므로 긴급 수정 불필요
  • APM 모니터링으로 LevelsController#show P95/P99 latency 추적 설정 권장

단기 개선 (1주 이내)#

  • app/repositories/level_repository.rb:105-305: permission_joins 쿼리를 단순화하거나, 단일 레코드 조회(show) 시에는 lighter-weight permission 검증 경로를 사용하도록 분기
    • 현재 show는 단일 ID로 조회하므로, 먼저 레코드를 가져온 후 Pundit policy check만으로 권한 검증이 가능할 수 있음 (이미 base_repository.rb:359에서 Pundit check가 존재)
    • 단일 레코드에 대해 11개 LEFT JOIN은 과도함 — find + policy check 패턴으로 전환 가능성 검토

장기 개선 (재발 방지)#

  • Permission 테이블에 대한 인덱스 최적화 검토 (facility_permissions, workspace_permissions, team_permissionsaccessor_id + accessor_type 복합 인덱스)
  • 읽기 전용 요청을 read replica로 라우팅하여 write contention 영향 최소화
  • Worker burst 처리 시 rate limiting 또는 connection pool 분리를 통해 API 쿼리 영향도 감소

Monitoring#

  • LevelsController#show P99 latency가 500ms 초과 시 alert 설정 권장
  • Datadog APM 쿼리:
text
avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#show} > 0.5
  • Worker concurrent execution 모니터링:
text
sum:sidekiq.queue.size{queue:default} > 100

Risk Assessment#

  • Risk level: low
  • 예상 복잡도: standard
  • 단일 발생이며 자동 회복된 transient 이슈. 동일 패턴이 반복될 경우 단기 개선 사항 적용 필요.