java - 是什么导致全局Tomcat/JVM变慢？

Question

我在Tomcat 7/Java 7上运行几个(约15个)Java EE类的Web应用程序实例( hibernate 4 + Spring + Quartz + JSF + Facelets + Richfaces)时遇到一个奇怪但严重的问题。
系统运行良好，但是经过很长的时间变化后，同一时间所有应用程序实例突然受到响应时间增加的困扰。基本上，该应用程序仍然可以运行，但是响应时间大约是原来的三倍。
这是两个图，显示了两个示例实例的两个特定的简短工作流程/操作(登录，研讨会访问列表，ajax刷新此列表，注销；下一行只是ajax刷新的请求时间)的响应时间。的应用程序:

如您所见，应用程序的两个实例在同一时间“爆炸”并保持缓慢。重新启动服务器后，一切恢复正常。该应用程序的所有实例同时“爆炸”。
我们将 session 数据存储到数据库中，并用于集群。我们检查了 session 的大小和数量，并且两者都很低(这意味着在具有其他应用程序的其他服务器上，我们有时会有更大和更多的 session )。集群中的另一个Tomcat通常会保持快速运行几个小时，并且在这个随机的时间之后也会“消失”。我们使用jconsole检查了堆大小，并且主堆大小保持在2.5到1 GB之间，数据库连接池基本上充满了免费连接以及线程池。最大堆大小为5 GB，还有大量的烫发生成空间。负载不是特别高；主CPU上只有大约5％的负载。服务器不交换。这也不是硬件问题，因为我们另外将应用程序部署到了问题仍然相同的虚拟机上。
我不知道要看哪里了，我没主意了。有人知道在哪里看吗？
2013-02-21更新:新数据!
我向应用程序添加了另外两个时序跟踪。至于测量:监视系统调用一个执行两个任务的servlet，在服务器上测量每个任务的执行时间，并将时间记为响应。这些值由监视系统记录。
我有几个有趣的新事实:对应用程序的热重新部署导致当前Tomcat上的单个实例发疯。这似乎也会影响原始CPU的计算性能(请参见下文)。这种个体上下文爆炸与随机发生的整体上下文爆炸不同。
现在获取一些数据:

首先是各行:

浅蓝色是小型工作流程的总执行时间(详细信息请参见上文)，以客户端

为准

红色是浅蓝色的“一部分”，是执行该工作流程的特殊步骤所花费的时间，以客户端

为准

深蓝色在应用程序中进行了测量，包括通过Hibernate从数据库中读取实体列表并对其进行迭代，以获取惰性集合和惰性实体。

Green是使用浮点和整数运算的小型CPU基准测试。据我所见，没有对象分配，所以没有垃圾。

