45

我在 Tomcat 7/Java 7 上运行 Java EE-ish Web 应用程序(Hibernate 4+Spring+Quartz+JSF+Facelets+Richfaces)的几个(大约 15 个)实例时遇到了一个奇怪但严重的问题。

系统运行得很好,但是在经过很长一段时间后,应用程序的所有实例同时突然出现响应时间增加的问题。基本上该应用程序仍然可以工作,但响应时间大约高出三倍。

这是两个图表,显示了两个示例实例的两个特定短工作流/操作(登录、研讨会访问列表、ajax-refresh 此列表、注销;下一行只是 ajax 刷新的请求时间)的响应时间应用程序:

上下文 1 的响应时间 上下文 2 的重新计算时间

如您所见,应用程序的两个实例同时“爆炸”并保持缓慢。重启服务器后一切恢复正常。应用程序的所有实例同时“爆炸”。

我们将会话数据存储到数据库中,并将其用于集群。我们检查了会话大小和数量,两者都相当低(这意味着在具有其他应用程序的其他服务器上,我们有时会拥有更大和更多的会话)。集群中的另一个 Tomcat 通常会快速保持几个小时,并且在这个随机的时间之后它也“死亡”。我们用 jconsole 检查了堆大小,主堆保持在 2.5 到 1 GB 大小之间,db 连接池基本上都是空闲连接,还有线程池。最大堆大小为 5 GB,还有大量可用的 perm gen 空间。负载不是特别高;主 CPU 上只有大约 5% 的负载。服务器不交换。这也不是硬件问题,因为我们另外将应用程序部署到问题仍然存在的 VM 上。

我不知道在哪里看了,我没有想法。有人知道在哪里看吗?

2013-02-21 更新:新数据!

我向应用程序添加了另外两个时序跟踪。至于测量:监控系统调用一个执行两个任务的servlet,测量服务器上每个任务的执行时间,并将所用时间写为响应。这些值由监控系统记录。

我有几个有趣的新事实:应用程序的热重新部署导致当前 Tomcat 上的单个实例发疯。这似乎也会影响原始 CPU 计算性能(见下文)。这种个体语境爆炸不同于随机发生的整体语境爆炸。

现在来看一些数据:

图 3 图4

首先是单行:

  1. 浅蓝色是小工作流的总执行时间(详情见上文),在客户端测量
  2. 红色是浅蓝色的“一部分”,是执行该工作流程的特殊步骤所花费的时间,在客户端上测量
  3. 深蓝色在应用程序中测量,包括通过 Hibernate 从数据库读取实体列表并迭代该列表,获取惰性集合和惰性实体。
  4. Green 是一个使用浮点和整数运算的小型 CPU 基准测试。据我所知,没有对象分配,所以没有垃圾。

现在来看爆炸的各个阶段:我用三个黑点标记了每张图像。第一个是或多或少只有一个应用程序实例中的“小”爆炸——在 Inst1 中它会跳跃(尤其是在红线中可见),而 Inst2 下面或多或少保持平静。

在这个小爆炸之后,发生了“大爆炸”,并且该 Tomcat 上的所有应用程序实例都爆炸了(第 2 个点)。请注意,这种爆炸会影响所有高级操作(请求处理、数据库访问),但不会影响CPU 基准测试。它在两个系统中都保持在低位。

之后,我通过触摸 context.xml 文件热重新部署了 Inst1。正如我之前所说,这个实例从爆炸到现在完全被摧毁(浅蓝色线不在图表中 - 它大约在 18 秒处)。注意 a) 这种重新部署根本不影响 Inst2 和 b) Inst1 的原始 DB 访问也没有受到影响 - 但是 CPU似乎突然变得更慢了!. 这太疯狂了,我说。

更新更新 当应用程序被取消部署时,Tomcat 的防泄漏监听器不会抱怨陈旧的 ThreadLocals 或 Threads。显然似乎存在一些清理问题(我认为这与大爆炸没有直接关系),但 Tomcat 对我没有任何提示。

2013-02-25 更新:应用环境和石英时间表

应用环境不是很复杂。除了网络组件(我不太了解这些),基本上还有一个应用程序服务器(Linux)和两个数据库服务器(MySQL 5 和 MSSQL 2008)。主要负载在 MSSQL 服务器上,另一个仅用作存储会话的地方。

