grpc 低级遥测日志记录

Question

我正在尝试在较低级别测量我的服务的延迟。四处寻找，我看到可以向 grpc 构建器添加 addStreamTracerFactory 。

我已经像这样完成了这个简单的实现并打印了日志：

val server = io.grpc.netty.NettyServerBuilder.forPort(ApplicationConfig.Service.bindPort).addStreamTracerFactory(ServerStreamTracerFactory)....

class Telemetry(fullMethodName: String, headers: Metadata) extends ServerStreamTracer with LazyLogging {
  override def serverCallStarted(callInfo: ServerStreamTracer.ServerCallInfo[_, _]): Unit = {
    logger.info(s"Telemetry '$fullMethodName' '$headers' callinfo:$callInfo")
    super.serverCallStarted(callInfo)
  }

  override def inboundMessage(seqNo: Int): Unit = {
    logger.info(s"inboundMessage $seqNo")
    super.inboundMessage(seqNo)
  }
  override def inboundMessageRead(seqNo: Int, optionalWireSize: Long, optionalUncompressedSize: Long): Unit = {
    logger.info(s"inboundMessageRead $seqNo $optionalWireSize $optionalUncompressedSize")
    super.inboundMessageRead(seqNo, optionalWireSize, optionalUncompressedSize)
  }
  override def outboundMessage(seqNo: Int): Unit = {
    logger.info(s"outboundMessage $seqNo")
    super.outboundMessage(seqNo)
  }
  override def outboundMessageSent(seqNo: Int, optionalWireSize: Long, optionalUncompressedSize: Long): Unit = {
    logger.info(s"outboundMessageSent $seqNo $optionalWireSize $optionalUncompressedSize")
    super.outboundMessageSent(seqNo, optionalWireSize, optionalUncompressedSize)
  }
  override def streamClosed(status: Status): Unit = {
    logger.info(s"streamClosed $status")
    super.streamClosed(status)
  }

}

object ServerStreamTracerFactory extends Factory with LazyLogging{
  logger.info("called")
  override def newServerStreamTracer(fullMethodName: String, headers: Metadata): ServerStreamTracer = {
    logger.info(s"called with $fullMethodName $headers")
    new Telemetry(fullMethodName, headers)
  }
}

我是运行一个循环中的简单 grpc 客户端，正在检查服务器流跟踪器的输出。

我看到 "lifecycle" 日志重复出现。这是一个迭代（但它一次又一次地喷出完全相同的内容）：

22:15:06 INFO  [grpc-default-worker-ELG-3-2] [newServerStreamTracer:38] [ServerStreamTracerFactory$] called with com.dy.affinity.service.AffinityService/getAffinities Metadata(content-type=application/grpc,user-agent=grpc-python/1.15.0 grpc-c/6.0.0 (osx; chttp2; glider),grpc-accept-encoding=identity,deflate,gzip,accept-encoding=identity,gzip)
22:15:06 INFO  [grpc-default-executor-0] [serverCallStarted:8] [Telemetry] Telemetry 'com.dy.affinity.service.AffinityService/getAffinities' 'Metadata(content-type=application/grpc,user-agent=grpc-python/1.15.0 grpc-c/6.0.0 (osx; chttp2; glider),grpc-accept-encoding=identity,deflate,gzip,accept-encoding=identity,gzip)' callinfo:io.grpc.internal.ServerCallInfoImpl@5badffd8
22:15:06 INFO  [grpc-default-worker-ELG-3-2] [inboundMessage:13] [Telemetry] inboundMessage 0
22:15:06 INFO  [grpc-default-worker-ELG-3-2] [inboundMessageRead:17] [Telemetry] inboundMessageRead 0 19 -1
22:15:06 INFO  [pool-1-thread-5] [outboundMessage:21] [Telemetry] outboundMessage 0
22:15:06 INFO  [pool-1-thread-5] [outboundMessageSent:25] [Telemetry] outboundMessageSent 0 0 0
22:15:06 INFO  [grpc-default-worker-ELG-3-2] [streamClosed:29] [Telemetry] streamClosed Status{code=OK, description=null, cause=null}

仅查看这些日志，我还不太清楚一些事情：

为什么要为每个请求创建一个新流？我认为 grpc 客户端应该重新使用连接。 "stream closed" 不应该这么叫吧？
如果流被重新使用，为什么我看到 inboundMessage 数字（和 outboundMessage）总是“0”。（此外，当我并行启动多个客户端时，它始终为 0）。什么情况下消息号不应该为0？
如果流没有被重新使用，我应该如何以不同方式配置客户端以重新使用连接？

Answer 1

在 gRPC 中，为每个 RPC 创建一个 HTTP2 流（而如果启用重试或对冲，则每个 RPC 可以有多个流）。 HTTP2 流在一个连接上多路复用，打开和关闭流的成本非常低。所以，重用的是连接，而不是流。

您从跟踪器方法中获得的 seqNo 是此流的消息的 seqNo，它从 0 开始。看起来您正在执行一元 RPC，它发出一个请求并获得一个响应然后关闭。你看到的是完全正常的。

grpc 低级遥测日志记录

grpc low level telemetry logging

java

python

grpc

grpc-java

grpc-python