GC 日志中非常频繁的 GC (ParNew) 和频繁的应用程序暂停 (Apache 2.2 + Tomcat 7 + Java 1.7)

【问题标题】：Very Frequent GC (ParNew) in GC Logs and frequent application pause (Apache 2.2 + Tomcat 7 + Java 1.7)GC 日志中非常频繁的 GC (ParNew) 和频繁的应用程序暂停 (Apache 2.2 + Tomcat 7 + Java 1.7)
【发布时间】：2016-01-08 20:03:38
【问题描述】：

我们正在提供基于 tomcat 7、java 1.7 和 Mod_proxy apache webserver 的 Spring Boot 服务。我们有大约 4 GB 的 RAM。我们尝试对应用程序运行负载测试，发现应用程序停止在 1014 个并发线程上工作。所以我们将 AJP 中的 Maxthread 限制为 1000 (server.xml)，将 Apache httpd.conf 限制为 (maxClient 250, serverLimit 10..)。httpd.conf 的设置

<IfModule worker.c>
StartServers         4
ServerLimit         10
MaxClients         225
MinSpareThreads     25
MaxSpareThreads     50 
ThreadsPerChild     25
MaxRequestsPerChild  5000
</IfModule>

在这些设置之后，一切看起来都很好，因为线程数永远不会达到 1014 。 但是在 GC 日志中，我们看到很多 [GC2014.255: [ParNew: 每隔几秒就会运行一次。 所以我有两个疑问：-

1) 我们是否应该担心这些非常频繁的应用程序线程由于 ParNew 每秒而暂停。

2) 另外我如何调整 JVM 条目以支持更多数量的线程 (1014)。我是否需要添加更多内存。我们在负载测试期间监控 APP，堆内存使用量从未超过 700-1000 MB。所以不确定，问题出在哪里：-

关于日志格式和问题的道歉..

以下是我们配置的 JVM 参数：

tomcat   24834     1 44 01:23 ?        00:15:53 /usr/lib/jvm/jre/bin/java -Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.port=1999
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false
-server
-Xms1024m
-Xmx1536m
-XX:PermSize=256m
-XX:MaxPermSize=256m
-Xincgc
-XX:+UseConcMarkSweepGC
-XX:+ScavengeBeforeFullGC
-Xloggc:/usr/share/tomcat/logs/GCLogs.log
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=2 -XX:GCLogFileSize=50M
-Djava.awt.headless=true
-classpath :/usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/commons-daemon.jar
-Dcatalina.base=/usr/share/tomcat
-Dcatalina.home=/usr/share/tomcat
-Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat/temp 
-Djava.util.logging.config.file=/usr/share/tomcat/conf/logging.properties
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
org.apache.catalina.startup.Bootstrap
start

GC日志：

1963.681: [GC1963.681: [ParNew: 146298K->17024K(153344K), 0.0476010 secs] 443232K->313989K(1031552K) icms_dc=0 , 0.0478920 secs] [Times: user=0.10 sys=0.00, real=0.05 secs]

1963.729: Total time for which application threads were stopped: 0.0485110 seconds, Stopping threads took: 0.0001100 seconds

1964.996: Total time for which application threads were stopped: 0.0005740 seconds, Stopping threads took: 0.0000920 seconds

1965.057: Total time for which application threads were stopped: 0.0003770 seconds, Stopping threads took: 0.0000890 seconds
1965.057: Total time for which application threads were stopped: 0.0001790 seconds, Stopping threads took: 0.0000340 seconds

1965.057: Total time for which application threads were stopped: 0.0003100 seconds, Stopping threads took: 0.0001900 seconds

1965.248: Total time for which application threads were stopped: 0.0004140 seconds, Stopping threads took: 0.0001020 seconds

1965.248: Total time for which application threads were stopped: 0.0001650 seconds, Stopping threads took: 0.0000360 seconds

1965.248: Total time for which application threads were stopped: 0.0001670 seconds, Stopping threads took: 0.0000340 seconds

