大家好,我是半夏之沫 😁😁 一名金融科技领域的JAVA系统研发😊😊
我希望将自己工作和学习中的经验以最朴实,最严谨的方式分享给大家,共同进步👉💓👈
👉👉👉👉👉👉👉👉💓写作不易,期待大家的关注和点赞💓👈👈👈👈👈👈👈👈
👉👉👉👉👉👉👉👉💓关注微信公众号【技术探界】 💓👈👈👈👈👈👈👈👈
前言
最近公司发生了一起严重的生产事件,概括原因就是有一个应用在开启的事务中进行了Kafka消息发送,但是对应的Topic被下线了,导致发送消息时拉取集群元数据一直失败,从而事务一直无法提交,而事务无法提交会造成连接无法归还到数据库连接池,最终这个应用的每个Pod实例的数据库连接池的连接全部被占满,业务在较长一段时间内处于不可用。
该事件之所以严重,是因为运维人员以及DBA所作的很多操作都没有效果,下面是他们所作的操作。
- 运维人员先重启了Pod。重启Pod后业务会一定程度缓解,但过一会儿又会业务中断;
- DBA进行了数据库实例的连接扩容和杀会话。也没能解决问题,业务在缓解一段时间后再次陷入中断。
这个事件的本质原因就是在事务中阻塞在了某一个操作上,那么如何知道一笔请求开启了事务并且还阻塞在某一个操作上,此时就需要基于Arthas和线程Dump进行联合分析,本文将对这部分内容进行深入讨论。
正文
一. 基础知识准备
在正式开始深入讨论之前,需要简单的介绍一下会使用到的一些知识,方便后续大家理解整个方案实现。
需要准备的知识点有。
- Arthas的vmtool指令;
- 线程Dump的核心概念。
1. Arthas的vmtool指令
Arthas是一款线上监控诊断产品,经常定位线上问题的帅逼们肯定对Arthas不会陌生,这里要介绍的是Arthas支持的vmtool指令,该指令是Arthas最为重要的指令之一。
vmtool指令的官方说明如下。
vmtool利用JVMTI接口,实现查询内存对象,强制GC等功能。
这里重点关注查询内存对象,也就是使用vmtool指令可以实时的获取和操作当前进程中的所有对象,下面以查询一个简单Springboot应用中的Thread对象进行举例说明。
(Arthas如何开启和使用不在这里的演示范围内,该部分内容在官方文档有详细说明,请自行查阅)
首先可以通过如下指令获取Thread对象。
vmtool --action getInstances --className java.lang.Thread
输出结果如下所示。
@Thread[][
@TaskThread[Thread[http-nio-8080-exec-7,5,main]],
@TaskThread[Thread[http-nio-8080-exec-8,5,main]],
@TaskThread[Thread[http-nio-8080-exec-9,5,main]],
@TaskThread[Thread[http-nio-8080-exec-10,5,main]],
@TaskThread[Thread[http-nio-8080-exec-1,5,main]],
@TaskThread[Thread[http-nio-8080-exec-2,5,main]],
@TaskThread[Thread[http-nio-8080-exec-3,5,main]],
@TaskThread[Thread[http-nio-8080-exec-4,5,main]],
@TaskThread[Thread[http-nio-8080-exec-5,5,main]],
@TaskThread[Thread[http-nio-8080-exec-6,5,main]],
]
上述指令中通过 --action指定了操作行为是getInstances,此时会去寻找类型为java.lang.Thread的对象并绑定到instances变量上(注意这里的instances变量是一个数组),然后会将instances变量输出出来,输出出来的内容就长上面这个样子。
注意到上面默认只返回了10个Thread对象的信息,这是Arthas自动为我们做了数量限制,目的是防止查询到的对象的数量太多从而给JVM造成较大压力,我们可以自行通过 --limit {num} 来指定返回对象的数量,示例如下。
vmtool --action getInstances --className java.lang.Thread --limit 20
输出结果如下所示。
@Thread[][
@Thread[Thread[JMX server connection timeout 53,5,]],
@[Thread[arthas-binding-thread,5,]],
@TaskThread[Thread[http-nio-8080-exec-7,5,main]],
@TaskThread[Thread[http-nio-8080-exec-8,5,main]],
@TaskThread[Thread[http-nio-8080-exec-9,5,main]],
@TaskThread[Thread[http-nio-8080-exec-10,5,main]],
@Thread[Thread[http-nio-8080-Acceptor,5,main]],
@Thread[Thread[JMX server connection timeout 49,5,]],
@Thread[Thread[DestroyJavaVM,5,main]],
@Thread[Thread[JMX server connection timeout 51,5,]],
@Thread[Thread[RMI TCP Connection(idle),5,]],
@TaskThread[Thread[http-nio-8080-exec-1,5,main]],
@TaskThread[Thread[http-nio-8080-exec-2,5,main]],
@Thread[Thread[JMX server connection timeout 50,5,]],
@TaskThread[Thread[http-nio-8080-exec-3,5,main]],
@TaskThread[Thread[http-nio-8080-exec-4,5,main]],
@Thread[Thread[RMI TCP Connection(idle),5,]],
@Thread[Thread[http-nio-8080-ClientPoller,5,main]],
@TaskThread[Thread[http-nio-8080-exec-5,5,main]],
@TaskThread[Thread[http-nio-8080-exec-6,5,main]],
]
此时输出了20个Thread对象的信息。
此时肯定有人就有疑问了,上面返回的Thread对象的内容其实只是Thread对象的toString() 方法的内容,那怎么看Thread对象的字段属性等内容呢,此时需要通过 -x {num} 来指定展开层级。Arthas为了控制返回内容的大小,同样为我们设置了默认的展开层级为1,此时可以返回的内容实际就是对象的toString() 方法的内容,下面来演示一下将展开层级设置为2时的返回结果。
vmtool --action getInstances --className java.lang.Thread -x 2 --limit 2
打印结果如下。
@Thread[][
@TaskThread[
log=@DirectJDKLog[org.apache.juli.logging.DirectJDKLog@605dd373],
creationTime=@Long[1719471688498],
name=@String[http-nio-8080-exec-1],
priority=@Integer[5],
threadQ=null,
eetop=@Long[582031360],
single_step=@Boolean[false],
daemon=@Boolean[true],
stillborn=@Boolean[false],
target=@WrappingRunnable[org.apache.tomcat.util.threads.TaskThread$WrappingRunnable@37acb6ad],
group=@ThreadGroup[java.lang.ThreadGroup[name=main,maxpri=10]],
contextClassLoader=@AppClassLoader[sun.misc.Launcher$AppClassLoader@18b4aac2],
inheritedAccessControlContext=@AccessControlContext[java.security.AccessControlContext@2bd1725c],
threadInitNumber=@Integer[11],
threadLocals=null,
inheritableThreadLocals=null,
stackSize=@Long[0],
nativeParkEventPointer=@Long[0],
tid=@Long[36],
threadSeqNumber=@Long[67],
threadStatus=@Integer[657],
parkBlocker=@ConditionObject[java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@225a0e4d],
blocker=null,
blockerLock=@Object[java.lang.Object@7091cd75],
MIN_PRIORITY=@Integer[1],
NORM_PRIORITY=@Integer[5],
MAX_PRIORITY=@Integer[10],
EMPTY_STACK_TRACE=@StackTraceElement[][isEmpty=true;size=0],
SUBCLASS_IMPLEMENTATION_PERMISSION=@RuntimePermission[("java.lang.RuntimePermission" "enableContextClassLoaderOverride")],
uncaughtExceptionHandler=null,
defaultUncaughtExceptionHandler=null,
threadLocalRandomSeed=@Long[0],
threadLocalRandomProbe=@Integer[0],
threadLocalRandomSecondarySeed=@Integer[0],
],
@TaskThread[
log=@DirectJDKLog[org.apache.juli.logging.DirectJDKLog@605dd373],
creationTime=@Long[1719471688498],
name=@String[http-nio-8080-exec-2],
priority=@Integer[5],
threadQ=null,
eetop=@Long[543098880],
single_step=@Boolean[false],
daemon=@Boolean[true],
stillborn=@Boolean[false],
target=@WrappingRunnable[org.apache.tomcat.util.threads.TaskThread$WrappingRunnable@389cb2e9],
group=@ThreadGroup[java.lang.ThreadGroup[name=main,maxpri=10]],
contextClassLoader=@AppClassLoader[sun.misc.Launcher$AppClassLoader@18b4aac2],
inheritedAccessControlContext=@AccessControlContext[java.security.AccessControlContext@2bd1725c],
threadInitNumber=@Integer[11],
threadLocals=null,
inheritableThreadLocals=null,
stackSize=@Long[0],
nativeParkEventPointer=@Long[0],
tid=@Long[37],
threadSeqNumber=@Long[67],
threadStatus=@Integer[657],
parkBlocker=@ConditionObject[java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@225a0e4d],
blocker=null,
blockerLock=@Object[java.lang.Object@4a46ebd1],
MIN_PRIORITY=@Integer[1],
NORM_PRIORITY=@Integer[5],
MAX_PRIORITY=@Integer[10],
EMPTY_STACK_TRACE=@StackTraceElement[][isEmpty=true;size=0],
SUBCLASS_IMPLEMENTATION_PERMISSION=@RuntimePermission[("java.lang.RuntimePermission" "enableContextClassLoaderOverride")],
uncaughtExceptionHandler=null,
defaultUncaughtExceptionHandler=null,
threadLocalRandomSeed=@Long[0],
threadLocalRandomProbe=@Integer[0],
threadLocalRandomSecondarySeed=@Integer[0],
],
]
展开层级越高,返回内容越多,所以展开层级和数量限制都要谨慎设置。
如果在查询内存对象上vmtool仅有上述的功能,vmtool还不能称之为强大,下面将介绍vmtool的 --express执行表达式。
以下面这个语句进行举例。
vmtool --action getInstances --className java.lang.Thread --express 'instances.{?#this.name.contains("http-nio-")}.{#this.getId()}' -x 1 --limit 10
输出结果如下。
@ArrayList[
@Long[36],
@Long[37],
@Long[38],
@Long[39],
@Long[40],
]
在 --express后面可以跟上OGNL表达式作为执行表达式,上面的OGNL表达式中,instances表示Thread对象数组,.{?#this.name.contains("http-nio-")} 表示将instances对象数组中的name字段包含http-nio- 的对象过滤出来(类似于Java流式编程中的filter),.{#this.getId()} 表示将当前数组中的每一个元素转换成调用其getId() 方法得到的结果(类似于Java流式编程中的map),所以instances.{?#this.name.contains("http-nio-")}.{#this.getId()} 表达式执行时,整个过程示意图如下。
基于vmtool的执行表达式,我们对于一个应用的内存里的对象,就有了很大的操作空间,我们可以在任意一个时刻,拿到我们想看的任何信息。
2. 线程Dump的核心概念
线程Dump其实就是应用某一刻存活线程的快照,包含线程信息及其堆栈信息。单个时间点的线程Dump意义通常不大,但是将若干个时间点的线程Dump进行联和分析,就很容易获取到一些有用的数据,例如。
- 某个线程状态一直是等待状态(WAITING或TIMED_WAITING);
- 某个线程一直阻塞在某个操作上。
上述第二点的实现思路也很简单,假若我们得到了两个时刻的线程Dump,通过字符串匹配我们可以得出两个时刻完全相同的线程的堆栈,假如我们得到了如下的堆栈。
"http-nio-8080-exec-1" #33 daemon prio=5 os_prio=0 tid=0x0000000018cf4800 nid=0x4be8 waiting on condition [0x000000001fbab000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:340)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
at com.lee.learn.dao.BookDao.queryAllBooks(BookDao.java:39)
at com.lee.learn.dao.BookDao$$FastClassBySpringCGLIB$$3365ba26.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
......
此时再拿java.util.concurrent.TimeUnit.sleep去匹配,如果能匹配上,就可以得出名为http-nio-8080-exec-1的线程在两个时刻均阻塞在TimeUnit的sleep() 方法上。如果只是两个时刻,极端巧合情况下可能会误判,但是只要采集的时刻越多,结论就越准。
生成线程Dump也很简单,步骤如下。
- 执行jps拿到Java进程号;
- 执行jstack并指定Java进程号来打印线程Dump信息。
二. 方案设计讨论
1. 如何判断事务开启
(这里讨论的是Spring中的声明式事务)
已知,通过@Transactional注解开启事务时,每开启一个事务,Spring事务管理器会从数据源获取一个连接并封装成ConnectionHolder,然后将数据源和ConnectionHolder与当前线程做绑定,对应的代码在TransactionSynchronizationManager的bindResource() 方法中,如下所示。
public static void bindResource(Object key, Object value) throws IllegalStateException {
Object actualKey = TransactionSynchronizationUtils.unwrapResourceIfNecessary(key);
Assert.notNull(value, "Value must not be null");
// resources是一个NamedThreadLocal
// 本质是ThreadLocal只不过多了一个名字
// resources的名字是Transactional resources
Map<Object, Object> map = resources.get();
// 每个线程有一个与之绑定的HashMap
if (map == null) {
map = new HashMap<>();
resources.set(map);
}
// 开启事务后就会把数据源作为key
// 把ConnectionHolder作为value
// 存放到线程绑定的HashMap中
Object oldValue = map.put(actualKey, value);
if (oldValue instanceof ResourceHolder && ((ResourceHolder) oldValue).isVoid()) {
oldValue = null;
}
if (oldValue != null) {
throw new IllegalStateException("Already value [" + oldValue + "] for key [" +
actualKey + "] bound to thread [" + Thread.currentThread().getName() + "]");
}
if (logger.isTraceEnabled()) {
logger.trace("Bound value [" + value + "] for key [" + actualKey + "] to thread [" +
Thread.currentThread().getName() + "]");
}
}
通过上面的分析,我们现在知道,每开启一个事务,那么肯定会存在一个ConnectionHolder存放在一个HashMap中,并且这个HashMap还会通过一个名字叫做Transactional resources的ThreadLocal与线程完成绑定,那熟悉ThreadLocal的帅逼们肯定知道,通过ThreadLocal来保存线程本地变量,其实就是将ThreadLocal作为键,本地变量作为值,保存在线程Thread对象的threadLocals字段中,而threadLocals字段本质就是一个ThreadLocalMap对象,那么到这里希望帅逼们还没晕,但其实晕了也没关系,下面用一张图来帮助大家理解。
所以要判断一个线程有没有开启事务,其实就是看这个线程的Thread对象的threadLocals中有没有ConnectionHolder,如果有,说明事务正在开启中,与此同时我们也得到了哪个线程正在开启事务,再进一步,如果两个时间点同一个Thread对象的threadLocals中有同一个ConnectionHolder对象,那么这个线程至少在这两个时间点之间开启了事务并且未关闭,再进一步,如果我们选择的两个时间点间隔时间比较大,例如5s,那么说明这个线程开启了事务并且至少持续了5s还没提交。
2. 如何判断线程阻塞
其实在介绍线程Dump概念时,已经顺带说明了如何基于线程Dump来判断线程阻塞在哪里,这里对具体步骤再次做一下说明。
- 在T0时刻采集线程Dump信息;
- 等待一定时间来到T1时刻;
- 在T1时刻采集线程Dump信息;
- 得到T0时刻和T1时刻存在相同堆栈的线程;
- 判断T0时刻和T1时刻存在相同堆栈的线程阻塞在哪个方法调用上。
上述的步骤5就是拿着我们预先设定好的可能阻塞的方法的全限定名去堆栈中做匹配,例如拿着java.util.concurrent.TimeUnit.sleep去堆栈中匹配,只要匹配上,那么就能够说明一个事情,那就是某一个线程在T0和T1时刻均阻塞在TimeUnit的sleep() 方法上,那么最终我们就可以得到这么一个关联关系,那就是线程和阻塞行为的关联关系。
3. 如何判断事务阻塞
我们这里将事务阻塞用如下伪码进行演示。
// 开启声明式事务
@Transactional
public void example(Order order, String uuid) {
// 操作数据库
orderDao.saveOrder(order);
// 操作数据库
shoppingCart.clearGoods(uuid);
// Kafka消息发送
// 但是对应Topic被操作人员误下线
// 这里阻塞了
kafkaTemplate.send(producerRecord);
}
也就是在一个开启了事务的方法里,做了一些可能会阻塞很久的行为,比如发送Kafka消息或者刷新Redis缓存等,此时一旦这些可能会阻塞很久的行为真的阻塞了很久,那么就会导致开启了事务的方法很久都无法结束,从而导致事务无法提交,对应的数据库连接无法归还到数据库,最终结果就是数据库连接池的连接耗尽。
那么对于上述这种情况,我们就可以基于本节第1和第2节的内容来进行判断,首先判断出哪个线程开启了事务且未关闭,然后再判断对应线程是否阻塞在某个方法调用上,最终就得到了线程开启事务未关闭且还阻塞在某个方法调用上。
三. 案例演示
假设我们有如下这段开启事务的代码。
@Transactional
public Book getBookById(int id) {
Book book;
try {
book = bookMapper.selectById(id);
TimeUnit.MINUTES.sleep(10);
bookMapper.selectById(id);
} catch (Exception e) {
log.error("查询一本书失败");
throw new BookException(e);
}
return book;
}
(真有人会这么写吗,还别说,真有。)
首先打开Json格式返回。
options json-format true
然后通过如下vmtool指令获取到线程和threadLocalMap的关联信息。
vmtool --action getInstances --className java.lang.Thread --express '#threads=instances.{?#this.name.contains("http-nio-")}, #threads.{?#this.threadLocals!=null}.{#tls=#this.threadLocals, #threadName=#this.getName(), {#threadName, #tls.toString()}}' --limit 10000
得到如下结果。
[
[
"http-nio-8080-exec-2",
"java.lang.ThreadLocal$ThreadLocalMap@538a9074"
],
[
"http-nio-8080-exec-4",
"java.lang.ThreadLocal$ThreadLocalMap@15c7f823"
],
[
"http-nio-8080-exec-1",
"java.lang.ThreadLocal$ThreadLocalMap@e807bde"
]
]
再然后通过如下vmtool指令获取到threadLocalMap和table(就是ThreadLocalMap中的Entry数组)的关联信息。
vmtool --action getInstances --className java.lang.Thread --express '#tlss=instances.{?#this.name.contains("http-nio-")}.{threadLocals}.{?#this!=null}, #tlss.{?#this.table!=null}.{#tlsStr=#this.toString(), #tableStr=#this.table.toString(), {#tlsStr, #tableStr}}' --limit 10000
得到如下结果。
[
[
"java.lang.ThreadLocal$ThreadLocalMap@538a9074",
"[Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;@6d2149f0"
],
[
"java.lang.ThreadLocal$ThreadLocalMap@15c7f823",
"[Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;@69faf750"
],
[
"java.lang.ThreadLocal$ThreadLocalMap@e807bde",
"[Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;@6ef4c32b"
]
]
最后通过如下vmtool指令获取到table和ConnectionHolder的关联信息。
vmtool --action getInstances --className java.lang.Thread --express '#tables=instances.{?#this.name.contains("http-nio-")}.{threadLocals}.{?#this!=null}.{table}, #tables.{?#this!=null}.{#tableStr=#this.toString(), #values=#this.{?#this!=null}.{?#this.value!=null}.{?#this.value.getClass().getName().contains("HashMap")}.{#this.value.values}.{#this.toString()}, {#tableStr, #values}}' --limit 10000
得到如下结果。
[
[
"[Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;@6d2149f0",
[
"[org.mybatis.spring.SqlSessionHolder@44582836, org.springframework.jdbc.datasource.ConnectionHolder@23d19784]"
]
],
[
"[Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;@69faf750",
[
"[org.mybatis.spring.SqlSessionHolder@1f3de0bd, org.springframework.jdbc.datasource.ConnectionHolder@1c3a4637]"
]
],
[
"[Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;@6ef4c32b",
[
"[org.mybatis.spring.SqlSessionHolder@7e985721, org.springframework.jdbc.datasource.ConnectionHolder@25c0410a]"
]
]
]
通过执行上述三条vmtool指令,可以完成线程关联threadLocalMap,threadLocalMap关联table,table关联ConnectionHolder,最终我们就获取到了当前应用进程中正在开启事务的线程,然后在下一个时刻再执行上述三条vmtool指令,又可以获取下一时刻正在开启事务的线程,两个时刻取交集,就得到了事务开启未关闭的线程。
现在对上述三条vmtool指令做一下简单说明。
- 为什么limit设置为10000。limit并不是决定返回数据的数量,而是决定初始样本的数量,对于上述三条vmtool指令来说,也就是最多获取出来的instances数量可以为10000,这样对于大部分应用来说,不会遗漏线程;
- limit设置为10000不会把应用程序打垮吗。上述三条vmtool指令在一开始就对线程基于线程名做了过滤,过滤条件就是线程名需要包含http-nio-,这是Tomcat的线程的命名规则,也就是我们主要分析的是在Tomcat线程中开启事务未关闭的情况;
- 为什么要通过三条指令来得到线程和ConnectionHolder的关联关系。可以三条指令合成一条,但是指令就很不可读,分开写的话指令会更可读,关联的过程可以在代码中做,更简单。
现在既然拿到了哪个线程开启了事务且未关闭,那么最后就是再结合线程Dump来得到哪个线程阻塞在哪里,这里就不再演示了。
总结
要解决本文前言中的问题,很关键的一点就是要判断出应用进程中有线程开启了事务且一段时间内都没有关闭,这里就需要结合Spring中的声明式事务的原理,也就是开启了事务的连接会被封装成ConnectionHolder然后通过一个名字叫做Transactional resources的ThreadLocal存放为开启事务的线程的本地变量,即存放在这个Thread对象的ThreadLocalMap中,在此基础上,我们祭出Arthas里面的vmtool指令,基于vmtool指令我们可以编写OGNL表达式来获取当前时刻应用进程中的所有对象和类的属性状态,这当然也包括Thread对象的所有属性和状态。
拿到了哪些线程在一段时间开启了事务且未关闭后,我们还需要进一步判断这些线程在开启事务期间做了什么事情导致了事务未关闭,很多时候也许就是在开启了事务的方法里做了一些可能阻塞的操作比如Kafka消息发送或Redis数据缓存,这些操作阻塞住了,就会导致所在的事务方法无法执行完毕,从而事务没办法提交或回滚,最终数据库连接无法被归还。要判断线程在一段时间内的阻塞行为,使用线程Dump是一个很好的选择,也就是在一段时间内的若干时间点基于jstack指令得到线程的快照,通过字符串比对和关键方法匹配就可以得到这段时间内某一个线程是不是阻塞在某一个方法上,而且采样的时间点越多,结果越准确。
知道了哪些线程在一段时间开启了事务未关闭,又知道了哪些线程在一段时间阻塞在哪里,只要同一个线程开启了事务未关闭且还阻塞在某一个方法调用上,此时结果就很明显了对吧。
操作员因为沟通不及时,误下掉了一个Kafka的Topic,同时业务代码中存在逻辑是会在一个开启了事务的方法中向这个Topic发送消息,那么发送消息时在拉取集群元数据这一步会阻塞住,从而事务无法及时提交或回滚,数据库连接无法及时被归还,最终数据库连接池连接耗尽,业务完全中断,喜提生产事件。
大家好,我是半夏之沫 😁😁 一名金融科技领域的JAVA系统研发😊😊
我希望将自己工作和学习中的经验以最朴实,最严谨的方式分享给大家,共同进步👉💓👈
👉👉👉👉👉👉👉👉💓写作不易,期待大家的关注和点赞💓👈👈👈👈👈👈👈👈
👉👉👉👉👉👉👉👉💓关注微信公众号【技术探界】 💓👈👈👈👈👈👈👈👈