报错是这么冒出来的。grpc 1.62 的 Python 客户端调推理服务的 Generate 接口,deadline 设 500ms,客户端报 StatusCode.DEADLINE_EXCEEDED,服务端埋点显示处理只用了 800ms,两边日志差了将近 300ms 的排队时间。

中间走过弯路,把「容器与宿主机时钟不同步,NTP 偏差让时间线对不上」当成主因,改完现象没变。

排查方向其实有限,先把可能性排一排。deadline 从客户端发起就开始计时,含 DNS 解析和连接建立。另一种情况是服务端统计的是进入 handler 之后的时间,不含反序列化。

不容易想到的是,中间代理对失败请求自动重试,剩余 deadline 被摊薄。

先在客户端测一次纯连接耗时

python -c "import time,grpc;t=time.time();ch=grpc.insecure_channel('127.0.0.1:50051');grpc.channel_ready_future(ch).result(timeout=5);print(round((time.time()-t)*1000,1))"

接着把 deadline 放到 5 秒看是否还超时

python -c "import grpc;ch=grpc.insecure_channel('127.0.0.1:50051');print(ch.unary_unary('/infer.Infer/Generate')(b'x',timeout=5)[:8])"

然后打开 gRPC 的环境变量日志观察重试

python -c "import os;os.environ['GRPC_VERBOSITY']='DEBUG';os.environ['GRPC_TRACE']='http';print('trace on')"

末了对齐两台机器的时钟偏差

python -c "import time;print(time.time(),time.time_ns())"

别只看报错消失,验证要多做一步。deadline 改成 5 秒后请求全部成功,服务端 handler 耗时仍在 800ms 左右,客户端记录的总耗时与 handler 加连接时间能对上。

提醒一点。deadline 是端到端预算,连接、排队、反序列化都在里面,拿它和服务端 handler 耗时直接比一定会觉得冤。拖得越久,排查成本越高,因为现场状态会被后续操作覆盖。

作者 9823189