Kombu Redis Cluster에서 brpop 응답 미수신으로 인한 CPU 스파이크 해결
Celery worker 에서 트래픽이 몰릴 때 CPU 가 100% 까지 치솟는 현상을 디버깅한 내용을 정리한다.
증상
평소에는 정상이다가, 트래픽 스파이크가 오면 Celery worker 의 CPU 가 급격히 치솟는 현상이 발생했다. Pyroscope 프로파일링 결과, on_poll_start 에서 4~6분 이상 을 소비하고 있었다.
특이한 점은 task 처리 자체가 느려진 게 아니라, task 를 꺼내오는 polling 과정 에서 CPU 를 점유하고 있었다는 것이다.
ss -t 로 Redis 와의 connection 을 보면 다음과 같은 상태가 지속됐다.
State Recv-Q Send-Q Local Address:Port Peer Address:Port Process
ESTAB 1866 0 **** ***:6379 users:(("celery",pid=40424,fd=23))
Recv-Q 가 0 으로 떨어지지 않고 계속 1866 bytes 를 유지하고 있다. 커널이 Redis 응답을 받아 buffer 에 넣어줬는데, 어플리케이션이 read 하지 않고 있다는 뜻이다.
우편함 비유로 이해하기
본격적으로 들어가기 전에, 핵심 개념을 우편함 비유로 정리하면 이해가 쉽다.
| 우편함 | 실제 |
|---|---|
| 우편함 (편지가 들어와 쌓이는 곳) | Socket Recv Buffer (Recv-Q) |
| “우편함에 편지 왔어요” 알림 | epoll ready list |
| 알림 듣고 우편함 열러 가는 것 | epoll_wait() 가 깨어남 |
| 편지 꺼내서 읽기 | recv() 호출 |
| 편지 다 꺼내면 우편함 비어있음 | Recv-Q = 0 |
| 알림 받고도 안 열러 가면? | 알림이 계속 옴 (level-triggered) |
이번 버그는 “알림은 계속 오는데, 우편함은 안 열러 가는” 상태가 지속된 것이다.
Background: Kombu Hub 의 event loop
Celery 는 broker 와의 통신을 Kombu 라이브러리에 위임한다. Kombu 의 핵심은 hub 라는 event loop 이다.
# kombu/asynchronous/hub.py 의 create_loop (단순화)
while True:
# 1) ready callback 실행
# 2) timer 실행
for tick_callback in self.on_tick:
tick_callback() # ← on_poll_start 가 여기서 실행됨
events = poll(poll_timeout) # ⭐ 핵심: epoll_wait 호출
for fd, event in events:
if event & READ:
readers[fd]() # ← on_readable 호출
poll(poll_timeout) 은 내부적으로 epoll_wait syscall 을 호출한다. 이 syscall 은:
| 상태 | 동작 |
|---|---|
| socket buffer 에 데이터 있음 | 즉시 반환 |
| 데이터 없음 | block (커널이 스레드를 sleep 시킴, CPU 안 씀) |
event loop 가 대부분의 시간을 epoll_wait 안에서 자고 있는 게 정상이다. CPU 사용률이 낮은 이유가 여기에 있다. while True 자체는 모든 event loop 의 표준 패턴이고, 진짜 idle 의 정체는 이 syscall 이다.
흐름 추적: BRPOP 한 번의 일생
Kombu 가 Redis 에서 task 를 꺼내오는 흐름은 이렇다.
[on_tick]
on_poll_start()
└─ if channel.qos.can_consume(): # ⭐ Gate 1: consumer 받을 수 있나?
_register_BRPOP(channel)
└─ channel._brpop_start()
└─ conn.send_command('BRPOP', key, timeout) # Redis 에 요청
[poll() 깨어난 후]
on_readable(fd)
└─ if chan.qos.can_consume(): # ⭐ Gate 2: consumer 여전히 받을 수 있나?
chan.handlers['BRPOP'](conn=conn)
└─ _brpop_read()
├─ parse_response() # socket 에서 read (Recv-Q 비움)
└─ deliver_response() # consumer 에 task 전달
두 군데에서 qos.can_consume() 으로 worker 의 여유를 체크한다.
- Gate 1 (
on_poll_start): “BRPOP 을 보낼지 말지” — 우편을 요청할지 말지 - Gate 2 (
on_readable): “도착한 응답을 read 할지 말지” — 우편함을 열러 갈지 말지
버그: _brpop_read 가 가드를 우회해서 BRPOP 을 발행
문제는 Buggy 버전의 _brpop_read 에 있었다.
def _brpop_read(self, **options):
conn = options.pop('conn')
try:
resp = self.parse_response(conn, 'BRPOP', **options)
except:
raise Empty()
# ⚠️ 응답 읽자마자 무조건 다음 BRPOP 발행 (qos 체크 없음!)
conn.redis_connection.connection.send_command('BRPOP', conn.key, conn.timeout)
if resp:
self.deliver_response(resp)
return True
원래 의도는 “다음 on_poll_start 까지 기다리지 말고 미리 다음 task 를 가져오자” 라는 최적화였다. 하지만 이 한 줄이 Gate 1 (on_poll_start 의 qos.can_consume() 체크) 를 우회해버린다.
무한루프 시나리오
조건은 두 가지가 동시에 성립해야 한다.
- Redis 큐에 task 가 계속 쌓여있음 (트래픽 폭주)
- Worker 가 모두 saturated (
qos.can_consume() == False)
이 상태에서:
[T0] BRPOP 발행됨 → 응답 도착 → Recv-Q = ~1KB
on_readable: can_consume()=True → _brpop_read 호출
_brpop_read: parse_response → Recv-Q = 0
send_command BRPOP → ⚠️ 다음 요청 발행
deliver_response → consumer 가 task 받음 → busy 시작
[T1] 큐에 task 있으니 Redis 가 즉시 응답 → Recv-Q = ~1KB
epoll: "fd 23 readable" → poll() 즉시 반환
on_readable: can_consume()=False → return (read 안 함!)
Recv-Q 그대로 남아있음
[T2] epoll: "fd 23 여전히 readable" → poll() 즉시 반환
on_readable: can_consume()=False → return
Recv-Q 그대로
[T3] poll() 즉시 반환 → return → poll() 즉시 반환 → return → ...
while loop 풀스피드 회전 → CPU 100% 🔥
ss -t 출력의 Recv-Q: 1866 은 바로 이 상태다. BRPOP 응답 한두 개가 우편함에 들어왔는데, 가지러 가질 않는 상태가 지속되는 것이다.
왜 평소에는 문제가 없었나?
이 버그가 평소에 드러나지 않은 이유는 두 조건의 AND 가 잘 안 만들어졌기 때문이다.
| 상황 | Redis 큐 | Worker | 결과 |
|---|---|---|---|
| 트래픽 적음 | 비어있음 | 여유 있음 | BRPOP 이 Redis 쪽에서 block → 응답 자체가 안 옴 → 문제 없음 |
| 간헐적 task | 데이터 있음 | 여유 있음 | 응답 와도 즉시 read → Recv-Q 비워짐 → 정상 |
| 트래픽 적음 + Worker busy | 비어있음 | busy | BRPOP 안 보내짐 + 큐도 비어있음 → 문제 없음 |
| 트래픽 폭주 + Worker busy | 데이터 있음 | busy | BRPOP 응답이 Recv-Q 에 쌓이는데 read 못함 → busy loop |
평소에는 BRPOP 이 Redis 쪽에서 block 하거나 (큐 비어서), worker 가 즉시 처리해서 (can_consume()=True) 문제가 표면화되지 않았다.
수정
Kombu PR #25 (“Do not schedule next brpop immediately”) 에서 핵심 변경:
def _brpop_read(self, **options):
conn = options.pop('conn')
try:
try:
resp = self.parse_response(conn, 'BRPOP', **options)
except:
raise Empty()
if resp:
self.deliver_response(resp)
return True
finally:
conn.in_poll = False # ⭐ 다음 BRPOP 은 normal flow 에 위임
send_command('BRPOP', ...) 한 줄을 제거했다. 이제 다음 BRPOP 은 on_poll_start 의 가드 (qos.can_consume()) 를 거친 경로로만 발행된다.
수정 후 흐름:
[T0] worker busy → can_consume()=False
[T1] on_poll_start: can_consume()=False → BRPOP 안 보냄
[T2] Redis 에 요청 안 갔으니 응답도 안 옴 → Recv-Q = 0
[T3] epoll: "readable 한 fd 없음" → poll() block 💤
[T4] worker 가 task 처리 완료 → can_consume()=True
[T5] on_poll_start: BRPOP 발행 → 응답 → 정상 read
poll() 이 다시 block 할 수 있게 되어 CPU 가 idle 상태로 들어간다.
결과
| 항목 | Before | After |
|---|---|---|
on_poll_start 소요 시간 |
4~6분 이상 | 1초 미만 |
Recv-Q |
1866 bytes 지속 | 0 (정상 동작) |
| CPU 메트릭 | 트래픽 몰리면 100% | 정상 |
| 처리 속도 | 영향 없음 | 영향 없음 |
정리
| 구분 | 설명 |
|---|---|
| 증상 | 트래픽 스파이크 + Worker saturated 시 CPU 100% |
| 원인 | _brpop_read 가 qos.can_consume() 체크 없이 다음 BRPOP 자동 발행 |
| 무한루프 발생 위치 | hub.create_loop 의 poll() 이 block 하지 못함 |
| 평소 무증상 이유 | “큐에 데이터 있음” + “worker busy” AND 조건이 잘 안 만들어짐 |
| 수정 | 자동 BRPOP 발행 제거 → on_poll_start 의 가드 경로로만 발행 |
디버깅 인사이트
while True가 도는 게 문제가 아니라, 그 안의 blocking syscall 이 block 못하는 게 문제다. event loop 의 CPU 사용률은 syscall 의 sleep 비율로 결정된다.Recv-Q가 누적되지 않아도 0 이 안 되면 문제다. 1KB 든 1MB 든, level-triggered epoll 입장에서는 똑같이 무한 트리거를 만든다.- 버그가 표면화되려면 여러 조건의 AND 가 필요한 경우가 많다. 이번 케이스는 “큐에 데이터 있음” + “worker busy” 두 조건이 동시에 성립해야 했다.
- Pyroscope 같은 continuous profiler 가 결정적이었다.
on_poll_start가 4~6분 점유하는 게 보이지 않았다면 원인을 찾기 어려웠을 것이다.
댓글남기기