记一次线上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工做，最终致使工程性能下降。