垃圾收集器在Tomcat Web应用程序中频繁运行,没有运行任何用户代码



我已经实现了一个Web应用程序,它包括Web服务和一些后台进程(线程),其中一个由Spring TaskScheduler启动(只启动一次,但一直运行…检查其他从进程是否开始主要通过DB处理事务)。从功能上讲,一切都运行得很好,但我正在进行调整,我看到相关JRE上出现了不可接受的周期性CPU消耗。Tomcat版本8.5.29 JVM/JRE(jdk_1.8.0_171).

我怀疑我的代码效率低下,导致GC不必要地运行(或者在任何情况下都只是正确地调整GC),所以我实现了另一个线程的一个建议(他们非常积极地将我从GC活动中赶了出来,而且形式不好),以跟踪GC活动,并仔细查看了相关文档。

完成后,我收到了许多与GC相关的消息,这些消息引导我进入下一步。当我调试用户代码时,我无法理解(或与我的用户代码活动相关)大量的GC调用。因此,在调试模式下,我在所有正在执行的用户代码中设置了一些断点,有效地瘫痪了所有与用户代码相关的执行,循环GC消息继续以用户代码运行时的节奏运行。结果是(独立于用户代码是否正在运行)每10-11秒调用GC并运行约11-12秒。

请记住,在用户代码被完全阻止的情况下。。这是一个示例输出。。

