Gc日誌引數

通過在tomcat啟動指令碼中新增相關引數生成gc日誌

-verbose.gc開關可顯示GC的操作內容。開啟它，可以顯示最忙和最空閒收集行為發生的時間、收集前後的記憶體大小、收集需要的時間等。

開啟-xx:+ printGCdetails開關，可以詳細瞭解GC中的變化。

開啟-XX: + PrintGCTimeStamps開關，可以瞭解這些垃圾收集發生的時間，自JVM啟動以後以秒計量。

最後，通過-xx: + PrintHeapAtGC開關了解堆的更詳細的資訊。

為了瞭解新域的情況，可以通過-XX:=PrintTenuringDistribution開關了解獲得使用期的物件權。

-Xloggc:$CATALINA_BASE/logs/gc.log gc日誌產生的路徑

XX:+PrintGCApplicationStoppedTime // 輸出GC造成應用暫停的時間

-XX:+PrintGCDateStamps // GC發生的時間資訊

Gc日誌

日誌中顯示了gc發生的時間，young區回收情況，整體回收情況，fullGC情況，回收所消耗時間等

常用JVM引數

分析gc日誌後，經常需要調整jvm記憶體相關引數，常用引數如下

-Xms：初始堆大小，預設為實體記憶體的1/64(<1GB)；預設(MinHeapFreeRatio引數可以調整)空餘堆記憶體小於40%時，JVM就會增大堆直到-Xmx的最大限制

-Xmx：最大堆大小，預設(MaxHeapFreeRatio引數可以調整)空餘堆記憶體大於70%時，JVM會減少堆直到 -Xms的最小限制

-Xmn：新生代的記憶體空間大小，注意：此處的大小是（eden+ 2 survivor space)。與jmap -heap中顯示的New gen是不同的。整個堆大小=新生代大小 + 老生代大小 + 永久代大小。 
在保證堆大小不變的情況下，增大新生代後,將會減小老生代大小。此值對系統性能影響較大,Sun官方推薦配置為整個堆的3/8。

-XX:SurvivorRatio：新生代中Eden區域與Survivor區域的容量比值，預設值為8。兩個Survivor區與一個Eden區的比值為2:8,一個Survivor區佔整個年輕代的1/10。

-Xss：每個執行緒的堆疊大小。JDK5.0以後每個執行緒堆疊大小為1M,以前每個執行緒堆疊大小為256K。應根據應用的執行緒所需記憶體大小進行適當調整。在相同實體記憶體下,減小這個值能生成更多的執行緒。但是作業系統對一個程序內的執行緒數還是有限制的，不能無限生成，經驗值在3000~5000左右。一般小的應用， 如果棧不是很深， 應該是128k夠用的，大的應用建議使用256k。這個選項對效能影響比較大，需要嚴格的測試。和threadstacksize選項解釋很類似,官方文件似乎沒有解釋,在論壇中有這樣一句話:"-Xss is translated in a VM flag named ThreadStackSize”一般設定這個值就可以了。

-XX:PermSize：設定永久代(perm gen)初始值。預設值為實體記憶體的1/64。

-XX:MaxPermSize：設定持久代最大值。實體記憶體的1/4。

Gc日誌分析工具

(1)GCHisto

直接點選gchisto.jar就可以執行，點add載入gc.log

統計了總共gc次數，youngGC次數，FullGC次數，次數的百分比，GC消耗的時間，百分比，平均消耗時間，消耗時間最小最大值等

 整個過程gc情況的趨勢圖，還顯示了gc型別，吞吐量，平均gc頻率，記憶體變化趨勢等

Tools裡還能比較不同gc日誌

(3)HPjmeter

工具很強大，但只能開啟由以下引數生成的GC log， -verbose:gc -Xloggc:gc.log,新增其他引數生成的gc.log無法開啟。

(4)GCViewer

http://www.tagtraum.com/gcviewer.html

這個工具用的挺多的，但只能在JDK1.5以下的版本中執行，1.6以後沒有對應。

(5)garbagecat

其它監控方法

Jvisualvm動態分析jvm記憶體情況和gc情況，外掛：visualGC

jvisualvm還可以heapdump出對應hprof檔案（預設存放路徑：監控的伺服器 /tmp下），利用相關工具，比如HPjmeter可以對其進行分析

grep Full gc.log粗略觀察FullGC發生頻率

jstat –gcutil [pid] [intervel] [count]

jmap -histo pid可以觀測物件的個數和佔用空間
jmap -heap pid可以觀測jvm配置引數，堆記憶體各區使用情況

jprofiler,jmap dump出來用MAT分析

如果要分析的dump檔案很大的話，就需要很多記憶體，很容易crash。

所以在啟動時，我們應該加上一些引數： Java –Xms512M –Xmx1024M –Xss8M 

GC Analyzer

Analysis of VerboseGC Traces

http://glezen.org/gca/index.html

支援JDK 1.4.2

支援命令列和介面

PrintGCStats

GC日誌分析指令碼

http://chenjianjx.iteye.com/blog/1681347

參考：
http://blog.csdn.net/gzh0222/article/details/8223277

