記一次線上gc調優的過程
近期公司運營同學經常表示線上我們一個後臺管理系統運行特別慢，而且經常出現504超時的情況。對於這種情況我們本能的認為可能是代碼有性能問題，可能有死循環或者是數據庫調用次數過多導致接口運行過慢。應領導要求，我們將主站中進行性能測試的框架代碼（見我前面一篇博文記錄一次通過性能日誌處理線上性能問題的過程）添加到了該後臺管理系統中。上線運行一段時間後，查看相關日誌可以看到如下分析日誌：
通過該日誌可以發現，dao方法一直獲取不到數據庫鏈接池，但是根據實際情況考慮應該不大可能，原因有兩點：
- 主站和後臺管理系統使用的是同一套數據庫，相較而言，主站的訪問量更高，數據量也更大，卻沒有出現問題；
- 該性能問題的出現有一定的頻率，即有的時候出現，有的時候情況好一些；
雖然根據分析我們認為不大可能是數據庫問題，但我們還是查看了線上數據庫鏈接的相關情況，具體鏈接情況如下：
這個兩個是主要用到的兩個數據庫，而其他的數據庫鏈接相對來說鏈接數也不高，總鏈接數加起來遠遠沒有達到我們配置的最大鏈接數，並且在processlist中也沒有發現什麽耗時比較高的鏈接。因而確實證實了出現的性能問題不是數據庫導致的。
既然不是數據庫導致的，通過性能日誌也可以確認不是代碼中有死循環或者數據庫調用次數過多的問題，我們就思考是否為jvm層面的問題。在登錄線上機器之後，我們使用首先使用top命令查看了該機器進程的運行情況：
可以看到，id為2580的進程cpu一直在100%以上，然後使用如下命令查看該進程中具體是哪個線程運行的cpu如此之高：
top -Hp 2580結果如下：
可以看到，id為2598的線程運行cpu達到了97.7%，基本上可以確定是這個線程的運行導致項目整體運行較慢。接下來我們使用jstack命令查看了該進行各個線程運行情況，具體的命令如下：
jstack 2580 > ~/jstack.log這裏有兩點需要註意：
- jstack命令需要在jdk的bin目錄下執行，並且必須要以當前啟動項目tomcat的用戶身份運行，如果不是該用戶登錄的，可以使用如下命令導出線程運行日誌：
sudo -u admin ~/jdk/bin/jstack 2580 > ~/jstack.log- 在線程日誌中，線程的id是使用十六進制的方式打印的，而在top -Hp命令中線程的id是10進制打印的，因而我們需要得到2598這個數字對應的16進制值，命令如下：
[admin@aws-99 bin]$ printf "%x\n" 2598
a26在導出的jstack.log中我們找到了該線程的運行情況，結果如下：
"main" #1 prio=5 os_prio=0 tid=0x00007f25bc00a000 nid=0xa15 runnable [0x00007f25c3fe6000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
at java.net.ServerSocket.implAccept(ServerSocket.java:545)
at java.net.ServerSocket.accept(ServerSocket.java:513)
at org.apache.catalina.core.StandardServer.await(StandardServer.java:446)
at org.apache.catalina.startup.Catalina.await(Catalina.java:713)
at org.apache.catalina.startup.Catalina.start(Catalina.java:659)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:351)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:485)
"VM Thread" os_prio=0 tid=0x00007f25bc120800 nid=0xa26 runnable
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f25bc01b000 nid=0xa16 runnable
"Gang worker#1 (Parallel GC Threads)" os_prio=0 tid=0x00007f25bc01d000 nid=0xa17 runnable
"Gang worker#2 (Parallel GC Threads)" os_prio=0 tid=0x00007f25bc01e800 nid=0xa18 runnable
"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f25bc020800 nid=0xa19 runnable
"Gang worker#4 (Parallel GC Threads)" os_prio=0 tid=0x00007f25bc022800 nid=0xa1a runnable
"Gang worker#5 (Parallel GC Threads)" os_prio=0 tid=0x00007f25bc024000 nid=0xa1b runnable可以看到，下方的"VM Thread"就是該cpu消耗較高的線程，查看相關文檔我們得知，VM Thread是JVM層面的一個線程，主要工作是對其他線程的創建，分配和對象的清理等工作的。從後面幾個線程也可以看出，JVM正在進行大量的GC工作。這裏的原因已經比較明顯了，即大量的GC工作導致項目運行緩慢。那麽具體是什麽原因導致這麽多的GC工作呢，我們使用了jstat命令查看了內存使用情況：
[admin@aws-99 bin]$ jstat -gcutil 2580 1000 5
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 98.07 100.00 100.00 96.04 92.74 2587 98.216 17803 25642.557 25740.773
0.00 100.00 100.00 100.00 96.04 92.74 2587 98.216 17804 25644.777 25742.993
0.00 100.00 100.00 100.00 96.04 92.74 2587 98.216 17804 25644.777 25742.993
0.00 91.59 100.00 100.00 96.04 92.74 2587 98.216 17805 25646.981 25745.197
0.00 100.00 100.00 100.00 96.04 92.74 2587 98.216 17806 25647.339 25745.555可以看到Suvivor space1、Eden Space和Old Space等內存使用情況幾乎都達到了100%，並且Young GC和Full GC運行時間和次數也非常高。接著我們使用了jmap查看了內存中創建的對象情況，結果如下：
[admin@aws-99 bin]$ jmap -histo 2580
num #instances #bytes class name
----------------------------------------------
1: 3658294 324799888 [C
2: 6383293 153199032 java.util.LinkedList$Node
3: 6369472 152867328 java.lang.Long
4: 6368531 152844744 com.homethy.lead.sites.util.SiteContextUtil$Node
5: 3631391 87153384 java.lang.String
6: 28357 30078512 [B
7: 135622 13019712 java.util.jar.JarFile$JarFileEntry
8: 132602 11668976 java.lang.reflect.Method
9: 224247 7175904 java.util.HashMap$Node
10: 46394 5601504 [Ljava.util.HashMap$Node;
11: 145769 4664608 java.util.concurrent.ConcurrentHashMap$Node
12: 81843 3273720 java.util.LinkedHashMap$Entry
13: 57903 3209512 [Ljava.lang.Object;
14: 56976 3190656 java.util.LinkedHashMap
15: 20857 2446960 java.lang.Class
16: 45890 2202720 org.aspectj.weaver.reflect.ShadowMatchImpl可以看到，SiteContextUtil類中的Node對象創建數量非常高，而LinkedList.Node和java.lang.Long的對象數量和SiteContextUtil.Node的數量幾乎一致，結合具體的業務情況我們知道SiteContextUtil.Node對象是放在LinkedList.Node中的，因而可以確認就是SiteContextUtil.Node的數量較高，創建頻率較快導致jvm進行了大量的gc工作，最終導致工程性能降低。
記一次線上gc調優的過程