坏代码导致的性能问题大赏:CPU占用飙到了900%!

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 坏代码导致的性能问题大赏:CPU占用飙到了900%!

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


1.jpg


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 是不会满意的,这个结论还得有人接锅才行。于是赶紧联系运维和网络组,向他们确认一下当时的网络状态。网络组同学回复说是我们探测服务所在机房的交换机老旧,存在未知的转发瓶颈,正在优化,这让我更放心了,于是在部门群里简单交待一下,算是完成任务。


问题爆发


本以为这次值班就起这么一个小波浪,结果在晚上八点多,各种接口的报警邮件蜂拥而至,打得准备收拾东西过周日单休的我措手不及。


这次几乎所有的接口都在超时,而我们那个大量网络 I/O 的接口则是每次探测必超时,难道是整个机房故障了么。


我再次通过服务器和监控看到各个接口的指标都很正常,自己测试了下接口也完全 OK,既然不影响线上服务,我准备先通过探测服务的接口把探测任务停掉再慢慢排查。

结果给暂停探测任务的接口发请求好久也没有响应,这时候我才知道没这么简单。


解决


内存泄漏


于是赶快登陆探测服务器,首先是 top free df 三连,结果还真发现了些异常。

2.jpg

我们的探测进程 CPU 占用率特别高,达到了 900%。


我们的 Java 进程,并不做大量 CPU 运算,正常情况下,CPU 应该在 100~200% 之间,出现这种 CPU 飙升的情况,要么走到了死循环,要么就是在做大量的 GC。


使用 jstat -gc pid [interval] 命令查看了 java 进程的 GC 状态,果然,FULL GC 达到了每秒一次。

3.jpg

这么多的 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 -n
     10  at java.lang.Class.forName0(Native Method)
     10  at java.lang.Object.wait(Native Method)
     16  at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
     44  at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    344  at 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。


4.jpg

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


5.jpg

分析代码

找到内存泄漏的对象了,在项目里全局搜索对象名,它是一个 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

6.png

这是事后的截图,当时的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导致的线程过高,但是找不到哪里造成的产生这么多对象,一直在找所有可能的死循环和可能的内存泄露。


7.jpg

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

8.png

这个是事后复盘的截图,当时的截图已经没有了


发现S0不停的再新建对象,然后gc,不停的反复如此gc,去看堆栈信息,没有什么发现,无非都是String和map对象最多,确定不了死循环的代码,也找不到问题的爆发点,至此陷入彻底的困惑。一番查找之后确认也不是内存泄露,苦苦寻找无果,我陷入了沉思。


CPU还是一直保持在超高,无奈之下,还是jstack 27683 看线程栈,无目的的乱看,但是发现了一个问题,当前的点我是下线的也就是没有用户访问的,CPU还是一直这么高,而且线程栈也在不停的打印,那么也就是说当前还在运行的线程很可能就是元凶,马上分析线程栈信息,有了重大发现。


9.png

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


10.jpg

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


11.jpg

这里面有个致命的问题,他http请求没有设置超时等待时间,connection如果不设置超时时间或者0就认为是无穷大,也就是会一直都不超时,这时候如果被请求的第三方页面如果不响应或者响应非常慢,这个请求就会一直的等待,或者是请求没回来接着又来一次,导致这个线程就卡住了,但是线程堆积在这里又不崩溃还一直的在做某些事情会产生大量的对象,然后触发了jvm不停的疯狂GC把服务器CPU飚到了极限,然后服务器响应变得非常慢,问题终于找到了,而且非常符合问题的特点,果然把这个地方换了一种写法加了2秒钟超时的限制,问题没有再出现。


这次问题的解决过程得出几点心得:


1、jvm的问题是很复杂的,通过日志看到的很可能不是问题的根源,解决问题也有运气成分,分析日志+业务场景+瞎蒙都是解决问题的方法,分析问题不要一条道走到黑,多结合当前的场景加上一些猜测。


2、这个问题的根源是CPU飙高,一开始总想着是代码里有死循环,后来又以为是内存泄露,所以走了很多弯路,最后还是用最笨的方法看线程栈的日志看出了问题,所以问题没有统一的解决方案,具体问题都要具体处理的,不能拘泥于以往的经验。


3、在写代码过程中尽量使用原项目中已经被广泛使用的公共工具类,尽量不要把自己自创的没有经过项目检验的代码引入工程,即使看起来很简单的一段代码可能给项目引入灾难,除非你有充足的把握了解你代码的底层,比如这个超时的设置问题。


