OkHttp3 connectionReleased事件解析与请求超时问题排查

我的Java 8应用使用OkHttp3 4.9.2版本向某端点发起N次HTTP请求，M个线程从队列中取出任务、解析并发送请求。初始约40%请求能成功获取响应，但后续开始出现超时。

我通过事件监听器（EventListener）启用日志，得到以下两类请求日志样本：

成功请求日志 #

12:51:25.833 [pool-1-thread-28] INFO callStart : 76089 : time=0 for id=974745017410
12:51:25.833 [pool-1-thread-28] INFO connectionAcquired : 76177 : time=0 for id=974745017410
12:51:25.833 [pool-1-thread-28] INFO requestHeadersStart : 76178 : time=0 for id=974745017410
12:51:25.833 [pool-1-thread-28] INFO requestHeadersEnd : 76178 : time=0 for id=974745017410
12:51:25.833 [pool-1-thread-28] INFO requestBodyStart : 76178 : time=0 for id=974745017410
12:51:25.833 [pool-1-thread-28] INFO requestBodyEnd : 76178 : time=0 for id=974745017410
12:51:26.137 [pool-1-thread-28] INFO responseBodyStart : 74586 : time=304 for id=974745017410
12:51:26.137 [pool-1-thread-28] INFO responseBodyEnd : 74586 : time=0 for id=974745017410
12:51:26.137 [pool-1-thread-28] INFO connectionReleased : 76177 : time=0 for id=974745017410
12:51:26.137 [pool-1-thread-28] INFO callEnd : 74586 : time=0 for id=974745017410

此日志包含所有事件，网络请求延迟为304ms。

超时请求日志 #

12:51:16.134 [pool-1-thread-55] INFO callStart : 76088 : time=0 for id=258173443243
12:51:16.134 [pool-1-thread-55] INFO connectionAcquired : 76176 : time=0 for id=258173443243
12:51:16.134 [pool-1-thread-55] INFO requestHeadersStart : 76177 : time=0 for id=258173443243
12:51:16.134 [pool-1-thread-55] INFO requestHeadersEnd : 76177 : time=0 for id=258173443243
12:51:16.134 [pool-1-thread-55] INFO requestBodyStart : 76177 : time=0 for id=258173443243
12:51:16.134 [pool-1-thread-55] INFO requestBodyEnd : 76177 : time=0 for id=258173443243
12:51:26.134 [pool-1-thread-55] INFO connectionReleased : 76176 : time=10000 for id=258173443243

补充信息：服务器具备无限扩容能力，仅在无法处理更多请求时返回限流错误，而我的应用仅发送了服务器可处理请求量的15%；我尝试设置自定义连接池，将maxIdleConnections设为线程数，但问题依旧。

疑问 #

1. 请解释connectionReleased事件的含义。
2. 超时请求中缺少responseBodyStart和responseBodyEnd事件：
   a. 是否代表服务器从未返回响应？
   b. 是否有其他事件可排查客户端是否因过载无法读取响应？

1. connectionReleased事件的含义 #

connectionReleased事件表示OkHttp已将当前请求使用的连接归还给连接池（或直接关闭连接，如果该连接不符合复用条件）。触发时机是请求完成（无论成功、失败、超时）后，OkHttp完成连接清理操作，将其放回连接池供后续请求复用，此时就会触发该事件。

超时请求日志中的time=10000正好对应默认10秒超时时间，说明连接是在超时后被释放的。

2. 关于缺少响应相关事件的分析 #

a. 是否代表服务器从未返回响应？ #

是的，大概率服务器没有返回任何响应数据。从日志看，请求已发送完成（requestBodyEnd触发），但直到超时都未触发responseBodyStart，说明客户端根本没收到服务器的响应头或响应体。结合服务器仅在过载时返回限流错误、请求量仅为服务器处理能力15%的信息，可能的原因包括：

• 网络链路问题（如中间代理、防火墙丢包）
• 服务器端处理逻辑异常，导致请求被挂起未返回
• OkHttp超时配置不合理（如仅设置了调用超时，未配置读取/写入超时）

b. 可排查客户端过载的其他事件 #

可以关注以下事件和指标：

• callFailed事件：请求超时后OkHttp会触发该事件，日志未出现可能是未正确监听，它会携带具体异常信息（如SocketTimeoutException），可直接确认超时类型。
• 连接池相关事件：监听connectionCreated和connectionClosed事件，统计连接创建、关闭频率，确认是否存在连接泄漏或连接池耗尽情况。
• 线程池状态：监控线程池的活跃线程数、队列任务数、拒绝次数，确认是否线程池过载导致请求无法及时处理。
• DNS解析事件：若启用DNS监听，dnsStart和dnsEnd事件可排查是否DNS解析延迟导致后续请求阻塞。

另外，建议检查OkHttp的超时配置，确保同时设置callTimeout、connectTimeout、readTimeout和writeTimeout，避免因单一超时配置缺失导致请求挂起。

内容的提问来源于stack exchange，提问作者Mohammed Abbas Ali