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