springboot2稳定版本_SpringBoot2.2.x版本CPU增高BUG分析|chu

一、发现问题

项目在上线之后&＃xff0c;运行24小时之后CPU突然增高&＃xff0c;导致不得不重启机器。

二、分析及定位问题

项目在上线前是经过压力测试&＃xff0c;刚开始定位是QPS过大&＃xff0c;通过增加机器。但结果并不是特别理想&＃xff0c;始终会有几台机器增高。

项目环境测试机 1c2g

1、测试

通过jmeter对该机器接口进行压力测试&＃xff0c;qps为90&＃xff0c;cpu增高到40%持续没多久下降到10%&＃xff0c;一直持续稳定。并未产生CPU过高的情况&＃xff0c;该机器配置比正式环境要低4倍&＃xff0c;第一步得出的结论应该不在接口上

2、更换项目中比较早期版本的插件及线程池

重新上线项目之后&＃xff0c;运行1天之后&＃xff0c;依然有2台机器的CPU持续增高&＃xff0c;并且越往后增加越大

3、开始针对线上高CPU服务器排查#查看java的pid top #查看pid下的占用高的tid top -Hp pid #打印tid16进制 printf "%xn" tid #查看栈 输出到xx.log jstack pid|grep -A 2000 tid的16进制 > xx.log #查看gc 打印每2000ms输出一次&＃xff0c;共10次 jstat -gcutil pid 2000 10

结论&＃xff1a;栈信息基本都是RUN或TIME_WATING 并没有相关的死锁的线程&＃xff0c;但是通过gc发现大量的YGC持续的增高&＃xff0c;这时候考虑到可能堆的信息有异常

4、针对堆信息查看#查看堆 jmap pid jmap -heap pid jmap -histo:live pid ... #常用的是最后一个 加一个more 防止过多内容刷屏 jmap -histo:live pid|more