2019-10-28T13:12:07.358+0100: 6206.987: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 201649K->160689K(264704K), 0.0019574 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:17.675+0100: 6217.304: [GC (Allocation Failure) [PSYoungGen: 41216K->320K(41472K)] 201649K->160761K(264704K), 0.0019036 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:17.899+0100: 6217.527: [GC (Allocation Failure) [PSYoungGen: 41280K->256K(41472K)] 201721K->160809K(264704K), 0.0019992 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:18.128+0100: 6217.756: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 201769K->160785K(264704K), 0.0022651 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:18.352+0100: 6217.981: [GC (Allocation Failure) [PSYoungGen: 41184K->288K(41472K)] 201745K->160873K(264704K), 0.0020136 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:18.575+0100: 6218.203: [GC (Allocation Failure) [PSYoungGen: 41248K->256K(41472K)] 201833K->160865K(264704K), 0.0019503 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:18.793+0100: 6218.422: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 201825K->160889K(264704K), 0.0019472 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:19.012+0100: 6218.641: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 201849K->160913K(264704K), 0.0019231 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:19.241+0100: 6218.870: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 201873K->160897K(264704K), 0.0022029 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:19.459+0100: 6219.088: [GC (Allocation Failure) [PSYoungGen: 41184K->224K(41472K)] 201857K->160905K(264704K), 0.0024031 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:19.685+0100: 6219.313: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 201865K->160945K(264704K), 0.0018694 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:19.902+0100: 6219.531: [GC (Allocation Failure) [PSYoungGen: 41216K->288K(41472K)] 201905K->160985K(264704K), 0.0019840 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:20.123+0100: 6219.752: [GC (Allocation Failure) [PSYoungGen: 41248K->224K(41472K)] 201945K->160929K(264704K), 0.0021776 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:20.338+0100: 6219.967: [GC (Allocation Failure) [PSYoungGen: 41184K->224K(41472K)] 201889K->160929K(264704K), 0.0018897 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:20.555+0100: 6220.183: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 201889K->160977K(264704K), 0.0019590 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:20.771+0100: 6220.399: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 201937K->160953K(264704K), 0.0022302 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:20.991+0100: 6220.619: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 201913K->161001K(264704K), 0.0020969 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:21.229+0100: 6220.858: [GC (Allocation Failure) [PSYoungGen: 41216K->288K(41472K)] 201961K->161041K(264704K), 0.0018507 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:21.445+0100: 6221.074: [GC (Allocation Failure) [PSYoungGen: 41248K->224K(41472K)] 202001K->160985K(264704K), 0.0023642 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:21.659+0100: 6221.288: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 201945K->161017K(264704K), 0.0019729 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:21.875+0100: 6221.504: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 201977K->161025K(264704K), 0.0019721 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:22.109+0100: 6221.738: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 201985K->161033K(264704K), 0.0021257 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:22.338+0100: 6221.966: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 201993K->161041K(264704K), 0.0018824 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:22.565+0100: 6222.194: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 202001K->161017K(264704K), 0.0019543 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:22.785+0100: 6222.414: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 201977K->161049K(264704K), 0.0019685 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:23.002+0100: 6222.630: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 202009K->161049K(264704K), 0.0018725 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:23.240+0100: 6222.869: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 202009K->161025K(264704K), 0.0021566 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:23.451+0100: 6223.080: [GC (Allocation Failure) [PSYoungGen: 41184K->224K(41472K)] 201985K->161025K(264704K), 0.0020730 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:23.682+0100: 6223.311: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 201985K->161057K(264704K), 0.0019011 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:23.933+0100: 6223.561: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 202017K->161025K(264704K), 0.0018953 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:24.185+0100: 6223.813: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 201985K->161065K(264704K), 0.0019484 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:24.419+0100: 6224.048: [GC (Allocation Failure) [PSYoungGen: 41216K->288K(41472K)] 202025K->161097K(264704K), 0.0019002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:24.644+0100: 6224.272: [GC (Allocation Failure) [PSYoungGen: 41248K->256K(41472K)] 202057K->161081K(264704K), 0.0018661 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:24.872+0100: 6224.501: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 202041K->161081K(264704K), 0.0019496 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:25.092+0100: 6224.721: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 202041K->161049K(264704K), 0.0022255 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:25.319+0100: 6224.948: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 202009K->161081K(264704K), 0.0020412 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:25.537+0100: 6225.165: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 202041K->161081K(264704K), 0.0019278 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:25.762+0100: 6225.391: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 202041K->161057K(264704K), 0.0020179 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:25.979+0100: 6225.608: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 202017K->161089K(264704K), 0.0018991 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:26.252+0100: 6225.880: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 202049K->161057K(264704K), 0.0018755 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:26.484+0100: 6226.112: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 202017K->161089K(264704K), 0.0019254 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:26.695+0100: 6226.324: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 202049K->161089K(264704K), 0.0019129 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:26.918+0100: 6226.547: [GC (Allocation Failure) [PSYoungGen: 41216K->288K(41472K)] 202049K->161121K(264704K), 0.0018535 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:27.156+0100: 6226.785: [GC (Allocation Failure) [PSYoungGen: 41248K->256K(41472K)] 202081K->161097K(264704K), 0.0019399 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:27.387+0100: 6227.016: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 202057K->161097K(264704K), 0.0020594 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:27.615+0100: 6227.244: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 202057K->161097K(264704K), 0.0021954 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:27.832+0100: 6227.461: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 202057K->161097K(264704K), 0.0020552 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:28.047+0100: 6227.676: [GC (Allocation Failure) [PSYoungGen: 41216K->256K(41472K)] 202057K->161097K(264704K), 0.0021104 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:28.266+0100: 6227.895: [GC (Allocation Failure) [PSYoungGen: 41216K->224K(41472K)] 202057K->161073K(264704K), 0.0019352 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:28.474+0100: 6228.103: [GC (Allocation Failure) [PSYoungGen: 41184K->224K(41472K)] 202033K->161073K(264704K), 0.0020573 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:28.690+0100: 6228.319: [GC (Allocation Failure) [PSYoungGen: 41184K->256K(41472K)] 202033K->161105K(264704K), 0.0023471 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] 
2019-10-28T13:12:39.012+0100: 6238.641: [GC (Allocation Failure) [PSYoungGen: 41216K->288K(41472K)] 202065K->161137K(264704K), 0.0020514 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

如果你看一下时间戳,你就能推断出我所说的周期性。。我可以提供更多的输出,但它总是一样的(至少在我监控它的1-2个小时内)。

所以我的问题是。。(1) 是什么导致了这些GC调用,(2)为什么这么多,当然,(3)如何控制和/或避免。。它确实占用了大量令人讨厌的CPU。

好的,我找到了第一个问题的答案。通过暂停/恢复环境中运行的各种线程,罪魁祸首是ContainerBackgroundProcessor守护进程线程。当我挂起这个线程时,所有GC调用都会停止,一切似乎都能完美运行(包括Web服务请求)。恢复线程,GC开始以相同的循环频率再次非常努力地工作。挂起它,GC调用停止。。等等。

我认为第二个问题在这一点上无关紧要。

至于第三个问题,一个不完整的答案只是"挂起线程"。不完整,因为尽管在开发环境中很容易,但在生产中显然很麻烦。更不用说(尽管所有功能似乎都能通过一些有限的测试正常工作)Tomcat启动该线程是有充分理由的,而且暂停它的所有含义(至少对我来说)都是未知的。

我已经对此做了一些调查,但信息很少,充其量只是粗略的。Tomcat的softdocs也没有太大帮助,只是简单地说"Private thread class在固定延迟后调用这个容器及其子容器的backgroundProcess方法。">

我怀疑它是因为我们通过使用的TaskScheduler启动的线程而启动的。这被设置为30秒的FixedDelay(据我所知,只有当线程的主循环退出时才会调用它。或者可以说作业结束时),并且线程只在特殊情况下不断退出。

因此,也许有人可以指出这可能是由Tomcat错误(8.5.29版)引起的,也可能是"功能"引起的,但无论如何,如何最好地处理这种情况。

最终答案-这是一个特性(也许它可以实现得更好,也许不是)。

在对Tomcat源代码进行彻底调试后,我确认它与Tomcat的热重新加载功能有关。通过设置server.xml的Context元素可以很容易地禁用此功能。

<Context ... reloadable="false">

为那些可能关心的人提供一些细节。。

ContainerBackgroundProcessor调用StandardContext.backgroundProcess方法,该方法又调用WebappLoader.backgroundProcess方法(其中选中"可重载"标志)。如果为true,它将继续检查所有可能在上一个缓存版本之后修改过的"资源"(类、库等)(在我简陋的实现中,最初有11841个)。

对于每个资源,它构建一个新的字符串,将"/WEB-INF/classes"连接到资源路径名。。因此GC将在此后不久清除12K个临时字符串。根据设计,这是循环的,每X秒运行一次(参数backgroundProcessorDelay默认为10)。但我认为,CPU消耗更多地是由于这里执行的处理(需要为每个"资源"调用11个嵌套方法来检查它是否被修改),而不是GC工作,尽管这可能会在一定程度上增加负载。

对我来说,这个热重新加载功能根本不值得花这么多钱。。即使在开发环境中,从我所看到的情况来看,它的好处也是值得怀疑的。

我的建议,关掉它。

最新更新