现在针对爆炸的各个阶段:我用三个黑点标记了每个图像。第一个是或多或少只有一个应用程序实例中的“小”爆炸-在Inst1中它会跳跃(特别是在红线中可见)，而在下面的Inst2中则保持平静。
在此小爆炸之后，发生“大爆炸”，并且该Tomcat上的所有应用程序实例爆炸(第二个点)。请注意，此爆炸会影响所有高级操作(请求处理，数据库访问)，但 不会(CPU基准)。在两个系统中它都保持较低状态。
之后，我通过触摸context.xml文件来热重新部署Inst1。就像我之前说的，这种情况从爆炸到现在完全灭绝了(淡蓝色线不在图表中-大约18秒)。请注意，a)此重新部署如何根本不影响Inst2，b)Inst1的原始DB访问如何也不受影响-但是CPU突然看起来变慢了!我说这太疯狂了。
更新更新
取消部署应用程序时，Tomcat的防泄漏侦听器不会提示过时的ThreadLocals或Threads。显然似乎存在一些清理问题(我认为这与Big Bang没有直接关系)，但是Tomcat对我没有任何提示。
2013-02-25更新:应用程序环境和Quartz时间表
应用程序环境不是很复杂。除了网络组件(我对此不太了解)之外，基本上只有一台应用程序服务器(Linux)和两台数据库服务器(MySQL 5和MSSQL 2008)。主要负载在MSSQL服务器上，另一负载仅用作存储 session 的地方。
应用程序服务器在两个Tomcat之间运行Apache作为负载平衡器。因此，我们有两个在同一硬件(两个Tomcat实例)上运行的JVM。我们使用此配置并不是为了真正平衡负载，因为应用程序服务器能够很好地运行应用程序(现在已经运行了好几年)，但是能够在不停机的情况下进行小的应用程序更新。所讨论的Web应用程序被部署为针对不同客户的单独上下文，每个Tomcat大约15个上下文。 (我似乎在发帖中混淆了“实例”和“上下文”-在办公室里，它们经常被当作同义词使用，我们通常会神奇地知道同事在说什么。我很不好意思，我真的很抱歉。)
为了更好地说明这种情况，请使用:我发布的图显示了同一JVM上同一应用程序的两个不同上下文的响应时间。大爆炸会影响一个JVM上的所有上下文，但不会在另一个JVM上发生(Tomcat爆炸的顺序是随机的)。在热重新部署一个Tomcat实例上的一个上下文后，它就发疯了(具有所有有趣的副作用，例如该上下文的CPU似乎变慢了)。
系统上的总负载相当低。这是一个内部核心业务相关软件，同时具有大约30个活跃用户。特定于应用程序的请求(服务器触摸)当前约为每分钟130个。单个请求的数量很少，但是请求本身通常需要对数据库进行数百次选择，因此它们相当昂贵。但是通常一切都是完全可以接受的。该应用程序也不会创建大型的无限缓存-缓存了一些查找数据，但是只保留了很短的时间。
在上面我写过，能够运行应用程序的服务器可以使用几年。我知道，找到问题的最佳方法是准确找出第一次出现问题的时间，并查看在此时间范围内发生了什么更改(在应用程序本身，关联的库或基础结构中)，但是问题是我们不知道什么时候第一次出现问题。只是让我们称其为次优的(在缺少的情况下)应用程序监视...:-/
我们排除了某些方面，但是在过去的几个月中，该应用程序已多次更新，因此我们不能简单地部署旧版本。没有功能更改的最大更新是从JSP到Facelets的切换。但是，“某些东西”一定是所有问题的原因，但是我不知道为什么Facelets例如应该影响纯DB查询时间。
quartz
至于Quartz时间表:总共有8个工作。它们中的大多数每天仅运行一次，并且与大容量数据同步有关(绝对不像“大数据大”中那样“大”；这仅比一般用户在日常工作中看到的更多)。但是，这些工作当然会在晚上运行，而问题会在白天发生。我在这里省略了详细的工作 list (如果有帮助，我当然可以提供更多详细信息)。在过去的几个月中，作业的源代码没有更改。我已经检查过爆炸是否与工作相吻合-但结果充其量是不确定的。实际上，我会说它们并不一致，但是由于每分钟都有几项作业在运行，所以我还不能排除它。在我看来，每分钟运行的辅助工作非常轻巧，它们通常会检查数据是否可用(在不同来源，数据库，外部系统，电子邮件帐户中)，如果有的话，将其写入数据库或将其推送到另一个系统。
但是，我当前正在启用单个作业执行的日志记录，以便我可以准确地看到每个作业执行的开始和结束时间戳记。也许这提供了更多的见解。
2013-02-28更新:JSF阶段和时间
我手动向该应用程序添加了JSF phae侦听器。我执行了一个示例调用(ajax刷新)，这就是我所得到的(左:正常运行的Tomcat实例，右:Big Bang之后的Tomcat实例-数字几乎同时从两个Tomcat中获取，以毫秒为单位):

RESTORE_VIEW:17 vs 46

APPLY_REQUEST_VALUES:170 vs 486

PROCESS_VALIDATIONS:78 vs 321

UPDATE_MODEL_VALUES:75 vs 307

RENDER_RESPONSE:1059与4162

