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

Question

我们有一个Java 8应用程序，由Apache服务器后面的Apache Tomcat 8提供服务，它使用CXF并行请求多个Web服务。有时，其中一个比其他的持续时间多 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 个，并开始处理它们。

服务器 2

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

或

4. 多或少在同一秒，应用程序日志中没有注册任何内容。

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

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

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

这听起来像是一个 gc 停止世界...但是我们已经分析了 gc.logs，这并没有错......难道还有其他原因吗？

谢谢！

编辑3：

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

谢谢。亲切问候。

Answer 1

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

Answer 2

问题是，服务器的Apache似乎收到了 3 秒后请求。

你是怎么弄清楚的？如果您正在查看 Apache 日志，您可能会被错误的时间戳误导。

我最初认为您的 Tomcat 6 需要 3 秒才能回答，而不是 0 到 500 毫秒，但从问题和评论来看，情况并非如此。

假设1：垃圾收集器

GC 以引入延迟而闻名。 使用 GC 详细程度参数突出显示日志中的 GC 活动。如果太难关联，你可以使用带有 gcutil 选项的 jstat 命令，你可以很容易地与 Tomcat 的日志进行比较。

假设2：网络超时

虽然 3s 是一个非常短的时间(例如，与 Windows 上的 21s TCP 默认超时相比)，但它可能是超时。 要跟踪超时，您可以使用 netstat 命令。使用netstat -an查找SYN_SENT连接，并使用netstat -s查找错误计数器。请检查是否有任何网络资源必须在此有罪的 Web 服务调用者中解析或访问。