环境
JDK1.8
SPringBoot 2.2.2
Arthas
Linux
测试代码:
@RequestMapping(value = "/bigThread") @ResponseBody public String bigThread(int id) { ArthasService.test(); while (true) { Thread t2 = new Thread(); t2.start(); id ++; if(100000 == id) { return String.valueOf(id); } } }
思路
2.thread -b 查看是否有阻塞线程
thread -b, 找出当前阻塞其他线程的线程,执行完之后并未发现,说明该线程并非一直阻塞,一直执行的
3.thread 查看占用最高的线程
当thread之后不跟参数时,显示当前全部线程信息,我觉得 thread -n 10,展示前10应该就够用,可根据实际需要自己决定。
下图可以很直观的看出,我们的应用瞬间占用了77%的CPU(这里我是发起请求瞬间,通过thread查看的,所以比较直观,生产环境应该只有阻塞,死锁这种状态才会比较直观)
4.thread id 查看具体信息
在上一步基础上,我们进一步查看,thread 15(因为上面的ID=15)
他的大致意思就是:线程在等待一个条件从而继续执行,可以看到方法是在执行LinkedBlockingQueue.take方法时候,查看这个方法的API提示如下:
public E take() throws InterruptedException { E x; int c = -1; final AtomicInteger count = this.count; final ReentrantLock takeLock = this.takeLock; takeLock.lockInterruptibly(); try { while (count.get() == 0) { notEmpty.await(); } x = dequeue(); c = count.getAndDecrement(); if (c > 1) notEmpty.signal(); } finally { takeLock.unlock(); } if (c == capacity) signalNotFull(); return x; }
其中:AtomicInteger是保证高并发情况下的原子性,ReentrantLock标识可重入锁,都是JUC包下需要了解的这里不赘述,需要的百度了解下。
这段代码关键点就在于:notEmpty.await(),从队列中消费数据,当队列为空是,线程阻塞,所以我们大致知道现在出现的问题是线程阻塞,但是还是不知道具体哪行代码的问题。
如果能够明确知道这次更改了哪些代码,可以直接执行步骤6,不知道的话可以通过步骤5来定位问题。
5.watch 查看哪个Controller执行了代码
watch org.springframework.web.servlet.DispatcherServlet getHandler returnObj
这个脚本可以检测一切通过DispatcherServlet匹配Handler的方法,也就是进入Controller的请求,如下:
找到了对应的代码之后,我们来进一步观察异常信息,这里可能会有一个问题:就是我明明能通过日志去查看错误信息,为什么还需要这么繁琐的去操作。我的业务场景是:日志还是非常大的,刚捞到就被刷过去了,这时候定位日志不是很好操作,当然想捞下来日志肯定也是可以的,也很直观,我一般也都是去查看日志进行问题定位,这里也是提供一个思路。
6.watch 该方法异常信息
watch 类全路径 方法名 "{params[0],throwExp}" -e -x 2
如上,错误很直观的提示了出来,下面就可以修复解决了,这里我们也可以通过trace指令,查看执行时长:
trace 类全路径 方法名 "{params[0],throwExp}" -e -x 2
返回信息如下,也可以看到错误信息,和每个方法执行的时长
[arthas@10999]$ trace com.arthas.controller.OrderController bigThread Press Q or Ctrl+C to abort. Affect(class count: 1 , method count: 1) cost in 53 ms, listenerId: 10 `---ts=2020-08-19 14:45:57;thread_name=http-nio-0.0.0.0-8080-exec-10;id=16;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6 `---[1452.684406ms] com.arthas.controller.OrderController:bigThread() [throws Exception] +---[0.168814ms] com.arthas.service.ArthasService:test() #20 `---throw:java.lang.OutOfMemoryError #-2 [unable to create new native thread]
7.jad 反编译热更新
在上面知道问题之后,我们就来定位问题就好了,
命令:jad 类全路径 方法名
[arthas@13190]$ jad com.arthas.controller.OrderController ClassLoader: +-org.springframework.boot.loader.LaunchedURLClassLoader@17f052a3 +-sun.misc.Launcher$AppClassLoader@3d4eac69 +-sun.misc.Launcher$ExtClassLoader@45f45fa1 Location: file:/opt/software/arthas/Arthas.jar!/BOOT-INF/classes!/ /* * Decompiled with CFR. * * Could not load the following classes: * com.arthas.service.ArthasService * org.springframework.stereotype.Controller * org.springframework.web.bind.annotation.RequestMapping * org.springframework.web.bind.annotation.ResponseBody */ package com.arthas.controller; import com.arthas.service.ArthasService; import org.springframework.stereotype.Controller; import org.springframework.web.bind.annotation.RequestMapping; import org.springframework.web.bind.annotation.ResponseBody; @Controller public class OrderController { @RequestMapping(value={"/bigThread"}) @ResponseBody public String bigThread(int id) { ArthasService.test(); do { Thread t2 = new Thread(); t2.start(); } while (100000 != ++id); return String.valueOf(id); } } Affect(row-cnt:1) cost in 1513 ms.
此时代码就被反编译了,为了能够更改,所以我们需要输出为java文件
指令:jad com.arthas.controller.OrderController > /tmp/OrderController.java
即:jad 类全路径 方法名 > 存储路径/存储名称
然后到tmp路径下vi修改java文件即可,修改完成之后,查看对应的classloader为编译做准备
sc -d *OrderController | grep classLoaderHash mc -c 17f052a3 /tmp/OrderController.java -d /tmp
但是这里编译出错了,官方提示:
所以我们本地编译好class文件,上传上去是一样的
编译前调用
[arthas@13190]$ trace com.arthas.controller.OrderController bigThread Press Q or Ctrl+C to abort. Affect(class count: 1 , method count: 1) cost in 77 ms, listenerId: 2 `---ts=2020-08-19 15:51:46;thread_name=http-nio-0.0.0.0-8080-exec-1;id=d;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6 `---[6734.666529ms] com.arthas.controller.OrderController:bigThread() [throws Exception] +---[0.786517ms] com.arthas.service.ArthasService:test() #20 `---throw:java.lang.OutOfMemoryError #-2 [unable to create new native thread]
更新前代码
@RequestMapping(value = "/bigThread") @ResponseBody public String bigThread(int id) { ArthasService.test(); while (true) { Thread t2 = new Thread(); t2.start(); id ++; if(100000 == id) { return String.valueOf(id); } } }
更新后代码
@RequestMapping(value = "/bigThread") @ResponseBody public String bigThread(int id) { ArthasService.test(); Thread t2 = new Thread(); t2.start(); return "success"; }
编译指令
[arthas@13190]$ redefine /tmp/OrderController.class redefine success, size: 1, classes: com.arthas.controller.OrderController
编译后调用三次
`---ts=2020-08-19 15:52:02;thread_name=http-nio-0.0.0.0-8080-exec-3;id=f;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6 `---[5.609405ms] com.arthas.controller.OrderController:bigThread() `---[0.204675ms] com.arthas.service.ArthasService:test() #20 `---ts=2020-08-19 15:52:04;thread_name=http-nio-0.0.0.0-8080-exec-4;id=10;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6 `---[3.900149ms] com.arthas.controller.OrderController:bigThread() `---[0.14636ms] com.arthas.service.ArthasService:test() #20 `---ts=2020-08-19 15:52:04;thread_name=http-nio-0.0.0.0-8080-exec-5;id=11;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6 `---[1.90945ms] com.arthas.controller.OrderController:bigThread() `---[0.147353ms] com.arthas.service.ArthasService:test() #20
可以发现时间从6734.666529ms变成3ms左右,说明热更新的代码生效了
8.profile 绘制火焰图做后续分析
📎20200819-102814.svg 附件如下图: