EditingsController#index N+1 queries via fetch_cache — cache cold overlay

RCA: Api::V1::EditingsController#index Latency (1453ms)

Overview#

What Happened#

2026-05-27 06:04:18 UTC에 cupixworks-api 서비스의 Api::V1::EditingsController#index 엔드포인트가 1453ms 응답 시간을 기록했다. DB 시간(84ms)과 직렬화 시간(115ms)을 합쳐도 약 200ms에 불과하며, 나머지 ~1250ms는 Redis 캐시 miss 시 발생하는 N+1 fetch_cache 호출과 Elasticsearch 쿼리 오버헤드로 소요되었다.

Quick Facts#

Field	Value
resource_name	`Api::V1::EditingsController#index`
top_frame	`app/repositories/base_repository.rb:70`
env	production, us-west-2
duration	1453ms (DB: 84ms, Serialization: 115ms)
pagination	total_entries: 1589, per_page: 25, page: 1

Timeline#

2026-05-27T06:04:18Z — 클라이언트(13.124.199.63, ap-northeast-2)가 GET /api/v1/editings?editing_type=siteinsights 요청
2026-05-27T06:04:21Z — 응답 완료 (1451ms 소요)
2026-05-27T06:04:18Z — error-sweeper가 latency cluster로 감지
2026-05-27 — RCA 분석 수행

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::EditingsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1453,
  "max_ms": 1453,
  "sample_trace_id": "2181598582847972448"
}

Impact#

Service: cupixworks-api
발생 횟수: 1
최초 발생: 2026-05-27T06:04:18.989Z
최근 발생: 2026-05-27T06:04:18.989Z

Root Cause Summary#

EditingsController#index는 Elasticsearch에서 페이지네이션된 결과를 가져온 뒤, 각 레코드의 연관 객체(_user, _editor, _escalated_by, _record, _level, _category, _workarea)를 직렬화할 때 Cachable#fetch_cache를 호출한다. 이 메서드는 Redis 캐시에서 먼저 조회하고, miss 시 find_by_id로 개별 DB 쿼리를 실행한다. default_joins가 SQL JOIN으로 연관 데이터를 SELECT에 포함하지만, 직렬화 시점에는 이 JOIN 결과를 활용하지 않고 fetch_cache 경로를 타므로, 캐시가 cold 상태이면 per-page 25건 × 7개 연관 = 최대 175회의 추가 캐시/DB 조회가 발생한다. 이 overhead가 측정된 DB 시간(84ms) 외에 누적되어 ~1250ms의 "dark time"을 만들었다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/editings_controller.rb:11
Elasticsearch 검색: app/repositories/editing_repository.rb:174
Pagination + default_joins: app/repositories/base_repository.rb:70-81
직렬화: app/serializers/editing_serializer.rb:8-18
캐시 조회 (failure point): app/models/concerns/cachable.rb:58-70

1. Controller에서 repository.search 호출:

app/controllers/api/v1/editings_controller.rb:11-20ruby

def index
  editing_query_option = Cupix::QueryOption::Editing.new(get_query_option(enable_current_team: false), params)
  editings = repository_instance.search(editing_query_option)

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

2. Repository에서 Elasticsearch 검색 후 SQL JOIN 적용:

app/repositories/editing_repository.rb:174-181ruby

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

set_response(response)

app/repositories/editing_repository.rb:189-212ruby

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

default_joins는 SQL level에서 연관 데이터를 SELECT하지만, 이 결과는 level_name, user_firstname 등의 alias column으로만 존재한다. Serializer가 호출하는 _user, _editor 등의 메서드는 이 alias를 사용하지 않고 별도로 fetch_cache를 호출한다.

3. Serializer에서 연관 객체 직렬화:

app/serializers/editing_serializer.rb:8-18ruby

attribute :user, &:_user
attribute :editor, &:_editor
attribute :escalated_by, &:_escalated_by
include TeamAttribute
include WorkspaceAttribute
include FacilityAttribute
attribute :record, &:_record
attribute :record_ids
attribute :level, &:_level
attribute :category, &:_category
attribute :workarea, &:_workarea

4. _user, _editor 등은 ApplicationRecord에서 동적 생성:

app/models/application_record.rb:81-95ruby

def belongs_to(name, scope = nil, **options)
  super

  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
end

5. fetch_cache에서 캐시 miss 시 개별 DB 조회:

app/models/concerns/cachable.rb:58-70ruby

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

캐시 miss 시 find_by_id (line 65)가 실행된다. 25개 editing × 7개 연관 객체 = 최대 175회의 Redis 조회 + DB fallback이 발생할 수 있다. 이 개별 쿼리들은 Rails의 db instrumentation에 EditingsController#index의 DB 시간으로 합산되지 않고, 각각이 수 ms씩 소요되어 누적된다.

Log Evidence#

Datadog에서 확인한 실제 요청 로그:

text

