java异常堆栈日志 java 堆栈日志

转载

技术领航舵手 2023-08-12 21:10:36

文章标签 java异常堆栈日志运维 linux jvm 堆栈 文章分类 Java 后端开发

上文《生产环境实践(二)：Linux常用运维工具》带大家熟悉了各种性能分析工具，本篇则让我们看看之前获取到的JAVA进程堆栈数据怎么帮助我们排查生产线上问题的。

jstack命令保存java线程dump

# 保存 java threads dump
jstack $pid >> $file_path/stack.log

jmap命令保存java堆dump

# 保存 java heap dump
jmap -dump:live,format=b,file=$file_path/heap.hprof $pid

Thread Dump

打开stack.log，观察发现类似下图信息。

java异常堆栈日志 java 堆栈日志_运维

线程名称
守护线程标志

daemon表示该线程为守护线程，非守护线程该列为空。

优先级

prio表示线程优先级默认为5，10表示最高。

线程ID

nid表示十六进制的线程ID，可以结合top -Hp $pid中十进制的线程ID，方面查找占用CPU资源的线程。

线程状态

waiting on condition：等待资源
waiting for monitor entry：等待获取监视器
in Object.wait()：对象等待中
runnable：执行中

Thread.State

NEW：尚未启动的线程。
RUNNABLE：可运行线程的状态。正在Java虚拟机中执行，但它可能正在等待来自操作系统的其他资源，例如处理器。
BLOCKED：等待监视器锁被阻止的线程状态。处于阻塞状态的线程正在等待监视器锁。同步块/方法阻塞或者IO阻塞等原因放弃CPU使用权导致阻塞。
WAITING：等待线程的线程状态。调用 Object.wait, Thread.join, LockSupport.park，处于等待状态的线程正在等待另一个线程执行特定的动作。
TIMED_WAITING：具有指定等待时间的等待线程的线程状态。调用Object.wait(long), Thread.join(long), LockSupport.parkNanos, LockSupport.parkUntil。

实例：Waiting to lock 和 Blocked

"pool-2-thread-2" #65 prio=5 os_prio=0 tid=0x0000000029f59000 nid=0x14c0 waiting for monitor entry [0x000000003896d000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.hibernate.id.MultipleHiLoPerTableGenerator.generate(MultipleHiLoPerTableGenerator.java:147)
	- waiting to lock <0x00000005c40a8b00> (a org.hibernate.id.MultipleHiLoPerTableGenerator)
	at org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:118)
	at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:209)
	at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:194)
	at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.performSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:114)
	at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:90)

线程状态为BLOCKED阻塞，waiting for monitor entry等待获取监视器，waiting to lock <0x00000005c40a8b00>表示等待0x00000005c40a8b00的锁。
继续在dump日志中搜索0x00000005c40a8b00，发现存在大量的waiting to lock该地址的记录。
搜索locked <0x00000005c40a8b00>查找谁占用了锁资源。

"pool-2-thread-4" #67 prio=5 os_prio=0 tid=0x0000000029f5a000 nid=0x8f8 waiting on condition [0x0000000038b6d000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000005c3b33dc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at org.apache.tomcat.dbcp.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:586)
	at org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:438)
	at org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:359)
	at org.apache.tomcat.dbcp.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at org.apache.tomcat.dbcp.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1532)
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
	at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
	at org.hibernate.engine.transaction.internal.jdbc.JdbcIsolationDelegate.delegateWork(JdbcIsolationDelegate.java:65)
	at org.hibernate.id.MultipleHiLoPerTableGenerator.generate(MultipleHiLoPerTableGenerator.java:213)
	- locked <0x00000005c40a8b00> (a org.hibernate.id.MultipleHiLoPerTableGenerator)

观察发现线程pool-2-thread-4获取了0x00000005c40a8b00的锁，然后获取数据库连接处于等待状态。搜索parking to wait for <0x00000005c3b33dc0>发现存在25条记录之多，证明数据库连接池被耗尽了，连接池的使用情况参考堆dump。

Heap DUMP

MAT是分析Java堆内存的一个工具，全称是 The Eclipse Memory Analyzer Tool，用来帮助分析内存泄漏和减少内存消耗。使用MAT分析Java堆快照，可以快速计算出对象的保留大小（Retained Sizes），查找到阻止对象被回收的原因，MAT会自动生成一个包含内存泄漏疑点的报告。

使用Memory Analyzer Tool工具打开heap.hprof文件，选择"Leak Suspects Report"然后点击"Finish"。

java异常堆栈日志 java 堆栈日志_linux_02

来到界面上方的功能栏，从左到右依次为：

Overview
概要界面

Details：显示了一些统计信息，包括整个堆内存的大小、类（Class）的数量、对象（Object）的数量、类加载器（Class Loader)的数量。
Biggest Objects by Retained Size：使用饼图的方式直观地显示了在JVM堆内存中最大的几个对象，当光标移到饼图上的时候会在左边Inspector和Attributes窗口中显示详细的信息。
Actions：这里显示了几种常用到的操作，算是功能的快捷方式，包括 Histogram、Dominator Tree、Top Consumers、Duplicate Classes，具体的含义和用法见下面；
Reports：列出了常用的报告信息，包括 Leak Suspects和Top Components，具体的含义和内容见下；
Step By Step：以向导的方式引导使用功能。

Histogram
直方图，可以查看每个类的实例（即对象）的数量和大小。

可以选择分组方式，例如Group by package按照类的package分组。

dominator_tree
支配树，列出Heap Dump中处于活跃状态中的最大的几个对象，默认按 retained size进行排序，因此很容易找到占用内存最多的对象。
OQL
MAT提供了一个对象查询语言（OQL），跟SQL语言类似，将类当作表、对象当作记录行、成员变量当作表中的字段。通过OQL可以方便快捷的查询一些需要的信息，是一个非常有用的工具。

例如SELECT x FROM java.io.File x 表示列出java.io.File的实例。

thread_overview
此工具可以查看生成Heap Dump文件的时候线程的运行情况，用于线程的分析。
Find Object by address
通过十六进制的地址查找对应的对象。

实例：连接池使用情况

上文ThreadDump中的实例一：Waiting to lock 和 Blocked有提到连接池等待造成阻塞。让我们通过MAT分析heap.hprof中连接池的使用情况。

从pool-2-thread-4的线程dump中找到关键类org.apache.tomcat.dbcp.dbcp2.PoolingDataSource

"pool-2-thread-4" #67 prio=5 os_prio=0 tid=0x0000000029f5a000 nid=0x8f8 waiting on condition [0x0000000038b6d000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000005c3b33dc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at org.apache.tomcat.dbcp.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:586)
	at org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:438)
	at org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:359)
	at org.apache.tomcat.dbcp.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at org.apache.tomcat.dbcp.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1532)
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
	at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
	at org.hibernate.engine.transaction.internal.jdbc.JdbcIsolationDelegate.delegateWork(JdbcIsolationDelegate.java:65)
	at org.hibernate.id.MultipleHiLoPerTableGenerator.generate(MultipleHiLoPerTableGenerator.java:213)
	- locked <0x00000005c40a8b00> (a org.hibernate.id.MultipleHiLoPerTableGenerator)

点击dominator_tree，选择分组方式Group by package，在树形图找到PoolingDataSource。

java异常堆栈日志 java 堆栈日志_堆栈_03