垃圾收集器在Tomcat Web App中经常运行，没有运行用户代码

问题描述 投票：1回答：2

我已经实现了一个Web应用程序，其中包括Web服务和一些后台进程（线程），其中的一个由Spring TaskScheduler启动（仅启动一次但始终运行。.检查其他从属进程是否主要通过以下方式开始处理事情：数据库）。从功能上来说，它运行良好，但是我正在进行调整，并且发现关联的JRE上的CPU消耗不可接受且周期性地消耗。 Tomcat 8.5.29版JVM / JRE（jdk_1.8.0_171）。

[怀疑我的代码效率低下并且导致GC不必要地运行（或者在任何情况下都只是正确地调整了GC），我已经从另一个线程中实施了一个建议（它们相当积极地将我淘汰并以错误的形式出现）用于跟踪GC活动，并仔细查看了相关文档。

完成后，我收到许多与GC相关的消息，这些消息使我进入了下一步。在调试用户代码时，我无法理解（或与我的用户代码活动相关）大量的GC调用。因此，在调试模式下，我在所有正在执行的用户代码中放置了一些断点，从而有效地使所有与用户代码相关的执行瘫痪，并且周期性的GC消息在用户代码运行时以其节奏继续运行。结果是（每10-11秒一次）（独立于用户代码是否在运行）GC会被调用并运行大约20秒。 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数量。

java tomcat optimization garbage-collection
2个回答
0
投票
[好，我找到了第一个问题的答案。通过挂起/恢复在环境中运行的各种线程，罪魁祸首是ContainerBackgroundProcessor守护程序线程。当我暂停该线程时，所有GC调用都将停止，并且一切似乎都运行良好（包括Web Service请求）。恢复线程后，GC将以相同的循环频率再次开始非常努力地工作。挂起它，GC调用停止。等等。

我想第二个问题在这一点上是不相关的。

关于第三个问题，不完整的答案仅仅是“挂起线程”。不完整，因为尽管在开发环境中很容易，但是在生产中显然很麻烦。更不用说（尽管在某些有限的测试中，所有功能似乎都可以正常工作），Tomcat启动Thread是出于一个很好的理由，而暂停它的所有含义都是未知的（至少对我来说是未知的。）>

我已经对此进行了一些调查，并且几乎没有可用的信息，而且充其量只是个粗略的信息。 Tomcat softdocs并不能说“在固定的延迟后调用私有线程类来调用此容器及其子容器的backgroundProcess方法”并没有太大帮助。

我怀疑它是由于我们通过正在使用的TaskScheduler启动的线程而启动的。将其设置为30秒的FixedDelay（据我了解，仅当线程的主循环退出..或Job结束时才调用），并且线程仅在特殊情况下不断退出。]

因此，也许有人可以指出这是由Tomcat错误（版本8.5.29）还是“功能”引起的，但是无论如何，如何最好地解决这种情况。

最终答案-这是一个功能（也许可以更好地实现，也许不是）。

在对Tomcat源代码进行了彻底调试之后，我已经确认它与Tomcat的Hot Reload功能有关。通过设置server.xml的Context元素可以很容易地禁用它。

<Context ... reloadable="false"> 

一些可能关心的人的详细信息。
ContainerBackgroundProcessor调用StandardContext.backgroundProcess方法，该方法又调用WebappLoader.backgroundProcess方法，在该方法中检查“可重载”标志。如果为true，它将继续检查所有“资源”（类，库等），这些资源在上次缓存的版本之后可能已被修改（在我卑鄙的实现中，最初有多达11,841个）。
对于每个资源，它会建立一个新的字符串，将“ / WEB-INF / classes”与资源路径名连接起来。因此，GC将在其后不久清理的12K临时字符串。这是设计使周期每X秒运行一次（参数backgroundProcessorDelay，默认值为10）。但是我认为，CPU消耗比GC工作更多，这是因为它在这里执行处理（每个“资源”需要调用11个嵌套方法以检查它是否已被修改），尽管这可能会增加负载。

对我来说，这个热重装功能根本不值得负担。即使在开发环境中，其好处也值得怀疑。

我的建议，将其关闭。

0
投票
最终答案-这是一个功能（也许可以更好地实现，也许不是）。

在对Tomcat源代码进行了彻底调试之后，我已经确认它与Tomcat的Hot Reload功能有关。通过设置server.xml的Context元素可以很容易地禁用它。

最新问题
© www.soinside.com 2019 - 2024. All rights reserved.