---------------------------------------------------

1.原始GC日誌（通過JVM配置GC Print引數獲取GC日誌）

...

695.775: [GC 695.776: [ParNew: 130944K->0K(131008K), 0.0174100 secs] 432961K->302710K(786368K), 0.0175930 secs]
697.323: [GC [1 CMS-initial-mark: 302710K(655360K)] 348624K(786368K), 0.1140530 secs]
697.438: [CMS-concurrent-mark-start]
699.494: [GC 699.494: [ParNew: 130944K->0K(131008K), 0.0115290 secs] 433654K->303891K(786368K), 0.0116990 secs]
701.381: [CMS-concurrent-mark: 1.204/3.944 secs]
701.381: [CMS-concurrent-preclean-start]
701.382: [CMS-concurrent-preclean: 0.000/0.000 secs]
701.420: [CMS-concurrent-abortable-preclean-start]
701.420: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
703.302: [GC 703.302: [ParNew: 130944K->0K(131008K), 0.0161480 secs] 434835K->305889K(786368K), 0.0163490 secs]
705.202: [GC[YG occupancy: 68582 K (131008 K)]705.202: [Rescan (parallel) , 0.1094800 secs]705.312: [weak refs processing, 0.0446420 secs] [1 CMS-remark: 305889K(655360K)] 374472K(786368K), 0.1543650 secs]
705.360: [CMS-concurrent-sweep-start]
705.644: [CMS-concurrent-sweep: 0.284/0.284 secs]
705.644: [CMS-concurrent-reset-start]
705.654: [CMS-concurrent-reset: 0.010/0.010 secs]
706.985: [GC 706.985: [ParNew: 130924K->0K(131008K), 0.0193060 secs] 432106K->302870K(786368K), 0.0195480 secs]
708.540: [GC [1 CMS-initial-mark: 302870K(655360K)] 350092K(786368K), 0.1140590 secs]
708.654: [CMS-concurrent-mark-start]
710.647: [GC 710.647: [ParNew: 130944K->0K(131008K), 0.0081390 secs] 433814K->303960K(786368K), 0.0083430 secs]
712.560: [CMS-concurrent-mark: 1.314/3.906 secs]
712.560: [CMS-concurrent-preclean-start]
712.560: [CMS-concurrent-preclean: 0.000/0.000 secs]
712.615: [CMS-concurrent-abortable-preclean-start]
712.615: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
713.567: [GC 713.567: [ParNew: 130944K->0K(131008K), 0.0104890 secs] 434904K->305163K(786368K), 0.0107090 secs]
715.109: [GC[YG occupancy: 68948 K (131008 K)]715.109: [Rescan (parallel) , 0.0884690 secs]715.198: [weak refs processing, 0.0441790 secs] [1 CMS-remark: 305163K(655360K)] 374111K(786368K), 0.1329350 secs]
715.243: [CMS-concurrent-sweep-start]
715.445: [CMS-concurrent-sweep: 0.203/0.203 secs]
715.445: [CMS-concurrent-reset-start]
715.454: [CMS-concurrent-reset: 0.009/0.009 secs]

...

2.日誌分析報告

針對原始GC日誌，分別用下面兩種工具做了分析，其中gcviewer分析還是比較具體的，就是解析日誌時會有些異常，但不影響最後的結果。

（1）通過gcviewer分析：

圖1（頂部的黑色線都代表Full GC，也可以理解為Major GC，是根據日誌中的CMS GC統計的；底部灰色線代表的是Minor GC）

圖2

圖3

可以看到Full GC非常多，佔所有pause時間比達到65.9%，這是有問題的，GC應該儘可能在年輕代完成，而不是到年老代，這個在第3部分引數說明中會提到。

========================================
SUMMARY:
========================================
# GC Events: 172925
GC Event Types: CMS_INITIAL_MARK, CMS_CONCURRENT, CMS_SERIAL_OLD_CONCURRENT_MODE_FAILURE, PAR_NEW, CMS_REMARK
Max Heap Space: 1079084K
Max Heap Occupancy: 716725K
Max Perm Space: 98304K
Max Perm Occupancy: 8993K
Throughput: 97%
Max Pause: 426 ms
Total Pause: 9033244 ms
First Timestamp: 250 ms
Last Timestamp: 342994691 ms

從這裡主要看pause time時間，分析報告中還有一部分不能處理的，這些日誌現在還沒找到最終原因：

