java - 只有一个部署在 Tomcat 中运行缓慢，另一个运行正常/快速

Question

环境:

• Tomcat 8(在 Tomcat 7 中结果相同)
• JDK 1.7
• Spring MVC 3
• 甲骨文 UCP 11.2.0.3
• window 服务器 2008 R2

我有一个 Tomcat 8 实例(在 Tomcat 7 中表现出相同的行为)，其中部署了两个独立的 Spring MVC 应用程序。他们共享一个共同的启动项目并且有许多共同点，包括他们使用 Oracle UCP，但执行不同的功能。

项目 #1 已经投入生产超过 9 个月，并且从未出现过任何速度问题。项目 #2 是最近开发的，与项目 #1 类似，但响应时间逐渐变慢。

奇怪的是，在同一个应用程序服务器中，项目 #1 总是运行良好/快速，而项目 #2 将在 24 到 48 小时内逐渐变慢，变得如此缓慢以至于几乎无法使用(10 秒以上的响应时间).由于这个证据，它似乎不是 Tomcat 问题而是项目问题。

我不认为这是内存泄漏，因为我有:

1. 使用 jVisualVM 分析应用程序，没有发现内存泄漏的证据
2. 重复进行堆转储并使用 MAT 对其进行分析，没有内存泄漏的迹象
3. 手动观察内存使用情况和垃圾收集情况，没有看到任何明显的内存泄漏迹象
4. 使用 FindBugs 扫描代码 - 未发现有害错误
5. 使用 SonarQube 扫描代码 - 未发现有害错误
6. Tomcat 的“检测泄漏”功能没有发现
7. 而且，它似乎永远不会耗尽内存，只是变得非常慢。重新部署应用程序会在一段时间内恢复到正常速度。

我还使用 jVisualVM 监视线程，没有任何意外的等待线程。有很多 UCP-Worker-Threads，但我确实维护了多个连接池，每个池最多 10 个连接。

查看项目 #2 的 Tomcat 应用程序特定日志，缓慢似乎并不是由应用程序的任何特定部分引起的。只是每次操作都变得很慢。例如，在(慢速)项目 #2 中解密一个字符串显示在部署速度变慢后需要超过 1 秒的时间来执行。但是，在(快速)项目 #1 中，完全相同的代码(相同的库)在毫秒(或不到一毫秒)内解密字符串。这两个测试是在一两分钟内执行的。

我还在 Tomcat 中单独运行(缓慢的)项目 #2(除了 Tomcat 管理器之外没有部署其他应用程序)并且随着时间的推移会出现相同的行为。这应该可以消除两个应用程序之间的冲突原因。

我已经为此研究了很长时间，但我的想法已经用完了。令我感到困惑的主要事情是一个部署如何运行得非常慢，而同一个 Tomcat 实例中的类似部署却可以快速运行。

寻找任何帮助、建议、指示、工具以用于更多研究、信息等...请:)

(粗略)时序比较

我在两个项目中都添加了一小段代码，这些代码简单地计数为 1 亿，将 100 万个字符附加到 StringBuffer，然后返回以纳秒为单位的计时信息 (System.nanoTime())。以下两个测试背靠背运行:

快速/正常项目 #1

Counted to 100 million in : 174604ns 
Appended 1 million characters to StringBuffer in 13075475ns 
Total execution time : 13475805ns

慢项目 #2

Counted to 100 million in : 218954364ns 
Appended 1 million characters to StringBuffer in 13098243ns 
Total execution time : 450329651ns

依赖信息