Ajax刷新本身属于搜索表单及其搜索结果。在应用程序的最外层请求过滤器和Web流程开始工作之间还存在另一个延迟:存在一个 FlowExecutionListenerAdapter，用于测量Web流程某些阶段所花费的时间。在未爆炸的Tomcat上，该侦听器报告“请求提交”(据我所知的第一个Web流事件)为1405毫秒，而整个请求的总数为1632毫秒，因此我估计大约需要200毫秒的开销。
但是在爆炸的Tomcat上，它报告的请求提交时间为5105毫秒(这意味着所有JSF阶段均在这5秒钟内发生)，而总请求持续时间为7105毫秒，因此，对于Web流提交的请求之外的所有内容，我们的开销几乎为2秒。
在我的测量过滤器下面，过滤器链包含一个 org.ajax4jsf.webapp.BaseFilter，然后调用Spring servlet。
2013-06-05更新:最近几周发生的所有事情
很小的更新，但是更新太晚了……应用程序性能在一段时间后仍然很糟糕，并且行为仍然不稳定。分析并没有太大帮助，它只是生成了大量难以剖析的数据。 (尝试在生产系统上浏览性能数据或对生产系统进行概要分析...。)我们进行了几次测试(删除了软件的某些部分，取消了对其他应用程序的部署等)，实际上进行了一些改进，影响了整个应用程序。我们的 EntityManager的默认刷新模式是 AUTO，并且在 View 渲染期间会发出大量提取和选择，始终包括检查是否需要刷新。
因此，我们构建了一个JSF阶段侦听器，该侦听器在 COMMIT期间将刷新模式设置为 RENDER_RESPONSE。这大大提高了整体性能，似乎已在某种程度上缓解了问题。
但是，在某些tomcat实例的某些情​​况下，我们的应用程序监视功能始终会产生完全疯狂的结果和性能。就像一个 Action 应该在一秒钟内完成(实际上是在部署后完成)，现在耗时超过四秒钟。 (这些数字在浏览器中受手动计时的支持，因此不是引起问题的监视程序)。
例如，请参见下图:

该图显示了两个运行相同上下文(意味着相同的数据库，相同的配置，相同的jar)的tomcat实例。再次，蓝线是纯DB读取操作(获取实体列表，对其进行迭代，延迟获取集合和关联数据)所花费的时间。绿松石色和红色线分别通过渲染几个 View 和执行Ajax刷新来测量。由两个以青绿色和红色表示的请求所提供的数据与为蓝线查询的数据基本相同。
现在在实例1(右)的0700左右，纯DB时间的增加似乎也影响了实际的渲染响应时间，但是仅在tomcat 1上。Tomcat0在很大程度上不受此影响，因此它不能由DB引起服务器或网络，两个tomcat在相同的物理硬件上运行。它必须是Java域中的软件问题。
在上一次测试中，我发现了一些有趣的东西:所有响应都包含标题“X-Powered-By:JSF/1.2，JSF/1.2”。有些(由WebFlow产生的重定向响应)甚至在其中有3次“JSF/1.2”。
我追踪了设置这些 header 的代码部分，并且第一次设置此 header 是由此堆栈引起的:

... at org.ajax4jsf.webapp.FilterServletResponseWrapper.addHeader(FilterServletResponseWrapper.java:384)
at com.sun.faces.context.ExternalContextImpl.<init>(ExternalContextImpl.java:131)
at com.sun.faces.context.FacesContextFactoryImpl.getFacesContext(FacesContextFactoryImpl.java:108)
at org.springframework.faces.webflow.FlowFacesContext.newInstance(FlowFacesContext.java:81)
at org.springframework.faces.webflow.FlowFacesContextLifecycleListener.requestSubmitted(FlowFacesContextLifecycleListener.java:37)
at org.springframework.webflow.engine.impl.FlowExecutionListeners.fireRequestSubmitted(FlowExecutionListeners.java:89)
at org.springframework.webflow.engine.impl.FlowExecutionImpl.resume(FlowExecutionImpl.java:255)
at org.springframework.webflow.executor.FlowExecutorImpl.resumeExecution(FlowExecutorImpl.java:169)
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:183)
at org.springframework.webflow.mvc.servlet.FlowController.handleRequest(FlowController.java:174)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:920)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:827)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)
... several thousands ;) more

第二次设置此 header

at org.ajax4jsf.webapp.FilterServletResponseWrapper.addHeader(FilterServletResponseWrapper.java:384)   
at com.sun.faces.context.ExternalContextImpl.<init>(ExternalContextImpl.java:131)   
at com.sun.faces.context.FacesContextFactoryImpl.getFacesContext(FacesContextFactoryImpl.java:108)   
at org.springframework.faces.webflow.FacesContextHelper.getFacesContext(FacesContextHelper.java:46)   
at org.springframework.faces.richfaces.RichFacesAjaxHandler.isAjaxRequestInternal(RichFacesAjaxHandler.java:55)   
at org.springframework.js.ajax.AbstractAjaxHandler.isAjaxRequest(AbstractAjaxHandler.java:19)   
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.createServletExternalContext(FlowHandlerAdapter.java:216)   
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:182)   
at org.springframework.webflow.mvc.servlet.FlowController.handleRequest(FlowController.java:174)   
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)   
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)   
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)   
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:920)   
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:827)   
at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)