1965.457: Total time for which application threads were stopped: 0.0004850 seconds, Stopping threads took: 0.0001530 seconds

1965.458: Total time for which application threads were stopped: 0.0002620 seconds, Stopping threads took: 0.0001240 seconds

1965.458: Total time for which application threads were stopped: 0.0002260 seconds, Stopping threads took: 0.0001000 seconds

1965.542: Total time for which application threads were stopped: 0.0005650 seconds, Stopping threads took: 0.0000980 seconds

1965.543: Total time for which application threads were stopped: 0.0001830 seconds, Stopping threads took: 0.0000390 seconds
1965.543: Total time for which application threads were stopped: 0.0001490 seconds, Stopping threads took: 0.0000330 seconds
1965.982: Total time for which application threads were stopped: 0.0009440 seconds, Stopping threads took: 0.0002110 seconds
1966.980: [GC1966.980: [ParNew: 153344K->12250K(153344K), 0.0563550 secs]  450309K->319369K(1031552K) icms_dc=0 , 0.0566880 secs]  [Times: user=0.10 sys=0.00, real=0.06 secs] 

1967.037: Total time for which application threads were stopped: 0.0574450 seconds, Stopping threads took: 0.0001050 seconds

1968.223: Total time for which application threads were stopped: 0.0009580 seconds, Stopping threads took: 0.0001130 seconds
1969.440: Total time for which application threads were stopped: 0.0254140 seconds, Stopping threads took: 0.0001590 seconds

1969.739: [GC1969.739: [ParNew: 148570K->17024K(153344K), 0.0477680 secs] 455689K->325515K(1031552K) icms_dc=0 , 0.0480340 secs] [Times: user=0.08 sys=0.01, real=0.05 secs] 

1969.787: Total time for which application threads were stopped: 0.0486130 seconds, Stopping threads took: 0.0001010 seconds
1970.248: Total time for which application threads were stopped: 0.0009970 seconds, Stopping threads took: 0.0000950 seconds
1972.314: Total time for which application threads were stopped: 0.0010300 seconds, Stopping threads took: 0.0001030 seconds

