JVM参数调整，GC优化

最新推荐文章于 2022-03-14 08:00:00 发布

weixin_34194087

最新推荐文章于 2022-03-14 08:00:00 发布

阅读量159

点赞数

文章标签： python java 数据库

原文链接：https://my.oschina.net/dreamnight/blog/716134

版权

2019独角兽企业重金招聘Python工程师标准>>>

线上有一个老的web服务，最近发现一个调用它的业务会出现响应超时的情况，频繁而且有规律，一小时出现一次平均响应尖峰，打印出详细日志就是请求超时了：

数据库超时？定时任务导致系统规律变慢？网络通路有规律的异常？在代码里打印耗时log，打印出access的日志，统计后都没有发现有系统响应特别慢的情况存在，最后定位到可能是gc导致的，由于项目太老，启动的JVM参数上没有配置gc日志的输出，增加gc日志输出参数：

-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/export/gc/gc.log

发现确实有规律的Full gc存在，每隔3600S就有一次Full GC，还是(System)的，怀疑系统里面有主动调用System.gc()的地方，没有找到：

0.561: [Full GC (System) 0.561: [CMS: 0K->1740K(16500352K), 0.0927660 secs] 17745K->1740K(16749568K), [CMS Perm : 11956K->11947K(262144K)], 0.0928480 secs] [Times: user=0.04 sys=0.06, real=0.10 secs] 
3600.657: [Full GC (System) 3600.658: [CMS: 2830102K->1202714K(16500352K), 4.9004880 secs] 2855816K->1202714K(16749568K), [CMS Perm : 52754K->52616K(262144K)], 4.9016860 secs] [Times: user=4.99 sys=0.00, real=4.91 secs] 
7205.563: [Full GC (System) 7205.564: [CMS: 2515330K->1257751K(16500352K), 5.7146790 secs] 2715949K->1257751K(16749568K), [CMS Perm : 52844K->52774K(262144K)], 5.7160190 secs] [Times: user=5.82 sys=0.00, real=5.71 secs] 
10811.283: [Full GC (System) 10811.284: [CMS: 2455380K->1278743K(16500352K), 5.7382590 secs] 2627947K->1278743K(16749568K), [CMS Perm : 53073K->53007K(262144K)], 5.7396370 secs] [Times: user=5.85 sys=0.00, real=5.74 secs]

最后确认是因为tomcat导致的，这个老的系统使用的apache-tomcat-6.0.29，server.xml有一段配置，这个listener每隔3600S会调用一次system.gc：

<Listener className="org.apache.catalina.core.JreMemoryLeakPreventionListener" />

继续调整JVM参数：

//不允许显式地调用GC
-XX:+DisableExplicitGC

//如今,被广泛接受的最佳实践是避免显式地调用GC(所谓的“系统GC”)，即在应用程序中调用system.gc()。
//然而，这个建议是不管使用的GC算法的，值得一提的是，当使用CMS收集器时，系统GC将是一件很不幸的事，
//因为它默认会触发一次Full GC。幸运的是，有一种方式可以改变默认设置。
//标志-XX:+ExplicitGCInvokesConcurrent命令JVM无论什么时候调用系统GC，都执行CMS GC，而不是Full GC。
//第二个标志-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses保证当有系统GC调用时，
//永久代也被包括进CMS垃圾回收的范围内。因此，通过使用这些标志，我们可以防止出现意料之外的”stop-the-world”的系统GC。
-XX:+ExplicitGCInvokesConcurrent
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses

由于堆内存设置较大，出现Full gc可能需要运行较长时间，观察一个晚上，发生了一次：

21256.872: [GC [1 CMS-initial-mark: 6295066K(12582912K)] 6519946K(16357824K), 1.1740300 secs] [Times: user=0.15 sys=1.01, real=1.17 secs] 
21258.048: [CMS-concurrent-mark-start]
21259.620: [CMS-concurrent-mark: 1.572/1.572 secs] [Times: user=5.33 sys=0.91, real=1.57 secs] 
21259.621: [CMS-concurrent-preclean-start]
21259.837: [CMS-concurrent-preclean: 0.214/0.216 secs] [Times: user=0.09 sys=0.14, real=0.22 secs] 
21259.838: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 21265.159: [CMS-concurrent-abortable-preclean: 5.307/5.321 secs] [Times: user=5.78 sys=0.05, real=5.31 secs] 
21265.162: [GC[YG occupancy: 403045 K (3774912 K)]21265.162: [Rescan (parallel) , 0.0376370 secs]21265.200: [weak refs processing, 0.0005800 secs]21265.200: [class unloading, 0.0112830 secs]21265.212: [scrub symbol & string tables, 0.0047700 secs] [1 CMS-remark: 6295066K(12582912K)] 6698111K(16357824K), 0.0572150 secs] [Times: user=0.48 sys=0.00, real=0.05 secs] 
21265.222: [CMS-concurrent-sweep-start]
21274.320: [CMS-concurrent-sweep: 9.074/9.098 secs] [Times: user=10.10 sys=0.14, real=9.10 secs] 
21274.321: [CMS-concurrent-reset-start]
21276.271: [CMS-concurrent-reset: 1.935/1.950 secs] [Times: user=0.14 sys=2.08, real=1.95 secs]

再看响应时间统计图，做cms gc时也出现了一个小峰值，有stop-the-world的影响，但是平均响应时间的峰值也不到前面峰值的十分之一了，停顿时间减小：