개요최초 문제 발생원인 파악을 위한 로그 확인메모리 과다 사용?스왑 메모리 할당문제 2번째 재발생메모리 누수 방지를 위한 worker 주기적 재시작문제 3번째 재발생visibility_timeout 설정문제 4번째 재발생 → 해결결론Reference
개요
Celery를 이용하다 celery worker OOM(Out of Memory) Kill 문제가 발생한 것을 해결한 경험을 정리합니다.
최초 문제 발생
Celery를 이용하던 중 어느 순간 도커를 이용하여 가동해 둔 Celery worker가 정지해 있는 것을 발견했습니다. 이를 재가동시킨 후 리소스 사용량이 많아 중지된 것인지 확인해 보았습니다.
재시작한 컨테이너의 평시 CPU, 메모리 사용량과 디스크 사용량을 확인해 보았습니다.
>> docker stats CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS 45dc370549da celery_worker-1 0.09% 172.2MiB / 3.691GiB 4.56% 413kB / 441kB 13.4MB / 27.6kB 3 1be1ff2194a6 celery_beat-1 0.32% 104.1MiB / 3.691GiB 2.75% 168kB / 166kB 7.46MB / 15.9kB 2 ad48005fed32 web-1 0.10% 367.6MiB / 3.691GiB 9.73% 540kB / 1.32MB 6.54MB / 56.8kB 13 94fcd19bd144 redis-1 0.72% 3.086MiB / 3.691GiB 0.08% 442kB / 413kB 4.32MB / 0B 6 >> df -h Filesystem Size Used Avail Use% Mounted on /dev/xvda1 50G 17G 34G 34% /
가용 용량에 비해서 여유롭게 작동하고 있어 평시에 문제가 발생하는 것은 아니고 특이한 사건으로 인해 종료된 것으로 보였습니다. 문제 원인을 정확히 파악하기 위해 로그를 확인해 보았습니다.
원인 파악을 위한 로그 확인
process kill과 out of memory로 로그들을 탐색해 본 결과 문제를 기록한 로그를 발견할 수 있었습니다.
>> dmesg | grep -i "killed process" [9990752.723909] Killed process 19580 (celery), UID 0, total-vm:1252908kB, anon-rss:118108kB, file-rss:0kB, shmem-rss:0kB >> journalctl -k | grep -i "out of memory" Jan 24 05:43:34 kernel: Out of memory: Kill process 19472 (celery) score 634 or sacrifice child
원인은 OOM Kill로 파악되었고, 더 자세한 로그를 확인해 보았습니다.
>> cat /var/log/messages ~~~ Jan 24 05:43:34 ~ kernel: 83495 total pagecache pages Jan 24 05:43:34 ~ kernel: 0 pages in swap cache Jan 24 05:43:34 ~ kernel: 1046429 pages RAM Jan 24 05:43:34 ~e kernel: 78810 pages reserved Jan 24 05:43:34 ~ kernel: [ pid ] uid tgid total_vm rss nr_ptes swapents oom_score_adj name Jan 24 05:43:34 kernel: [26161] 0 26161 394550 4502 68 0 -999 containerd Jan 24 05:43:34 kernel: [26171] 0 26171 496387 13525 150 0 -500 dockerd Jan 24 05:43:34 kernel: [22889] 0 22889 189205 6441 87 0 0 python Jan 24 05:43:34 kernel: [28619] 996 28619 10527 405 23 0 0 nginx Jan 24 05:43:34 kernel: [28620] 996 28620 10527 405 23 0 0 nginx Jan 24 05:43:34 kernel: [19197] 0 19197 335474 198 23 0 -500 docker-proxy Jan 24 05:43:34 kernel: [19209] 0 19209 335538 196 23 0 -500 docker-proxy Jan 24 05:43:34 kernel: [19221] 0 19221 309112 676 18 0 -998 containerd-shim Jan 24 05:43:34 kernel: [19248] 0 19248 309112 703 19 0 -998 containerd-shim Jan 24 05:43:34 kernel: [19254] 999 19254 24926 13127 47 0 0 redis-server Jan 24 05:43:34 kernel: [19280] 999 19280 54608 3321 33 0 0 postgres Jan 24 05:43:34 kernel: [19373] 0 19373 356116 518 31 0 -500 docker-proxy Jan 24 05:43:34 kernel: [19395] 0 19395 309048 670 18 0 -998 containerd-shim Jan 24 05:43:34 kernel: [19401] 0 19401 309112 686 18 0 -998 containerd-shim Jan 24 05:43:34 kernel: [19411] 999 19411 54648 13938 77 0 0 postgres Jan 24 05:43:34 kernel: [19412] 999 19412 54608 1939 31 0 0 postgres Jan 24 05:43:34 kernel: [19413] 999 19413 54608 1617 28 0 0 postgres Jan 24 05:43:34 kernel: [19414] 999 19414 54746 708 31 0 0 postgres Jan 24 05:43:34 kernel: [19415] 999 19415 18243 600 23 0 0 postgres Jan 24 05:43:34 kernel: [19416] 999 19416 54715 664 29 0 0 postgres Jan 24 05:43:34 kernel: [19429] 0 19429 309112 701 18 0 -998 containerd-shim Jan 24 05:43:34 kernel: [19471] 0 19471 74923 26265 110 0 0 celery Jan 24 05:43:34 kernel: [19472] 0 19472 665470 612985 1266 0 0 celery Jan 24 05:43:34 kernel: [19485] 0 19485 7658 3771 18 0 0 gunicorn Jan 24 05:43:34 kernel: [19579] 0 19579 198485 29335 116 0 0 celery Jan 24 05:43:34 kernel: [19580] 0 19580 313227 29527 125 0 0 celery Jan 24 05:43:34 kernel: [27111] 999 27111 55039 1363 45 0 0 postgres Jan 24 05:43:34 kernel: [31758] 0 31758 121146 22579 105 0 0 gunicorn Jan 24 05:43:34 kernel: [32072] 0 32072 102709 22446 103 0 0 gunicorn Jan 24 05:43:34 kernel: [32211] 0 32211 63208 15032 64 0 0 gunicorn Jan 24 05:43:34 kernel: [32239] 0 32239 42355 11292 56 0 0 gunicorn Jan 24 05:43:34 kernel: [32275] 999 32275 55068 4046 61 0 0 postgres Jan 24 05:43:34 kernel: [32276] 999 32276 55068 4045 61 0 0 postgres Jan 24 05:43:34 kernel: [32296] 999 32296 54842 779 31 0 0 postgres Jan 24 05:43:34 kernel: [32298] 999 32298 54744 698 31 0 0 postgres ~~~ Jan 24 05:43:34 kernel: Out of memory: Kill process 19472 (celery) score 634 or sacrifice child Jan 24 05:43:34 kernel: Killed process 19580 (celery), UID 0, total-vm:1252908kB, anon-rss:118108kB, file-rss:0kB, shmem-rss:0kB Jan 24 05:44:12 dockerd: time="2025-01-24T05:44:12.416256184+09:00" level=info msg="ignoring event" container=5d6ff103eb37d69545589bf936d3b5a9025db680339d1d1eaeacfa22834d9d2e module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete" Jan 24 05:44:12 containerd: time="2025-01-24T05:44:12.431421595+09:00" level=info msg="shim disconnected" id=5d6ff103eb37d69545589bf936d3b5a9025db680339d1d1eaeacfa22834d9d2e Jan 24 05:44:12 containerd: time="2025-01-24T05:44:12.458245411+09:00" level=warning msg="cleaning up after shim disconnected" id=5d6ff103eb37d69545589bf936d3b5a9025db680339d1d1eaeacfa22834d9d2e namespace=moby Jan 24 05:44:12 containerd: time="2025-01-24T05:44:12.458711497+09:00" level=info msg="cleaning up dead shim" Jan 24 05:44:12 containerd: time="2025-01-24T05:44:12.483107139+09:00" level=warning msg="cleanup warnings time=\"2025-01-24T05:44:12+09:00\" level=info msg=\"starting signal loop\" namespace=moby pid=32402 runtime=io.containerd.runc.v2\n"
OOM kill 당시의 로그를 확인했을 때 pid 19472번의 celery 프로세스가 rss(resident set size) 612985를 차지하고 있는 것을 볼 수 있었습니다.
이는 612985 * 4kb = 2400mb 정도로 다른 프로세스와 비교해서 매우 높은 사용량이었습니다. 스왑 메모리 설정이 없음을 감안할 때 OOM Killer가 작동하기 충분한 사용량이었습니다.
메모리 과다 사용?
프로세스가 종료된 원인은 메모리 초과로 인한 OOM Killer 인 것을 확인했습니다.
그렇다면 메모리가 초과된 원인은 무엇일지 생각해 보았을 때, 메모리 누수 또는 메모리 과다 사용이 원인이 될 수 있을 거라는 생각이 들었습니다.
- 메모리 누수 가정
- 가비지 컬렉션이 돌아가는 파이썬에서 메모리 누수가 발생하기는 어렵다고 생각했습니다. pandas 등의 C를 부분적으로 사용하는 라이브러리가 있었으나, 이런 유명 라이브러리에서 메모리 누수가 발생했을 확률은 낮다고 생각했습니다.
- 순간적인 메모리 과다 사용
- 그렇기에 celery에서 태스크가 동시에 실행되며 발생한 문제일 가능성이 높다고 보았습니다.
- 실제로 문제가 발생한 05:43분의 로그를 보았을 때 리소스를 많이 사용하는 Celery task가 동시에 돌아갔던 기록이 있습니다.
- 특히, pandas 라이브러리를 이용하여 꽤나 큰 규모의 데이터를 다루었기에 순간적으로 메모리 사용이 급증할 수 있었습니다.
그렇기에 최종적으로 메모리 누수보다는 메모리 과다 사용을 원인으로 가정하고 조치를 취했습니다.
스왑 메모리 할당
그렇기에 우선 스왑 메모리를 할당해 준 후 문제가 다시 발생하는지 경과를 지켜보기로 했습니다.
sudo fallocate -l 4G /swapfile sudo chmod 600 /swapfile sudo mkswap /swapfile sudo dd if=/dev/zero of=/swapfile bs=1M count=4096 # 재시작 이후에도 사용되게 하려면 sudo vi /etc/fstab # 후 아래 추가 /swapfile none swap sw 0 0 # 적용 확인 >> sudo swapon --show NAME TYPE SIZE USED PRIO /swapfile file 4G 0B -2
또한 gunicorn을 4 workers 4 threads 구성으로 가동하고 있었는데, 이렇게 많은 리소스는 필요가 없기에 2/2로 축소시켜 주었습니다. 이걸로도 작지만 조금의 램을 더 확보할 수 있었습니다.
문제 2번째 재발생
그러나 4일 후 문제가 재발생 했습니다.
로그를 확인해 보니 똑같은 로그가 한 줄 추가된 것을 볼 수 있었습니다.
>> dmesg | grep -i "killed process" [9990752.723909] Killed process 19580 (celery), UID 0, total-vm:1252908kB, anon-rss:118108kB, file-rss:0kB, shmem-rss:0kB [10380513.241921] Killed process 4379 (celery), UID 0, total-vm:1186760kB, anon-rss:104132kB, file-rss:0kB, shmem-rss:0kB
OOM Killer 로그를 확인했을 때 추가적인 스왑 메모리를 할당해 주었음에도, 이를 모두 사용하면서 오류가 난 것을 볼 수 있었습니다.
>> zgrep -i 'celery' /var/log/messages-20250202 ########################[ pid ] uid tgid total_vm rss nr_ptes swapents oom_score_adj name Jan 28 17:59:35 kernel: [ 4235] 0 4235 1683340 763307 3259 854902 0 celery Jan 28 17:59:35 kernel: [ 4258] 0 4258 75036 2852 110 24029 0 celery Jan 28 17:59:35 kernel: [ 4379] 0 4379 296690 26033 122 3281 0 celery Jan 28 17:59:35 kernel: [ 4384] 0 4384 198260 26026 117 2956 0 celery Jan 28 17:59:35 kernel: Out of memory: Kill process 4235 (celery) score 804 or sacrifice child Jan 28 17:59:35 kernel: Killed process 4379 (celery), UID 0, total-vm:1186760kB, anon-rss:104132kB, file-rss:0kB, shmem-rss:0kB
순간적으로 메모리 사용량이 증가한다 해도 기존보다 2배나 큰 메모리를 모두 사용하지는 않을 것이라 보았기에, 메모리 사용량이 갑자기 늘어난 것이 원인이 아닌 메모리가 누수되고 있거나 계속 메모리를 차지하는 원인이 있다고 보았습니다.
메모리 누수 방지를 위한 worker 주기적 재시작
우선 Celery worker를 주기적으로 재실행해 누수가 발생하더라도 초기화할 수 있게 했습니다.
워커는 자기 자신을 복제한 자식들을 만들어 자식으로 task를 넘겨 처리하는 방식으로 작동합니다.
CELERY_WORKER_MAX_TASKS_PER_CHILD = 8 # Worker가 처리할 최대 작업 수 CELERY_WORKER_MAX_MEMORY_PER_CHILD = 200000 # Worker가 사용할 최대 메모리 크기 (KB)
--max-tasks-per-child 옵션을 지정해 주면 n번의 task를 처리 후 worker(자식 worker)가 삭제되고 새로 만들어지게 됩니다. 또한 --max-memory-per-child 옵션으로 최대 사용 가능한 메모리도 설정해 주었습니다.문제 3번째 재발생
그러나 기대가 무색하게도 문제는 재발생 했습니다.
실제로 task를 실행하는 자식 프로세스를 주기적으로 재실행해줬는데도 문제가 다시 발생했기에 자식 worker가 문제가 아닌 메인 worker에서 문제가 발생한다는 것을 알았습니다.
다행히도 이번에는 메모리가 초과되어 워커가 종료된 후 문제를 발견한 것이 아닌, 메모리 사용량이 증가하는 도중 포착하여 문제를 좀 더 자세히 살필 수 있었습니다.
# 보통 200MB 정도를 사용하던 컨테이너가 600MB를 사용하는 모습 CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS 62276b42f0d4 celery_worker-1 0.21% 600.1MiB / 3.691GiB 15.88% 616MB / 471MB 1.95MB / 28.7kB 3
우선 가동되는 태스크를 확인해 보기로 했습니다.
>> docker compose exec celery_worker celery -A proj inspect active -> celery@62276b42f0d4: OK - empty - >>docker compose exec celery_worker celery -A proj inspect reserved -> celery@62276b42f0d4: OK - empty - docker compose exec celery_worker celery -A proj inspect scheduled -> celery@62276b42f0d4: OK * {'eta': '2025-02-17T08:42:41.146385+09:00', 'priority': 6, 'request': {'id': '877f8916-fce0-42dd-81f6-94ca9cbf1f08', 'name': 'tasks.task', 'args': ['~'], 'kwargs': {}, 'type': 'tasks.task', 'hostname': 'celery@62276b42f0d4', 'time_start': None, 'acknowledged': False, 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': True}, 'worker_pid': None}} ~~~ 35000건 정도의 태스크 ~~~
현재 작동 중이거나 예약 중인 태스크는 없었으나, 가동 예정인 scheduled 태스크가 35000건 이상 쌓여있는 것을 확인할 수 있었습니다.
해당 태스크들은 모두 같은 id를 가지고 있어 동일한 태스크를 retry() 한 것임을 알 수 있었습니다.
또한 고유한 eta를 가지는 태스크 자체도 5000건 정도로 많았으나,
redelivered: True로 되어 있는 태스크가 30000건 정도로 태스크의 양을 늘리고 있었습니다.{'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': False} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True} {'eta': '2025-02-17T08:44:53.258089+09:00', 'redelivered': True}
이 많은 태스크가 어디서 온 지 파악하고자 beat를 확인해 보았습니다.
>> docker compose logs -f celery_beat celery_beat-1 | celery beat v5.4.0 (opalescent) is starting. celery_beat-1 | __ - ... __ - _ celery_beat-1 | LocalTime -> 2025-02-14 12:06:36 celery_beat-1 | Configuration -> celery_beat-1 | . broker -> redis://redis:6379// celery_beat-1 | . loader -> celery.loaders.app.AppLoader celery_beat-1 | . scheduler -> django_celery_beat.schedulers.DatabaseScheduler celery_beat-1 | celery_beat-1 | . logfile -> [stderr]@%INFO celery_beat-1 | . maxinterval -> 5.00 seconds (5s) celery_beat-1 | [2025-02-14 12:06:36,169: INFO/MainProcess] beat: Starting... celery_beat-1 | [2025-02-14 12:16:00,011: INFO/MainProcess] Scheduler: Sending due task ~ (tasks.task)
beat 문제는 아닐 것이라 생각했었고, 예상대로 로그를 보았을 때는 예상대로 beat에서 나온 태스크들은 아닌 것으로 확인할 수 있었습니다.
다음은 worker의 로그를 확인했습니다
redis 브로커 또한 확인해 보았습니다.
>> docker compose exec redis redis-cli 127.0.0.1:6379> KEYS * 1) "unacked" 2) "unacked_index" 3) "_kombu.binding.celery.pidbox" 4) "_kombu.binding.celery" 5) "_kombu.binding.celeryev" 127.0.0.1:6379> TYPE unacked hash 127.0.0.1:6379> HGETALL unacked ...
확인결과 4,000건 이상의 unacked 요청이 발견되었습니다.
이런 로그를 바탕으로 찾아본 결과 의심되는 것은 visibility_timeout과 관련된 문제였습니다.
visibility_timeout 설정
디버깅을 위해 찾아보던 중 redis를 브로커로 사용했을 때 celery의 문제점을 알 수 있었습니다.
Celery에서는 task를 워커로 보냅니다. 다만 워커가 작동 중 중단되어 버릴 수도 있는 등 task의 전달이 task의 성공적인 완료를 보장해주지는 않습니다.
AMQP 프로토콜을 사용하는 RabbitMQ 등을 브로커로 사용한다면 AMQP 프로토콜에서 task가 완료되는 것을 보장해 주지만, redis 등을 브로커로 사용하면 AMQP 프로토콜을 구현한 구현체가 아니기에 이를 보장해주지 못합니다.
그렇기에 redis 등의 브로커에서는 visibility timeout이라는 로직이 존재합니다. 이는 task를 워커로 보낸 후 일정 시간(visibility_timeout)이 지나도 ack이 다시 반환되지 않으면 task가 누락되었다고 보고 다시 task를 워커로 보내는 로직입니다.
문제는 task 재시도 시간이 visibility_timeout 시간을 넘어갈 때 발생합니다. visibility_timeout의 기본값은 3600초(1시간) 입니다. 서비스에서는 task가 실패 시에 재시도를 하게 되는데, 매번 재시도 시간이 2배씩 늘어나는 exponential backoff 방식을 사용하고 있었습니다.
문제는 재시도 시간이 1시간을 넘어가게 되면 재시도를 대기 중인 task는 ack을 보내지 않게 되는데, 1시간을 넘게 대기하고 있으니 브로커 입장에서는 task가 유실된 것으로 보고 다시 워커로 task를 보내게 되는 것입니다.
해당 문제를 해결하기 위해서는 근본적으로 task의 구조를 바꾸는 것이 좋지만, 현재 구조를 그대로 가져가는 게 장점이 더 크다고 느꼈기에 visibility_timeout 설정을 변경하는 것으로 방향을 잡았습니다.
CELERY_RESULT_BACKEND_TRANSPORT_OPTIONS = {"visibility_timeout": 1209600}
문제 4번째 재발생 → 해결
설정을 수정해 주었음에도 다시 문제가 발생했습니다. 문제는 visibility_timeout 설정 적용을 위해서는
result_backend_transport_options 뿐만 아니라 broker_transport_options 옵션 또한 설정해주어야 하기 때문이었습니다.
CELERY_RESULT_BACKEND_TRANSPORT_OPTIONS = {"visibility_timeout": 1209600} CELERY_BROKER_TRANSPORT_OPTIONS = {"visibility_timeout": 1209600}
결론
Celery는 RabbitMQ를 브로커로 사용함을 전제로 만들어졌고, Redis 등을 브로커로 사용하는 것은 이에 대한 대안으로 사용되는 것입니다. 그렇기에 완전한 기능을 지원하지 않는 경우가 있습니다.
그럼 RabbitMQ를 브로커로 사용하면 모든 문제가 해결될까요? 여러 답변을 찾아보았을 때 근본적인 해결책은 RabbitMQ를 사용하는 것이 아닌, 지나치게 retry 간격이 긴 상황을 지양하는 것입니다.
이런 구조가 필요하다면 celery cronjob을 이용해서 다시 시도하는 방향으로 구현하는 것이 좋습니다.
