记一次线上gc调优的过程

原创
2018/01/27 09:44
阅读数 1.4W

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

       读者朋友如果觉得本文还不错,可以点击下面的广告链接,这可以为作者带来一定的收入,从而激励作者创作更好的文章,非常感谢!

在项目开发过程中,企业会有很多的任务、需求、缺陷等需要进行管理,CORNERSTONE 提供敏捷、任务、需求、缺陷、测试管理、WIKI、共享文件和日历等功能模块,帮助企业完成团队协作和敏捷开发中的项目管理需求;更有甘特图、看板、思维导图、燃尽图等多维度视图,帮助企业全面把控项目情况。

展开阅读全文
打赏
2
40 收藏
分享
加载中
666
2018/02/14 21:16
回复
举报
charming丶博主

引用来自“huihrt”的评论

那找出问题之后呢,代码怎么优化的呢

引用来自“爱宝贝丶”的评论

优化方案的话需要根据具体的业务场景进行优化。我们这里这个对象是进行一些日志统计时产生的对象,由于访问比较频繁,因而产生的日志比较多。为了维护服务的稳定,刚开始我们只是简单的将该日志统计功能关闭了。但由于缺少该功能,我们也就失去了该功能的统计数据。后来我们处理这个问题的基本思路是这样的:由于每次请求都会产生这个对象,请求完之后则会丢弃,而垃圾回收机制又不能及时回收该对象,因而解决办法就是请求完成之后不丢弃这个对象,这里需要说明的是这些对象是存储在一个LinkedList中的,因而我们只需要维护一个LinkedList的池,每次请求的时候都从该池中获取一个LinkedList(没有则创建),当请求完成之后将该LinkedList返还到该池中。通过这种方式来达到创建的对象复用的目的,当然这种方式中间还涉及到了一点数据的清理工作。

引用来自“huihrt”的评论

大概意思就是用池化的方式来避免重复创建LinkedList对象吧。不过像这种日志功能的实现的话,可以在内存中开辟一个合适大小的队列,然后异步地讲日志数据写入磁盘。或者如果访问很频繁的话,可以异步地讲日志消息投递给消息队列,然后在消费端慢慢消费就行了吧。
额,是可以,这样可以把处理过程与正常的业务逻辑抽离开来,不过我理解这种方式还是需要维护一个对象池吧,不然还是会创建过多的对象
2018/02/12 15:11
回复
举报

引用来自“huihrt”的评论

那找出问题之后呢,代码怎么优化的呢

引用来自“爱宝贝丶”的评论

优化方案的话需要根据具体的业务场景进行优化。我们这里这个对象是进行一些日志统计时产生的对象,由于访问比较频繁,因而产生的日志比较多。为了维护服务的稳定,刚开始我们只是简单的将该日志统计功能关闭了。但由于缺少该功能,我们也就失去了该功能的统计数据。后来我们处理这个问题的基本思路是这样的:由于每次请求都会产生这个对象,请求完之后则会丢弃,而垃圾回收机制又不能及时回收该对象,因而解决办法就是请求完成之后不丢弃这个对象,这里需要说明的是这些对象是存储在一个LinkedList中的,因而我们只需要维护一个LinkedList的池,每次请求的时候都从该池中获取一个LinkedList(没有则创建),当请求完成之后将该LinkedList返还到该池中。通过这种方式来达到创建的对象复用的目的,当然这种方式中间还涉及到了一点数据的清理工作。
大概意思就是用池化的方式来避免重复创建LinkedList对象吧。不过像这种日志功能的实现的话,可以在内存中开辟一个合适大小的队列,然后异步地讲日志数据写入磁盘。或者如果访问很频繁的话,可以异步地讲日志消息投递给消息队列,然后在消费端慢慢消费就行了吧。
2018/02/12 14:12
回复
举报
charming丶博主

引用来自“huihrt”的评论

那找出问题之后呢,代码怎么优化的呢
优化方案的话需要根据具体的业务场景进行优化。我们这里这个对象是进行一些日志统计时产生的对象,由于访问比较频繁,因而产生的日志比较多。为了维护服务的稳定,刚开始我们只是简单的将该日志统计功能关闭了。但由于缺少该功能,我们也就失去了该功能的统计数据。后来我们处理这个问题的基本思路是这样的:由于每次请求都会产生这个对象,请求完之后则会丢弃,而垃圾回收机制又不能及时回收该对象,因而解决办法就是请求完成之后不丢弃这个对象,这里需要说明的是这些对象是存储在一个LinkedList中的,因而我们只需要维护一个LinkedList的池,每次请求的时候都从该池中获取一个LinkedList(没有则创建),当请求完成之后将该LinkedList返还到该池中。通过这种方式来达到创建的对象复用的目的,当然这种方式中间还涉及到了一点数据的清理工作。
2018/02/12 14:00
回复
举报
那找出问题之后呢,代码怎么优化的呢
2018/02/12 10:36
回复
举报
厉害��,受教了
2018/01/29 16:37
回复
举报
厉害,学习了。
2018/01/29 13:04
回复
举报
厉害厉害,学习了
2018/01/27 14:46
回复
举报
更多评论
打赏
8 评论
40 收藏
2
分享
返回顶部
顶部