解读Envoy访问日志中的%DURATION%字段

场景与日志示例 #

在启用Istio的OpenShift环境中，作为边缘代理（入口Pod）的Envoy实例，入站请求日志示例如下：

[2024-12-13T09:38:04.576Z] "POST /SomeGrpcApi/MyApi HTTP/2" 200 - via_upstream - "-" 279 147 1073 226 "21.37.16.1,21.37.12.122,21.37.1.33" "grpc-java-netty/1.41.0" "855230dc-8934-4g46-afa8-73a608b7f5fa" "some-host.example.com" "29.64.6.238:8080" outbound|8081||example.example-svc.svc.cluster.local 21.37.23.240:59452 21.37.23.240:10802 21.37.1.33:3478 some-host.example.com -

其中1073对应%DURATION%字段，226对应%RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)%字段。Envoy官方文档对%DURATION%的定义如下：

%DURATION%
HTTP/THRIFT
Total duration in milliseconds of the request from the start time to the last byte out.
TCP
Total duration in milliseconds of the downstream connection.
UDP
Not implemented (0).

疑问与解答 #

• 疑问1：上述定义中哪一个适用于GRPC连接？
  gRPC基于HTTP/2协议实现，因此%DURATION%遵循HTTP/THRIFT类别的定义，即从请求开始时间到最后一个字节发出的总时长（毫秒）。

• 疑问2：请求的“开始时间”具体指哪个时间节点？
  这里的“开始时间”是Envoy接收到客户端请求第一个字节的时间点，不包含TCP/TLS握手阶段的耗时——握手属于连接建立环节，%DURATION%是针对单个请求的计时，从请求数据开始抵达Envoy时启动。

• 疑问3：“最后一个字节”具体指哪个时间节点？
  “最后一个字节”指Envoy向客户端发送完响应最后一个字节的时间点。该时长覆盖了Envoy处理请求、转发至上游服务、接收上游响应，直到把响应全部发回客户端的完整流程。

• 关于公式%DURATION% = %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% + t的解析

  • %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)%是上游服务的处理耗时：从Envoy把请求全部发送给上游服务，到上游服务返回响应最后一个字节给Envoy的时长。
  • t包含以下几部分：
    1. Envoy从客户端接收请求全部数据的耗时（客户端到Envoy的网络延迟+数据传输时间）
    2. Envoy转发请求到上游服务的网络延迟+数据传输时间
    3. Envoy接收上游响应后，向客户端发送响应的网络延迟+数据传输时间
    4. Envoy自身的请求处理开销（如路由匹配、认证、日志等操作的耗时）
  • 显然，t包含了客户端与Envoy、Envoy与上游服务之间的网络延迟，以及Envoy自身的处理成本。

内容的提问来源于stack exchange，提问作者Alexander Ishmuradov