什么可能导致全局Tomcat/JVM减速？

Question

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

系统运行得很好,但是在大量不同的时间之后,应用程序的所有实例同时突然受到响应时间上升的影响.基本上应用程序仍然有效,但响应时间大约高出三倍.

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

正如您所看到的,应用程序的两个实例在同一时间"爆炸"并保持缓慢.重新启动服务器后,一切都恢复正常.应用程序的所有实例同时"爆炸".

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

我不知道在哪里看,我没有想法.有人知道在哪里看？

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

我在应用程序中添加了两个时序跟踪.至于测量:监视系统调用执行两个任务的servlet,测量服务器上每个任务的执行时间,并写入作为响应的时间.监视系统记录这些值.

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

现在有些数据:

首先是个别行:

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

现在针对爆炸的各个阶段:我用三个黑点标记每个图像.第一个是或多或少只有一个应用实例的"小"爆炸 - 在Inst1中它跳跃(特别是在红线中可见),而Inst2低于或多或少保持平静.

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

之后,我通过触摸context.xml文件热重新部署了Inst1.正如我之前所说的那样,这个例子现在从爆炸变为完全被破坏(浅蓝色线在图表之外 - 大约是18秒).请注意a)这种重新部署根本不会影响Inst2,以及b)Inst1的原始数据库访问如何也不会受到影响 - 但CPU突然变得越来越慢!.我说这很疯狂.

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

2013-02-25更新:应用程序环境和Quartz计划

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

应用程序服务器运行Apache作为两个Tomcats之间的负载平衡器.因此,我们在同一硬件上运行两个JVM(两个Tomcat 实例).我们使用此配置实际上不平衡负载,因为应用程序服务器能够正常运行应用程序(它已经多年来一直运行),但是可以在不停机的情况下实现小型应用程序更新.有问题的Web应用程序作为不同客户的单独上下文部署,每个Tomcat大约15个上下文.(我认为在我的帖子中混淆了"实例"和"背景" - 在办公室里,他们经常被同义词使用,我们通常神奇地知道同事在谈论什么.我的不好,我真的很抱歉.)

用更好的措辞来澄清情况:我发布的图表显示了同一JVM上同一应用程序的两个不同上下文的响应时间.大爆炸会影响一个JVM上的所有上下文但不会发生在另一个JVM上(Tomcats爆炸的顺序是随机的btw).在热重新部署之后,一个Tomcat实例上的一个上下文变得疯狂(带有所有有趣的副作用,就像上下文中看似较慢的CPU一样).

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

上面我写道,能够运行应用程序的服务器已经好几年了.我知道找到问题的最佳方法是找出第一次出现问题的确切时间,并查看在此时间范围内(在应用程序本身,相关库或基础架构中)已更改的内容,但问题是我们不知道问题何时首次发生.让我们称之为次优(在缺席的意义上)应用程序监控...: - /

我们排除了一些方面,但是在过去几个月中应用程序已经多次更新,因此我们不能简单地部署旧版本.非功能更改的最大更新是从JSP切换到Facelets.但仍然,"某些东西"必然是所有问题的原因,但我不知道为什么Facelets会影响纯数据库查询时间.

石英

至于Quartz时间表:总共有8个工作岗位.它们中的大多数每天只运行一次,并且与大容量数据同步有关(绝对不像"大数据大"那样"大";它只是比平常用户通过他日常工作所看到的更多).然而,这些工作当然是在夜间运行,问题发生在白天.我在这里省略了一份详细的工作清单(如果有益,我可以提供更多详细信息).在过去的几个月里,工作的源代码没有被改变.我已经检查了爆炸是否与工作一致 - 但结果最多也是不确定的.我实际上说他们没有对齐,但由于每分钟都有几个工作,我还不能排除它.在我看来,每分钟运行的实际工作相当轻,他们通常会检查数据是否可用(在不同的来源,数据库,外部系统,电子邮件帐户),如果是,请将其写入数据库或将其推送到另一个系统.

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

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

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

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

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

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