org.apache.poi - 3.9
org.json - 20131018
com.oracle.ucp - 11.2.0.3
com.oracle.ons - 11.2.0.3
com.oracle.ojdbc6 - 11.2.0.3
org.springframework.spring-context - 3.2.3.RELEASE
org.springframework.spring-webmvc - 3.2.3.RELEASE
org.springframework.spring-context-support - 3.2.3.RELEASE
org.aspectj.aspectjrt - 1.7.3
org.aspectj.aspectjweaver - 1.7.3
org.apache.httpcomponents.httpclient - 4.3
org.apache.httpcomponents.httpcore - 4.3
com.google.code.gson - 2.2.2
cglib - 2.2.2
org.codehaus.jackson.jackson-core-asl - 1.9.12
org.codehaus.jackson.jackson-mapper-asl - 1.9.12
com.nimbusds.nimbus-jose-jwt - 2.10.1
org.slf4j.slf4j-api - 1.7.5
ch.qos.logback.logback-classic - 1.0.13
ch.qos.logback.logback-core - 1.0.13
javax.inject - 1
javax.servlet.servlet-api - 2.5
javax.servlet.jsp.jsp-api - 2.1
javax.servlet.jstl - 1.2
org.jsoup - 1.7.2
commons-fileupload - 1.3
com.google.guava - 16.0.1
+1 proprietary internal library

<!-- Test Scope - shouldn't affect deployment -->
junit - 4.11
org.mockito.mockito-core - 1.9.5
org.springframework.spring-test - 3.2.3.RELEASE
org.hsqldb - 2.3.1
commons-dbcp - 1.2.2
org.hamcrest.hamcrest-all - 1.3
com.jayway.jsonpath.json-path - 0.8.1
com.jayway.jsonpath.json-path-assert - 0.8.1

有进展吗？

虽然今天负载很重，但我注意到几个 HTTP APR 线程阻塞以等待 logback。 (快速)项目 #1 不使用 logback，而是使用 log4j。这是少数不同的依赖项之一......我们可能有一个罪魁祸首。当我有更多信息时，我会回复。

Answer 1

在重负载下监视线程时，我注意到我的几个 HTTP APR 线程间歇性地阻塞。我进行了多次线程转储并将资源追溯到:

ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:170)
- waiting to lock <0x00000000d02bf8c0> (a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy)

0x00000000d02bf8c0 是我锁定的资源，它的类可能足以找到原因，但我在转储中挖掘了有关该资源的更多信息:

"http-apr-8080-exec-119" daemon prio=6 tid=0x0000000014262000 nid=0x1e9c runnable [0x000000002a63b000]
   java.lang.Thread.State: RUNNABLE
    at java.util.zip.CRC32.updateBytes(Native Method)
    at java.util.zip.CRC32.update(CRC32.java:65)
    at java.util.zip.ZipOutputStream.write(ZipOutputStream.java:327)
    - locked <0x00000000e6d5c758> (a java.util.zip.ZipOutputStream)
    at ch.qos.logback.core.rolling.helper.Compressor.zipCompress(Compressor.java:110)
    at ch.qos.logback.core.rolling.helper.Compressor.compress(Compressor.java:58)
    at ch.qos.logback.core.rolling.FixedWindowRollingPolicy.rollover(FixedWindowRollingPolicy.java:157)
    at ch.qos.logback.core.rolling.RollingFileAppender.rollover(RollingFileAppender.java:138)
    - locked <0x00000000d02bf750> (a ch.qos.logback.core.spi.LogbackLock)
    at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:171)
    - locked <0x00000000d02bf8c0> (a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy)

你已经知道了 - logback 正在阻止在归档/压缩符合定义的 SizeBasedTriggeringPolicy 的日志时尝试记录的线程。

我查看了配置，发现日志大小设置为只有 5MB。实际上，我在研究它时使问题变得更糟，因为我将 appender 级别设置为 DEBUG，因此我们可以更快地生成更多日志语句。我大大增加了日志文件的大小，此后就再也没有遇到过问题。我计划很快转向基于日期的日志策略，因为这是我以前一直使用的策略，而且看起来没有太多考虑这个项目的日志配置:)

@user1676075 在共享资源的想法上走在了正确的轨道上，但我没有想到我的日志记录是一种资源。

我不太确定的是应用程序在遇到此瓶颈后无法恢复的原因。如果它处于持续负载下，那么我可以看到它备份线程池并耗尽所有工作线程。但是，一旦出现这种情况，应用程序就会非常缓慢，直到重新部署或服务器重新启动。我需要确保它在达到新的/更高的文件大小限制时或在我转向基于日期的滚动策略时不会消失。

谢谢大家的建议!