Api::V1::Admin::UsersController#assign_editings (avg 1893ms, max 3644ms)
RCA: Api::V1::Admin::UsersController#assign_editings Latency
Overview#
What Happened#
2026-05-26 03:21~05:19 UTC 사이에 ap-southeast-2 리전의 assign_editings 엔드포인트에서 평균 1,893ms, 최대 3,644ms의 응답 지연이 발생했다. Retool 관리 도구를 통해 반복 호출되는 패턴이며, DB 시간(30-60ms)은 정상이나 애플리케이션 레이어 오버헤드가 전체 지연의 95% 이상을 차지한다.
Quick Facts#
| Field | Value |
|---|---|
| resource_name | Api::V1::Admin::UsersController#assign_editings |
| top_frame | app/repositories/concerns/finalization_repository.rb:70 |
| env | production, ap-southeast-2 |
| avg_duration | 1,893ms |
| max_duration | 3,644ms |
Timeline#
- 2026-05-26 03:21 UTC — 최초 고지연 요청 감지 (ap-southeast-2)
- 2026-05-26 05:19 UTC — 마지막 고지연 요청 기록
- 2026-05-26 05:44 UTC — 동일 시간대 editings 테이블에서 Deadlock 발생 (관련 write contention 확인)
Error Log#
json
{
"resource_name": "Api::V1::Admin::UsersController#assign_editings",
"service": "cupixworks-api",
"occurrences": 5,
"avg_ms": 1893,
"max_ms": 3644,
"sample_trace_id": "3237344936267895142"
}
Impact#
- Service:
cupixworks-api - 발생 횟수: 5 (>500ms 기준, 전체 22건 >1000ms)
- 최초 발생: 2026-05-26T03:21:54.434Z
- 최근 발생: 2026-05-26T05:19:39.245Z
Root Cause Summary#
assign_editings 액션은 동일 record/level에 속한 모든 unassigned editing을 찾아 개별적으로 update!를 호출한다. 각 update!는 set_assigned_at before_update 콜백을 트리거하며, 이 콜백은 관련 Capture/Pointcloud의 update_all, find_each + save_partial_json_to_file_in_worker, bulk_operation! 호출을 수행한다. N개의 editing에 대해 이 작업이 반복되면서 총 응답 시간이 수 초로 증가한다. DB 쿼리 자체는 빠르지만(30-60ms), 콜백 내 외부 서비스 호출과 반복적 I/O가 지연의 주 원인이다.
Technical Analysis#
Code Path#
- Entry point:
app/controllers/concerns/editorable_controller.rb:16 - Repository:
app/repositories/concerns/editorable_repository.rb:17(assign_editings) - ES 검색:
app/repositories/concerns/finalization_repository.rb:25(unassigned_editing_records) - N+1 업데이트:
app/repositories/concerns/finalization_repository.rb:70 - 콜백 트리거:
app/models/editing.rb:32(set_assigned_at) - Priority 재계산:
app/models/editing.rb:33(recalculate_priority_score)
1단계: Controller에서 repository 호출
app/controllers/concerns/editorable_controller.rb:16-29ruby
def assign_editings
editings = repository_instance.assign_editings(params)
render_api Renderable.new({
search_result: editings,
is_collection: true,
serializer: EditingSerializer,
serializer_option: {
fields: {
editing: @fields
}
}
})
end
2단계: Repository에서 unassigned editing 조회 후 할당
app/repositories/concerns/editorable_repository.rb:31-48ruby
unassigned_editings = editing_repo.unassigned_editing_records(states: target_states, editing_type: editing_type, additional_sorts: additional_sorts, exclude_filters: exclude_filters)
if unassigned_editings.count.zero?
Cupix::Logger.info('Unassigned editings are empty', class: self.class.name, function: __method__, editing_type: editing_type)
return SearchResult.new({...})
end
target_editing = unassigned_editings.first
assigned_editings = editing_repo.assign_editings(target_user.id, target_editing, editing_type, target_states)
unassigned_editings.count 호출 시 ES 쿼리가 실행되고, 이후 assign_editings에서 동일 record/level 기준으로 다시 ES 쿼리를 수행한다 (이중 쿼리).
3단계: N+1 개별 update! (핵심 병목)
app/repositories/concerns/finalization_repository.rb:62-75ruby
def assign_editings(user_id, target_editing, editing_type, states)
if editing_type == 'siteinsights'
target_editing.update!(editor_id: user_id)
return [target_editing]
end
assigned_editings = unassigned_editing_records(record_id: target_editing.record_id, level_id: target_editing.level_id, editing_type: editing_type, states: states)
assigned_editings.each do |editing|
editing.update!(editor_id: user_id) # 각 editing마다 개별 트랜잭션 + 콜백
end
assigned_editings
end
각 editing.update! 호출은 독립적인 트랜잭션이며, 매번 set_assigned_at 콜백이 실행된다.
4단계: 무거운 before_update 콜백
app/models/editing.rb:43-86ruby
def set_assigned_at
self.assigned_at = DateTime.now
capture_entity_ids = editing_entities.where(entity_type: 'Capture').map(&:entity_id)
pointcloud_entity_ids = editing_entities.where(entity_type: 'Pointcloud').map(&:entity_id)
::Capture.where(id: capture_entity_ids).update_all(
editor_id: editor_id,
updated_at: DateTime.now
)
::Pointcloud.where(id: pointcloud_entity_ids).update_all(
editor_id: editor_id,
updated_at: DateTime.now
)
if ::Capture.included_modules.include?(DataWareHouse::PartialJson)
capture_entity_ids.each_slice(100) do |batch_ids|
::Capture.where(id: batch_ids).find_each do |capture|
capture.save_partial_json_to_file_in_worker(
operation: '(updated)',
changes: { 'editor_id' => [nil, editor_id],
'updated_at' => [capture.updated_at, DateTime.now] },
timestamp: Time.current.to_i
)
end
end
end
# Pointcloud도 동일 패턴...
::Capture.bulk_operation!(capture_entity_ids, 'update') if capture_entity_ids.present?
::Pointcloud.bulk_operation!(pointcloud_entity_ids, 'update') if pointcloud_entity_ids.present?
end
이 콜백은 editing 하나당: (1) editing_entities 쿼리 2회, (2) update_all 2회, (3) find_each + save_partial_json_to_file_in_worker 반복, (4) bulk_operation! 2회를 수행한다. 동일 record의 editing이 5-10개라면 이 모든 작업이 5-10번 반복된다.
Log Evidence#
Datadog APM 트레이스에서 확인된 주요 패턴:
text
service:cupixworks-api resource_name:"Api::V1::Admin::UsersController#assign_editings" env:production @duration:>500ms
고지연 요청 샘플 (ap-southeast-2):
text
03:19:56 UTC | Duration: 3,744ms | DB: 33ms | Overhead: 3,710ms | host: ip-10-1-83-125.ap-southeast-2
03:41:19 UTC | Duration: 3,643ms | DB: 33ms | Overhead: 3,608ms | host: ip-10-1-83-125.ap-southeast-2
05:58:01 UTC | Duration: 3,380ms | DB: 61ms | Overhead: 3,317ms | host: ip-10-1-145-251.ap-southeast-2
05:19:42 UTC | Duration: 2,132ms | DB: 86ms | Overhead: 2,044ms | host: ip-10-1-145-251.ap-southeast-2
DB 시간은 30-86ms로 일관되게 낮지만, 전체 duration은 2,000-3,700ms로 비-DB 오버헤드가 95% 이상이다.
동일 시간대 Deadlock 발생 확인:
text
service:cupixworks-api status:error "Deadlock"
json
{
"timestamp": "2026-05-26T05:44:02Z",
"error": "ActiveRecord::Deadlocked",
"message": "Mysql2::Error: Deadlock found when trying to get lock; try restarting transaction",
"resource": "PATCH /api/v1/editings/1115585",
"duration_ms": 1684
}
리전별 평균 비교:
text
ap-southeast-2: avg 415ms, max 3,380ms (40건)
us-west-2: avg 135ms, max 1,181ms (49건)
ap-southeast-2 리전이 us-west-2 대비 3배 높은 평균 지연을 보인다. 이는 리전 간 네트워크 지연(ES 클러스터, 외부 서비스 호출)이 콜백 내 다수의 외부 호출에 의해 증폭되는 것으로 해석된다.
Hypotheses Considered#
| # | Hypothesis | Evidence for | Evidence against | Verdict |
|---|---|---|---|---|
| H1 | N+1 update! + set_assigned_at 콜백 반복 호출로 인한 누적 지연 |
DB time 30-60ms인데 총 duration 3,700ms → 비-DB 오버헤드 95%. 코드에서 assigned_editings.each { update! } 패턴 확인 (finalization_repository.rb:70). 콜백 내 find_each + save_partial_json_to_file_in_worker + bulk_operation! 반복 |
— | Confirmed |
| H2 | DB 쿼리 자체의 성능 문제 (slow query) | — | DB time이 30-86ms로 일관되게 낮음. Deadlock은 별도 리소스(editings update)에서 발생 | Rejected |
| H3 | ap-southeast-2 리전 인프라 이슈 (인스턴스 리소스 부족) | ap-southeast-2가 us-west-2 대비 3배 높은 latency | 두 버전(3e770a15, dd7bd097) 모두에서 발생하고, us-west-2에서도 >1000ms 건 존재. 인프라보다는 외부 호출의 네트워크 홉 차이로 설명됨 | Rejected |
| H4 | Retool 자동화에 의한 동시 요청으로 인한 lock contention | Deadlock 발생 확인 (05:44 UTC). Burst 패턴: user 8526이 2분 내 7건 호출 | Deadlock은 latency의 결과이지 원인이 아님. 고지연은 단일 요청 내에서도 발생 | Rejected |
Fix Recommendation#
즉시 조치 (Critical)#
- 파일:
app/repositories/concerns/finalization_repository.rb:70-72 - 방향:
assigned_editings.each { update! }패턴을 제거하고,update_all(editor_id: user_id)로 일괄 업데이트한 뒤 콜백 로직을 한 번만 수행하도록 변경. 또는set_assigned_at콜백을 비동기 worker로 이동.
단기 개선 (1주 이내)#
set_assigned_at콜백 비동기화:before_update에서 수행하는 Capture/Pointcloud 업데이트와save_partial_json_to_file_in_worker호출을 별도 Sidekiq worker로 위임. 이렇게 하면 HTTP 응답 시간에서 제외됨.- 이중 ES 쿼리 제거:
editorable_repository.rb:31에서unassigned_editing_records를 호출한 뒤finalization_repository.rb:68에서 동일 쿼리를 다시 수행하는 패턴을 제거. 첫 번째 결과를 재활용하거나 record_id/level_id를 직접 전달.
장기 개선 (재발 방지)#
- Batch assignment API 설계: 동일 record/level의 editing 할당을 원자적 배치 작업으로 재설계하여, 콜백이 editing 단위가 아닌 배치 단위로 한 번만 실행되도록 함.
- TSLA-7235 완료: 코드 주석에
TODO: remove this on TSLA-7235로 표시된 Capture/Pointcloudeditor_id동기화 로직의 근본적 제거 또는 이벤트 기반 비동기 처리로 전환.
Monitoring#
- APM 모니터:
assign_editingsP95 latency가 1,000ms 초과 시 알림 - 쿼리 예시:
text
service:cupixworks-api resource_name:"Api::V1::Admin::UsersController#assign_editings" @duration:>1000ms
set_assigned_at콜백 실행 시간을 custom metric으로 추적 (editing.assign_callback_duration)- Deadlock 모니터:
service:cupixworks-api status:error "Deadlocked"발생 시 알림
Risk Assessment#
- Risk level: medium
- 예상 복잡도: standard (콜백 비동기화는 기존 worker 패턴 활용 가능, 배치 update는 콜백 우회 주의 필요)