RCA: Api::V1::ReviewsController#flush_records 10s latency

Overview#

What Happened#

2026-06-10 12:29 KST 시점에 cupixworks-api 의 Api::V1::ReviewsController#flush_records 엔드포인트가 review i74udb 요청에 대해 10.08초가 소요되어 latency 클러스터로 감지되었다. 요청 자체는 HTTP 200 으로 정상 응답하였으며, 동일 14일 윈도우 내 동일한 리소스에서 추가 occurrence 는 없었다 (count=1).

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-10 12:29:10 KST — review i74udb 의 일반 GET 요청 (#show, #meta) 정상 응답.
2. 2026-06-10 12:29:11 KST — PUT /api/v1/reviews/i74udb/flush_records 요청 처리 시작 (Review::flush_records | begins, ReviewRepository::flush_records | begins).
3. 2026-06-10 12:29:11 ~ 12:29:21 KST — 약 10초 동안 동일 review/요청에 대한 추가 로그 없음.
4. 2026-06-10 12:29:21 KST — 요청 200 OK 로 종료 ([200] PUT /api/v1/reviews/i74udb/flush_records).
5. 2026-06-10 12:29:23 KST — Sidekiq FlushReviewRecordsWorker JID-455e63017b7bd8073e6354db: done: 3.312 sec (요청과 분리되어 비동기로 정상 완료).
6. 이후 동일 review 의 후속 GET 요청들 (/load, /levels, /panos 등) 정상 응답.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ReviewsController#flush_records",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10080,
  "max_ms": 10080,
  "sample_trace_id": "2896434637969618957"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-10 12:29 KST
• 최근 발생: 2026-06-10 12:29 KST
• 사용자 영향: 단일 사용자 1회. 요청은 결국 200 OK 로 종료되어 데이터 손상이나 실패는 없음. 다만 ~10초 동안 UI 가 spinner 상태로 멈췄을 가능성이 있음.

Root Cause Summary#

Latency 의 직접 원인을 단정할 수 있는 결정적 evidence (DB lock 메시지, Redis timeout, GC pause 등) 는 Datadog error/warn 레벨 로그에서 발견되지 않았다. 코드 경로상 flush_records 요청은 (1) model.updatable_by? 권한 체크, (2) fresh_state 상태 체크, (3) touch_false + refreshing_fresh_state! 단일 row update, (4) FlushReviewRecordsWorker.perform_async 비동기 enqueue, (5) show serializer 렌더링으로 구성된다. 어느 단계도 정상적으로는 수 ms~수백 ms 수준이며 실제 무거운 작업은 Sidekiq worker 가 비동기로 수행한다 (해당 worker 는 같은 시각 3.3 초만에 완료).

begins 로그 직후 10 초간 동일 request 에서 어떤 info 레벨 로그도 출력되지 않은 점, 동일 14일 윈도우의 다른 flush_records 요청들은 0.04~수 초 범위로 정상 완료된 점, 단발성 1회 occurrence 인 점을 종합하면 transient infrastructure stall (state-machine row update 시 Postgres row lock 대기 또는 Redis 세션/perform_async enqueue stall) 이 가장 가능성 있는 원인이다. 즉시 행동을 요하는 코드 결함은 확인되지 않았으며, 재발 추적을 위한 관측성 보강이 필요하다 — uncertain, evidence 부족으로 단정 불가.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/reviews_controller.rb:54
• Repository call: app/repositories/review_repository.rb:167
• Model state transition + worker enqueue: app/models/concerns/fresh_state/review.rb:8-15
• Async worker: app/workers/flush_review_records_worker.rb:5-12

def flush_records
  @model = repository_instance.flush_records

  show
end

def flush_records
  Cupix::Logger.info('ReviewRepository::flush_records | begins')

  raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied') unless self.model.updatable_by?(self.current_user)
  raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: 'Review already up to date') if self.model.fresh_state_fresh?
  raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: 'Review already refreshing') if self.model.fresh_state_refreshing?

  self.model.flush_records

  @model
end

def flush_records
  Cupix::Logger.info('Review::flush_records | begins')

  touch_false
  refreshing_fresh_state!

  FlushReviewRecordsWorker.perform_async(key)
end

class FlushReviewRecordsWorker
  include Sidekiq::Worker
  sidekiq_options queue: :fresh, retry: 1

  def perform(review_key = nil)
    return if review_key.nil?

    review = Review.find_by_key(review_key)
    Cupix::Logger.error("Review not found: #{review_key}") and return if review.nil?

    review.flush_records_in_worker
  end
end

기대 동작: 컨트롤러는 권한/상태 검증 후 review row 의 fresh_state 컬럼을 refreshing 으로 전이시키고 (touch_false + refreshing_fresh_state!), Sidekiq enqueue (Redis LPUSH) 를 즉시 반환한 뒤 serializer 로 review 객체를 렌더한다. 보통 100~300 ms 이내.