========================================
30 UNIDENTIFIED LOG LINE(S):
========================================
39629.723: [Full GC 39629.723: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor6720]
40724.189: [Full GC 40724.189: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor1945]
40785.929: [Full GC 40785.929: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor10169]
40922.428: [Full GC 40922.428: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor10175]
124477.019: [Full GC 124477.019: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor33989]
124997.427: [Full GC 124997.427: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34622]
125059.257: [Full GC 125059.257: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34638]
125348.006: [Full GC 125348.006: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34644]
125940.674: [Full GC 125940.674: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor2017]
126047.093: [Full GC 126047.093: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor5743]
128938.724: [Full GC 128938.724: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor5715]
209586.704: [Full GC 209586.704: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58696]
210272.871: [Full GC 210272.872: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedMethodAccessor5749]
211428.317: [Full GC 211428.318: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor7545]
212198.995: [Full GC 212198.995: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedMethodAccessor5806]
212408.355: [Full GC 212408.355: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58795]
212525.304: [Full GC 212525.304: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58807]
212819.763: [Full GC 212819.763: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58817]
212881.623: [Full GC 212881.623: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58821]
214567.777: [Full GC 214567.778: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor1643]
214980.856: [Full GC 214980.856: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58897]
215119.546: [Full GC 215119.546: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58903]
294794.469: [Full GC 294794.469: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81521]
298186.036: [Full GC 298186.036: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81595]
300171.660: [Full GC 300171.660: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81708]
300318.420: [Full GC 300318.420: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81738]
300380.550: [Full GC 300380.550: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81772]
300756.398: [Full GC 300756.398: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81744]
300818.348: [Full GC 300818.348: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81788]
301812.025: [Full GC 301812.025: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor10606]

3.問題根源（當前引數配置及說明，其中紅色標註的是設定不妥的地方）

 98％的java物件，在建立之後不久就變成了非活動物件；只有2％的物件，會在長時間一直處於活動狀態。major gc需要的時間比minor gc長的多，所以我們要減少major gc次數，提高minor gc的效率，儘量將非活動物件消滅在年輕代。

針對上述分析報告，從JVM當前引數配置中找到了些原因，如下：

-Xms768m -Xmx1280m  jvm堆的最小值和最大值設定，一般設成相同值，避免頻繁分配堆空間

-XX:NewSize=128m -XX:MaxNewSize=128m  年輕代最小值和最大值設定（年輕代設定了，年老代也就定了），也可以用引數-XX:NewRatio=4，年老代和年輕代的大小比，這裡128m有點小了，官方建議的是heap的3/8，差不多280m

-XX:PermSize=96m -XX:MaxPermSize=128m 持久代最小值和最大值設定

-XX:MaxTenuringThreshold=0  經過多少次minor gc 後進入年老代,設定為0的話直接進入年老代，這是不太合理的，正常應該在年輕代多呆一段時間，真正需要到年老代的才轉過去

-XX:SurvivorRatio=20000  年輕代中eden和一塊suvivor區的空間比例，這裡設定成20000有問題，suvivor區空間幾乎為0，一次minor gc後基本都轉到年老代了，年輕代沒有起到過濾左右

-XX:+UseParNewGC  年輕代採用並行gc策略，JDK5.0以上,JVM會根據系統配置自行設定,所以無需再設定此值。使用多執行緒收集，提高吞吐量（-XX:ParallelGCThreads 並行收集器的執行緒數，此值最好配置與處理器數目相等，如果超過當前cpu數，會加大機器負載）

-XX:+UseConcMarkSweepGC  年老代採用併發gc策略，和應用程式併發執行，減少pause time，但是需要更大的堆區，因為併發執行，有碎片（-XX:+UseParallelOldGC 年老代垃圾收集方式為並行收集，這個是JAVA 6出現的引數選項）

 -XX:+CMSPermGenSweepingEnabled  為了避免Perm區滿引起的full gc，建議開啟CMS回收Perm區選項

 -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps  列印gc日誌

 -XX:CMSInitiatingOccupancyFraction=1 年老代使用空間比達到這個值時開始cms gc,預設是在年老代佔滿68%的時候開始進行CMS收集，這裡設定成1是不合理的，會導致CMS GC頻繁發生，從gc日誌裡可以看出來，CMS GC和minor GC幾乎一樣多

 -XX:+CMSIncrementalMode 啟動i-CMS模式，增量模式，將cms gc過程分成6個階段，其中階段initial Mark和remark時需要pause，這6個階段在兩次minor gc的間隔期執行，具體執行起止時間由下面兩個引數決定。拆分成小階段增量執行時，可以避免應用被中斷時間過長，極端情況是如果只有一個cpu，那麼得等全部做完這6個階段才能釋放cpu，如果是多cpu這個模式開啟與否應該影響不大。

-XX:CMSIncrementalDutyCycleMin=10 預設值10 啟動CMS的下線

-XX:CMSIncrementalDutyCycle=30 預設值50 啟動CMS的上線

-XX:+UseCMSCompactAtFullCollection  在FULL GC的時候， 對年老代的壓縮。CMS是不會移動記憶體的， 因此這個非常容易產生碎片， 導致記憶體不夠用， 因此， 記憶體的壓縮這個時候就會被啟用。 可能會影響效能,但是可以消除碎片，增加這個引數是個好習慣。

-XX:CMSFullGCsBeforeCompaction=0  上面配置開啟的情況下,這裡設定多少次Full GC後,對年老代進行壓縮，這裡設定成0不知道什麼意思，可以根據線上full gc 的頻率確定，頻率高，這個值可以大點，比如5，反之頻率低，這個值可以小點，比如1

-XX:CMSMarkStackSize=8M

-XX:CMSMarkStackSizeMax=32M