坏代码导致的性能问题大赏（CPU占用飙到了900%！） java后端性能优化

读过《重构 - 改善既有代码的设计》一书的同学们应该都很了解“代码的坏味道”。当然确定什么是代码“坏味道”是主观的，它会随语言、开发人员和开发方法的不同而不同。在工作当中，很多时候都是在维护之前的项目和在此基础上增加一些新功能，为了能让项目代码易于理解和维护，要时刻注意代码中的“坏味道”，当发现代码如果有坏味道了，要及时去重构它使其变成优秀的整洁的代码。今天我们要聊的是“坏味道的代码”给系统性能带来的影响，笔者会给大家展示几个案例，希望能对大家有所启发和帮助。

文章图片

FGC实战：坏代码导致服务频繁FGC无响应问题分析问题网络问题？
晚上七点多开始，我就开始不停地收到报警邮件，邮件显示探测的几个接口有超时情况。多数执行栈都在：

java.io.BufferedReader.readLine(BufferedReader.java:371) java.io.BufferedReader.readLine(BufferReader.java:389) java_io_BufferedReader$readLine.call(Unknown Source) com.domain.detect.http.HttpClient.getResponse(HttpClient.groovy:122) com.domain.detect.http.HttpClient.this$2$getResponse(HttpClient.groovy)

这个线程栈的报错我见得多了，我们设置的 HTTP DNS 超时是 1s， connect 超时是 2s， read 超时是 3s，这种报错都是探测服务正常发送了 HTTP 请求，服务器也在收到请求正常处理后正常响应了，但数据包在网络层层转发中丢失了，所以请求线程的执行栈会停留在获取接口响应的地方。这种情况的典型特征就是能在服务器上查找到对应的日志记录。而且日志会显示服务器响应完全正常。与它相对的还有线程栈停留在 Socket connect 处的，这是在建连时就失败了，服务端完全无感知。
我注意到其中一个接口报错更频繁一些，这个接口需要上传一个 4M 的文件到服务器，然后经过一连串的业务逻辑处理，再返回 2M 的文本数据，而其他的接口则是简单的业务逻辑，我猜测可能是需要上传下载的数据太多，所以超时导致丢包的概率也更大吧。
根据这个猜想，群登上服务器，使用请求的 request_id 在近期服务日志中搜索一下，果不其然，就是网络丢包问题导致的接口超时了。
当然这样 leader 是不会满意的，这个结论还得有人接锅才行。于是赶紧联系运维和网络组，向他们确认一下当时的网络状态。网络组同学回复说是我们探测服务所在机房的交换机老旧，存在未知的转发瓶颈，正在优化，这让我更放心了，于是在部门群里简单交待一下，算是完成任务。
问题爆发
【坏代码导致的性能问题大赏（CPU占用飙到了900%！）】本以为这次值班就起这么一个小波浪，结果在晚上八点多，各种接口的报警邮件蜂拥而至，打得准备收拾东西过周日单休的我措手不及。
这次几乎所有的接口都在超时，而我们那个大量网络 I/O 的接口则是每次探测必超时，难道是整个机房故障了么。
我再次通过服务器和监控看到各个接口的指标都很正常，自己测试了下接口也完全 OK，既然不影响线上服务，我准备先通过探测服务的接口把探测任务停掉再慢慢排查。
结果给暂停探测任务的接口发请求好久也没有响应，这时候我才知道没这么简单。
解决内存泄漏
于是赶快登陆探测服务器，首先是 top free df 三连，结果还真发现了些异常。

文章图片

我们的探测进程 CPU 占用率特别高，达到了 900%。
我们的 Java 进程，并不做大量 CPU 运算，正常情况下，CPU 应该在 100~200% 之间，出现这种 CPU 飙升的情况，要么走到了死循环，要么就是在做大量的 GC。
使用 jstat -gc pid [interval] 命令查看了 java 进程的 GC 状态，果然，FULL GC 达到了每秒一次。

文章图片

这么多的 FULL GC，应该是内存泄漏没跑了，于是使用 jstack pid > jstack.log 保存了线程栈的现场，使用 jmap -dump:format=b,file=heap.log pid 保存了堆现场，然后重启了探测服务，报警邮件终于停止了。
jstat
jstat 是一个非常强大的 JVM 监控工具，一般用法是： jstat [-options] pid interval
它支持的查看项有：

class 查看类加载信息
compile 编译统计信息
gc 垃圾回收信息
gcXXX 各区域 GC 的详细信息如 -gcold

使用它，对定位 JVM 的内存问题很有帮助。
排查问题虽然解决了，但为了防止它再次发生，还是要把根源揪出来。
分析栈
栈的分析很简单，看一下线程数是不是过多，多数栈都在干嘛。

> grep 'java.lang.Thread.State' jstack.log| wc -l > 464

才四百多线程，并无异常。

> grep -A 1 'java.lang.Thread.State' jstack.log| grep -v 'java.lang.Thread.State' | sort | uniq -c |sort -n10at java.lang.Class.forName0(Native Method) 10at java.lang.Object.wait(Native Method) 16at java.lang.ClassLoader.loadClass(ClassLoader.java:404) 44at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) 344at sun.misc.Unsafe.park(Native Method)