1972.813: [GC1972.813: [ParNew: 153344K->12761K(153344K), 0.0256370 secs] 461835K->323410K(1031552K) icms_dc=0 , 0.0259140 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 

1972.839: Total time for which application threads were stopped: 0.0265610 seconds, Stopping threads took: 0.0001230 seconds
1974.313: Total time for which application threads were stopped: 0.0234590 seconds, Stopping threads took: 0.0000960 seconds

1975.468: [GC1975.468: [ParNew: 149081K->17024K(153344K), 0.0435810 secs] 459730K->327707K(1031552K) icms_dc=0 , 0.0438540 secs] [Times: user=0.09 sys=0.00, real=0.04 secs] 

1975.512: Total time for which application threads were stopped: 0.0446000 seconds, Stopping threads took: 0.0000960 seconds
1976.017: Total time for which application threads were stopped: 0.0010350 seconds, Stopping threads took: 0.0001010 seconds
1977.449: Total time for which application threads were stopped: 0.0227850 seconds, Stopping threads took: 0.0004530 seconds

1978.374: [GC1978.374: [ParNew: 153344K->17024K(153344K), 0.0481180 secs] 464027K->328081K(1031552K) icms_dc=0 , 0.0484080 secs] [Times: user=0.09 sys=0.00, real=0.05 secs] 

1978.422: Total time for which application threads were stopped: 0.0491500 seconds, Stopping threads took: 0.0001130 seconds

1980.018: Total time for which application threads were stopped: 0.0250790 seconds, Stopping threads took: 0.0000930 seconds

1981.036: [GC1981.036: [ParNew: 153344K->17024K(153344K), 0.0477460 secs] 464401K->329107K(1031552K) icms_dc=0 , 0.0480190 secs] [Times: user=0.09 sys=0.00, real=0.04 secs] 

1981.084: Total time for which application threads were stopped: 0.0487950 seconds, Stopping threads took: 0.0001380 seconds

1983.442: Total time for which application threads were stopped: 0.0215340 seconds, Stopping threads took: 0.0001980 seconds
1983.532: Total time for which application threads were stopped: 0.0009750 seconds, Stopping threads took: 0.0001160 seconds
1983.953: [GC1983.953: [ParNew: 153344K->17024K(153344K), 0.0878980 secs] 465427K->329737K(1031552K) icms_dc=0 , 0.0882080 secs] [Times: user=0.09 sys=0.00, real=0.09 secs] 

1984.041: Total time for which application threads were stopped: 0.0889640 seconds, Stopping threads took: 0.0001000 seconds

1984.624: Total time for which application threads were stopped: 0.0007510 seconds, Stopping threads took: 0.0001560 seconds
1985.000: Total time for which application threads were stopped: 0.0007720 seconds, Stopping threads took: 0.0000730 seconds
1985.906: Total time for which application threads were stopped: 0.0010110 seconds, Stopping threads took: 0.0001240 seconds

1987.265: [GC1987.265: [ParNew: 153344K->14785K(153344K), 0.0414370 secs] 466057K->327643K(1031552K) icms_dc=0 , 0.0417400 secs] [Times: user=0.04 sys=0.00, real=0.04 secs] 

1987.307: Total time for which application threads were stopped: 0.0424830 seconds, Stopping threads took: 0.0000950 seconds
1987.453: Total time for which application threads were stopped: 0.0007550 seconds, Stopping threads took: 0.0000650 seconds
1988.956: Total time for which application threads were stopped: 0.0011020 seconds, Stopping threads took: 0.0001060 seconds
1989.146: Total time for which application threads were stopped: 0.0265930 seconds, Stopping threads took: 0.0000940 seconds
1990.111: [GC1990.111: [ParNew: 151105K->17024K(153344K), 0.0844250 secs] 463963K->330057K(1031552K) icms_dc=0 , 0.0847360 secs] [Times: user=0.08 sys=0.00, real=0.08 secs] 

1990.196: Total time for which application threads were stopped: 0.0856010 seconds, Stopping threads took: 0.0001250 seconds

1990.463: Total time for which application threads were stopped: 0.0004750 seconds, Stopping threads took: 0.0001210 seconds
1991.458: Total time for which application threads were stopped: 0.0009900 seconds, Stopping threads took: 0.0000670 seconds
1993.304: [GC1993.304: [ParNew: 153344K->12580K(153344K), 0.0330520 secs] 466377K->325743K(1031552K) icms_dc=0 , 0.0333350 secs] [Times: user=0.04 sys=0.00, real=0.03 secs] 

1993.337: Total time for which application threads were stopped: 0.0341580 seconds, Stopping threads took: 0.0001670 seconds
1993.420: Total time for which application threads were stopped: 0.0229950 seconds, Stopping threads took: 0.0001300 seconds

1996.200: [GC1996.201: [ParNew: 148900K->17024K(153344K), 0.0502420 secs] 462063K->330222K(1031552K) icms_dc=0 , 0.0505590 secs] [Times: user=0.09 sys=0.00, real=0.05 secs] 

1996.251: Total time for which application threads were stopped: 0.0513140 seconds, Stopping threads took: 0.0001070 seconds
1997.334: Total time for which application threads were stopped: 0.0009640 seconds, Stopping threads took: 0.0000770 seconds
1999.319: Total time for which application threads were stopped: 0.0257960 seconds, Stopping threads took: 0.0000830 seconds
1999.386: [GC1999.386: [ParNew: 153344K->13204K(153344K), 0.0347240 secs] 466542K->326436K(1031552K) icms_dc=0 , 0.0350030 secs] [Times: user=0.07 sys=0.00, real=0.04 secs] 
1999.421: Total time for which application threads were stopped: 0.0356910 seconds, Stopping threads took: 0.0001360 seconds
2002.039: Total time for which application threads were stopped: 0.0009860 seconds, Stopping threads took: 0.0001110 seconds
2002.211: [GC2002.211: [ParNew: 149524K->10931K(153344K), 0.0236810 secs] 462756K->324176K(1031552K) icms_dc=0 , 0.0239590 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 

2002.235: Total time for which application threads were stopped: 0.0245110 seconds, Stopping threads took: 0.0000930 seconds
2003.379: Total time for which application threads were stopped: 0.0221890 seconds, Stopping threads took: 0.0001030 seconds
2005.031: [GC2005.031: [ParNew: 147251K->17023K(153344K), 0.0407460 secs] 460496K->330302K(1031552K) icms_dc=0 , 0.0410350 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 

2005.072: Total time for which application threads were stopped: 0.0419870 seconds, Stopping threads took: 0.0002260 seconds
2007.878: [GC2007.879: [ParNew: 153343K->11785K(153344K), 0.0952470 secs] 466622K->334421K(1031552K) icms_dc=0 , 0.0955490 secs] [Times: user=0.10 sys=0.00, real=0.10 secs] 

2007.974: Total time for which application threads were stopped: 0.0963630 seconds, Stopping threads took: 0.0001530 seconds
2010.508: Total time for which application threads were stopped: 0.0009220 seconds, Stopping threads took: 0.0000710 seconds
2011.075: [GC2011.076: [ParNew: 148102K->10294K(153344K), 0.0239530 secs] 470738K->332930K(1031552K) icms_dc=0 , 0.0242770 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 

2011.100: Total time for which application threads were stopped: 0.0251870 seconds, Stopping threads took: 0.0001170 seconds

2011.887: Total time for which application threads were stopped: 0.0009950 seconds, Stopping threads took: 0.0001360 seconds
2013.227: Total time for which application threads were stopped: 0.0009640 seconds, Stopping threads took: 0.0001000 seconds
2014.255: [GC2014.255: [ParNew: 146609K->10476K(153344K), 0.0253220 secs] 469245K->333112K(1031552K) icms_dc=0 , 0.0256140 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 

2014.281: Total time for which application threads were stopped: 0.0263760 seconds, Stopping threads took: 0.0001050 seconds
2015.066: Total time for which application threads were stopped: 0.0281610 seconds, Stopping threads took: 0.0001050 seconds
2015.568: Total time for which application threads were stopped: 0.0010850 seconds, Stopping threads took: 0.0001290 seconds

2017.248: [GC2017.248: [ParNew: 146792K->17024K(153344K), 0.0466400 secs] 469428K->339857K(1031552K) icms_dc=0 , 0.0469230 secs] [Times: user=0.09 sys=0.00, real=0.05 secs] 

2017.295: Total time for which application threads were stopped: 0.0477890 seconds, Stopping threads took: 0.0002280 seconds
2018.143: Total time for which application threads were stopped: 0.0010350 seconds, Stopping threads took: 0.0000990 seconds
2020.387: [GC2020.387: [ParNew: 153344K->13904K(153344K), 0.0269430 secs] 476177K->339014K(1031552K) icms_dc=0 , 0.0272200 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]

2020.414: Total time for which application threads were stopped: 0.0279890 seconds, Stopping threads took: 0.0001190 seconds

2020.737: Total time for which application threads were stopped: 0.0217700 seconds, Stopping threads took: 0.0001320 seconds
2021.639: Total time for which application threads were stopped: 0.0011000 seconds, Stopping threads took: 0.0001110 seconds
2022.909: [GC2022.909: [ParNew: 150224K->7208K(153344K), 0.0222110 secs] 475334K->332318K(1031552K) icms_dc=0 , 0.0224940 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 

2022.932: Total time for which application threads were stopped: 0.0233040 seconds, Stopping threads took: 0.0001090 seconds
2025.210: Total time for which application threads were stopped: 0.0282050 seconds, Stopping threads took: 0.0000990 seconds
2025.324: [GC2025.324: [ParNew: 143528K->15460K(153344K), 0.0496190 secs] 468638K->340570K(1031552K) icms_dc=0 , 0.0500120 secs] [Times: user=0.08 sys=0.00, real=0.05 secs] 

2025.374: Total time for which application threads were stopped: 0.0556920 seconds, Stopping threads took: 0.0051480 seconds
2028.418: Total time for which application threads were stopped: 0.0010870 seconds, Stopping threads took: 0.0001000 seconds

2028.422: [GC2028.422: [ParNew: 151780K->12272K(153344K), 0.0614850 secs] 476890K->347074K(1031552K) icms_dc=0 , 0.0617760 secs] [Times: user=0.11 sys=0.01, real=0.07 secs] 

2028.484: Total time for which application threads were stopped: 0.0622880 seconds, Stopping threads took: 0.0000890 seconds
2029.400: Total time for which application threads were stopped: 0.0006520 seconds, Stopping threads took: 0.0001050 seconds
2029.897: Total time for which application threads were stopped: 0.0008070 seconds, Stopping threads took: 0.0000980 seconds

2030.668: Total time for which application threads were stopped: 0.0221630 seconds, Stopping threads took: 0.0000940 seconds

2030.957: [GC2030.957: [ParNew: 148592K->17024K(153344K), 0.0447140 secs] 483394K->352150K(1031552K) icms_dc=0 , 0.0450230 secs] [Times: user=0.08 sys=0.01, real=0.04 secs] 

2031.002: Total time for which application threads were stopped: 0.0456290 seconds, Stopping threads took: 0.0000990 seconds
2031.005: Total time for which application threads were stopped: 0.0008820 seconds, Stopping threads took: 0.0001030 seconds
2032.007: Total time for which application threads were stopped: 0.0010870 seconds, Stopping threads took: 0.0001060 seconds

2033.007: Total time for which application threads were stopped: 0.0010490 seconds, Stopping threads took: 0.0001100 seconds

2033.212: Total time for which application threads were stopped: 0.0228570 seconds, Stopping threads took: 0.0000990 seconds

2033.670: [GC2033.670: [ParNew: 153344K->17024K(153344K), 0.0483170 secs] 488470K->354977K(1031552K) icms_dc=0 , 0.0485860 secs] [Times: user=0.09 sys=0.00, real=0.05 secs]

【问题讨论】：

    标签： apache garbage-collection jvm tomcat7 jvm-arguments


    【解决方案1】：

    1) 我们是否应该担心这些非常频繁的应用程序线程由于 ParNew 每秒而暂停。

    没有。似乎只有一小部分时间花在了他们身上。

    我们尝试对应用程序运行负载测试，发现应用程序在 1014 个并发线程上停止工作。

    考虑改用 NIO 连接器，它可以同时服务的请求数不受线程数的限制。

    【讨论】：

    • 在 server.xml 中切换回默认的 http1.1 之前，我们尝试了 NIO 协议。但这没有帮助。事实上，NIO 协议的 1014 线程计数非常频繁地达到，这开始引发错误“OOM：无法创建本机线程”。所以我们切换回默认协议。但是在这种情况下，由于对 Maxthread 和 MaxClient 设置了限制，线程数永远不会达到 1014，但是如果我们不限制 maxclient 或设置更高，一旦计数达到 1014，apache 就会立即下降。
    • ..... 所以如果 NIO 协议具有更高的 MaxClient ，它会开始抛出 OOM:Unable to create Native Threads。但是如果默认使用 hight max 客户端，apache 会在线程超过 1014 时停止响应。
    猜你喜欢
    • 2016-06-28
    • 2018-07-23
    • 2016-06-02
    • 1970-01-01
    • 2013-03-03
    • 1970-01-01
    • 2010-11-30
    • 1970-01-01
    • 1970-01-01
    相关资源
    最近更新 更多
    热门标签
    Java Python linux javascript Mysql C# Docker 算法 前端 SpringBoot Redis Vue spring 设计模式 .net core .net kubernetes c++ 数据库 数据结构 大数据 js 机器学习 微服务 Android Go 程序员 面试 JVM ASP.net core 云原生 人工智能 后端 PHP git CSS golang k8s Nginx Django mybatis 深度学习 多线程 React 架构 devops 爬虫 云计算 Spring Boot LeetCode