应用程序服务器运行 Apache 作为两个 Tomcat 之间的负载平衡器。所以我们有两个 JVM 在同一个硬件上运行(两个 Tomcat实例)。我们使用这种配置并不是为了真正平衡负载,因为应用程序服务器能够很好地运行应用程序(多年来一直如此),而是在不停机的情况下启用小型应用程序更新。有问题的 Web 应用程序被部署为不同客户的单独上下文,每个 Tomcat 大约有 15 个上下文。(我似乎在我的帖子中混淆了“实例”和“上下文” - 在办公室里,它们经常被用作同义词,我们通常神奇地知道同事在说什么。我的错,我真的很抱歉。)

为了用更好的措辞澄清这种情况:我发布的图表显示了同一应用程序在同一 JVM 上的两个不同上下文的响应时间。大爆炸会影响一个 JVM 上的所有上下文,但不会在另一个 JVM 上发生(顺便说一句,Tomcat 爆炸的顺序是随机的)。热重新部署后,一个 Tomcat 实例上的一个上下文变得疯狂(具有所有有趣的副作用,例如该上下文的 CPU 似乎较慢)。

系统的整体负载相当低。它是一个内部核心业务相关软件,同时拥有大约 30 个活跃用户。特定于应用程序的请求(服务器接触)目前约为每分钟 130 个。单个请求的数量很少,但请求本身通常需要对数据库进行数百次选择,因此它们相当昂贵。但通常一切都是完全可以接受的。该应用程序也不会创建大型无限缓存 - 一些查找数据被缓存,但只缓存很短的时间。

上面我写道,能够运行应用程序的服务器可以正常运行几年。我知道找到问题的最佳方法是准确找出第一次出现问题的时间,并查看在此时间范围内发生了什么变化(在应用程序本身、相关的库或基础设施中),但问题是我们不知道问题是什么时候出现的。让我们称之为次优(在不存在的意义上)应用程序监控......:-/

我们排除了某些方面,但该应用程序在过去几个月中已多次更新,因此我们不能简单地部署旧版本。最大的更新不是功能更改是从 JSP 到 Facelets 的转换。但是,“某事”一定是所有问题的原因,但我不知道为什么 Facelets 会影响纯 DB 查询时间。

石英

至于 Quartz 时间表:总共有 8 个作业。它们中的大多数每天只运行一次,并且与大容量数据同步有关(绝对不是“大数据”中的“大”;这只是普通用户在日常工作中看到的更多)。但是,这些工作当然是在夜间运行,而问题发生在白天。我在这里省略了详细的工作清单(如果有帮助,我当然可以提供更多细节)。作业的源代码在过去几个月中没有更改。我已经检查了爆炸是否与工作一致——但结果充其量是不确定的。我实际上会说它们没有对齐,但是由于每分钟都有几项工作在运行,所以我还不能排除它。在我看来,每分钟运行的实际工作重量都很轻,

但是,我目前正在启用单个作业执行的日志记录,以便我可以准确地看到每个单个作业执行的开始和结束时间戳。也许这提供了更多的洞察力。

2013-02-28 更新:JSF 阶段和时序

我手动向应用程序添加了一个 JSF phae 侦听器。我执行了一个示例调用(ajax 刷新),这就是我所得到的(左:正常运行的 Tomcat 实例,右:Big Bang 之后的 Tomcat 实例 - 这些数字几乎同时从两个 Tomcat 中获取,以毫秒为单位):

  1. RESTORE_VIEW:17 对 46
  2. APPLY_REQUEST_VALUES:170 与 486
  3. PROCESS_VALIDATIONS:78 对 321
  4. UPDATE_MODEL_VALUES:75 对 307
  5. RENDER_RESPONSE:1059 与 4162

ajax 刷新本身属于搜索表单及其搜索结果。在应用程序的最外层请求过滤器和 web 流开始工作之间还有另一个延迟:有一个FlowExecutionListenerAdapter用于测量 web 流某些阶段所花费的时间。此侦听器报告“已提交请求”(据我所知是第一个 Web 流事件)的 1405 毫秒,而未爆炸的 Tomcat 上的完整请求总共需要 1632 毫秒,因此我估计大约有 200 毫秒的开销。
但是在爆炸的 Tomcat 上,它报告的请求提交时间为 5332 毫秒(这意味着所有 JSF 阶段都发生在这 5 秒内),而总请求持续时间为 7105 毫秒,因此对于提交的 Web 流请求之外的所有内容,我们最多有 2 秒的开销.
在我的测量过滤器下方,过滤器链包含一个org.ajax4jsf.webapp.BaseFilter,然后调用 Spring servlet。

2013-06-05 更新:最近几周发生的所有事情

