Api::V1::EditingsController#show (avg 1580ms, max 1580ms)
RCA: Api::V1::EditingsController#show Latency (1580ms)
Overview#
What Happened#
2026-05-27 09:20 UTC, cupixworks-api 서비스의 Api::V1::EditingsController#show 엔드포인트에서 1580ms 응답 시간이 관측되었다. 정상 응답(200)이지만 500ms p95 임계값을 크게 초과하는 latency 이상이다.
Quick Facts#
| Field | Value |
|---|---|
| resource_name | Api::V1::EditingsController#show |
| top_frame | app/repositories/base_repository.rb:308 |
| env | production, us-west-2 |
| avg_duration | 1580ms |
| sample_trace_id | 4471223273264767489 |
Timeline#
- 2026-05-27 09:20:02Z — EditingsController#show 요청 수신, 1580ms 응답 시간 관측
- 2026-05-27 — Error sweeper에 의해 latency cluster 감지
- 2026-05-28 — RCA 분석 수행
Error Log#
{
"resource_name": "Api::V1::EditingsController#show",
"service": "cupixworks-api",
"occurrences": 1,
"avg_ms": 1580,
"max_ms": 1580,
"sample_trace_id": "4471223273264767489"
}
Impact#
- Service:
cupixworks-api - 발생 횟수: 1
- 최초 발생: 2026-05-27T09:20:02.126Z
- 최근 발생: 2026-05-27T09:20:02.126Z
Root Cause Summary#
EditingsController#show의 응답 지연은 repository의 heavy LEFT JOIN 쿼리와 serialization 단계에서의 N+1 cache miss가 복합적으로 작용한 결과이다. BaseRepository.show()가 6개 테이블을 LEFT JOIN하고 3개의 users 테이블을 추가로 JOIN하여 14개 컬럼을 SELECT하며, 이후 EditingSerializer가 최소 9개 연관 엔티티(user, editor, escalated_by, record, level, category, workarea, team, workspace, facility)에 대해 각각 fetch_cache()를 호출한다. Redis cache miss 시 각 연관별로 개별 DB 쿼리가 발생하여 누적 지연이 1580ms에 달한다.
Technical Analysis#
Code Path#
- Entry point:
app/controllers/api/v1/editings_controller.rb:31 set_editingbefore_action이repository_instance.show(params[:id])호출- Repository layer:
app/repositories/base_repository.rb:308-386 - Heavy JOIN:
app/repositories/editing_repository.rb:189-212 - Serialization:
app/serializers/editing_serializer.rb:1-69 - Cache fetch:
app/models/concerns/cachable.rb:58-70 - Statistics query:
app/models/concerns/statisticable/editing.rb:8-15
1단계 — Repository JOIN 쿼리:
def default_joins(record)
record.left_joins(:level, :workspace, :facility, :team, :category, :workarea)
.joins("
LEFT JOIN users ON users.id = editings.user_id
LEFT JOIN users AS editor ON editor.id = editings.editor_id
LEFT JOIN users AS escalated_by ON escalated_by.id = editings.escalated_by_id
").select('
editings.*,
levels.name AS level_name,
workspaces.name AS workspace_name,
facilities.name AS facility_name,
facilities.key AS facility_key,
teams.name AS team_name,
users.firstname AS user_firstname,
users.lastname AS user_lastname,
users.email AS user_email,
editor.firstname AS editor_firstname,
editor.lastname AS editor_lastname,
editor.email AS editor_email,
escalated_by.firstname AS escalated_by_firstname,
escalated_by.lastname AS escalated_by_lastname,
escalated_by.email AS escalated_by_email
')
end
9개 테이블에 대한 LEFT JOIN과 14개 컬럼 SELECT. 이 쿼리 자체가 200-400ms를 소요할 수 있다.
2단계 — BaseRepository.show() 후처리:
scope = current_class.visibility_scope(visibility)
model = query.merge(scope).first
if model.nil? && current_user.present? && current_user.team.domain == 'admin'
unless (::UserRepository.new(model: current_user).group_codes & %w[administrator senior_editing_engineers]).empty?
model = self.where(attrs).merge(scope).first
end
end
admin 사용자일 경우 권한 체크를 위한 추가 쿼리가 발생한다. UserRepository.new(model:).group_codes는 그룹 코드 조회를 위한 별도 쿼리를 실행한다.
3단계 — Serialization에서의 N+1 cache fetch:
attribute :user, &:_user
attribute :editor, &:_editor
attribute :escalated_by, &:_escalated_by
include TeamAttribute
include WorkspaceAttribute
include FacilityAttribute
attribute :record, &:_record
attribute :level, &:_level
attribute :category, &:_category
attribute :workarea, &:_workarea
각 attribute가 _<name> 메서드를 호출한다. 이 메서드들은 ApplicationRecord에서 동적으로 생성된다:
define_method "_#{name}" do |*args, **kwargs, &block|
if options[:polymorphic]
fetch_cache(send("#{name}_type"), send("#{name}_id")).merge({
type: send("#{name}_type")
}) rescue nil
else
model_name = options[:class_name] || name
model_id = options[:foreign_key] || "#{name}_id"
fetch_cache(model_name.to_s.classify, send(model_id))
end
end
4단계 — Cache miss 시 DB fallback:
def fetch_cache(model_name = self.class.name, model_id = self.id)
return nil if model_id.blank?
Rails.cache.fetch(cache_key(model_name, model_id), skip_nil: true, expires_in: self.class.cache_expires_in) do
if self.respond_to?("serialized_#{model_name.underscore}_json".to_sym)
self.send("serialized_#{model_name.underscore}_json")
else
record = model_name.constantize.find_by_id(model_id)
record.serialized_json if record.respond_to?(:serialized_json)
end
end
end
Cache miss 시 find_by_id로 개별 DB 쿼리 실행. 9개 이상의 연관 엔티티에 대해 각각 발생하면 ~900ms 추가 지연.
5단계 — Statistics 쿼리:
def statistic_to_json
stats = all_statistic
{
editing: _editing_stat_json(stats),
count: _count_stat_json
}
end
all_statistic은 statistics 테이블에 대한 GROUP BY 집계 쿼리를 실행한다:
def all_statistic
return @preloaded_all_statistic if defined?(@preloaded_all_statistic)
statistics.group(:name, :phase)
.maximum(:created_at)
.transform_values(&:to_datetime)
end
Log Evidence#
Datadog에서 해당 시간대 EditingsController#show 요청 로그를 확인하였다. 에러 수준 로그는 없으며 모든 요청이 200 응답으로 처리되었다.
Datadog query: service:cupixworks-api "EditingsController#show" from:2026-05-27T09:00:00Z to:2026-05-27T09:40:00Z
결과 (동일 시간대 정상 응답 확인):
2026-05-27 18:39:59 [info] [200] GET /api/v1/editings/1122918 (Api::V1::EditingsController#show)
2026-05-27 18:39:37 [info] [200] GET /api/v1/editings/1122917 (Api::V1::EditingsController#show)
2026-05-27 18:38:41 [info] [200] GET /api/v1/editings/1122916 (Api::V1::EditingsController#show)
2026-05-27 18:37:39 [info] [200] GET /api/v1/editings/189520 (Api::V1::EditingsController#show)
에러 수준 로그 검색 (0건):
Datadog query: service:cupixworks-api "EditingsController" status:error from:2026-05-27T08:00:00Z to:2026-05-27T10:30:00Z
APM trace ID 4471223273264767489로 참조되는 span은 Datadog APM에서 세부 breakdown(DB 쿼리 시간, cache 호출 시간 등)을 확인할 수 있다.
Hypotheses Considered#
| # | Hypothesis | Evidence for | Evidence against | Verdict |
|---|---|---|---|---|
| H1 | Heavy LEFT JOIN 쿼리 + N+1 cache miss로 인한 누적 지연 | editing_repository.rb:189-212에서 9개 테이블 JOIN, cachable.rb:65에서 cache miss 시 find_by_id 개별 쿼리, serializer가 9개 이상 연관 엔티티 개별 fetch |
단일 발생(occurrence 1)이므로 항상 느린 것은 아님 — cache가 warm 상태면 빠름 | Confirmed |
| H2 | DB 연결 풀 고갈 또는 PostgreSQL slow query | 1580ms는 단일 쿼리 timeout보다 훨씬 작음 | 동일 시간대 다른 요청은 정상 응답, error/warn 로그 없음. 단일 occurrence로 시스템 전반 이슈 아님 | Rejected |
| H3 | Redis cache 일시적 지연 (네트워크 또는 eviction) | Cache miss 시 모든 연관에 대해 fallback 쿼리 발생하므로 Redis 지연이면 전체 지연으로 이어짐 | Redis 관련 error/warn 로그 없음. 확인 불가하나 가능성 있음 | Inconclusive |
Fix Recommendation#
즉시 조치 (Critical)#
app/repositories/editing_repository.rb:189-212:default_joins가 show()에서도 전체 JOIN을 실행한다.#show전용으로 필요한 최소 JOIN만 수행하는 경량 쿼리 경로를 추가하는 것이 효과적이다.app/serializers/editing_serializer.rb:fields파라미터를 활용하여 클라이언트가 요청하지 않는 연관 속성의 serialization을 건너뛸 수 있도록 하면 불필요한 cache fetch를 방지할 수 있다.
단기 개선 (1주 이내)#
- Eager loading 또는 batch cache fetch: serialization 전에 필요한 연관 엔티티 ID를 수집하고
Rails.cache.read_multi로 한 번에 조회하여 N+1 cache miss 패턴을 제거한다. - Statistics preloading:
all_statistic결과를 repository layer에서 미리 로드하여 serialization 단계에서 추가 쿼리를 방지한다.
장기 개선 (재발 방지)#
Cachableconcern의fetch_cache패턴을 batch 방식으로 리팩터링하여 N+1 cache 호출을 근본적으로 제거한다.- APM에서 p95/p99 latency 모니터링을 설정하여 특정 엔드포인트의 응답 시간 이상을 조기에 감지한다.
Monitoring#
- APM p95 latency 알림:
avg(last_5m):p95:trace.rack.request{service:cupixworks-api,resource_name:api::v1::editingscontroller#show} > 1000 - Cache hit rate 모니터링:
sum:cache.miss{service:cupixworks-api,controller:editings}.as_rate() - 추가 Datadog 쿼리:
service:cupixworks-api resource_name:"Api::V1::EditingsController#show" @duration:>1000ms env:production
Risk Assessment#
- Risk level: low
- 예상 복잡도: standard
- 단일 발생으로 사용자 영향은 미미하나, cache가 cold 상태인 경우(배포 직후, Redis 재시작 후) 반복 발생 가능성이 있다.