线程状态好像也无异常，接下来分析堆文件。
下载堆 dump 文件
堆文件都是一些二进制数据，在命令行查看非常麻烦，Java 为我们提供的工具都是可视化的，Linux 服务器上又没法查看，那么首先要把文件下载到本地。
由于我们设置的堆内存为 4G，所以 dump 出来的堆文件也很大，下载它确实非常费事，不过我们可以先对它进行一次压缩。
gzip 是个功能很强大的压缩命令，特别是我们可以设置 -1 ~ -9 来指定它的压缩级别，数据越大压缩比率越大，耗时也就越长，推荐使用 -6~7， -9 实在是太慢了，且收益不大，有这个压缩的时间，多出来的文件也下载好了。
使用 MAT 分析 jvm heap
MAT 是分析 Java 堆内存的利器，使用它打开我们的堆文件（将文件后缀改为 .hprof）, 它会提示我们要分析的种类，对于这次分析，果断选择 memory leak suspect。

文章图片

从上面的饼图中可以看出，绝大多数堆内存都被同一个内存占用了，再查看堆内存详情，向上层追溯，很快就发现了罪魁祸首。

文章图片

分析代码
找到内存泄漏的对象了，在项目里全局搜索对象名，它是一个 Bean 对象，然后定位到它的一个类型为 Map 的属性。
这个 Map 根据类型用 ArrayList 存储了每次探测接口响应的结果，每次探测完都塞到 ArrayList 里去分析，由于 Bean 对象不会被回收，这个属性又没有清除逻辑，所以在服务十来天没有上线重启的情况下，这个 Map 越来越大，直至将内存占满。
内存满了之后，无法再给 HTTP 响应结果分配内存了，所以一直卡在 readLine 那。而我们那个大量 I/O 的接口报警次数特别多，估计跟响应太大需要更多内存有关。
给代码 owner 提了 PR，问题圆满解决。
小结其实还是要反省一下自己的，一开始报警邮件里还有这样的线程栈：

groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:166) groovy.json.internal.JsonParserCharArray.decodeJsonObject(JsonParserCharArray.java:132) groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:186) groovy.json.internal.JsonParserCharArray.decodeJsonObject(JsonParserCharArray.java:132) groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:186)

看到这种报错线程栈却没有细想，要知道 TCP 是能保证消息完整性的，况且消息没有接收完也不会把值赋给变量，这种很明显的是内部错误，如果留意后细查是能提前查出问题所在的，查问题真是差了哪一环都不行啊。
来源 | https://zhenbianshu.github.io/
记一次jvm疯狂gc导致CPU飙高的问题解决背景线上web服务器不时的出现非常卡的情况，登录服务器top命令发现服务器CPU非常的高，重启tomcat之后CPU恢复正常，半天或者一天之后又会偶现同样的问题。解决问题首先要找到问题的爆发点，对于偶现的问题是非常难于定位的。
重启服务器之后只能等待问题再次出现，这时候首先怀疑是否某个定时任务引发大量计算或者某个请求引发了死循环，所以先把代码里面所有怀疑的地方分析了一遍，加了一点日志，结果第二天下午问题再次出现，
这次的策略是首先保护案发现场，因为线上是两个点，把一个点重启恢复之后把另一个点只下线不重启保留犯罪现场。
排查在问题的服务器上首先看业务日志，没有发现大量重复日志，初步排除死循环的可能，接下来只能分析jvm了。
第一步：top命令查看占用CPU的pid

文章图片

这是事后的截图，当时的cpu飙高到500多，pid是27683
然后ps aux | grep 27683 搜索一下确认一下是不是我们的tomcat占用的cpu，这个基本是可以肯定的，因为tomcat重启之后CPU立马就降下来了。
也可以使用jps显示java的pid
第二步：top -H -p 27683 查找27683下面的线程id，显示线程的cpu的占用时间，占用比例，发现有很多个线程都会CPU占用很高，只能每个排查。
第三步：jstack查看线程信息，命令：jstack 27683 >> aaaa.txt 输出到文本中再搜索，也可以直接管道搜索 jstack 27683 | grep "6c23" 这个线程id是16进制表示，需要转一下，可以用这个命令转 printf "%x\n" tid 也可以自己计算器转一下。
悲剧的是我在排查的时候被引入了一个误区，当时搜索到6c26这个线程的时候，发现是在做gc，疯狂gc导致的线程过高，但是找不到哪里造成的产生这么多对象，一直在找所有可能的死循环和可能的内存泄露。

文章图片

然后通过命名 jstat -gcutil 【PID】 1000 100 查看每秒钟gc的情况。

文章图片

这个是事后复盘的截图，当时的截图已经没有了
发现S0不停的再新建对象，然后gc，不停的反复如此gc，去看堆栈信息，没有什么发现，无非都是String和map对象最多，确定不了死循环的代码，也找不到问题的爆发点，至此陷入彻底的困惑。一番查找之后确认也不是内存泄露，苦苦寻找无果，我陷入了沉思。
CPU还是一直保持在超高，无奈之下，还是jstack 27683 看线程栈，无目的的乱看，但是发现了一个问题，当前的点我是下线的也就是没有用户访问的，CPU还是一直这么高，而且线程栈也在不停的打印，那么也就是说当前还在运行的线程很可能就是元凶，马上分析线程栈信息，有了重大发现。

