記一次線上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 space一、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工做，最終致使工程性能下降。