前置知识
jstack简介
jstack
是JVM
自带的工具,用于追踪Java进程
线程id的堆栈信息、锁信息,或者打印core file
,远程调试Java堆栈信息
等。
而我们常用的指令则是下面这条:
# 打印对应java进程的堆栈信息
jstack [ option ] pid
option
常见选项
-F 当正常输出的请求不被响应时,强制输出线程堆栈
-m 如果调用到本地方法的话,可以显示C/C++的堆栈
-l 除堆栈外,显示关于锁的附加信息,在发生死锁时可以用jstack -l pid来观察锁持有情况
Monitor锁工作机制
这个知识涉及到了Java锁底层的工作原理,感兴趣的读者可以参阅笔者这篇文章的Synchronized 是怎样实现的
这一小节
聊聊Java关键字synchronized
线程状态复习
在使用jstack
排查问题之前,我们必须了解堆栈中的信息,所以我们首先必须复习一下线程中的六大状态:
New
:线程处于创建但还未启动的状态。RUNNABLE
:RUNNABLE
其实是JVM
自定义的一种状态,如果和操作系统的线程状态进行等价理解的话,RUNNABLE
是处于操作系统Running或者Ready状态,因为CPU在这两个状态间的切换几乎是瞬时的,所以JVM统一用RUNNABLE表示。Waiting
:线程处于等待唤醒状态。Timed Waiting
:在有限时间内线程等待唤醒。Blocked
:程序等待进入同步区域,等待监视器锁中,线程处于阻塞状态。Terminated
:线程工作完成,处于结束状态了。
了解过线程状态后,我们就可以了解一下jstack导出的dump文件中线程会基于这些状态出现的各种情况:
runnable:线程处于执行中
deadlock:死锁(重点关注)
blocked:线程被阻塞 (重点关注)
Parked:停止
locked:对象加锁
waiting:线程正在等待
waiting to lock:等待上锁
Object.wait():对象等待中
waiting for monitor entry:等待获取监视器(重点关注)
Waiting on condition:等待资源(重点关注),最常见的情况是线程在等待网络的读写
MAT(Memory Analyzer)下载安装
下载地址
https://www.eclipse.org/mat/previousReleases.php
为了后续我们可以查看JVM
输出的hprof
日志,我们需要下载一个MAT
的工具,如下图所示,选择更早版本
以笔者为例,笔者就选择了1.7
版本
完成下载后,双击下面这个exe
文件能打开就说明一切正常
线程死锁问题排查思路
问题代码
如下所示,笔者使用spring boot
写了一段死锁的代码,如下所示,然后将其放到服务器中启动
@RestController
public class TestController {
private static Logger logger = LoggerFactory.getLogger(TestController.class);
private Object lock1 = new Object();
private Object lock2 = new Object();
/**
* 模拟一个线程死锁的请求
*
* @return
*/
@GetMapping("deadLock")
public String deadLock() throws Exception {
Thread t1 = new Thread(() -> {
logger.info("线程1开始工作,先获取锁1");
synchronized (lock1) {
try {
Thread.sleep(3000);
} catch (InterruptedException e) {
e.printStackTrace();
}
logger.info("线程1获得锁1,尝试获得锁2");
synchronized (lock2) {
logger.info("线程1获得锁2成功");
}
}
});
Thread t2 = new Thread(() -> {
logger.info("线程2开始工作,先获取锁2");
synchronized (lock2) {
try {
Thread.sleep(3000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (lock1) {
logger.info("线程2获得锁1成功");
}
}
});
t1.setName("my-thread-1");
t2.setName("my-thread-2");
t1.join();
t2.join();
t1.start();
t2.start();
return "success";
}
}
重现问题
由于这只是一个demo
,我们日常发现这种问题的时候大概率是多线程中的业务没有结束,所以重现问题也很简单,通过命令调用一下接口即可
curl http://localhost:8888/deadLock
排查思路
首先确定当前发生死锁的java
应用,我们通过jps
确定进程id,可以看到笔者服务器的进程id
为23334
[root@xxxxtmp]# jps
23830 Jps
23334 jar
然后通过jstack -l
查看锁以及锁的附加信息
jstack -l 23334
最终可以在jstack
的最下方看到这样一段信息(Found one Java-level deadlock)
,由此确认出现my-thread-1
持有0x00000000ec509610
等待0x00000000ec509620
,my-thread-2
反之。
然后我们通过jstack信息即可定位到问题代码在TestController.java:53
以及TestController.java:37
。
Found one Java-level deadlock:
=============================
"my-thread-2":
waiting to lock monitor 0x00007f2800ac9318 (object 0x00000000ec509610, a java.lang.Object),
which is held by "my-thread-1"
"my-thread-1":
waiting to lock monitor 0x00007f27e40062c8 (object 0x00000000ec509620, a java.lang.Object),
which is held by "my-thread-2"
Java stack information for the threads listed above:
===================================================
"my-thread-2":
at com.example.jstackTest.TestController.lambda$deadLock$1(TestController.java:53)
- waiting to lock <0x00000000ec509610> (a java.lang.Object)
- locked <0x00000000ec509620> (a java.lang.Object)
at com.example.jstackTest.TestController$$Lambda$582/2089009876.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"my-thread-1":
at com.example.jstackTest.TestController.lambda$deadLock$0(TestController.java:37)
- waiting to lock <0x00000000ec509620> (a java.lang.Object)
- locked <0x00000000ec509610> (a java.lang.Object)
at com.example.jstackTest.TestController$$Lambda$581/1994255298.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
Found 1 deadlock.
CPU 飙升问题排查思路
简介
导致CPU 100%
的原因有很多,一般来说都是编码不当导致的,所以常规的排查思路为:
- 定位进程号,如果是
Java
进程则查看是哪个线程导致的。 - 定位导致CPU 飙升的线程号,转为16进制。
- 导致
JVM
锁信息日志,使用线程号定位代码。 - 排查并修复代码问题。
问题复现
首先笔者准备了一个导致CPU
飙升的问题代码,可以看到线程池中的线程不会停止不断工作
private ExecutorService threadPool = Executors.newFixedThreadPool(100);
private static Object lock = new Object();
private static Logger logger = LoggerFactory.getLogger(TestController.class);
public TestController() {
}
@GetMapping({"/test"})
public void test() {
for(int i = 0; i < 100; ++i) {
this.threadPool.execute(() -> {
logger.info("加法线程开始工作");
long sum = 0L;
Object var2 = lock;
synchronized(lock){}
try {
while(true) {
sum += 0L;
}
} finally {
;
}
});
}
}
然后我们发起请求
curl http://localhost:9550/test
排查过程
此时使用top
命令查看,可以看到24411
号进程CPU
占用百分比飙升。此时我们就需要进一步定位这个进程的哪一个线程出问题了。
所以我们需要进一步定位这个问题是哪一个线程导致的,命令如下所示,使用线程模式查看对应pid的线程情况
top -Hp 24411
可以看到25321
这个线程CPU
占用过高,此时我们就可以通过thread dump
定位导致问题的代码段
键入jstack -l 24411 >/tmp/log.txt
到处日志,然后将线程号25321转为16进制,这里笔者使用了一个在线的网站地址
https://www.sojson.com/hexconvert.html
可以看到25321
转换为16进制值为62e9
,所以我们就使用62e9
到导出的日志文件中查看这个线程堆栈情况。
使用转换的值从刚刚导出的日志中定位,可以看到该线程处于运行状态,很明显这个线程一直处于运行中,有一段逻辑肯定在不停的消耗CPU资源,所以我们查看代码位置在TestController.java:32
,由此得到问题代码并修复问题。
OOM问题排查思路
问题简述
出现OOM
问题大抵是有两个原因:
- 大流量导致服务器创建大量的对象把内存打爆了,面对这种情况我们除了熔断以外别无他法。
- 程序编写不规范导致,大流量情况下出现垃圾内存进而出现
OOM
,笔者本地探讨的就是这种情况。
复现问题
如下所示,笔者初始化了一个Spring Boot
程序,创建一个线程池,模拟无数个线程池将不断将内存写入4M的数据,并且不清理。
RestController
public class TestController {
final static ThreadPoolExecutor poolExecutor = new ThreadPoolExecutor(100, 100, 1, TimeUnit.MINUTES,
new LinkedBlockingQueue<>());// 创建线程池,通过线程池,保证创建的线程存活
final static ThreadLocal<Byte[]> localVariable = new ThreadLocal<Byte[]>();// 声明本地变量
(value = "/test0")
public String test0(HttpServletRequest request) {
poolExecutor.execute(() -> {
Byte[] c = new Byte[4* 1024* 1024];
localVariable.set(c);// 为线程添加变量
});
return "success";
}
}
完成后部署到服务器上,并使用以下命令启动,可以看到笔者调整的jvm
堆内存大小(笔者服务器内存为1g故这里设置为100m)
,以及设置OOM
输出参数
java -jar -Xms100m -Xmx100m # 调整堆内存大小
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof # 表示发生OOM时输出日志文件,指定path为/tmp/heapdump.hprof
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/tmp/heapTest.log # 打印日志、gc时间以及指定gc日志的路径
demo-0.0.1-SNAPSHOT.jar
完成后我们启动项目使用API post
进行并发请求(笔者本次堆区设置很小,所以在服务器中curl
一样可以重现问题)
可以看到服务器不久之后就出现了OOM
问题
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.7.8)
2023-01-28 23:42:39.579 INFO 3721 --- [ main] c.e.jstackTest.JstackTestApplication : Starting JstackTestApplication v0.0.1-SNAPSHOT using Java 1.8.0_202 on iZ8vb7bhe4b8nhhhpavhwpZ with PID 3721 (/tmp/jstackTest-0.0.1-SNAPSHOT.jar started by root in /tmp)
2023-01-28 23:42:39.588 INFO 3721 --- [ main] c.e.jstackTest.JstackTestApplication : No active profile set, falling back to 1 default profile: "default"
2023-01-28 23:42:42.300 INFO 3721 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8888 (http)
2023-01-28 23:42:42.340 INFO 3721 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2023-01-28 23:42:42.340 INFO 3721 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.71]
2023-01-28 23:42:42.613 INFO 3721 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2023-01-28 23:42:42.615 INFO 3721 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 2875 ms
2023-01-28 23:42:44.324 INFO 3721 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8888 (http) with context path ''
2023-01-28 23:42:44.351 INFO 3721 --- [ main] c.e.jstackTest.JstackTestApplication : Started JstackTestApplication in 5.923 seconds (JVM running for 7.085)
2023-01-28 23:43:29.742 INFO 3721 --- [nio-8888-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-01-28 23:43:29.742 INFO 3721 --- [nio-8888-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2023-01-28 23:43:29.748 INFO 3721 --- [nio-8888-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 5 ms
java.lang.OutOfMemoryError: Java heap space
Dumping heap to /tmp/heapdump.hprof ...
Heap dump file created [151939570 bytes in 1.112 secs]
Exception in thread "pool-1-thread-5" java.lang.OutOfMemoryError: Java heap space
at com.example.jstackTest.TestController.lambda$test0$0(TestController.java:25)
at com.example.jstackTest.TestController$$Lambda$582/394910033.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Exception in thread "pool-1-thread-7" java.lang.OutOfMemoryError: Java heap space
at com.example.jstackTest.TestController.lambda$test0$0(TestController.java:25)
at com.example.jstackTest.TestController$$Lambda$582/394910033.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Exception in thread "pool-1-thread-9" java.lang.OutOfMemoryError: Java heap space
排查思路
然后笔者使用top
定位,可以看到哪个堆区大小设置为100m
的进程内存占用达到10%
,很明显这个进程是有问题的。
然后使用top -Hp 3721
查看进程的线程信息,可以看到这里面的每一个线程基本都把堆区内存打满了,我们不妨查看任意一个线程
我们首先使用jstack -l 3721
将日志导出,这里就以3873
转为16进制
查看线程状态,可以发现线程处于等待状态,而且日志中并没有存在死锁的信息,所以我们必须进一步查看堆区情况确认是否是因为内存泄漏导致的。
然后使用jmap查看堆区使用情况
jmap -heap 3721
从下面的日志可以看出老年代使用率高达82%
,很明显有一些长期没有释放的对象在内存中导致OOM
问题。
我们从上文设置的oom
日志路径中找到日志/tmp/heapdump.hprof
,导出到本地,使用MAT
打开
找到使用率最高的Byte
数组,点击下图Histogram
,点击内存占用最高的选项展开。
这里补充一下截图中看到的两个选项:
with incoming references
: 表示的是 当前查看的对象,被外部的应用。with outGoing references
: 表示的是 当前对象,引用了外部对象。
所以我们的选择with incoming reference
可以定位到就是我们一个线程池中的threadLocal
使用不当导致OOM
问题了
参考文献
Java内存分析工具MAT(Memory Analyzer Tool)安装使用实例
JVM参数-XX:+HeapDumpOnOutOfMemoryError使用方法
Java 内存限制
Java 性能调优实战
面渣逆袭(Java 虚拟机-JVM面试题八股文)必看👍
Java程序员必备:jstack命令解析
内存分析工具MAT的使用入门