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#
- 2026-06-06 05:32 KST —
LevelsController#show요청 4818ms 응답 (정상 대비 ~60x 느림) - 2026-06-06 05:32-05:35 KST — 동일 trace_id에서 capture 709116 처리 작업 다수 진행 중
- 2026-06-06 05:34-05:40 KST — worker에서 S3 connection timeout, voxel-service 503 에러 다수 발생
- 2026-06-06 ~05:45 KST — latency 정상 수준으로 회복
Error Log#
{
"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.show → LevelRepository.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:38—before_action :set_level
def set_level
@model = repository_instance.show(params[:id])
end
BaseRepository#showinstance method 호출:app/repositories/base_repository.rb:121
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.showclass method:app/repositories/base_repository.rb:306-343— current_user가 있으므로permission_joins분기 진입
elsif current_user.present?
permission_joins(default_joins(current_class), current_user).where(attrs)
else
- Failure point (bottleneck):
app/repositories/level_repository.rb:105-305—LevelRepository.permission_joins
이 메서드는 단일 SQL 쿼리에서 11개의 LEFT JOIN subquery를 생성하여 level_permissions, facility_permissions, workspace_permissions, team_permissions, review_permissions, grouped_users 테이블을 모두 조인한다:
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-77—LevelSerializer를 통해_user,_team,_workspace,_facility등 cached association을 Redis에서 fetch
def show
render_api Renderable.new({
contents: @model,
serializer_option: @serializer_option
})
end
Log Evidence#
Datadog APM 메트릭 쿼리:
avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#show}
정상 시간대 평균 응답 시간 (초):
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):
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):
service:cupixworks-worker status:error
{
"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"
}
{
"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):
service:cupixworks-api trace_id:6172692582349211334
{
"timestamp": "2026-06-06 05:35:11",
"message": "skatmaster is invoked for capture 709116. job id: 1108448",
"class": "Capture",
"function": "run_skat_master"
}
{
"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#showP95/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_permissions의accessor_id+accessor_type복합 인덱스) - 읽기 전용 요청을 read replica로 라우팅하여 write contention 영향 최소화
- Worker burst 처리 시 rate limiting 또는 connection pool 분리를 통해 API 쿼리 영향도 감소
Monitoring#
LevelsController#showP99 latency가 500ms 초과 시 alert 설정 권장- Datadog APM 쿼리:
avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#show} > 0.5
- Worker concurrent execution 모니터링:
sum:sidekiq.queue.size{queue:default} > 100
Risk Assessment#
- Risk level: low
- 예상 복잡도: standard
- 단일 발생이며 자동 회복된 transient 이슈. 동일 패턴이 반복될 경우 단기 개선 사항 적용 필요.