一、问题现象
告警现象:
有一个异步处理的任务日志没有往后继续打印了
这个任务对应的队列存在消息积压
系统日志无任何ERROR堆栈,服务既不崩溃也不恢复
第一反应:服务没挂但卡住了,极大概率是线程阻塞问题。
二、初步诊断:jstack第一眼看到什么
2.1 获取Java进程PID
# 找到拓扑服务的进程ID ps aux | grep topology | grep -v grep # 结果:PID=234562.2 生成第一次线程堆栈
jstack -l 23456 > thread_dump_1.log2.3 统计线程状态分布(快速判断问题类型)
grep "java.lang.Thread.State" thread_dump_1.log | sort | uniq -c结果:
87 java.lang.Thread.State: RUNNABLE 23 java.lang.Thread.State: TIMED_WAITING 15 java.lang.Thread.State: WAITING ← 异常!有15个线程在无限期等待 2 java.lang.Thread.State: BLOCKED初步判断:15个WAITING状态的线程不正常,需要深入分析。
三、核心排查:逐层分析问题线程
3.1 查找所有WAITING状态的线程
grep -B 5 "WAITING" thread_dump_1.log | grep "PE_EVT" -A 10发现目标线程:
"PE_EVT1-1" #63 prio=5 tid=0x00007feffa0e7800 nid=0x68 waiting on condition java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006cc4cb2f8> (a java.util.concurrent.locks.StampedLock) at java.util.concurrent.locks.StampedLock.acquireWrite(StampedLock.java:1119) at java.util.concurrent.locks.StampedLock.writeLock(StampedLock.java:354) at com.tethrnet.terra.service.sr.topology.lib.api.model.NetworkGraph.addVertex(NetworkGraph.java:27) at com.tethrnet.terra.service.sr.server.topology.service.TopologyManager.updateNode(TopologyManager.java:553) at com.tethrnet.terra.service.sr.server.topology.service.TopologyManager.removePeInfos(TopologyManager.java:1929) at com.tethrnet.terra.service.sr.server.topology.service.ProdTopologyManager.process(ProdTopologyManager.java:294) at com.tethrnet.terra.service.sr.server.topology.service.ProdTopologyManager.processPeEvent(ProdTopologyManager.java:151)3.2 解读这个堆栈的关键信息
第一层:线程状态
WAITING (parking):线程被挂起了,在等某个条件被满足才能继续第二层:在等什么
parking to wait for <0x00000006cc4cb2f8> (StampedLock):在等一把读写锁StampedLock.writeLock():具体是在等写锁第三层:业务在做什么
TopologyManager.removePeInfos:在处理PE设备删除操作NetworkGraph.addVertex:正在向内存拓扑图中添加顶点疑问来了:删除PE信息,为啥在添加顶点?这需要看代码逻辑,但暂时先不管,继续追锁问题。
3.3 找到锁的占用者(关键一步)
在完整的堆栈文件中搜索这把锁:
grep -B 15 -A 30 "0x00000006cc4cb2f8" thread_dump_1.log找到占用线程:
"Topology-Processor-5" #120 prio=5 tid=0x00007feffa123800 nid=0x90 runnable java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3123) at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:2248) at com.mysql.jdbc.ResultSetImpl.next(ResultSetImpl.java:474) - locked <0x00000006cc4cb2f8> (a java.util.concurrent.locks.StampedLock) at com.tethrnet.terra.service.sr.topology.lib.api.model.NetworkGraph.rebuildIndex(NetworkGraph.java:89) at com.tethrnet.terra.service.sr.topology.lib.api.model.NetworkGraph.syncFromDB(NetworkGraph.java:156) at com.tethrnet.terra.service.sr.server.topology.service.TopologyManager.initGraph(TopologyManager.java:201)真相大白!
- 持有锁的线程在
RUNNABLE状态 - 它在执行数据库查询(
MysqlIO.readFully) - 问题很明确:在持有写锁的情况下,执行了耗时的数据库操作
四、确认问题持续时长:连续采样
4.1 多次采样判断是否是瞬时问题
for i in 1 2 3; do echo "=== 第${i}次采样 ===" jstack -l 23456 > thread_dump_${i}.log sleep 10 done4.2 对比三次结果
# 检查PE_EVT1-1线程在三次采样中的状态 for i in 1 2 3; do echo "=== dump_${i} ===" grep -A 2 "PE_EVT1-1" thread_dump_${i}.log | grep "WAITING" done结果:
=== dump_1 === java.lang.Thread.State: WAITING (parking) === dump_2 === java.lang.Thread.State: WAITING (parking) === dump_3 === java.lang.Thread.State: WAITING (parking)结论:至少30秒内线程状态没有任何变化,确认是持续阻塞,不是瞬时抖动。
五、根因定位:代码层面分析
5.1 问题代码定位
通过堆栈信息锁定到具体代码行:
NetworkGraph.addVertex第27行NetworkGraph.rebuildIndex第89行查看代码发现问题:
// 问题代码:NetworkGraph.java public void addVertex(Vertex v) { long stamp = lock.writeLock(); // 第27行,获取写锁 try { validateVertex(v); persistToDatabase(v); // ← 数据库操作在锁内! vertexMap.put(v.getId(), v); } finally { lock.unlockWrite(stamp); } } public void rebuildIndex() { long stamp = lock.writeLock(); // 同样的问题 try { syncFromDB(); // ← 数据库同步在锁内 rebuildInvertedIndex(); } finally { lock.unlockWrite(stamp); } }根因确认:
- 写锁保护了内存操作,但错误地包裹了数据库IO操作
- 当数据库响应慢时,锁被长时间占用
- 其他所有需要写锁的线程(包括PE事件处理)全部被阻塞
六、解决方案与验证
6.1 代码修复
// 修复后的代码 public void addVertex(Vertex v) { // 1. 耗时操作移到锁外 validateVertex(v); persistToDatabase(v); // ← 移出锁保护范围 // 2. 只在必要时加锁 long stamp = lock.writeLock(); try { vertexMap.put(v.getId(), v); } finally { lock.unlockWrite(stamp); } } // 或者更好的方案:使用并发容器 private final ConcurrentHashMap<String, Vertex> vertexMap = new ConcurrentHashMap<>(); public void addVertex(Vertex v) { validateVertex(v); persistToDatabase(v); vertexMap.put(v.getId(), v); // ConcurrentHashMap内部处理并发 }6.2 修复后验证
# 部署修复版本后,再次观察线程状态 jstack -l 45678 > thread_dump_fixed.log grep "java.lang.Thread.State" thread_dump_fixed.log | sort | uniq -c修复后结果:
105 java.lang.Thread.State: RUNNABLE 18 java.lang.Thread.State: TIMED_WAITING 0 java.lang.Thread.State: WAITING ← WAITING线程消失! 0 java.lang.Thread.State: BLOCKED七、经验总结:线程阻塞问题定位方法论
7.1 完整排查流程图
【现象】服务响应慢/假死 ↓ 1. 统计线程状态分布 grep "Thread.State" dump.log | sort | uniq -c → 大量WAITING/BLOCKED = 锁竞争问题 ↓ 2. 定位问题线程 grep -B 5 "WAITING" dump.log | grep "业务关键字" → 找到卡住的业务线程 ↓ 3. 分析线程堆栈 - 看状态:WAITING/BLOCKED/RUNNABLE - 看锁对象:waiting to lock <地址> - 看业务代码:定位到具体行号 ↓ 4. 找到锁占用者 grep -A 30 "锁地址" dump.log → 找到持有锁的线程 ↓ 5. 确认问题持续时长 连续采样3次,间隔10秒 → 对比线程状态是否变化 ↓ 6. 定位代码并修复 - 缩小锁范围 - 耗时操作移出锁外 - 使用并发容器替代手动锁7.2 核心排查技巧
| 问题特征 | 排查方向 | 典型堆栈特征 |
|---|---|---|
| 大量WAITING线程 | 锁竞争,找锁占用者 | waiting to lock <地址> |
| 两个线程相互等待 | 死锁,jstack会明确提示 | Found one Java-level deadlock |
| 线程RUNNABLE但不动 | 可能是死循环 | 堆栈反复出现在同一行 |
| 线程WAITING,锁占用者是RUNNABLE | 锁内执行耗时操作 | 锁占用者的堆栈中有IO/DB调用 |
7.3 一次成功定位的关键点
- 第一时间做线程dump:问题出现时立即保存现场,错过了可能就再也复现不了
- 连续采样:单次dump只能看到"此时此刻",多次才能判断"持续多久"
- 寻找锁地址:把
waiting to lock的地址复制出来,全文搜索找占用者 - 关注业务代码:不要只看框架堆栈,一定要追到自己的业务代码行
7.4 防止类似问题的编码原则
// ❌ 错误:锁内包含耗时操作 synchronized(lock) { databaseCall(); // 网络IO httpRequest(); // 网络IO fileWrite(); // 磁盘IO complexCalcuation(); // 大量计算 } // ✅ 正确:只锁必要的最小范围 Object result = expensiveOperation(); // 锁外执行 synchronized(lock) { sharedState.update(result); // 只锁状态修改 }八、写在最后
这次排查让我深刻体会到:
jstack是Java开发者最锋利的瑞士军刀,掌握它就能应对80%的线程问题
不要被表象迷惑:WAITING状态本身不是bug,谁持有锁才是关键
代码审查的盲区:锁的范围往往是code review容易忽略的地方