执行多次最后一个命令&＃xff0c;发现一个队列在持续的增高&＃xff0c;几百几百的增加并无然后减少的情况1: 111885 139385304 [Ljava.lang.Object; 3: 10515 15412904 [I 4: 142407 13450056 [C 5: 13892 4170928 [B 6: 135968 3263232 java.lang.String ..... 34: 6423 308304 java.util.HashMap 35: 12459 299016 java.util.concurrent.ConcurrentLinkedQueue$Node

最后一行就是发现增长过快的队列&＃xff0c;到此算是发现了一个比较有用的信息&＃xff0c;回头就去分析代码。但依然没有什么结论&＃xff0c;代码逻辑并不复杂也并未使用到该队列。

5、咨询大佬&＃xff0c;建议通过火焰图定位某个阶段执行过程的消耗情况#开始安装火陷图插件 #具体安装插件的过程&＃xff0c;大家自行搜索&＃xff0c;本文不具体描述如何安装火陷图

6、执行命令生成火陷图

通过上图&＃xff0c;我们能直观的看到在MimeTypeUtils方法中&＃xff0c;使用到了过多的这个队列&＃xff0c;然后就直接去看源码了。目前官方已经修复了一版在2.2.6版本中(但是很不幸运&＃xff0c;并没有完全修复)

下面是2.2.6版本修复一版的代码&＃xff0c;去除了之前的一些没有意义判断,MimeTypeUtils.java文件private static class ConcurrentLruCache { private final int maxSize; private final ConcurrentLinkedQueue queue &＃61; new ConcurrentLinkedQueue<>(); .... public V get(K key) { this.lock.readLock().lock(); try { if (this.queue.size()

单纯的阅读代码&＃xff0c;并没有什么大的BUG&＃xff0c;但是我们可以去关注队列本身的问题。

查看ConcurrentLinkedQueue remove 源码public boolean remove(Object o) { if (o !&＃61; null) { Node next, pred &＃61; null; for (Node p &＃61; first(); p !&＃61; null; pred &＃61; p, p &＃61; next) { boolean removed &＃61; false; E item &＃61; p.item; if (item !&＃61; null) { if (!o.equals(item)) { next &＃61; succ(p); continue; } removed &＃61; p.casItem(item, null); } next &＃61; succ(p); if (pred !&＃61; null && next !&＃61; null) // unlink pred.casNext(p, next); if (removed) return true; } } return false; }

如果存在多个则删除第一个&＃xff0c;并返回true&＃xff0c;否者返回false&＃xff0c;例如&＃xff1a;多个线程同时要获取到同一个要删除的元素&＃xff0c;则只删除一个&＃xff0c;其他返回false&＃xff0c;再结合MimeTypeUtils方法&＃xff0c;会再去执行add&＃xff0c;这就导致会对队列出现无限的增长【可能】(非百分百)。

7、结论

造成CPU性能过高&＃xff0c;是因为队列长度过长&＃xff0c;remove方法需要遍历整个队列内容。队列过长的原因是因为remove 并发情况下返回false&＃xff0c;开发过程中可能并未关注到remove会返回false&＃xff0c;导致无限的执行add方法的可能。

三、验证问题

通过debug发现spring boot在执行过程中会针对用户请求的Accept和返回的Content-Type都会调用该方法。这时候其实就可以恶意构造Accept去请求某个api&＃xff0c;Accept中每个用逗号分割都会过一次方法&＃xff0c;导致大量性能消耗。本地通过构造多个Accpet值&＃xff0c;发现在MimeTypeUtils中确实可以超出本身对队列的长度设置&＃xff0c;导致缓慢增长。

1、通过官方github-issues搜索相关问题&＃xff0c;发现已经有人在最近提到过该问题&＃xff0c;并已经被close。

2、通过再次回复官方研发人员&＃xff0c;并提供更多的相关信息证明2.2.6版本修复之后依然存在该问题

3、在此期间又有人给出通过MediaType 上传类型构造的Accept

4、具体构造验证

找一台低配版的服务 1c2g

使用jmeter&＃xff0c;设置线程组&＃xff0c;不需要特别高50个线程&＃xff0c;永久发送

设置header的Accpet&＃xff0c;可以先使用内容如下&＃xff1a;application/stream&＃43;x-jackson-smile, application/vnd.spring-boot.actuator.v3&＃43;json, application/vnd.spring-boot.actuator.v2&＃43;json, application/json, multipart/form-data; boundary&＃61;----WebKitFormBoundaryVHfecvFDYeDEjhu4, multipart/form-data; boundary&＃61;----WebKitFormBoundarymKzwdDkWNDNzQFP0, multipart/form-data; boundary&＃61;----WebKitFormBoundaryiWpMXOUbWwBwq2AX, application/x-www-form-urlencoded, text/html;charset&＃61;UTF-8, application/octet-stream, application/vnd.ms-excel;charset&＃61;utf8, application/msword, multipart/form-data; boundary&＃61;----WebKitFormBoundaryGF2AJ2ZdPqbWOyEO, multipart/form-data; boundary&＃61;----WebKitFormBoundaryTZLPpyBs2F0ycmkB, multipart/form-data; boundary&＃61;----WebKitFormBoundaryBUClXdZPA3oxpUpx, image/jpeg;charset&＃61;UTF-8, multipart/form-data; boundary&＃61;----WebKitFormBoundarysODcdeMwzfHwEjtw, multipart/form-data; boundary&＃61;----WebKitFormBoundary26i2en6YQUSXUBzs, multipart/form-data; boundary&＃61;----WebKitFormBoundaryxUUWAyZnZjwlM1oy, multipart/form-data; boundary&＃61;----WebKitFormBoundarysVMYk11tVTTsXuEB, multipart/form-data; boundary&＃61;----WebKitFormBoundaryXsI4dpNsVTCWWrRo, multipart/form-data; boundary&＃61;----WebKitFormBoundaryiV1owCGwTHyQzja0, multipart/form-data; boundary&＃61;----WebKitFormBoundarygf1XpLmgasAQU9fi, multipart/form-data; boundary&＃61;----WebKitFormBoundaryBNaQtUvpQ2VV7YYA, multipart/form-data; boundary&＃61;----WebKitFormBoundaryW1rdrg4AbJ5Jn3Po, multipart/form-data; boundary&＃61;----WebKitFormBoundaryoBwFj2ABM5LflDmW, multipart/form-data; boundary&＃61;----WebKitFormBoundary40xI2TxryjbkSCtO, multipart/form-data; boundary&＃61;----WebKitFormBoundarytaCC9B6g8u4urnLF, multipart/form-data; boundary&＃61;----WebKitFormBoundaryOrhplGKYP9ozLkCs, multipart/form-data; boundary&＃61;----WebKitFormBoundaryvEUouFAr3R3YJYBh, multipart/form-data; boundary&＃61;----WebKitFormBoundaryuQ9tEKtn59w5hPLY, multipart/form-data; boundary&＃61;----WebKitFormBoundaryRGvPXUBAuZ6xJ95u, application/vnd.openxmlformats-officedocument.wordprocessingml.document, multipart/form-data; boundary&＃61;----WebKitFormBoundary7jpljZi4k61KhCNN, multipart/form-data; boundary&＃61;----WebKitFormBoundary7GVKDTHVuBABvjGB, multipart/form-data; boundary&＃61;----WebKitFormBoundaryZbNBPl3T4VZ44q6B, audio/mp3, multipart/form-data; boundary&＃61;----WebKitFormBoundaryI6rUM76YvxrIEcqv, multipart/form-data; boundary&＃61;----WebKitFormBoundaryag4BDWrzifHRdDiR, multipart/form-data; boundary&＃61;----WebKitFormBoundary1YRsWAdVqDin8g8p, multipart/form-data; boundary&＃61;----WebKitFormBoundaryDaatlrV3KAyZu7wA, multipart/form-data; boundary&＃61;----WebKitFormBoundaryyhvikZJdRGH1AjQq, multipart/form-data; boundary&＃61;----WebKitFormBoundary2z4SJhqeEx5XtVj4, multipart/form-data; boundary&＃61;----WebKitFormBoundaryeDLd1MTvuhmcmzNe, multipart/form-data; boundary&＃61;----WebKitFormBoundarybKizrvRESfhxHAMQ, multipart/form-data; boundary&＃61;----WebKitFormBoundary24U8tmsOluZqcRXX, multipart/form-data; boundary&＃61;----WebKitFormBoundarye4j6KdQyBjY4FqSk, multipart/form-data; boundary&＃61;----WebKitFormBoundaryjPmgLdzMcMYYB3yS, multipart/form-data; boundary&＃61;----WebKitFormBoundaryxzBZ9w6Je3IJ53NM, multipart/form-data; boundary&＃61;----WebKitFormBoundaryScy0j73cvx3iCFyY, multipart/form-data; boundary&＃61;----WebKitFormBoundaryTBoS8s4YWwmBGTDA, image/*, multipart/form-data; boundary&＃61;----WebKitFormBoundaryRUutFo3RXlNPgoBS, text/html;charset&＃61;utf-8, multipart/form-data; boundary&＃61;----WebKitFormBoundarykLObBi1tJMf158kt, multipart/form-data; boundary&＃61;----WebKitFormBoundary8M8MfCWBEFcsxnBU

开始进行请求&＃xff0c;然后我们再通过服务器中针对堆信息查看命令&＃xff0c;查看 ConcurrentLinkedQueue队列增长情况

持续压测&＃xff0c;然后再打开另三个jemter&＃xff0c;做同样的请求操作&＃xff0c;将header的Accept分别设置如下三种情况&＃xff0c;也可以更多&＃xff1a;#第一种 text/html,application/xhtml&＃43;xml,application/xml;q&＃61;0.9,image/webp,image/apng,*/*;q&＃61;0.8,application/signed-exchange;v&＃61;b3;q&＃61;0.9 #第二种 text/css,*/*;q&＃61;0.1 #第三种 application/json

以上三个线程可以设置每个为30&＃xff0c;永久。

我们再通过打印堆信息可以发现ConcurrentLinkedQueue队列开始突破限制突然增高&＃xff0c;又突然减少&＃xff0c;这时候可以把第一个jmeter请求先暂停。然后再持续观察堆信息[xx&＃64;xxx ~]$ jmap -histo:live 10114|grep java.util.concurrent.ConcurrentLinkedQueue 33: 4809 115416 java.util.concurrent.ConcurrentLinkedQueue$Node 768: 36 864 java.util.concurrent.ConcurrentLinkedQueue [xx&＃64;xxx ~]$ jmap -histo:live 10114|grep java.util.concurrent.ConcurrentLinkedQueue 30: 5530 132720 java.util.concurrent.ConcurrentLinkedQueue$Node 768: 36 864 java.util.concurrent.ConcurrentLinkedQueue [xx&＃64;xxx8 ~]$ jmap -histo:live 10114|grep java.util.concurrent.ConcurrentLinkedQueue 30: 5530 132720 java.util.concurrent.ConcurrentLinkedQueue$Node 767: 36 864 java.util.concurrent.ConcurrentLinkedQueue [xx&＃64;xxx ~]$ jmap -histo:live 10114|grep java.util.concurrent.ConcurrentLinkedQueue 29: 6994 167856 java.util.concurrent.ConcurrentLinkedQueue$Node 768: 36 864 java.util.concurrent.ConcurrentLinkedQueue [xx&＃64;xxx ~]$ jmap -histo:live 10114|grep java.util.concurrent.ConcurrentLinkedQueue 29: 7262 174288 java.util.concurrent.ConcurrentLinkedQueue$Node 768: 36 864 java.util.concurrent.ConcurrentLinkedQueue [xx&＃64;xxx ~]$ jmap -histo:live 10114|grep java.util.concurrent.ConcurrentLinkedQueue 26: 9829 235896 java.util.concurrent.ConcurrentLinkedQueue$Node 777: 36 864 java.util.concurrent.ConcurrentLinkedQueue

明显可以发现ConcurrentLinkedQueue在增高。到此针对SpringBoot在2.2.6版本中cpu持续增高情况已经可以完全的复现&＃xff0c;复现过程可能会存在不成功&＃xff0c;可以多试几次。

四、解决方案

1、目前发现在多核CPU的情况下增长比较缓慢&＃xff0c;但是到一定的长度之后也会加速加大CPU的消耗&＃xff0c;所以高配置可能是一个解决方案

2、降级方案&＃xff0c;目前通过对比。SpringFramework在5.1.x版本无太大影响。

3、等待更新 目前master再次修复一版&＃xff0c;预计4.27发布&＃xff0c;官方也将MimeTypeUtils列为5.3.x版本重构之一#修复方案从 ConcurrentLinkedQueue 队列切换到了 ConcurrentLinkedDeque 队列

五、补充

验证 ConcurrentLinkedQueue 队列&＃xff0c;出现false情况import java.util.concurrent.ConcurrentLinkedQueue; import java.util.concurrent.LinkedBlockingQueue; public class Main { private static ConcurrentLinkedQueue queue &＃61; new ConcurrentLinkedQueue<>(); public static void main(String[] args) { for (int i &＃61; 0; i <1000; i&＃43;&＃43;) { Thread thread1 &＃61; new QueueThread(String.valueOf(i)); thread1.start(); } try { Thread.sleep(5000); } catch (InterruptedException e) { e.printStackTrace(); } System.out.println("end"); } static class QueueThread extends Thread { private int value &＃61; 0; private String name; public QueueThread(String name) { this.name &＃61; name; queue.add(value); } &＃64;Override public void run() { for (int i &＃61; 1; i <1000; i&＃43;&＃43;) { try { boolean flag &＃61; queue.remove(value); System.out.println("remove: " &＃43; value &＃43; " "&＃43; flag); queue.add(value); value&＃43;&＃43;; } catch (Exception e) { System.out.println(e); } } } } }

备注&＃xff1a;如果是2.2.1-2.2.5 版本是会造成频繁的拿锁与解锁&＃xff0c;本篇是以2.2.6版本为分析