记一次Synchronized关键字使用不合理,导致的多线程下线程阻塞问题排查


在为客户进行性能诊断调优时,碰到了一个Synchronized关键字使用不合理导致多线程下线程阻塞的情况。用文字记录下了问题的整个发现-排查-分析-优化过程,排查过程中使用了我司商业化产品——XLand性能分析平台,通过文章主要希望跟大家分享下分析和优化思路以及注意点,有兴趣深入了解的同学可以评论交流。


现象


在执行单接口负载“判断登陆是否正常接口”测试时候,发现10用户增加至50用户并发,TPS保持不变,响应时间处于持续递增状态,应用CPU为27%,数据库CPU为3%,资源消耗维持稳定状态,由此判断应用程序可能存在瓶颈。


12.jpg

13.jpg

14.jpg

分析


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

15.jpg

16.jpg

风险点


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!

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
相关文章
|
7月前
|
移动开发 运维 监控
掌握Linux运维利器:查看CPU和内存占用,轻松解决性能问题!
掌握Linux运维利器:查看CPU和内存占用,轻松解决性能问题!
267 0
|
24天前
|
存储 缓存
CPU性能
【10月更文挑战第30天】CPU性能
38 3
|
2月前
|
存储 缓存 监控
如何提高服务器CPU性能?
如何提高服务器CPU性能?
159 3
|
3月前
|
调度
CPU调度器实现提示:针对特定体系结构代码【ChatGPT】
CPU调度器实现提示:针对特定体系结构代码【ChatGPT】
|
4月前
|
弹性计算 固态存储 ice
阿里云服务器2核16G、4核32G、8核64G配置不同ECS实例规格收费标准和CPU性能差异
2024年阿里云提供2核16G、4核32G及8核64G等多种服务器配置,用户可根据需求选择不同实例规格如内存型r8i、通用算力型u1等。以华北2(北京)为例,2核16G月费从286.2至385.99元不等;4核32G为572.4至771.97元;8核64G则在1144.8至1543.94元区间。公网带宽与系统盘(如ESSD云盘)亦有多样化选择与价格方案。长期租赁可享折扣,具体价格请访问阿里云官网确认。
159 7
|
3月前
|
编解码 算法 测试技术
CPU性能调节【ChatGPT】
CPU性能调节【ChatGPT】
|
5月前
|
缓存 弹性计算 数据库
阿里云2核4G服务器支持多少人在线?程序效率、并发数、内存CPU性能、公网带宽多因素
2核4G云服务器支持的在线人数取决于多种因素:应用效率、并发数、内存、CPU、带宽、数据库性能、缓存策略、CDN和OSS使用,以及用户行为和系统优化。阿里云的ECS u1实例2核4G配置,适合轻量级应用,实际并发量需结合具体业务测试。
83 0
阿里云2核4G服务器支持多少人在线?程序效率、并发数、内存CPU性能、公网带宽多因素
|
5月前
|
机器学习/深度学习 TensorFlow API
Keras是一个高层神经网络API,由Python编写,并能够在TensorFlow、Theano或CNTK之上运行。Keras的设计初衷是支持快速实验,能够用最少的代码实现想法,并且能够方便地在CPU和GPU上运行。
Keras是一个高层神经网络API,由Python编写,并能够在TensorFlow、Theano或CNTK之上运行。Keras的设计初衷是支持快速实验,能够用最少的代码实现想法,并且能够方便地在CPU和GPU上运行。
|
6月前
|
并行计算 异构计算 Python
python代码torch.device("cuda:0" if torch.cuda.is_available() else "cpu")是什么意思?
【6月更文挑战第3天】python代码torch.device("cuda:0" if torch.cuda.is_available() else "cpu")是什么意思?
606 4
|
6月前
|
弹性计算 安全 前端开发
阿里云服务器ECS通用型、计算型和内存实例区别、CPU型号、性能参数表
阿里云ECS实例有计算型(c)、通用型(g)和内存型(r)系列,区别在于CPU内存比。计算型1:2,如2核4G;通用型1:4,如2核8G;内存型1:8,如2核16G。实例有第五代至第八代,如c7、g5、r8a等,每代CPU型号和主频提升。例如,c7使用Intel Ice Lake,g7支持虚拟化Enclave。实例性能参数包括网络带宽、收发包能力、IOPS等,适合不同场景,如视频处理、游戏、数据库等
165 0