gRPC 데드라인 없이 하위 서비스 하나가 느려지면 전체가 멈출까?

Q: gRPC 데드라인 없이 하위 서비스 하나가 느려지면 전체가 멈출까?

느린 하위 호출이 중간 서비스의 작업 스레드 4개를 붙잡아 그 호출과 무관한 메서드도 0.001~0.016초에서 7.9~10.1초로 늘었고, 1초 데드라인을 전파하자 최대 0.719~0.771초였다.

이번 시간에는 Python gRPC로 A→B→C 호출 체인을 만들어 보면서, 데드라인을 걸지 않을 때와 남은 시간을 하위 호출에 넘길 때가 어떻게 다른지 Docker 컨테이너에서 측정하며 배워가는 시간입니다.

예를 들어서 주문 서비스 A가 가격 서비스 B를 부르고, B는 시세 서비스 C를 부른다고 해볼게요. 어느 날 C가 5초씩 늦게 답하기 시작했어요.

A의 주문 응답이 느려지는 건 예상할 수 있죠. 그런데 C를 전혀 부르지 않는 B의 Ping 메서드까지 8~10초가 걸립니다. 평소에는 0.01초 안에 끝나던 호출인데 말이에요.

gRPC의 데드라인은 호출이 언제까지 끝나야 하는지 호출하는 쪽이 정해 주는 마감 시각이에요. 마감이 지나면 호출은 DEADLINE_EXCEEDED로 실패합니다.

실습 준비

이 글의 명령은 모두 실습 코드의 grpc-deadline/ 디렉터리에서 실행합니다.

Dockerfile: grpcio를 설치한 이미지
chain.proto: 서비스 A, B, C 정의
server.py: ROLE에 따라 A, B, C로 뜨는 서버
client.py: 주문이나 Ping을 여러 번 보내고 결과를 한 줄씩 찍는 클라이언트
compose.yaml: 서버 세 개와 클라이언트 정의

그 밖의 파일은 데이터·보조 스크립트입니다.

이미지는 python:3.12-slim에 grpcio==1.84.0과 grpcio-tools==1.84.0을 설치해서 써요. Dockerfile은 이렇습니다.

FROM python:3.12-slim
RUN pip install --no-cache-dir grpcio==1.84.0 grpcio-tools==1.84.0

서비스 정의는 chain.proto에 있어요. A에는 Order, C에는 Quote가 있고, B에는 C를 부르는 Price와, C를 부르지 않고 바로 답하는 Ping을 둡니다.

server.py 하나를 환경 변수 ROLE에 따라 A, B, C로 띄워요. 실습에서 바꿀 값은 이렇습니다.

MODE: A와 B가 하위 서비스를 부를 때 데드라인을 거는 방식이에요. none은 걸지 않고, fixed는 항상 3초를 걸고(이 글에서는 쓰지 않아요), propagate는 들어온 요청의 남은 시간에서 50ms를 뺀 값을 겁니다. propagate는 들어온 요청이 끝나면 하위 호출을 취소하는 콜백도 등록해요.
C_DELAY: C가 응답하기까지 걸리는 시간(초)이에요. 0.1초씩 나눠 잠듭니다.

작업 스레드는 A와 C가 16개, B는 4개예요. B의 스레드를 일부러 적게 두었습니다.

클라이언트 client.py는 A의 Order나 B의 Ping을 여러 번 부르고, 요청마다 끝난 시간, 요청 ID, 상태 코드, 걸린 시간을 한 줄로 찍어요. --deadline을 주면 그만큼 타임아웃을 걸어요.

compose.yaml은 서버 a, b, c와 client 서비스를 정의해요. 모든 컨테이너의 메모리를 128MB로 제한했고, 클라이언트는 profiles로 묶어 docker compose up에서는 뜨지 않게 했습니다.

이제 compose 프로젝트 이름을 정하고 셸 함수 두 개를 만들어 놓을게요. client는 클라이언트 컨테이너를 한 번 실행하고, logs는 지정한 시간 이후 A, B, C의 로그를 시간순으로 합쳐 보여 줘요.

아래 블록은 파일로 만들지 말고 실습 디렉터리에서 연 터미널에 그대로 붙여 넣어 주세요. 이후 명령은 모두 이 터미널에서 실행하고, 터미널을 새로 열면 다시 붙여 넣으시면 됩니다.

export COMPOSE_PROJECT_NAME=grpcdl

client() { docker compose run --rm client "$@"; }

logs() { docker compose logs --no-log-prefix --since "$1" a b c | grep -v listening | sort; }

이미지를 만들고, proto에서 Python 코드를 생성한 뒤 버전을 확인해 볼게요.

docker compose build a
docker compose run --rm --entrypoint python client -m grpc_tools.protoc -I. --python_out=. --grpc_python_out=. chain.proto
ls chain_pb2*
docker compose run --rm --entrypoint python client -c "import grpc, sys; print(grpc.__version__, sys.version.split()[0])"

chain_pb2_grpc.py
chain_pb2.py
1.84.0 3.12.14