실제 동작: 상기 코드 경로 안에서 10.08 초가 소요되었다. 두 info 로그 (Review::flush_records | begins, ReviewRepository::flush_records | begins) 는 12:29:11 에 모두 찍혔으나 200 응답은 12:29:21 에 발생했다. flush_records 본문 안에서 추가 info 로그가 없으므로 stall 위치는 (a) state_machine transition 시 reviews row 의 Postgres lock 획득 대기, (b) Sidekiq.perform_async 의 Redis 호출 stall, (c) show serializer 의 cache fetch 중 어딘가다 — 정확한 지점은 추가 trace span 데이터 없이 단정할 수 없다 (uncertain — needs verification).

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "i74udb"
2026-06-10T03:29:00Z TO 2026-06-10T03:29:30Z
sort: timestamp asc

해당 review 의 시간순 로그 (KST 표기):

2026-06-10 12:29:10  [200] GET /api/v1/reviews/i74udb (Api::V1::ReviewsController#show)
2026-06-10 12:29:11  [200] GET /api/v1/reviews/i74udb/facilities/meta (Api::V1::ReviewsController#meta)
2026-06-10 12:29:11  Review::flush_records | begins
2026-06-10 12:29:11  ReviewRepository::flush_records | begins
2026-06-10 12:29:21  [200] PUT /api/v1/reviews/i74udb/flush_records (Api::V1::ReviewsController#flush_records)
2026-06-10 12:29:22  [200] GET /api/v1/reviews/i74udb (Api::V1::ReviewsController#show)

Sidekiq worker 측 로그 (service:cupixworks-worker "FlushReviewRecordsWorker", 동일 시간 윈도우):

2026-06-10 12:29:23  FlushReviewRecordsWorker JID-455e63017b7bd8073e6354db: done: 3.312 sec

worker 는 perform_async 직후 정상적으로 큐에서 픽업되어 3.312 초 만에 정상 완료했다. 즉, worker 처리 시간이 컨트롤러 응답을 지연시킨 것이 아니다.

flush_records 관련 동일 시간대(2026-06-10 12:00 ~ 13:00 KST) 다른 요청들의 응답 시간은 정상 범위이며 (worker done 메시지 기준 0.04 ~ 13.997 초이지만 worker duration 은 컨트롤러 latency 와 무관), 단일 occurrence 임을 확인:

service:cupixworks-api status:warn "flush_records"  → 0건 (now-7d)
service:cupixworks-api status:error "flush_records" → 0건 (now-7d)

→ error/warn 로그 부재. 14일 retention 내 동일 fingerprint 재발 0회 (cluster occurrence_count = 1).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

해당 단일 occurrence 만으로 코드 변경을 정당화할 evidence 가 없음. 즉시 코드 수정 권장 사항 없음. RCA 의 가치는 재발 시 빠르게 분석할 수 있도록 관측성을 강화하는 것에 둔다.

단기 개선 (1주 이내)#

• app/repositories/review_repository.rb:167-177 flush_records 메서드에 단계별 timing 로그 추가 (updatable_by? 후, fresh_state 체크 후, model.flush_records 후 / Sidekiq enqueue 후) — 다음 occurrence 발생 시 어느 구간이 stall 인지 즉시 식별 가능.
• 동일 패턴이 적용된 app/models/concerns/fresh_state/review.rb:8-15 Review#flush_records 에도 Sidekiq enqueue 전후 timing 로그 추가.
• Datadog APM trace 에서 Api::V1::ReviewsController#flush_records resource 에 대한 p95 latency 모니터를 활성화하여 anomaly 시 즉시 알림.

장기 개선 (재발 방지)#

• state_machine transition (refreshing_fresh_state!) 가 트리거하는 before_transition / after_transition 콜백, feed/notification 발행, 그리고 update_fresh_state_updated_at 의 DB 작업이 단일 트랜잭션 내에서 직렬화되어 row lock contention 을 일으킬 가능성을 검토 (app/models/concerns/fresh_state.rb:18-47). 필요 시 with_lock(timeout: ...) 또는 SELECT ... FOR UPDATE NOWAIT 패턴으로 lock timeout 명시.
• Sidekiq Redis 클러스터의 ap-southeast-1 리전 latency 모니터링 강화 (sidekiq.enqueue.duration 등 client-side metric).

Monitoring#

• 추가할 메트릭/알림:
  • APM resource latency p95 alert (Api::V1::ReviewsController#flush_records > 2s 5min 지속)
  • 단계별 timing 로그 도입 후, 각 단계 stall 카운트 모니터링

service:cupixworks-api "ReviewRepository::flush_records | begins"

service:cupixworks-api "Api::V1::ReviewsController#flush_records"

service:cupixworks-worker @class:FlushReviewRecordsWorker

Risk Assessment#

• Risk level: low — 단일 occurrence, 200 OK 종료, 사용자 영향 1명 ~10초 spinner. 데이터 정합성 영향 없음.
• 예상 복잡도: trivial — 즉시 코드 수정 불필요. 단기 권장은 timing 로그 추가 정도로 trivial.