ExportWorker N+1 query in pointcloud — timeout on shutdown

RCA: Database export model failed — Sidekiq::Shutdown during read_capture

Overview#

What Happened#

2026-04-23 07:20~08:15 UTC 사이, cupixworks-api 서비스의 ExportWorker가 migration id(1252)의 데이터베이스 export 작업 중 반복적으로 Sidekiq::Shutdown 예외를 수신했다. 약 5분 간격으로 Sidekiq 프로세스가 종료되면서 read_capture 단계에서 실행 중이던 MySQL 쿼리가 중단되었고, 12회 연속 실패 후 대량의 retry job이 동시에 쌓여 concurrency 충돌이 발생했다.

Quick Facts#

Field	Value
exception.class	`Sidekiq::Shutdown`
exception.message	`Sidekiq::Shutdown`
top_frame	`mysql2/client.rb:148:in '_query'`
runtime	Ruby 3.3.0, Rails 7.2.2, Sidekiq 7.3.9
env	production, us-west-2

Timeline#

07:18:43Z — ExportWorker 최초 실행 시작 (migration id 1252, facility 9168)
07:20:31Z — 첫 번째 Sidekiq::Shutdown 발생 (read_capture 단계, ~2분 실행 후)
07:25:27Z ~ 08:15:31Z — 약 5분 간격으로 11회 추가 Sidekiq::Shutdown 반복 (모두 read_capture 단계)
08:22:19Z — 누적된 retry job들이 동시 실행되어 "sidekiq is already running" 경고 대량 발생
08:22:19Z — retries exhausted 로그 없음 — job이 최종 실패 없이 retry 큐에 남아있는 상태

Error Log#

Datadog Logs