文章图片

大量的这个线程信息出现，httpProxy_jsp这个jsp的线程在不停的活跃，这个是什么鬼jsp？难道服务器被攻击了？马上去代码里找，发现确实有这个jsp，查看git的提交记录，是几天之前另一个同事提交的代码，时间点和问题第一次出现的时间非常吻合，感觉自己运气好应该是找到问题的点了，把同事叫过来分析他的代码，这个jsp其实非常简单，就是做一个代理请求，发起了一个后端http请求。

文章图片

HttpRequestUtil如下，是同事自己写的工具类，没有用公用工具，其中一个post方法里connection没有设置链接超时时间和read超时时间：

文章图片

这里面有个致命的问题，他http请求没有设置超时等待时间，connection如果不设置超时时间或者0就认为是无穷大，也就是会一直都不超时，这时候如果被请求的第三方页面如果不响应或者响应非常慢，这个请求就会一直的等待，或者是请求没回来接着又来一次，导致这个线程就卡住了，但是线程堆积在这里又不崩溃还一直的在做某些事情会产生大量的对象，然后触发了jvm不停的疯狂GC把服务器CPU飚到了极限，然后服务器响应变得非常慢，问题终于找到了，而且非常符合问题的特点，果然把这个地方换了一种写法加了2秒钟超时的限制，问题没有再出现。
这次问题的解决过程得出几点心得：
1、jvm的问题是很复杂的，通过日志看到的很可能不是问题的根源，解决问题也有运气成分，分析日志+业务场景+瞎蒙都是解决问题的方法，分析问题不要一条道走到黑，多结合当前的场景加上一些猜测。
2、这个问题的根源是CPU飙高，一开始总想着是代码里有死循环，后来又以为是内存泄露，所以走了很多弯路，最后还是用最笨的方法看线程栈的日志看出了问题，所以问题没有统一的解决方案，具体问题都要具体处理的，不能拘泥于以往的经验。
3、在写代码过程中尽量使用原项目中已经被广泛使用的公共工具类，尽量不要把自己自创的没有经过项目检验的代码引入工程，即使看起来很简单的一段代码可能给项目引入灾难，除非你有充足的把握了解你代码的底层，比如这个超时的设置问题。
记一次Synchronized关键字使用不合理，导致的多线程下线程阻塞问题排查在为客户进行性能诊断调优时，碰到了一个Synchronized关键字使用不合理导致多线程下线程阻塞的情况。用文字记录下了问题的整个发现-排查-分析-优化过程，排查过程中使用了我司商业化产品——XLand性能分析平台，通过文章主要希望跟大家分享下分析和优化思路以及注意点，有兴趣深入了解的同学可以评论交流。
现象在执行单接口负载“判断登陆是否正常接口”测试时候，发现10用户增加至50用户并发，TPS保持不变，响应时间处于持续递增状态，应用CPU为27%，数据库CPU为3%，资源消耗维持稳定状态，由此判断应用程序可能存在瓶颈。

文章图片

文章图片

分析通过XLand分析平台线程分析，发现某线程存在锁等待情况，通过XLand中的x分析定位，发现AuthProvider类中getAccessor方法有Synchronized关键字，当两个以上线程同时调用该同步方法时，每次只能有一个线程能进入该方法，其他线程必须等前一个线程执行完该同步方法后，才能有机会进入。

文章图片

文章图片

风险点 Synchronized关键字解决的是多个线程之间访问资源的同步性，Synchronized关键字可以保证被它修饰的方法或者代码块在任意时刻只能有一个线程执行。谨慎使用Synchronized关键字，以防导致不必要的线程阻塞，影响响应时间。
优化措施把AuthProvider类中的Synchronized关键字去掉，发现在10用户并发下判断登陆是否正常接口TPS由原来的174笔/秒增长至624笔/秒，增长了3倍。在日常编程中谨慎使用synchronized，如果没有多线程修改静态变量或单例属性这类需求就不要用，如果有需要也建议只锁必要的代码块，而不是锁整个方法。
后记 Java 应用性能的瓶颈点非常多，比如磁盘、内存、网络 I/O 等系统因素，Java 应用代码，JVM GC，数据库，缓存等。一般将 Java 性能优化分为 4 个层级：应用层、数据库层、框架层、JVM 层。每层优化难度逐级增加，涉及的知识和解决的问题也会不同。但说实话，其实大多数问题还没有需要你懂框架源代码、JVM参数、GC工作机制这一步，只需要略会分析SQL，理解代码逻辑，会定位到有问题的Java代码并作修改即可。毕竟不是有这么一句话是这么说来着——80%的性能问题都是你写的烂代码导致的，哈哈哈。虽然有点犀利，但是保持良好的编码习惯，合理使用某些可能引起问题的关键字，谨慎使用内存资源，的确能规避很大一部分问题。好了，最后祝大家都徒手千行无bug！