배포 장애 추적해보기
배포 장애
팀에서 api 신규 배포 중 리소스 사용량이 피크를 찍으면서 서비스 장애가 났다. 문제는 우리쪽 리소스도 아니고, 내가 할당받은 프로젝트도 아니라서 로그 조회 권한이 굉장히 제한적이었다. 그래도 장애나면 니꺼 내꺼가 어딨나, 팀원 계정으로 어떻게 어떻게 로그 받아서 한 번 쭉 살펴봤다. 눈에 띄는 시스템 로그는 스레드풀 고갈 경고가 유일했고, 역추적을 하며 여러 추론을 해봤다. 딴 얘기긴 한데 예전부터 모니터링 고도화를 진행해보고 싶었는데, 고객 내부의 리소스와 망을 사용하는 환경 때문에 제약이 많은 것 같다. 로그를 최대한 상세하게 찍는게 현재로서는 최선인데, 자원 사용량같은거는 어떻게 하나 싶긴한다.
추론 1. 지속된 DB 커넥션 생성으로 인한 스레드 고갈
우리 코드를 살펴보다 보니, 지속적으로 DB 클라이언트를 신규 생성하는 코드가 존재했다. 클래스를 생성자로 계속 만들어서 사용하는 코드인데, 별도의 리소스 정리 코드(.close(), .quit())가 없어서 일단 얘를 후보로 놔봤다. 예상 시나리오는
- 스레드 지속 생성, 회수 불가능 상태 → 기존 리소스 정리 불가로 인해 자원 폭주, 배포 오류
이런식으로 세워봤다. 그런데 시나리오를 세우면서도 의문이었던 점은 문제라고 추정하는 코드가 올해 1월에 작성되었다. 이게 문제였다면 3개월이 지난 지금까지 어떻게 버텼을까? 그리고 왜 하필 배포 시점에 터진걸까? 트래픽이 극도로 적었거나, 이게 문제가 아니거나 둘 중 하나인데 라는 생각을 하며 탐색해봤다.
상황 재현
로컬 환경에서 재현해보기 위해 코드로 리소스 사용량을 좀 체크해봤다.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
PID = os.getpid()
proc = psutil.Process(PID)
tracemalloc.start()
current, peak = tracemalloc.get_traced_memory()
# OS 전체 리소스 측정
rss = proc.memory_info().rss / 1024 ** 2
num_threads = proc.num_threads()
cpu_percent = proc.cpu_percent(interval=0.1)
# GC 상태 측정
unreachable = gc.collect()
objects = len(gc.get_objects())
print(f"\n[Python 힙 메모리]")
print(f" 현재 사용: {current / 1024 ** 2:.2f} MB | 최대 피크: {peak / 1024 ** 2:.2f} MB")
print(f"\n[OS 전체 리소스]")
print(f" RSS: {rss:.2f} MB | 스레드 수: {num_threads} | CPU 사용률: {cpu_percent}%")
print(f"\n[GC 정보]")
print(f" 수집되지 않은 객체 수: {unreachable}")
print(f" 현재 추적 중인 객체 수: {objects}")
print("-" * 50)
## ......
## 이벤트 루프 모니터링
task_refs = weakref.WeakSet()
async def monitor_event_loop(interval=2.0):
loop = asyncio.get_running_loop()
while True:
await asyncio.sleep(interval)
all_tasks = asyncio.all_tasks(loop)
task_refs.update(all_tasks)
running = [t for t in all_tasks if not t.done()]
done = [t for t in all_tasks if t.done()]
print(f"\n[Loop Monitoring @ {time.strftime('%X')}]")
print(f" Total tracked tasks: {len(task_refs)}")
print(f" Currently alive: {len(all_tasks)}")
print(f" ↳ Running: {len(running)}")
print(f" ↳ Done: {len(done)}")
# Optional: latency check
start = loop.time()
await asyncio.sleep(0)
latency = loop.time() - start
print(f" Loop latency: {latency * 1000:.2f} ms")
커스텀 이벤트 루프도 기존 코드에서 사용하길래, 다양한 상황을 고려하기 위해 코드를 붙여넣어봤다. 그리고 DB 커넥션 갯수가 실제로 증가하는지 몽고DB 자체 쿼리도 계속 실행해봤다.
1
db.serverStatus().connections
이 쿼리를 실행하면 현재 커넥션 갯수, 가능한 갯수, 살아있는 커넥션 등등 나오더라. 확인 결과는 다음과 같다.
정확히 측정이 되지 않은 항목도 조금 있는 것 같은데, 일단 주요 관심사는 스레드가 증가하는지의 여부였기 때문에 스레드 위주로 봤다. 그런데 기존 코드에서 스레드는 계속 늘어나지 않는 것으로 보였다. 참조 관계가 상당히 복잡해서 객체의 라이프 사이클에 영향을 주지 않았을까 걱정했으나 GC도 잘 이루어지고 있었다. 그러나 아직 의문인 건 GC가 호출된다고 커넥션이 정리되지는 않을텐데, 몽고DB 커넥션 숫자는 일정하게 계속 유지되었다. 물론 리소스 자동 정리 코드가 pymongo쪽 클라이언트 내부 까보면 작성되어 있기는 한데, 이게 GC가 이루어진다고 실행되는 구조는 아닐 것 같아서 미제 사건으로 남았다.
1
2
def __exit__(self, exc_type: Any, exc_val: Any, exc_tb: Any) -> None:
self.close()
그렇다면 만약 새로운 객체를 만들어도 내부적으로 커넥션 풀이 일정하게 관리되는건가 싶어서, GC 대상이 되지 않게 리스트에 계속 객체를 넣어서 참조를 살려봤다.
그런데 스레드도 계속 늘어나고, os 자체의 메모리 사용량도 지속적으로 증가하는 걸 보면 그건 또 아닌 것 같다. 물론 DB 커넥션 갯수도 계속 증가했다.
추론 2. 물리 메모리 부족
그냥 서버 스펙 부족이었던 것으로 또 다른 시나리오를 세워봤다. 이번 배포 장애 때 cpu, 램 사용량 지표들이 최고치까지 튀었고, 기존 메모리 사용량이 85프로 언저리에서 간당간당 했던 것을 기억해보면 이 시나리오가 더 적합할 것 같았다. 우리가 Azure App service를 사용하는데, 간단히만 소개하면 코드나 컨테이너 기반으로 배포를 간편하게 할 수 있도록 도와주고, 부하가 증가하면 자동 수평 스케일링을 지원한다. aws로 따지면 빈스톡이랑 거의 유사한 서비스가 아닐까 싶다.
애저 앱서비스의 배포 방식을 살펴보니 슬롯 어쩌구 하는데, 동일 vm 내에서 포트가 다른 컨테이너를 띄우고, 성공적으로 뜬다면 라우팅 방향을 바꿔주는 방식 같다. 롤링이랑 비슷하려나? 그러면 메모리 부족으로 계속된 페이지 폴트, 스레싱 → 시스템 먹통 시나리오가 가능하다고 생각했는데, 현재 모니터링 되고 있는 지표가 cpu, 램, 그리고 네트워크 요청 횟수 정도가 전부라 더 이상 확인은 불가능했다.
이번 장애를 겪으면서 정말 많은 생각을 하게 되었다. 주로 팀 문화에 대한 생각들인데, 잘 모르겠다. 이만 글을 줄여야겠다…