一个小而且相当晚的更新...应用程序性能在一段时间后仍然很糟糕,并且行为仍然不稳定.分析没有多大帮助,它只是产生了大量难以剖析的数据.(尝试在性能数据上探讨或描述生产系统......叹息)我们进行了多次测试(剥离软件的某些部分,取消部署其他应用程序等),并且实际上有一些改进会影响整个应用程序.我们的默认刷新模式EntityManager是AUTO在视图渲染期间发出大量的提取和选择,总是包括检查是否需要刷新.
所以我们构建了一个JSF阶段监听器,它将刷新模式设置为COMMIT期间RENDER_RESPONSE.这种改进的整体表现有很多,似乎已经有所缓解的问题.

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

请参见下图:

此图显示了两个运行相同上下文的tomcat实例(意思是相同的db,相同的配置,相同的jar).蓝线再次是纯DB读取操作所花费的时间量(获取实体列表,迭代它们,懒惰地获取集合和相关数据).绿松石色和红色线分别通过渲染几个视图和进行ajax刷新来测量.绿松石色和红色中的两个请求呈现的数据与蓝线查询的数据大致相同.

现在在实例1(右)的0700左右,纯数据库时间的这种巨大增长似乎也影响了实际的渲染响应时间,但仅限于tomcat 1. Tomcat 0在很大程度上不受此影响,因此它不能由数据库引起服务器或网络,两个tomcats在同一物理硬件上运行.它必须是Java域中的软件问题.

在我上次测试期间,我发现了一些有趣的内容:所有响应都包含标题"X-Powered-By:JSF/1.2,JSF/1.2".一些(WebFlow产生的重定向响应)甚至有三次"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/synchronized),然后执行几个原始整数计算.我知道,这并不是非常复杂,但是......它似乎在图表中显示了一些东西,但是我不确定它显示的是什么.我做了现场更新,以防止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 Performance:The Definitive Guide"时,我终于走上了正确的轨道.它有一章关于JIT编译器,它讨论了我之前没有听说过的代码缓存.

编译器已禁用

当监视执行的编译数量(使用jstat监视)和代码缓存的大小(使用VisualVM的内存池插件监视)时,我看到大小增加到最大大小(在我们的环境中默认为48 MB - - 默认值因Java版本和Java编译器而异.当代码缓存已满时,JIT编译器被关闭.我读过"CodeCache已满.编译器已被禁用." 当发生这种情况时应该打印但是我没有看到那个消息; 也许我们使用的版本没有该消息.我知道编译器已关闭,因为执行的编译数量停止增加.

去优化仍在继续

JIT编译器可以对先前编译的函数进行优化,这将使得函数再次被解释器执行(除非该函数被改进的编译替换).可以对去优化的函数进行垃圾收集以释放代码高速缓存中的空间.

由于某种原因,即使没有编译来替换它们,功能仍然被优化.代码高速缓存中将有越来越多的内存可用,但JIT编译器未重新启动.

当我们遇到减速时,我从来没有启用-XX:+ PrintCompilation但是我很确定我会看到ConcurrentReferenceHashMap.get()或它所依赖的函数,在那时被去优化.

结果

我们没有看到任何减速,因为我们将代码高速缓存的最大大小增加到256 MB,并且我们也看到了一般的性能改进.我们的代码缓存中目前有110 MB.

Answer 2

首先,我要说你已经做了很好的工作,抓住了有关问题的详细事实 ; 我真的很喜欢你如何弄清楚你知道什么以及你在猜测什么 - 这真的很有帮助.

编辑1在上下文与实例更新后进行大量编辑

我们可以排除:

• GC(会影响CPU基准测试服务线程并加速主CPU)
• Quartz作业(会影响Tomcats或CPU基准测试)
• 数据库(会影响Tomcats)
• 网络数据包风暴和类似(这将影响两个Tomcats)

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

• 网络电话,包括
  • JDBC
  • EJB或RMI
  • JNDI
  • DNS
  • 文件共享
• 磁盘读写
• 穿线
  • 从队列中读取(有时写入)
  • 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热点http://static-aws.ej-technologies.com/SanJPN2pU9HB3g30N03BZsAwd77YzUtpXAsZoe9VUCi.png

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

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

这是相同的,但显示网络延迟:

当你知道什么是阻塞时,希望解决问题的途径会更加明确.