现网性能问题分析

转载自https://my.oschina.net/zhangxufeng/blog/1613808

    近期公司运营同学经常表示线上我们一个后台管理系统运行特别慢，而且经常出现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
" 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工作，最终导致工程性能降低。