排查 Java 客户端库中的延迟问题

简介

如果您的应用在使用 Java Datastore 客户端时遇到高于平常的延迟时间、吞吐量低或超时问题，则问题可能源于客户端 gRPC 配置，而不是 Firestore/Datastore 后端。本指南将帮助您诊断和解决常见的客户端节流问题、不正确的渠道池设置以及过多的渠道 churn。

诊断

使用 Java 客户端时，启用详细的 gRPC 和 gax-java 日志记录对于监控渠道池动态、诊断节流、连接重用问题或识别过多的渠道 churn 至关重要。

为 Java 客户端启用日志记录

如需启用详细的日志记录，请按如下所示修改 logging.properties 文件：

## This tracks the lifecycle events of each grpc channel 
io.grpc.ChannelLogger.level=FINEST
## Tracks channel pool events(resizing, shrinking) from GAX level
com.google.api.gax.grpc.ChannelPool.level=FINEST

此外，请更新 logging.properties 中的输出日志记录级别，以捕获这些日志：


# This could be changed to a file or other log output
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

应用配置

您可以使用以下两种方法之一应用 logging.properties 文件：

1. 通过 JVM 系统属性

启动 Java 应用时添加此实参：

-Djava.util.logging.config.file=/path/to/logging.properties

2. 以编程方式加载

此方法适用于集成测试或在代码中管理日志记录配置的应用。确保此代码在应用生命周期的早期运行。

LogManager logManager = LogManager.getLogManager();
  try (final InputStream is = Main.class.getResourceAsStream("/logging.properties")) {
logManager.readConfiguration(is);
}

日志记录示例

启用详细日志记录后，您会看到来自 com.google.api.gax.grpc.ChannelPool 和 io.grpc.ChannelLogger 的混合消息：

触发了渠道池扩容的资源配置不足的渠道：

09:15:30.123 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6. 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.125 [grpc-nio-worker-ELG-1-5] TRACE io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] newCall() called 
09:15:30.126 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:30.127 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<7>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}} 
09:15:31.201 [grpc-nio-worker-ELG-1-6] TRACE io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] newCall() called 
09:15:31.202 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:31.203 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<8>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}

过度预配的渠道，导致渠道池缩小：

09:13:59.609 [grpc-nio-worker-ELG-1-4] DEBUG io.grpc.ChannelLogger - [Channel<21>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<23>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}
09:14:01.998 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput drop to 0, shrinking channel pool size: 8 -> 6.
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Terminated
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Terminated

这些日志条目可用于：

  1. 监控渠道调整大小决策
  2. 确定频道重用与频道重定向之间的区别。流失
  3. 发现传输连接问题

解读日志以诊断症状

在排查高延迟或错误等性能问题时，请先为 com.google.api.gax.grpc.ChannelPool 和 io.grpc.ChannelLogger 启用日志记录。然后，将您观察到的症状与本指南中的常见场景进行匹配，以解读日志并找到解决方案。

症状 1：启动时或流量高峰期间出现高延迟

您可能会注意到，应用启动后的前几个请求速度较慢，或者每当流量突然增加时，延迟时间都会大幅增加。

可能的原因

当您的渠道池配置不足时，通常会出现这种延迟。每个 gRPC 通道可处理的并发请求数量有限（Google 中间件限制为 100 个）。达到此限制后，新的 RPC 将在客户端排队，等待可用槽位。这种排队是延迟的主要来源。

虽然通道池旨在适应负载变化，但其调整大小逻辑会定期运行（默认情况下为每分钟），并且会逐渐扩展（默认情况下，每次最多添加 2 个通道）。因此，从初始流量高峰到池的扩展之间存在固有的延迟。在此期间，当新请求等待饱和通道清空或等待池在其下一个调整大小周期中添加新通道时，会发生延迟。

要查找的日志

查找指示渠道池正在扩大的日志。这是客户端对已超出其当前容量的流量高峰做出反应的主要证据。

渠道池扩展日志：

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6.

解读：该池已检测到流量高峰，正在打开新连接以处理增加的负载。频繁扩展（尤其是在启动附近）清楚地表明，您的初始配置不足以应对典型工作负载。

如何解决

目标是在流量到达之前准备好足够的渠道，防止客户端不得不在压力下创建渠道。

增加 initialChannelCount（启动时延迟时间较长）：

如果您在启动时发现延迟时间较长，最有效的解决方案是增加 ChannelPoolSettings 中 initialChannelCount 的值。默认情况下，此值设置为 10，对于在启动时处理大量流量的应用来说，此值可能过低。

如需为应用找到合适的值，您应执行以下操作：

  1. 为 com.google.api.gax.grpc.ChannelPool 启用 FINEST 级日志记录。
  2. 在典型初始工作负载或流量高峰下运行应用。
  3. 观察渠道池扩展日志，了解池稳定在什么大小。

例如，如果您看到如下日志：
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 80, expanding channel pool size: 4 -> 6.

然后，一分钟后，您会看到以下日志：

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 95, expanding channel pool size: 6 -> 8.

如果您看到扩展后的渠道池大小稳定在 8 个渠道，并且找不到更多扩展日志，则表明您的应用需要 8 个渠道来处理其工作负载。一个不错的起点是将 initialChannelCount 设置为 8。这样可确保预先建立连接，从而减少或消除因临时伸缩容而造成的延迟。

