JVM參數調整，GC優化

線上有一個老的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的影響，可是平均響應時間的峯值也不到前面峯值的十分之一了，停頓時間減少：