실습 1: 기다리는 호출이 스레드를 붙잡습니다

C가 5초 걸리게 두고, 클라이언트도 A도 B도 데드라인을 걸지 않은 채(MODE=none) A에 주문 8건을 동시에 보내면서, 같은 순간부터 B의 Ping을 0.2초 간격으로 10번 불러 볼게요. 먼저 부하 없이 Ping만 10번 불러 기준 시간을 잽니다. 환경 변수를 바꿀 때마다 --force-recreate로 컨테이너를 다시 만듭니다.

MODE=none C_DELAY=5 docker compose up -d --force-recreate
sleep 3
client ping --n 10 --interval 0.2 --tag p
client order --n 8 --tag o1- > orders.txt &
client ping --n 10 --interval 0.2 --tag p1-
wait
cat orders.txt

06:42:15.994 p1 OK 0.010s
06:42:16.188 p2 OK 0.003s
06:42:16.390 p3 OK 0.004s
06:42:16.590 p4 OK 0.002s
06:42:16.797 p5 OK 0.009s
06:42:17.006 p6 OK 0.016s
06:42:17.194 p7 OK 0.004s
06:42:17.393 p8 OK 0.002s
06:42:17.594 p9 OK 0.001s
06:42:17.794 p10 OK 0.001s
06:42:36.425 p1-1 OK 10.093s
06:42:36.427 p1-2 OK 9.894s
06:42:36.426 p1-3 OK 9.691s
06:42:36.429 p1-4 OK 9.493s
06:42:36.431 p1-5 OK 9.295s
06:42:36.427 p1-6 OK 9.089s
06:42:36.425 p1-7 OK 8.619s
06:42:36.426 p1-8 OK 8.384s
06:42:36.429 p1-9 OK 8.185s
06:42:36.426 p1-10 OK 7.904s
06:42:36.523 o1-1 OK 10.283s
06:42:31.346 o1-2 OK 5.104s
06:42:36.522 o1-3 OK 10.279s
06:42:31.346 o1-4 OK 5.100s
06:42:36.746 o1-5 OK 10.499s
06:42:31.346 o1-6 OK 5.098s
06:42:31.346 o1-7 OK 5.098s
06:42:36.407 o1-8 OK 10.157s

부하가 없을 때 Ping은 0.001~0.016초였어요. 주문 8건이 들어간 뒤에는 7.904~10.093초가 걸렸고, 10개 모두 06:42:36.4 무렵에 한꺼번에 끝났습니다.

주문은 4건이 약 5.1초, 나머지 4건이 약 10.2초에 끝났어요. 같은 실험을 세 번 반복했을 때 부하 중 Ping은 7.9~10.1초였습니다. 두 번째 반복에서만 첫 Ping 하나가 주문보다 먼저 B에 도착해 0.004초에 끝났어요.

Ping은 C를 부르지 않는데도 C가 느린 만큼 늦어졌죠. 왜 그럴까요?

원인은 B의 작업 스레드예요. Python의 동기 gRPC 서버는 들어온 요청을 ThreadPoolExecutor에 넘깁니다. 스레드 4개가 모두 C의 응답을 기다리는 Price로 차 있으면, 뒤에 들어온 Price 4개와 Ping은 executor의 대기열에서 스레드가 빌 때까지 기다려요.

첫 번째 Price 4개가 5초 뒤에 끝나면 대기열 앞쪽의 Price 4개가 스레드를 차지하고, Ping은 그것까지 끝난 10초 무렵에야 처리되는 거예요.

실습 2: 1초 데드라인을 전파하면

그럼 같은 실험을 클라이언트 데드라인 1초, MODE=propagate로 반복해 볼게요.

MODE=propagate C_DELAY=5 docker compose up -d --force-recreate
sleep 3
t=$(date +%s)
client ping --n 10 --interval 0.2 --tag p
client order --n 8 --deadline 1 --tag o1- > orders.txt &
client ping --n 10 --interval 0.2 --tag p1-
wait
cat orders.txt

06:44:11.816 p1 OK 0.051s
06:44:12.251 p2 OK 0.077s
06:44:12.383 p3 OK 0.004s
06:44:12.719 p4 OK 0.001s
06:44:13.113 p5 OK 0.007s
06:44:13.308 p6 OK 0.001s
06:44:13.816 p7 OK 0.033s
06:44:13.986 p8 OK 0.001s
06:44:14.188 p9 OK 0.001s
06:44:14.389 p10 OK 0.001s
06:44:22.773 p1-1 OK 0.023s
06:44:23.705 p1-2 OK 0.754s
06:44:23.710 p1-3 OK 0.554s
06:44:23.710 p1-4 OK 0.353s
06:44:23.712 p1-5 OK 0.154s
06:44:23.764 p1-6 OK 0.004s
06:44:23.971 p1-7 OK 0.008s
06:44:24.172 p1-8 OK 0.007s
06:44:24.366 p1-9 OK 0.001s
06:44:24.567 p1-10 OK 0.001s
06:44:23.702 o1-1 DEADLINE_EXCEEDED 0.934s
06:44:23.710 o1-2 DEADLINE_EXCEEDED 0.934s
06:44:23.702 o1-3 DEADLINE_EXCEEDED 0.917s
06:44:23.702 o1-4 DEADLINE_EXCEEDED 0.910s
06:44:23.714 o1-5 DEADLINE_EXCEEDED 0.921s
06:44:23.714 o1-6 DEADLINE_EXCEEDED 0.919s
06:44:23.713 o1-7 DEADLINE_EXCEEDED 0.917s
06:44:23.710 o1-8 DEADLINE_EXCEEDED 0.912s