text

Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown: Sidekiq::Shutdown /var/app/current/vendor/bundle/ruby/3.3.0/gems/mysql2-0.5.4/lib/mysql2/client.rb:148:in `_query'
/var/app/current/app/operations/migration_export_operation.rb:632:in `create_pointcloud_data'
/var/app/current/app/operations/migration_export_operation.rb:495:in `block in create_model_data'
/var/app/current/app/operations/migration_export_operation.rb:485:in `create_model_data'
/var/app/current/app/operations/migration_export_operation.rb:419:in `read_panos'
/var/app/current/app/workers/export_worker.rb:138:in `block in perform'
/var/app/current/app/workers/export_worker.rb:134:in `perform'

Impact#

Service: cupixworks-api
발생 횟수: 12 (11 in cluster + 1 initial)
최초 발생: 2026-04-23T07:25:27.111Z
최근 발생: 2026-04-23T08:15:31.350Z
영향: migration id(1252)의 facility 9168 데이터 export 작업이 ~1시간 동안 완료되지 못함. 200+ record, 다수의 capture를 포함하는 대규모 facility의 cross-region migration이 지연됨.

Root Cause Summary#

Sidekiq migration 프로세스(sidekiq_migration.yml, concurrency: 1)가 약 5분 간격으로 반복 종료되면서 Sidekiq::Shutdown 신호를 수신했다. ExportWorker는 facility 9168의 read_capture 단계에서 200+ record에 대해 batch(10개씩) 단위로 capture, video, cluster, pointcloud 등 다수의 DB 쿼리를 수행하는데, 각 batch 내에서 create_model_data → create_pointcloud_data가 개별 레코드마다 Pointcloud.find(row['id'])로 N+1 쿼리를 실행하여 작업 시간이 길어진다. Sidekiq의 shutdown timeout(기본 25초) 내에 현재 batch를 완료할 수 없어 Sidekiq::Shutdown이 MySQL 쿼리 실행 중에 raise된다. Worker는 이를 catch하여 StandardError로 re-raise해 retry 카운트를 증가시키는 로직이 있지만, 5분마다 반복되는 shutdown으로 인해 checkpoint(read_capture 단계까지만 기록)로 resume해도 동일한 긴 batch에서 다시 종료된다.

Technical Analysis#

Code Path#

Entry point: app/workers/export_worker.rb:19 — perform(arg) 메서드
주요 단계: read_facility → read_level → read_floorplan → read_workarea_group → read_record → read_capture → read_pano
Failure point: read_capture 단계 내부, app/operations/migration_export_operation.rb:632 — create_pointcloud_data

1. ExportWorker의 checkpoint/resume 메커니즘:

app/workers/export_worker.rb:50-61ruby

proceed = MigrationWorker::Util.retrieve_cache(migration_id, EXPORT_PROCEED_CACHE_KEY) || {
  last_step: 'initialize',
  facility_id: initial_facility_id,
  level_ids: [],
  floorplan_ids: [],
  workarea_group_ids: [],
  record_ids: [],
  capture_ids: [],
  capture_read_record_batch_ids: [],
  pano_read_capture_batch_ids: []
}

proceed[:last_step]으로 마지막 완료 단계를 기록하고 retry 시 해당 단계부터 재개한다. 그러나 read_capture 단계의 경우, 단계 시작 시점에서 last_step이 read_record로 설정되어 있어, batch 중간에 실패하면 전체 read_capture 단계를 처음부터 다시 실행한다.

2. read_capture 단계의 batch 처리:

app/workers/export_worker.rb:117-128ruby

when 'read_capture'
  record_ids = proceed[:record_ids]
  capture_read_record_batch_ids = proceed[:capture_read_record_batch_ids]

  record_ids.each_slice(MIGRATION_RECORD_BATCH_SIZE).each_with_index do |record_batch, batch_idx|
    next if capture_read_record_batch_ids.include?(batch_idx)

    proceed[:capture_ids].concat(export_operation.read_captures(record_batch, batch_idx, target_capture_ids))
    proceed[:capture_ids].sort!
    proceed[:capture_read_record_batch_ids] << batch_idx
  end

MIGRATION_RECORD_BATCH_SIZE는 10 (config/initializers/migration.rb:1). 200+ record를 10개씩 batch 처리하므로 20+ batch가 필요하다. 각 batch 완료 후 capture_read_record_batch_ids에 batch index를 기록하여 sub-batch 수준 resume이 가능하지만, proceed 캐시 저장은 단계 완료 후에만 수행된다:

app/workers/export_worker.rb:146-147ruby

proceed[:last_step] = current_step
MigrationWorker::Util.store_cache(migration_id, EXPORT_PROCEED_CACHE_KEY, proceed)

이 저장은 read_capture 단계의 모든 batch가 완료된 후에만 실행되므로, 중간에 shutdown되면 batch 진행 상태가 유실된다.

3. create_pointcloud_data의 N+1 쿼리:

app/operations/migration_export_operation.rb:660-661ruby

def create_pointcloud_data(model_name, row)
  model = model_name.camelize.constantize.find(row['id'])

create_model_data가 각 row에 대해 create_pointcloud_data를 호출하고, 이 메서드는 Pointcloud.find(row['id'])로 개별 DB 조회를 수행한다. capture 1개당 여러 관련 모델(capture, video, cluster, pointcloud 등)이 있으므로 batch 1개 처리에 수백 건의 DB 쿼리가 발생한다.

4. Sidekiq::Shutdown 처리:

app/workers/export_worker.rb:170-191ruby

rescue StandardError, Sidekiq::Shutdown => e
  Cupix::Logger.error("Database export model failed: migration id(#{migration_id}) last step(#{proceed[:last_step]}) - #{e.class}: #{e.message} #{e.backtrace&.join("\n")}", class: self.class.name, method: __method__)

  result = 'error'
  MigrationOperation.check_export(migration_id: migration_id, result: 'retrying')
  MigrationWorker::Util.store_cache(migration_id, EXPORT_SIDEKIQ_STATUS_CACHE_KEY, 'error')

  if e.is_a?(Sidekiq::Shutdown)
    # Sidekiq::Shutdown을 StandardError로 변환하여 retry 카운트를 증가시킴
    # (Sidekiq::Shutdown 자체는 retry count를 증가시키지 않고 단순 requeue하므로)
    raise StandardError, 'Sidekiq::Shutdown', cause: nil
  end

  raise e
end

이 코드는 Sidekiq::Shutdown을 StandardError로 변환하여 Sidekiq의 retry 메커니즘을 통해 retry count를 증가시킨다. 이는 무한 requeue 방지를 위한 의도적 설계이지만, rescue 블록 내에서 proceed 캐시를 저장하지 않아 batch 진행 상태(capture_read_record_batch_ids)가 유실된다.

Log Evidence#

사용한 Datadog 쿼리:

text

service:cupixworks-api "migration id(1252)" status:error

text

service:cupixworks-api "migration id(1252)" "Database export begin"

text

service:cupixworks-api "migration id(1252)" ("already running" OR "retries exhausted")

에러 패턴 — 5분 간격 반복:

text

07:20:31.738Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
07:25:27.111Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
07:30:28.474Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
07:35:27.864Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
07:40:27.326Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
07:45:28.746Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
07:50:28.021Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
07:55:27.289Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
08:00:28.358Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
08:05:26.263Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
08:10:26.855Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown
08:15:31.350Z — Database export model failed: migration id(1252) last step(read_capture) - Sidekiq::Shutdown

12회 모두 last step(read_capture) — 이전 단계(read_record)까지는 완료되었으나 read_capture 단계를 한 번도 완료하지 못함.

최초 실행 로그:

text

07:18:43.373Z — Database export begin - migration id(1252) retry_limit(5)
07:18:43.373Z — proceed({:last_step=>"initialize", :facility_id=>nil, ...})
07:18:43.374Z — read facility(facility, facility permission)
07:18:43.374Z — read level(level, level permission) for facility id(9168)
07:18:43.374Z — read floorplan(floorplan, floorplan source) for facility id(9168)

최초 실행에서 read_facility ~ read_record 단계까지 정상 완료 후 read_capture 진입.

Retry 폭발 (08:22):

text

08:22:19.561Z — Database export begin - migration id(1252) retry_limit(5)  (×7 동시)
08:22:19.561Z — sidekiq(209afe00da38cc1255ae3657) is already running  (×7 동시)

누적된 retry job들이 동시에 실행되어 concurrency 충돌 발생. migrationable? 체크가 중복 실행을 방지했으나, 불필요한 job 실행이 다수 발생.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	5분 간격 rolling deployment 또는 scheduled restart로 Sidekiq 프로세스가 반복 종료됨	에러가 정확히 ~~5분 간격 (07:20→07:25→07:30...), `[Job] state changed from running to stopping` 로그 다수 존재 (07:15~~07:18)	—	Confirmed
H2	`read_capture` 단계의 처리 시간이 Sidekiq shutdown timeout(25s)보다 길어 종료 신호 후 완료 불가	200+ record를 10개씩 batch 처리, 각 batch에서 N+1 쿼리(`create_pointcloud_data`가 개별 `find` 호출), 12회 연속 동일 단계 실패	—	Confirmed
H3	batch 중간 진행 상태가 유실되어 매 retry마다 `read_capture` 전체를 처음부터 재시작	`proceed` 캐시 저장이 step 완료 후에만 실행 (`export_worker.rb:146-147`), rescue 블록에서 캐시 미저장	`capture_read_record_batch_ids` 배열이 sub-batch resume을 위해 존재하지만, 저장되지 않으므로 무의미	Confirmed
H4	MySQL 쿼리 자체가 느려서 timeout 발생	`Sidekiq::Shutdown`이 `mysql2/client.rb:148:in '_query'`에서 발생	`Sidekiq::Shutdown`은 SIGTERM 신호에 의한 것이지 쿼리 timeout이 아님. `handle_interrupt` 컨텍스트에서 발생	Rejected
H5	Sidekiq retry 카운트 소진으로 최종 실패	`retries exhausted` 로그 없음	MAX_RETRY_COUNT=5이지만, `Sidekiq::Shutdown`→`StandardError` 변환으로 retry가 정상 진행. 12회 에러 중 일부는 requeue (shutdown flow), 일부는 retry (re-raise flow)	Rejected

Fix Recommendation#

즉시 조치 (Critical)#

app/workers/export_worker.rb:170 — rescue 블록 내에서 Sidekiq::Shutdown 발생 시 현재 proceed 상태를 캐시에 저장하도록 수정. 특히 capture_read_record_batch_ids와 pano_read_capture_batch_ids가 보존되어야 sub-batch resume이 작동함.
app/workers/export_worker.rb:121-128 — read_capture batch 루프 내에서 각 batch 완료 후 MigrationWorker::Util.store_cache를 호출하여 중간 진행 상태를 즉시 저장.

단기 개선 (1주 이내)#

app/operations/migration_export_operation.rb:660 — create_pointcloud_data에서 개별 find 대신 batch preload 패턴을 적용하여 N+1 쿼리 제거. read_captures 메서드에서 이미 pointclouds를 batch로 조회하므로, create_model_data 호출 시 preloaded 데이터를 전달하는 방식으로 변경.
read_pano 단계의 동일한 batch 진행 상태 저장 로직도 함께 적용.

장기 개선 (재발 방지)#

Sidekiq migration 프로세스의 5분 간격 재시작 원인 조사 — rolling deployment 설정, ECS task 교체, health check 실패 등 확인 필요.
대규모 facility export 시 작업 시간 예측 및 shutdown timeout 조정 (Sidekiq timeout 옵션 또는 migration 전용 프로세스의 graceful shutdown 시간 연장).
read_capture/read_pano 단계를 별도 sub-job으로 분리하여 각 batch를 독립적으로 실행하고 실패 시 해당 batch만 retry하는 아키텍처 검토.

Monitoring#

read_capture 단계 처리 시간 메트릭 추가
Datadog 쿼리 예시:

text

service:cupixworks-api "Database export model failed" "Sidekiq::Shutdown"

text

service:cupixworks-api "migration id" "last step(read_capture)"

Sidekiq migration 프로세스의 restart 빈도 모니터링 — 5분 미만 간격의 반복 재시작 감지 시 알림

Risk Assessment#

Risk level: medium
예상 복잡도: standard — rescue 블록 내 캐시 저장 추가 및 batch 루프 내 중간 저장은 기존 패턴을 따르는 변경. N+1 쿼리 개선은 create_model_data 인터페이스 변경이 필요하여 약간의 리팩터링 수반.