java - CXF Webservice 随机等待 Apache Tomcat 响应 3 秒

Question

我们有一个由 Apache 服务器后面的 Apache Tomcat 8 提供的 Java 8 应用程序，它使用 CXF 并行请求多个网络服务。有时，其中一个比其余的多持续 3 秒(应该只有 500 毫秒左右)。

我已经激活了 CXF 调试，现在我在 CXF 中找到了丢失 3 秒的地方:

14/03/2018 09:20:49.061 [pool-838-thread-1] DEBUG o.a.cxf.transport.http.HTTPConduit - No Trust Decider for Conduit '{http://ws.webapp.com/}QueryWSImplPort.http-conduit'. An affirmative Trust Decision is assumed. 
14/03/2018 09:20:52.077 [pool-838-thread-1] DEBUG o.a.cxf.transport.http.HTTPConduit - Sending POST Message with Headers to http://172.16.56.10:5050/services/quertServices Conduit :{http://ws.webapp.com/}QueryWSImplPort.http-conduit

如您所见，这两行之间相隔了三秒。当请求正常时，这两条线之间通常需要0ms。

我一直在研究 CXF 代码，但不知道这 3 秒的原因...

服务器应用程序(也由我们维护)由另一个 Apache Tomcat 6.0.49 提供服务，它位于另一个 Apache 服务器后面。问题是服务器的 Apache 似乎在 3 秒后收到了请求。

谁能帮帮我？

编辑: 我们监控了服务器的发送/接收包，似乎客户端的服务器在它应该发送的时间发送协商包，而服务器在 3 秒后回复。 这些是我们找到的包:

481153  11:31:32 14/03/2018 2429.8542795    tomcat6.exe SOLTESTV010     SOLTESTV002     TCP TCP:Flags=CE....S., SrcPort=65160, DstPort=5050, PayloadLen=0, Seq=2858646321, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192  {TCP:5513, IPv4:62}
481686  11:31:35 14/03/2018 2432.8608381    tomcat6.exe SOLTESTV002     SOLTESTV010     TCP TCP:Flags=...A..S., SrcPort=5050, DstPort=65160, PayloadLen=0, Seq=436586023, Ack=2858646322, Win=8192 ( Negotiated scale factor 0x8 ) = 2097152    {TCP:5513, IPv4:62}

481687  11:31:35 14/03/2018 2432.8613607    tomcat6.exe SOLTESTV010     SOLTESTV002     TCP TCP:Flags=...A...., SrcPort=65160, DstPort=5050, PayloadLen=0, Seq=2858646322, Ack=436586024, Win=256 (scale factor 0x8) = 65536    {TCP:5513, IPv4:62}
481688  11:31:35 14/03/2018 2432.8628380    tomcat6.exe SOLTESTV010     SOLTESTV002     HTTP    HTTP:Request, POST /services/consultaServices    {HTTP:5524, TCP:5513, IPv4:62}

因此，服务器的 Tomcat 似乎被某些东西阻止了。有什么线索吗？

编辑 2:

尽管那是昨天发生的(第一台服务器等待 3 秒等待第二台服务器的确认)，但这并不是最常见的情况。通常发生的情况是我在开头描述的(两个 CXF 日志之间的 3 秒，服务器在 3 秒后收到第一个日志的任何请求。

服务器(接收请求的服务器)有时会挂起 3 秒。例如:

1. 服务器 1 同时(假设)向服务器 2 发送 5 个请求。

2. 服务器 2 在同一秒内收到其中的 4 个，并开始处理它们。

3. 服务器 2 在 30 毫秒内完成处理这 4 个请求中的 2 个并回复服务器 1。

4. 几乎在同一秒内，应用程序日志中没有任何记录。

5. 三秒后，日志再次注册，服务器完成处理剩余的 2 个请求。因此，虽然过程本身只有几毫秒，但 response_time - request_time 是 3 秒零几毫秒。

6. 与此同时，剩余的请求(已发送的 5 个请求中的最后一个)在网络监视器中注册，并在几毫秒内由应用程序处理。但是全局处理时间是3s多一点，发送后3秒到达服务器。

所以过程中间好像挂了。在此挂起之前成功处理了 2 个请求，并在几分之一秒内回复。其他 2 个请求持续了一点点，发生了挂起，并以 3 秒的处理时间结束。最后一个，刚好在挂起时到达服务器，所以挂起后它没有进入应用程序。

这听起来像是 gc stop the world...但是我们已经分析了 gc.logs 并且没有任何问题...还有其他原因吗？

谢谢!

编辑 3:

查看我上周粘贴的 TCP 标志，我们注意到有很多带有 CE 标志的数据包，这是 TCP 拥塞的通知。我们不是网络专家，但发现这可能会使我们在数据包重传之前有 3 秒的延迟...... 任何人都可以给我们一些帮助吗？

谢谢。亲切的问候。

Answer 1

最后，一切都是由我们通过查看 TCP 标志发现的网络拥塞引起的。我们的网络管理员一直在研究这个问题，试图减少拥塞，减少重新传输的超时时间。