我不知道这是否可以指示问题，但是我在运行于我们任何服务器上的其他应用程序中都没有注意到这一点，因此也可能会提供一些提示。我真的不知道框架代码在做什么(承认我还没有深入研究它)……也许有人有一个想法？还是我快要死了？
附录
我的CPU基准测试代码包含一个循环，该循环计算Math.tan并使用结果值修改servlet实例上的某些字段(在该实例中没有volatile/未同步)，然后执行几次原始整数计算。我知道，这并不是很复杂，但是……似乎在图表中显示了一些东西，但是我不确定它显示了什么。我进行字段更新以防止HotSpot优化我所有的宝贵代码;)

    long time2 = System.nanoTime();
    for (int i = 0; i < 5000000; i++) {
        double tan = Math.tan(i);
        if (tan < 0) {
            this.l1++;
        } else {
            this.l2++;
        }
    }

    for (int i = 1; i < 7500; i++) {
        int n = i;
        while (n != 1) {
            this.steps++;
            if (n % 2 == 0) {
                n /= 2;
            } else {
                n = n * 3 + 1;
            }
        }
    }
    // This execution time is written to the client.
    time2 = System.nanoTime() - time2;

Answer 1

解

增加代码缓存的最大大小:

-XX:ReservedCodeCacheSize=256m

背景

我们正在使用在Tomcat 7和Java 1.7.0_15上运行的ColdFusion 10。我们的症状与您相似。有时，由于没有明显的原因，响应时间和服务器上的CPU使用率会大量增加。好像CPU变慢了。唯一的解决方案是重新启动ColdFusion(和Tomcat)。

初步分析

我从查看内存使用情况和垃圾收集器日志开始。那里没有什么可以解释我们的问题。

我的下一步是计划每小时进行一次堆转储，并使用VisualVM定期执行采样。目标是从减速前后获取数据，以便进行比较。我设法做到了。

采样中有一个突出的功能:coldfusion.runtime.ConcurrentReferenceHashMap中的get()。与之前相比，减速后花了很多时间。我花了一些时间了解该函数的工作原理，并提出了一个理论，即散列函数可能存在问题，从而导致了一些巨大的问题。使用堆转储，我可以看到最大的存储桶仅包含6个元素，因此我放弃了这一理论。

代码缓存

当我阅读“Java性能:权威指南”时，我终于走上了正确的轨道。它有一章关于JIT编译器，讨论了我以前从未听说过的代码缓存。

编译器已禁用

当监视执行的编译数量(通过jstat监视)和代码缓存的大小(通过VisualVM的Memory Pools插件监视)时，我发现该大小增加到最大大小(在我们的环境中默认为48 MB- -默认值取决于Java版本和Java编译器)。当代码缓存已满时，JIT编译器已关闭。我已经读到“CodeCache已满。已禁用编译器。”发生这种情况时应打印，但我没有看到该信息；也许我们正在使用的版本没有该消息。我知道编译器已关闭，因为执行的编译数量停止增加。

取消优化继续

JIT编译器可以取消优化先前编译的函数，这将提示该函数再次由解释器执行(除非该函数被改进的编译代替)。可以对未优化的功能进行垃圾回收，以释放代码缓存中的空间。

由于某些原因，即使没有编译任何功能来替代它们，功能也继续受到优化。越来越多的内存将在代码缓存中可用，但是JIT编译器没有重新启动。

当我们遇到速度减慢时，我从未启用过-XX:+ PrintCompilation，但是我可以肯定的是，那时我会看到ConcurrentReferenceHashMap.get()或它所依赖的函数未进行优化。

结果

自从我们将代码缓存的最大大小增加到256 MB以来，我们没有看到任何速度下降，而且总体性能得到了改善。当前，我们的代码缓存中有110 MB。