asyncio 앱에서 블로킹 코드를 잡아내는 가장 확실한 방법은 이벤트 루프에 짧은 대기를 반복 예약해두고, 실제로 깨어난 시각과 예약한 시각의 차이를 재는 것입니다. 이 차이가 커진다는 건 그 사이에 무언가가 루프를 붙잡고 놓아주지 않았다는 뜻이거든요. 이 글에서는 asyncio 표준 라이브러리의 디버그 모드와, 직접 짜는 워치독 코루틴 두 가지 방식으로 이벤트 루프 지연을 실제로 측정하고, 어떤 코드가 범인인지 찾아내는 방법을 다룹니다. Python 3.10 이상 기준으로 설명하며, 코드와 함께 실행 결과 예시도 붙였습니다.
이벤트 루프 지연, 왜 이렇게 위험한가요?
asyncio는 단일 스레드에서 이벤트 루프가 코루틴을 순서대로 돌려가며 실행하는 구조입니다. await로 제어권을 넘기는 지점이 없으면 다른 태스크는 실행될 기회 자체를 얻지 못합니다.
문제는 time.sleep(), 동기 requests.get(), 큰 파일을 통으로 읽는 open().read() 같은 코드가 코루틴 안에 섞여 들어가도 문법적으로는 아무 오류가 나지 않는다는 점입니다. 겉으로는 정상 작동하는 asyncio 앱인데, 요청 하나가 몰릴 때마다 다른 모든 요청의 응답이 함께 늦어지는 현상이 생깁니다. 헬스체크 타임아웃, 웹소켓 핑퐁 끊김, DB 커넥션 풀 대기 시간 증가가 대표적인 증상입니다.
이런 증상은 로그만 봐서는 원인을 특정하기 어렵습니다. 그래서 루프 지연 자체를 숫자로 측정해서, 지연이 발생한 시점과 그 시점에 실행 중이던 코루틴을 대조하는 접근이 필요합니다.
asyncio 디버그 모드로 블로킹 코드 찾아내기
가장 손쉬운 시작점은 asyncio에 내장된 디버그 모드입니다. asyncio.run(main(), debug=True)로 실행하거나, 환경 변수 PYTHONASYNCIODEBUG=1을 설정하면 됩니다. 디버그 모드가 켜지면 콜백 하나가 loop.slow_callback_duration(기본값 0.1초, 100ms)보다 오래 실행됐을 때 경고 로그를 남깁니다.
import asyncio
import time
async def do_blocking_work():
time.sleep(0.3) # 실수로 동기 sleep이 들어간 상황
async def main():
await asyncio.gather(do_blocking_work(), do_blocking_work())
asyncio.run(main(), debug=True)
실행하면 콘솔에 대략 이런 경고가 찍힙니다.
WARNING:asyncio:Executing <Task pending name='Task-2' coro=<do_blocking_work() running at app.py:4>> took 0.301 seconds
took 0.301 seconds라는 문구와 함께 어떤 코루틴이 실행 중이었는지 이름과 위치까지 나오기 때문에, 블로킹 코드를 찾아내는 첫 단서로는 충분합니다. 자세한 동작 방식은 Python 공식 문서의 slow_callback_duration 항목에 정리돼 있습니다.
커스텀 콜백으로 이벤트 루프 지연을 직접 측정합니다
디버그 모드는 오버헤드가 있어서 운영 서버에 상시 켜두기는 부담스럽습니다. 대신 가벼운 워치독 코루틴 하나를 앱과 함께 띄워두면, 별도 라이브러리 없이 지연 수치를 계속 관찰할 수 있습니다. 원리는 interval초짜리 sleep을 예약해놓고, 실제로 깨어나기까지 걸린 시간에서 예약 시간을 뺀 값을 지연으로 보는 것입니다.
import asyncio
async def watch_loop_lag(interval: float = 0.5, threshold: float = 0.1):
loop = asyncio.get_running_loop()
while True:
start = loop.time()
await asyncio.sleep(interval)
lag = (loop.time() - start) - interval
if lag > threshold:
print(f"[loop-lag] {lag * 1000:.1f}ms 지연 감지")
이 코루틴을 asyncio.create_task(watch_loop_lag())로 앱 시작 시점에 함께 실행해두면, 부하가 몰릴 때 다음과 같은 출력이 쌓입니다.
[loop-lag] 187.4ms 지연 감지
[loop-lag] 342.9ms 지연 감지
interval은 0.5~1초 정도가 무난합니다. 너무 짧게 잡으면 워치독 자체가 스케줄링 부담을 늘리고, 너무 길게 잡으면 짧게 스쳐 지나가는 블로킹을 놓칠 수 있습니다.
loop.slow_callback_duration 임계값은 이렇게 조정해 보세요
기본 임계값 0.1초는 요청 처리 SLA가 50ms 수준인 앱에는 느슨하고, 배치성 작업이 섞인 앱에는 너무 예민할 수 있습니다. 실행 중인 루프 객체를 가져와 직접 값을 바꾸면 됩니다.
import asyncio
async def main():
loop = asyncio.get_running_loop()
loop.slow_callback_duration = 0.05 # 50ms로 낮춰서 더 민감하게 감지
...
asyncio.run(main(), debug=True)
주의할 점은 이 속성이 debug=True로 실행했을 때만 실제로 경고 로그에 반영된다는 것입니다. 디버그 모드 없이 값만 바꾸면 아무 효과가 없습니다. 개발·스테이징 환경에서는 임계값을 낮춰서 더 자주 걸리게 하고, 그렇게 잡아낸 코루틴 이름을 단서로 코드를 역추적하는 방식이 실무에서 효율적입니다.
측정 결과를 실무에 적용할 때 걸리는 지점들
두 방법으로 지연을 감지했다고 해도, 로그에 찍히는 건 코루틴 이름과 소요 시간까지입니다. 그 코루틴 내부의 몇 번째 줄이 블로킹인지는 알려주지 않습니다. 이 부분은 반드시 짚고 넘어가야 할 한계입니다. 지연이 잡히는 시점에 py-spy dump --pid <PID>로 실제 스택을 떠보거나, 의심 구간에 cProfile을 걸어 함수 단위로 좁혀가는 작업이 추가로 필요합니다.
실제로 asyncio 앱에서 자주 걸리는 블로킹 지점은 이런 패턴입니다.
| 블로킹 유형 | 예시 | 대체 방법 |
|---|---|---|
| 동기 HTTP 호출 | requests.get() |
aiohttp, httpx.AsyncClient |
| 동기 DB 드라이버 | psycopg2 |
asyncpg, psycopg[async] |
| CPU 연산 | 이미지 처리, 해시 계산 | loop.run_in_executor()로 스레드/프로세스 풀에 위임 |
| 동기 파일 I/O | 큰 파일 통째로 읽기 | aiofiles, 청크 단위 읽기 |
여기서 한 가지 트레이드오프가 있습니다. run_in_executor()로 블로킹 코드를 스레드 풀에 넘기면 루프 자체는 막히지 않지만, GIL 때문에 CPU 바운드 작업은 여전히 다른 스레드와 자원을 다툽니다. I/O 바운드 블로킹에는 효과가 크지만, 순수 연산이 무거운 작업이라면 ProcessPoolExecutor나 별도 워커 프로세스로 분리하는 편이 낫습니다.
또한 디버그 모드는 태스크 생성 시점의 소스 트레이스백까지 추가로 저장하기 때문에, 상시 켜두면 메모리와 CPU 오버헤드가 눈에 띄게 늘어납니다. 그래서 운영 환경에서는 앞서 소개한 워치독 코루틴만 상시 배치하고, 디버그 모드는 문제가 재현되는 순간에만 잠깐 켜는 방식을 권합니다.
블로킹 코드 찾아내기, 다음 단계는 프로파일러입니다
정리하면, 개발 단계에서는 asyncio.run(debug=True)와 낮춘 slow_callback_duration으로 넓게 훑고, 운영 환경에서는 가벼운 워치독 코루틴으로 지연 수치를 상시 기록해두는 조합이 실용적입니다. 지연이 특정 시간대에 튄다면 그 순간 py-spy 같은 도구로 스택을 떠서 실제 블로킹 라인까지 좁히면 됩니다.
지금 서비스 중인 asyncio 앱이 있다면, watch_loop_lag() 코루틴부터 하나 추가해서 배포해 보시길 권합니다. 코드 세 줄로 지연 여부를 상시 관찰할 수 있고, 이후 디버그 모드나 프로파일러 투입 여부는 그 로그를 보고 판단하면 됩니다.
