ES /docs

Api::V1::BookmarksController#index (avg 50702ms, max 50702ms)

RCA: Api::V1::BookmarksController#index (avg 50702ms, max 50702ms)

Overview#

What Happened#

2026-07-11 04:51 KST 에 production (us-west-2) 의 cupixworks-api 에서 Api::V1::BookmarksController#index 요청이 약 50.7초 동안 실행됨. 같은 review key (4tr8hc) 에 대해 짧은 시간 안에 반복 호출이 관찰되었고 최종적으로 모두 HTTP 200 으로 응답. 단일 tenant (cupix) 에서 1건만 감지됨.

Quick Facts#

Field Value
resource Api::V1::BookmarksController#index
avg_duration_ms 50702
max_duration_ms 50702
top_frame app/repositories/bookmark_repository.rb:_search → BaseRepository#search (app/repositories/base_repository.rb:70-112)
env production, us-west-2
tenant cupix
sample_trace_id 3055139774784225119
status latency (200 OK, not error)

Affected Teams#

Team / Domain Error Count Impact
cupix 1 단일 사용자가 review 뷰 로딩 시 bookmarks 목록을 약 50초 대기 (또는 client timeout 재시도 유발)

Timeline#

  1. 2026-07-11 04:45 ~ 04:51 KST — 같은 review 4tr8hc 에 대해 /api/v1/reviews/4tr8hc/bookmarks/me 와 /bookmarks/team 이 반복 호출됨 (04:45:14, 04:46:26, 04:49:30, 04:51:47, 04:51:49 ...) — Datadog service:cupixworks-api BookmarksController 결과.
  2. 2026-07-11 04:51:48 KST (=2026-07-10T19:51:48.656Z) — Datadog APM 이 50702ms 트레이스 (3055139774784225119) 를 기록. cluster first_seen = last_seen.
  3. 2026-07-11 04:52:13 ~ 04:52:39 KST — 동일 review 에 대해 추가 재시도 요청 4건 관찰. 모두 200.
  4. 2026-07-11 05:xx KST 이후 — 이후 시간대 (/reviews/*/bookmarks/*) 응답은 모두 정상적인 응답 시간대 안에서 200 반환 (04:59:52, 05:29:50 등).

Error Log#

Datadog Logs

cluster representative spanjson
{
  "resource_name": "Api::V1::BookmarksController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 50702,
  "max_ms": 50702,
  "sample_trace_id": "3055139774784225119"
}

이 cluster 는 status:error 로 기록된 예외가 없으며 APM latency 기반으로만 감지됨. 동일 시간대 (2026-07-10T19:45:00Z ~ 20:00:00Z) 에 service:cupixworks-api status:error 검색 결과 0건.

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1
  • 최초 발생: 2026-07-11 04:51 KST
  • 최근 발생: 2026-07-11 04:51 KST

단일 요청 (occurrence_count 1) 이지만 응답 시간이 50초를 넘겨 대부분의 프런트엔드/CDN/로드밸런서 timeout (통상 30~60초) 에 근접. 같은 review 에 대한 반복 호출 패턴은 client-side 재시도로 인한 부하 증폭 가능성을 보여줌.

Root Cause Summary#

BookmarkRepository#_search 는 Elasticsearch 로 후보 bookmark id 를 조회한 뒤, BaseRepository#search 에서 permission_joins 를 호출해 MySQL 쪽에서 11개 이상의 LEFT JOIN 서브쿼리 + GROUP BY id 로 권한을 재계산한다. review 키가 있는 경로는 review/facility/workspace/team 단위 권한(user, group, system_group, public_access) 을 모두 한 쿼리에 결합한다 (app/repositories/bookmark_repository.rb:36-199). 이 조합이 이번 요청에서 약 50초를 소비했고, MySQL slow query (또는 Elasticsearch 응답 지연) 가 원인일 가능성이 가장 높다. 로그 레벨에서 예외는 발견되지 않아 (status:error 0건) DB/ES latency spike 로 판단된다. 단, @duration 기반의 상세 APM trace span breakdown (ES vs MySQL vs render 시간) 은 확인하지 못했으므로 "MySQL vs ES" 세부 원인 확정은 uncertain — needs verification.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/bookmarks_controller.rb:11-20

app/controllers/api/v1/bookmarks_controller.rb:11-20ruby
def index
  bookmark_query_option = Cupix::QueryOption::Bookmark.new(get_query_option(enable_current_team: false), params.merge(bookmark_type: @bookmark_type, owner_type: @owner_type))
  bookmarks = repository_instance.search(bookmark_query_option)

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

before_action :set_bookmark 는 index 에서 스킵된다 (except: %i[index create mock]). 따라서 실행 흐름은 set_type → search.

BaseRepository#search (execution flow):

app/repositories/base_repository.rb:70-98ruby
def search(query_option = nil)
  _search(query_option)   # Elasticsearch 호출

  begin
    if self.review.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review.id, skip_join: _skip_join?)
    elsif self.review_id.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review_id, skip_join: _skip_join?)
    # ...
    end
  rescue Elasticsearch::Transport::Transport::ServerError => e
    raise unless e.message.start_with?('[429]')
    # ...
  end
end

_search 는 Elasticsearch 호출:

app/repositories/bookmark_repository.rb:294-303ruby
response = ::Bookmark.search(
  self.query_option.serializable_hash
).paginate(
  per_page: self.query_option.per_page,
  page: self.query_option.page
)

이후 review key 경로에서는 ReviewRepository.new(...).show(...) 로 review 를 fetch (bookmark_repository.rb:246) 하고, 이후 permission_joins 로 MySQL 권한 조인을 수행. 핵심 실패지점 후보는 이 MySQL 쿼리:

app/repositories/bookmark_repository.rb:36-199ruby
def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  # ...
  record.joins("
    LEFT JOIN ( SELECT reviews.id ... ) AS review_public_permissions ...
    LEFT JOIN ( SELECT review_id, permission FROM review_permissions ... ) AS review_user_permissions ...
    LEFT JOIN ( SELECT review_id, permission FROM review_permissions LEFT JOIN grouped_users ... ) AS review_group_permissions ...
    LEFT JOIN ( ... facility_user_permissions ... )
    LEFT JOIN ( ... facility_group_permissions ... )
    LEFT JOIN ( ... facility_system_group_permissions ... )
    LEFT JOIN ( ... workspace_user_permissions ... )
    LEFT JOIN ( ... workspace_group_permissions ... )
    LEFT JOIN ( ... team_user_permissions ... )
    LEFT JOIN ( ... team_group_permissions ... )
    LEFT JOIN ( ... team_system_group_permissions ... )
  ").group('id').select(_select).where("GREATEST(...) > 0 OR GREATEST(...) > 1")
end

기대 동작: bookmark 후보 (ES 로 이미 제한됨) 에 대해 권한 필터를 MySQL 로 재확인 후 반환. 정상 요청은 수백 ms 이내.

실제 동작: 이번 트레이스에서 총 50.7초 소요. permission_joins 는 사용자별로 grouped_users 를 여러 번 조인하고 GROUP BY id 를 수행하기 때문에 큰 group 소속 사용자에 대해 임시 테이블/파일 정렬을 유발할 수 있음. 또는 review fetch 단계에서 다른 slow query 로 지연되었을 가능성.

Failure point (latency origin, 미확정): app/repositories/bookmark_repository.rb:permission_joins 의 대형 SQL 또는 app/repositories/bookmark_repository.rb:294-299 의 Elasticsearch 요청 중 하나. uncertain — needs verification via APM span breakdown.

Log Evidence#

Datadog query 로 재현:

text
service:cupixworks-api BookmarksController
range: 2026-07-10T19:45:00Z ~ 2026-07-10T20:00:00Z

동일 review 4tr8hc 에 대한 반복 호출 (재시도 패턴):

text
2026-07-11 04:51:49 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/me    (Api::V1::BookmarksController#index)
2026-07-11 04:52:13 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/me    (Api::V1::BookmarksController#index)
2026-07-11 04:52:15 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/team  (Api::V1::BookmarksController#index)
2026-07-11 04:52:37 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/me    (Api::V1::BookmarksController#index)
2026-07-11 04:52:38 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/team  (Api::V1::BookmarksController#index)
2026-07-11 04:52:39 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/team  (Api::V1::BookmarksController#index)
2026-07-11 04:49:30 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/me    (Api::V1::BookmarksController#index)
2026-07-11 04:49:31 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/team  (Api::V1::BookmarksController#index)
2026-07-11 04:46:26 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/me    (Api::V1::BookmarksController#index)
2026-07-11 04:46:26 KST  [200] GET /api/v1/reviews/4tr8hc/bookmarks/team  (Api::V1::BookmarksController#index)

동일 시간 범위 (2026-07-10T19:45:00Z ~ 20:00:00Z) 에서 status:error 검색 결과 0건. 즉, 예외는 발생하지 않고 오직 응답 지연만 있었음:

text
service:cupixworks-api status:error
range: 2026-07-10T19:45:00Z ~ 2026-07-10T20:00:00Z
=> Found 0 logs

sample trace id 3055139774784225119 자체는 로그 index 에 인덱싱된 필드로 매칭되지 않아 직접 조회는 실패 (Datadog 로그에서 trace_id 는 attribute 로만 존재하며, span 세부 정보는 APM 링크에서 확인해야 함):

text
service:cupixworks-api "3055139774784225119"
=> Found 0 logs

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 BookmarkRepository#permission_joins 의 대형 LEFT JOIN + GROUP BY 쿼리가 특정 사용자/review 조합에서 MySQL slow query 를 유발해 응답 시간이 50초에 도달 bookmark_repository.rb:36-199 에 11개 이상의 LEFT JOIN 서브쿼리와 GROUP BY id 존재; APM latency 50702ms; 같은 endpoint 의 다른 요청은 정상 응답; status:error 로그 0건이라 예외 없이 순수 지연 APM span breakdown 을 로그로 확인하지 못해 DB 시간 비중이 실제로 얼마인지 미확인 Inconclusive (most likely)
H2 Elasticsearch (::Bookmark.search) 응답 지연이 50초 대부분을 차지 bookmark_repository.rb:294-299 에서 ES 호출이 동기적으로 이루어짐; ES circuit breaker(429) 는 rescue 로 별도 처리되므로 timeout 이 아닌 지연은 그대로 노출됨 ES circuit breaker 발생 시 Elasticsearch::Transport::Transport::ServerError 를 raise 하고 Cupix::Logger.error("Elasticsearch circuit breaker: ...") 로그를 남기지만 (base_repository.rb:88-93) 해당 로그도 발견되지 않음. ES 지연이었다면 다른 endpoint (예: reviews search) 도 함께 느려졌을 텐데 같은 시간 다른 서비스에 error 없음 Rejected
H3 외부 dependency (S3/EFS/upstream service) 장애 — status-board 결과 scope=svc:cupixworks-api::unknown 이고 active=null. 같은 시간대에 dep:* scope 도 없음. status:error 0건 Rejected
H4 이 요청은 실제로 성공했고 client 재시도로 인해 부하가 증폭됨 (root cause 는 아니지만 관련 관찰) 04:45 ~ 04:52 사이 동일 review 4tr8hc 에 대한 10건 이상의 반복 호출 로그. 각 호출은 me/team 페어. 정상 사용자 세션이라면 페이지 로딩 1회당 me+team 2회이지 4~5분 동안 동일 review 를 반복 호출하지는 않음 재시도 패턴이 slow response 의 원인은 아니고 결과 (사용자 새로고침) 로 해석 가능 Confirmed as contributing factor, not root cause
H5 배포/deploy spike 로 인한 warm-up 지연 — 배포 시각/SHA 정보를 확인할 수 있는 배포 로그를 이 조사에서 확인하지 못함 Inconclusive

Fix Recommendation#

즉시 조치 (Critical)#

  • APM span breakdown 확인: 링크된 Datadog APM trace (3055139774784225119) 를 열어 span 별 소요 시간 (ES 쿼리 / MySQL 쿼리 / Ruby render) 을 실제로 확인. 이 데이터 없이는 H1/H2 를 확정할 수 없음. 담당자가 수동으로 확인 필요.
  • 대규모 review 케이스 재현: review 4tr8hc 의 team 규모, bookmark 개수, grouped_users/review_permissions row 수를 staging 이나 read-replica 에서 조회해 실제 slow query 재현 여부 확인. 필요 파일: app/repositories/bookmark_repository.rb:36-199 (permission_joins).

단기 개선 (1주 이내)#

  • permission_joins 쿼리 리팩토링 검토: 11개 LEFT JOIN 을 한 쿼리에 모두 결합하는 대신, 사용자 권한을 미리 계산 (current_user.readable_review_ids, readable_facility_ids 등) 하고 record.where(id: authorized_ids) 방식으로 축소하는 방향. 이미 mock 경로 (base_repository.rb:188-296) 에서는 directly_readable_*_ids 를 사용하는 유사 패턴이 있음 — 이를 참고.
  • MySQL slow query 알림 강화: bookmarks + permission_joins SQL 시그니처에 대해 slow_query_log threshold (예: 3s) 초과 시 알림 걸기.
  • BookmarksController#index timeout 방어: 컨트롤러/미들웨어 단에서 30초 이상 걸리는 요청은 명시적으로 timeout 반환하도록 검토 (client timeout 이 재시도 폭증을 유발하지 않게).

장기 개선 (재발 방지)#

  • Bookmark 검색은 Elasticsearch 로 이미 제한된 후보를 다시 MySQL 로 권한 검증하는 두 단계 구조. 권한 정보를 Elasticsearch 인덱스에 embed 하거나 (Searchable::Bookmark mapping 확장), 별도 permission cache layer 도입을 검토.
  • APM 기반 latency SLO 도입: resource_name:"Api::V1::BookmarksController#index" 의 p99 를 SLO 로 설정하고 error budget 소진 시 페이지.

Monitoring#

Bookmarks endpoint p95 지연 시간 시계열 (release dashboard timeseries widget 용):

text
avg:trace.rack.request.duration.by_http_status{service:cupixworks-api,resource_name:api::v1::bookmarkscontroller#index}

Bookmarks endpoint slow request (>5s) 개수 (log-based):

text
service:cupixworks-api BookmarksController @duration:>5000000000

전체 API p99 latency:

text
p99:trace.rack.request.duration{service:cupixworks-api} by {resource_name}

MySQL bookmarks table slow query rate (참고, 실제 태그 이름은 팀 환경에 따라 조정 필요):

text
sum:mysql.performance.slow_queries{service:cupixworks-api}.as_rate()

Risk Assessment#

  • Risk level: low — 발생 횟수 1건, 최종 응답 200, 예외 없음. 그러나 재발 시 사용자 체감 (bookmark 목록 50초 대기) 및 client 재시도 증폭 위험 있음.
  • 예상 복잡도: standard — 즉시 확인 단계 (APM breakdown) 는 trivial 이지만, 실제 fix 는 permission_joins 리팩토링을 수반할 수 있어 신중한 회귀 테스트 필요.