주문 8건은 모두 1초 안에 DEADLINE_EXCEEDED로 끝났어요. 주문이 들어간 직후 도착한 Ping 몇 개는 스레드가 빌 때까지 최대 0.754초를 기다렸지만, 그 뒤의 Ping은 0.001~0.008초로 돌아왔습니다.

세 번 반복한 결과도 같았어요. 기다린 Ping은 최대 0.719~0.771초였고, 나머지는 0.023초 이하였습니다.

주문은 실패했지만, C가 느려진 동안 B가 다른 요청에 답하지 못하는 시간은 10초에서 1초 안쪽으로 줄었어요. 데드라인이 실패를 빨리 확정하니 스레드도 그만큼 빨리 돌아오는 거죠.

이 실험은 Python 동기 서버 기준이에요. grpc.aio를 쓰는 asyncio 서버는 요청마다 스레드를 차지하지 않으니까 같은 숫자가 나오지 않을 수 있습니다.

실습 3: 남은 시간을 넘기지 않으면

그럼 코드에서 남은 시간을 넘기지 않으면 어떻게 될까요? 같은 1초 데드라인을 MODE=none으로 보내 확인해 볼게요. logs로 A, B, C가 남긴 로그도 함께 봅니다.

MODE=none C_DELAY=5 docker compose up -d --force-recreate
sleep 3
t=$(date +%s)
client order --deadline 1 --tag none1-
sleep 6
logs $t

06:48:31.216 none1-1 DEADLINE_EXCEEDED 1.005s
06:48:30.227 a call B start req=none1-1 timeout_left=0.985s
06:48:30.239 b call C start req=none1-1 timeout_left=9223372035063938048.000s
06:48:30.252 c start req=none1-1 n=1 previous=0 timeout_left=9223372035063938048.000s
06:48:35.308 c done req=none1-1 slept=5.0s active=True
06:48:35.312 b call C end req=none1-1 status=OK after=5.073s
06:48:35.313 a call B end req=none1-1 status=OK after=5.087s

A는 0.985초가 남은 요청을 받았지만, B에게는 데드라인이 없는 요청으로 보였어요. Python grpcio는 서버 핸들러 안에서 다른 서비스를 부를 때 들어온 요청의 데드라인을 자동으로 넘기지 않기 때문이에요.

그래서 클라이언트는 1.005초에 포기했는데 A, B, C는 5초를 다 쓰고 OK로 끝났습니다.

로그의 timeout_left는 각 서버가 읽은 time_remaining() 값이에요. Python API 문서는 데드라인이 없으면 time_remaining()이 None을 돌려준다고 적고 있지만, grpcio 1.84.0에서는 약 2,900억 년에 해당하는 값이 나왔습니다. 데드라인이 있는지 판단해야 한다면 None만 확인해서는 안 되고, 값이 비정상적으로 큰지도 함께 확인해 주세요.

grpc.io의 Deadlines 가이드에 따르면 Java와 Go는 이 전파가 기본으로 켜져 있고 C++은 직접 켜야 해요. 이 실습은 Python만 확인했습니다. Python에서는 time_remaining()을 읽어 하위 호출의 timeout에 넣는 코드를 직접 써 주셔야 해요.

정리

범위: Python 3.12, grpcio 1.84.0, Docker 컨테이너 A, B, C(B 작업 스레드 4개), C 응답 지연 5초, 조건마다 세 번 반복.

스레드 4개인 B에 주문 8건이 들어가자 C를 부르지 않는 Ping이 0.001~0.016초에서 7.9~10.1초로 늘었고, 1초 데드라인을 전파하자 기다린 Ping도 최대 0.719~0.771초였습니다. 느린 하위 호출이 작업 스레드를 붙잡지 않게 데드라인을 거세요.
남은 시간을 넘기지 않으면 클라이언트가 1.005초에 포기한 뒤에도 A, B, C가 5초를 다 쓰고 OK로 끝났습니다. Python grpcio는 데드라인을 하위 호출에 자동으로 넘기지 않으니 timeout에 남은 시간을 직접 넣어 주세요.
grpcio 1.84.0에서 데드라인이 없을 때 time_remaining()은 None이 아니라 약 2,900억 년에 해당하는 값이었습니다. 데드라인이 있는지는 None만이 아니라 값이 비정상적으로 큰지도 함께 확인하세요.