一个小而相当晚的更新......应用程序性能在一段时间后仍然很糟糕,并且行为仍然不稳定。剖析还没有太大帮助,它只是产生了大量难以剖析的数据。(尝试在生产系统上查看性能数据或配置文件...叹息)我们进行了几次测试(删除软件的某些部分,取消部署其他应用程序等),实际上进行了一些影响整个应用程序的改进。我们的默认刷新模式EntityManagerAUTO在视图渲染期间发出大量的获取和选择,始终包括检查是否需要刷新。
所以我们构建了一个 JSF 阶段监听器,将刷新模式设置为COMMITduring RENDER_RESPONSE这大大提高了整体性能并且似乎在一定程度上缓解了这些问题。

然而,我们的应用程序监控在某些 tomcat 实例的某些上下文中不断产生完全疯狂的结果和性能。就像一个应该在一秒钟内完成的动作(实际上是在部署后完成的),而现在需要超过四秒钟。(这些数字由浏览器中的手动计时支持,因此导致问题的不是监控)。

例如看下图:
图表

此图显示了两个运行相同上下文的 tomcat 实例(意味着相同的数据库、相同的配置、相同的 jar)。同样,蓝线是纯 DB 读取操作(获取实体列表,迭代它们,延迟获取集合和相关数据)所花费的时间。绿松石色和红线分别通过渲染几个视图和进行 ajax 刷新来测量。由绿松石色和红色的两个请求呈现的数据与蓝线查询的数据基本相同。

现在在实例 1(右)的 0700 左右,纯 DB 时间大幅增加,这似乎也影响了实际的渲染响应时间,但仅在 tomcat 1 上。Tomcat 0 基本上不受此影响,因此它不是由 DB 引起的服务器或网络,两个 tomcat 都运行在相同的物理硬件上。它必须是 Java 域中的软件问题。

在我上次的测试中,我发现了一些有趣的事情:所有响应都包含标题“X-Powered-By: JSF/1.2, JSF/1.2”。有些(WebFlow 产生的重定向响应)甚至在其中包含 3 次“JSF/1.2”。
我追踪了设置这些标头的代码部分,第一次设置此标头时,它是由此堆栈引起的:

... 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

此标头第二次由

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;
4

7 回答 7

45

解决方案

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

-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。

于 2014-09-19T20:07:07.817 回答
10

首先,让我说您在抓住问题的详细事实方面做得非常出色;我真的很喜欢你如何清楚地说明你知道什么和你在推测什么——这真的很有帮助。

编辑 1上下文与实例更新后的大规模编辑

我们可以排除:

  • GC(这会影响 CPU 基准服务线程和主 CPU 峰值)
  • Quartz 作业(会影响 Tomcat 或 CPU 基准测试)
  • 数据库(会影响两个 Tomcat)
  • 网络数据包风暴和类似的(会影响两个 Tomcat)

我相信您正在遭受JVM 中某处延迟的增加。延迟是线程正在(同步)等待来自某个地方的响应的地方 - 它增加了您的 servlet 响应时间,但对 CPU 没有任何成本。典型的延迟是由以下原因引起的:

  • 网络通话,包括
    • JDBC
    • EJB 或 RMI
    • JNDI
    • 域名系统
    • 文件共享
  • 磁盘读写
  • 穿线
    • 读取(有时写入)队列
    • synchronized方法或块
    • futures
    • Thread.join()
    • Object.wait()
    • Thread.sleep()

确认问题是延迟