目标是确保池有足够的容量来处理峰值负载，而不会使请求排队。

增幅 minChannelCount（流量高峰）：

如果您在流量高峰期开始时遇到高延迟，则表明您的流量增长速度快于渠道池反应性创建新连接的速度。对于流量可预测且会突然爆发的应用，这种情况很常见。

在正常流量期间，该池会稳定在少量渠道，并随着流量的增加主动添加更多渠道，以防止饱和。此伸缩过程需要时间，导致突发请求中的初始请求排队，从而导致高延迟。

增加 minChannelCount 会提高永久开放渠道的基准。这样可确保有足够的容量来处理初始突增，从而消除伸缩延迟和相关的延迟峰值。

增幅 maxChannelCount（流量高峰）：

如果您在流量高峰期间发现延迟时间较长，并且日志显示渠道池始终处于最大规模 (maxChannelCount)，则当前限制可能过低，无法应对流量高峰。默认情况下，maxChannelCount 设置为 200。如需确定更合适的值，请使用连接池配置指南，根据应用的每秒查询次数 (QPS) 峰值和平均请求延迟时间计算最佳连接数。

症状 2：间歇性超时或 RPC 失败

有时，应用在大部分时间运行正常，但偶尔会遇到间歇性超时或 RPC 失败的情况，即使在流量正常时也是如此。

可能的原因：网络不稳定

客户端与 Datastore 服务之间的连接正在断开。gRPC 客户端将尝试自动重新连接，但此过程可能会导致暂时性故障和延迟。

要查找的日志

用于诊断网络问题的最关键日志是 TRANSIENT_FAILURE。

  • 瞬时故障日志：
[grpc-nio-worker-ELG-1-7] DEBUG io.grpc.ChannelLogger - [Channel<9>: (datastore.googleapis.com:443)] Entering TRANSIENT_FAILURE state
  • 解读：此日志是一个严重警告，表明渠道已断开连接。单个孤立的故障可能只是轻微的网络故障。不过，如果我们经常看到这些消息，或者某个频道一直处于此状态，则表明存在严重的底层问题。

如何解决

调查网络环境。检查应用与 datastore.googleapis.com 之间是否存在防火墙、代理、路由器问题或一般网络不稳定问题。

症状 3：延迟时间长，每个客户端的并发请求数超过 20,000 个

此特定症状适用于以极高规模运行的应用，通常是指单个客户端实例必须处理超过 20,000 个并发请求的情况。应用在正常情况下表现良好，但当流量增加到每个客户端超过 20,000 个并发请求时，您会发现性能急剧下降。延迟时间显著增加，并在整个流量高峰期内保持较高水平。这是因为客户端的连接池已达到其最大大小，无法进一步扩容。

可能的原因

客户端因通道池已达到配置的 maxChannelCount 而出现通道饱和问题。默认情况下，该池配置的渠道数量上限为 200。由于每个 gRPC 通道最多可处理 100 个并发请求，因此只有当单个客户端实例同时处理大约 20,000 个请求时，才会达到此限制。

当池达到此上限后，便无法再创建连接。所有 200 个渠道都过载，新请求在客户端排队，导致延迟时间急剧增加。

以下日志有助于确认是否已达到 maxChannelCount。

要查找的日志

关键指标是观察到，即使负载持续增加，渠道池也会在达到配置的限制时停止扩展。

  • 日志：您会看到池的早期日志展开。在默认设置下，您在延迟峰值之前看到的最后一个扩展日志是池达到 200 个渠道的日志：
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - ... expanding channel pool size: 198 -> 200.
  • 指示：在高延迟期间，您将不会再看到“扩大渠道池大小”日志。如果缺少这些日志，且延迟时间较长，则强烈表明已达到 maxChannelCount 限制。

如何解决

目标是确保池有足够的容量来处理峰值负载，而不会使请求排队。

  • 增加 maxChannelCount：主要解决方案是将 maxChannelCount 设置增加到可以支持应用峰值流量的值。请参阅连接池配置指南，根据应用的每秒查询次数 (QPS) 峰值和平均请求延迟时间计算最佳连接数。

附录

以下部分提供了有助于问题排查的补充信息。

了解频道状态

日志中可能会显示以下渠道状态，从而帮助您了解连接行为：

州 说明
IDLE 渠道已创建，但没有有效的连接或 RPC。正在等待出现流量。
正在连接 通道正在积极尝试与 gRPC 服务器建立新的网络传输（连接）。
READY 渠道已建立并具有正常的传输，并且已准备好发送 RPC。
TRANSIENT_FAILURE 渠道遇到了可恢复的故障（例如网络故障、服务器暂时不可用）。系统会自动尝试重新连接。
SHUTDOWN 渠道已关闭，可能是手动关闭（例如，shutdown() 调用）或由于空闲超时。无法再发起新的 RPC。

提示

  • 如果您使用结构化日志记录框架（例如 SLF4J 或 Logback），则必须在 logback.xml 或其他记录器配置文件中配置等效的日志级别。日志记录外观会映射 java.util.logging 级别。