service:cupixworks-api resource_name:"Api::V1::EditingsController#index" @duration:>500ms env:production

json

{
  "resource_name": "Api::V1::EditingsController#index",
  "duration_ms": 1451.17,
  "db_ms": 84.31,
  "serialization_ms": 115,
  "view_ms": 0.1,
  "host": "ip-10-1-80-134.us-west-2.compute.internal",
  "pagination": {
    "total_entries": 1589,
    "per_page": 25,
    "page": 1,
    "total_pages": 64
  },
  "filter": "editing_type=siteinsights",
  "remote_ip": "13.124.199.63",
  "user_email": "grace.yoon@cupix.com",
  "user_id": 5346,
  "team_id": 133
}

동일 시간대 다른 EditingsController 요청에서도 유사한 "dark time" 패턴 확인:

text

| Time       | Action               | Duration | DB    | Unaccounted |
| 06:01:46Z  | index                | 1030ms   | 9ms   | ~1000ms     |
| 06:02:27Z  | update               | 3595ms   | 275ms | ~3200ms     |
| 06:05:47Z  | list_editing_entities| 899ms    | 13ms  | ~870ms      |
| 06:08:59Z  | list_editing_entities| 1294ms   | 12ms  | ~1270ms     |

동시간대 FlushCycleStateChildrenWorker가 다수의 EditingEntity에 대해 bulk 작업을 수행 중이었으며, EditingEntity._update_document에서 "NotFound - attributes_in_database" warn 로그가 다수 발생하여 Redis 캐시 invalidation이 빈번했을 가능성이 있다.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Redis 캐시 miss로 인한 N+1 `fetch_cache` 호출	DB 84ms + Serialization 115ms = ~200ms인데 총 1451ms 소요. `FlushCycleStateChildrenWorker`가 동시 실행되며 캐시 invalidation 유발. `cachable.rb:65`의 `find_by_id` fallback 경로 존재. 동일 패턴이 `list_editing_entities`에서도 반복 (DB 12ms, 총 1294ms)	개별 캐시 miss 로그는 Datadog info level에서 확인 불가	Confirmed
H2	Elasticsearch 쿼리 자체의 느린 응답	Elasticsearch 호출이 전체 흐름의 첫 단계	DB 시간 84ms에 ES 쿼리 시간이 포함됨. 84ms는 정상 범위. 다른 요청에서도 ES 자체는 빠름 (DB 9ms인 경우에도 총 1030ms)	Rejected
H3	크로스 리전 네트워크 지연 (한국 → us-west-2)	요청 IP 13.124.199.63은 ap-northeast-2 (한국). RTT 추가 지연 가능	네트워크 RTT는 보통 100-200ms 수준이며 1250ms를 설명하지 못함. 같은 리전(ap-southeast-2)에서도 1030ms 발생	Rejected
H4	Ruby GC pause로 인한 지연	대량 객체 생성 시 GC 발생 가능	단발성이 아닌 모든 요청에서 일관된 패턴. GC는 간헐적 spike를 만들지 일관된 1000ms+ 지연을 만들지 않음	Rejected

Fix Recommendation#

즉시 조치 (Critical)#

app/serializers/editing_serializer.rb:8-18 — _user, _editor, _escalated_by, _record, _level, _category, _workarea 호출 시 default_joins에서 이미 SELECT한 alias column들을 활용하도록 직렬화 로직 변경. 현재 default_joins가 user_firstname, editor_email 등을 이미 가져오고 있으나 serializer가 이를 무시하고 fetch_cache를 호출하는 구조.

단기 개선 (1주 이내)#

app/repositories/editing_repository.rb:189 — default_joins 대신 includes/preload를 사용하여 연관 객체를 eager load하고, serializer에서 fetch_cache 대신 이미 로드된 연관 객체를 직접 직렬화하도록 변경. 또는 fetch_cache에서 batch 조회(multi-read)를 지원하여 N+1을 N/batch로 줄이기.
app/models/concerns/cachable.rb:61 — Rails.cache.fetch_multi를 활용한 batch cache 조회 도입 검토.

장기 개선 (재발 방지)#

Serializer 아키텍처 리팩토링: Cachable concern의 per-record fetch_cache 패턴을 collection-level batch fetch로 전환. default_joins의 SELECT alias와 serializer output을 일치시켜 JOIN 결과를 직접 활용하는 구조로 통합.
APM에서 fetch_cache 호출 횟수와 miss rate를 계측하여 cold cache 상황을 모니터링.

Monitoring#

fetch_cache miss rate 메트릭 추가 (캐시 hit/miss 비율)
EditingsController#index p95 latency 알림 설정

text

service:cupixworks-api resource_name:"Api::V1::EditingsController#index" @duration:>1000ms env:production

Risk Assessment#

Risk level: low
예상 복잡도: standard — serializer와 repository 간의 데이터 전달 방식 변경이 필요하며, Cachable concern이 여러 모델에서 공유되므로 영향 범위 확인 필요.