我建议使用商业分析工具。我喜欢 [JProfiler](http://www.ej-technologies.com/products/jprofiler/overview.html,提供 15 天试用版),但StackOverflow 社区也推荐YourKit 。在本次讨论中,我将使用 JProfiler 术语。

在运行良好时附加到 Tomcat 进程,并感受它在正常条件下的外观。特别是,使用高级 JDBC、JPA、JNDI、JMS、servlet、套接字和文件探测来查看 JDBC、JMS 等操作需要多长时间(截屏。当服务器出现问题时再次运行并进行比较。希望你会看到到底是什么被放慢了。在下面的产品截图中,你可以看到使用 JPA Probe 的 SQL 计时:

JPA 热点
(来源:ej-technologies.com

但是,探针可能没有隔离问题 - 例如,它可能是一些线程问题。转到应用程序的线程视图;这显示了每个线程的状态运行图,以及它是在 CPU 上执行,在一个 中Object.wait(),是在等待进入一个synchronized块还是在等待网络 I/O。当您知道哪个或哪些线程出现问题时,转到 CPU 视图,选择线程并使用线程状态选择器立即深入查看昂贵的方法及其调用堆栈。[Screencast](( screencast )。您将能够深入了解您的应用程序代码。

这是可运行时间的调用堆栈:

在此处输入图像描述

这是同一个,但显示了网络延迟:

在此处输入图像描述

当你知道什么是阻塞时,希望解决的路径会更清晰。

于 2013-02-24T10:46:15.583 回答
2

我们遇到了同样的问题,运行在 Java 1.7.0_u101(Oracle 支持的版本之一,因为最新的公共 JDK/JRE 7 是 1.7.0_u79),运行在 G1 垃圾收集器上。我无法确定问题是否出现在其他 Java 7 版本或其他 GC 中。

我们的过程是运行 Liferay Portal 的 Tomcat(我相信 Liferay 的确切版本在这里不感兴趣)。

这是我们观察到的行为:使用 5GB 的 -Xmx,启动后的初始代码缓存池大小约为 40MB。一段时间后,它下降到大约 30MB(这很正常,因为在启动期间有很多代码在运行,这些代码将永远不会再次执行,因此预计会在一段时间后从缓存中逐出)。我们观察到有一些 JIT 活动,因此 JIT 实际上填充了缓存(与我稍后提到的大小相比,似乎相对于整体堆大小的小缓存大小对 JIT 提出了严格的要求,这使得后者相当紧张地驱逐缓存)。然而,过了一段时间,再也没有编译过,JVM 变得非常缓慢。我们不得不时不时地杀死我们的 Tomcat 以恢复足够的性能,

JDK 7 JVM 中似乎有几个错误导致它无法重新启动 JIT(请查看此博客文章:https ://blogs.oracle.com/poonam/entry/why_do_i_get_message ),即使在 JDK 7 中,在紧急刷新(博客提到 Java 错误 8006952、8012547、8020151 和 8029091)。

这就是为什么手动将代码缓存增加到不太可能发生紧急刷新的级别“修复”问题(我猜 JDK 7 就是这种情况)。

在我们的例子中,我们没有尝试调整代码缓存池的大小,而是选择升级到 Java 8。这似乎已经解决了这个问题。此外,代码缓存现在似乎相当大(启动大小约为 200MB,巡航大小约为 160MB)。正如预期的那样,在闲置一段时间后,缓存池大小会下降,如果某个用户(或机器人或其他任何东西)浏览我们的站点,缓存池会再次恢复,从而导致执行更多代码。

希望以上数据对您有所帮助。

忘了说:我发现这篇文章的阐述、支持数据、推理逻辑和结论非常非常有帮助。谢谢你,真的!

于 2016-12-01T11:54:15.077 回答
1

有人知道在哪里看吗?

  1. 问题可能出在 Tomcat/JVM 之外——您是否有一些批处理作业会启动并像公共数据库一样对共享资源施加压力?

  2. 进行线程转储,看看当应用程序响应时间爆炸时 Java 进程在做什么?

  3. 如果您使用的是 Linux,请使用strace 之类的工具并检查 java 进程在做什么。

于 2013-02-14T14:44:09.933 回答
1

你检查过 JVM GC 时间吗?一些 GC 算法可能会“暂停”应用程序线程并增加响应时间。

您可以使用jstat实用程序来监控垃圾收集统计信息:

jstat -gcutil <pid of tomcat> 1000 100

上面的命令将每 1 秒打印 100 次 GC 统计信息。查看 FGC/YGC 列,如果数字不断增加,则说明您的 GC 选项有问题。

如果您想保持较低的响应时间,您可能需要切换到 CMS GC:

-XX:+UseConcMarkSweepGC

您可以在此处查看更多 GC 选项。

于 2013-02-14T15:14:35.533 回答
1

在您的应用程序运行缓慢一段时间后会发生什么,它会恢复正常运行吗?如果是这样,那么我会检查此时是否有任何与您的应用程序无关的活动。诸如防病毒扫描或系统/数据库备份之类的东西。

如果没有,那么我建议使用分析器(JProfiler、yourkit 等)运行它。这个工具可以很容易地将你指向你的热点。

于 2013-02-23T03:03:29.450 回答
0

您正在使用 Quartz,它管理定时进程,这似乎发生在特定时间。

发布您的 Quartz 时间表并让我们知道是否符合要求,如果符合,您可以确定哪个内部应用程序进程可能会启动以消耗您的资源。

或者,您的应用程序代码的一部分可能最终被激活并决定将数据加载到内存缓存中。您正在使用休眠;检查对数据库的调用,看看是否有任何重合。

于 2013-02-22T15:28:52.057 回答