java线程卡住排查_基于 Java 线程栈 排查问题
除日志外，還有沒有別的方式跟蹤線上服務問題呢？或者，跟蹤并排除日志里無法發現的問題？
方法當然是有的，就是通過現場快照定位并發現問題。我們所說的現場，主要指這兩方面：
Java 線程棧。線程棧是Java線程工作的快照，可以獲得當前線程在做什么；
Java 內存堆。堆是JVM的內存快照，可以獲取內存分配相關信息。
今天，我們從 Java 線程角度，研究下基于線程棧如果排除問題。
1. Java 線程狀態變換
在正式介紹線程棧之前，有必要先了解下 Java 線程的相關狀態。
Java 線程就是在這幾個狀態間完成自己的整個生命周期。
狀態
是夠消耗 CPU
描述RUNNABLE
不確定
運行中 或者 就緒
WAITING
不消耗
1. object monitor 2. unpark
TIME_WAITING
不消耗
1. object monitor 2. unpark 3. sleep
BLOCKED
不消耗
object monitor
2. Java 線程棧
線程棧是問題的第一現場，從線程棧中可以獲得很多日志以外的瞬時信息。
2.1 獲取棧
jstack pid
kill -3 pid
強烈建議使用 jstack 命令！一者，方便重定向；二者，最大限度的避免 kill 這種高危命令的使用。
3.2 棧信息
核心信息：
線程名。務必給線程起一個優雅的名字；
Java 線程 id。全局唯一，16進制顯示；
Native 線程 id。OS 線程id，16進制，與系統資源對應起來；
狀態。線程所處狀態，最關心 RUNNABLE 狀態，實實在在消耗 CPU；
鎖信息。獲取鎖、等待鎖；
調用棧信息。方法調用鏈，類、方法、代碼行號，問題排查關鍵；
3.3 線程棧視角
從線程中獲取信息，有兩個視角。
單次線程棧
總線程數量
是否發生死鎖
線程所處狀態
線程調用棧
多次線程棧
是否一直執行同一段代碼
是否一直等待同一個鎖
一般會導出多份線程棧，共 10 份，每個 2s 打一份。
3. 問題排查
線程棧不同于日志，是程序運行時的快照，可以定位很多詭異問題。
3.1 死鎖
死鎖是程序最為嚴重的問題，導致進程 hold 在那，無法處理正常請求。
死鎖發生存在幾個條件：
存在互斥條件；
保持并請求資源；
不能剝奪資源；
出現環路等待
3.1.1 Object 死鎖
主要指使用 synchronized 關鍵字，通過對象鎖保護資源，導致的死鎖。
測試代碼如下：
private final Object objectA = new Object();
private final Object objectB = new Object();
private String objectMethod1(){
synchronized (this.objectA){
sleepForMs(10);
synchronized (this.objectB){
return getCurrentTime();
}
}
}
private String objectMethod2(){
synchronized (this.objectB){
sleepForMs(10);
synchronized (this.objectA){
return getCurrentTime();
}
}
}
private ExecutorService deadlockExecutor = Executors.newFixedThreadPool(20, new BasicThreadFactory
.Builder()
.namingPattern("DeadLock-Thread-%d")
.build()
);
@RequestMapping("object")
public DeferredResult object(){
DeferredResult result = new DeferredResult<>(10 * 1000L, "TimeOut");
CompletableFuture r1 = CompletableFuture.supplyAsync(this::objectMethod1, this.deadlockExecutor);
CompletableFuture r2 = CompletableFuture.supplyAsync(this::objectMethod2, this.deadlockExecutor);
CompletableFuture.allOf(r1, r2).thenRun( ()-> result.setResult("SUCCESS"));
return result;
}
請求 /deadlock/object 返回超時，打印 Java 棧信息，發生死鎖：
從棧信息中，我們可以獲得以下信息：
發生死鎖現象
發生死鎖的相關線程
線程獲取哪個鎖，又再等待什么鎖
3.1.2 Lock 死鎖
主要指使用 Lock 對象進行資源保護，從而導致的死鎖。
測試代碼如下：
private final Lock lockA = new ReentrantLock();
private final Lock lockB = new ReentrantLock();
private String lockMethod1(){
try {
this.lockA.lock();
sleepForMs(10);
try {
this.lockB.lock();
return getCurrentTime();
}finally {
this.lockB.unlock();;
}
}finally {
this.lockA.unlock();
}
}
private String lockMethod2(){
try {
this.lockB.lock();
sleepForMs(10);
try {
this.lockA.lock();
return getCurrentTime();
}finally {
this.lockA.unlock();;
}
}finally {
this.lockB.unlock();
}
}
@RequestMapping("lock")
public DeferredResult lock(){
DeferredResult result = new DeferredResult<>(10 * 1000L, "TimeOut");
CompletableFuture r1 = CompletableFuture.supplyAsync(this::lockMethod1, this.deadlockExecutor);
CompletableFuture r2 = CompletableFuture.supplyAsync(this::lockMethod2, this.deadlockExecutor);
CompletableFuture.allOf(r1, r2).thenRun( ()-> result.setResult("SUCCESS"));
return result;
}
請求 /deadlock/lock 返回超時，打印 Java 棧信息，發生死鎖：
和上個棧信息非常相似，發生了死鎖現象。但，丟失了很重要的一個信息“線程獲得哪個鎖，又在申請哪個鎖”，這可能就是 JVM 內置鎖和 AQS 家族的區別。
3.2 線程數過高
線程數過高，主要由于線程池的不合理使用，比如沒有設置最大線程數。
測試代碼：
@RestController
@RequestMapping("many-thread")
public class ManyThreadController {
private ExecutorService executorService = Executors.newCachedThreadPool(new BasicThreadFactory
.Builder()
.namingPattern("Many-Thread-%d")
.build()
);
@RequestMapping("/{tasks}")
public DeferredResult manyThreads(@PathVariable int tasks){
DeferredResult result = new DeferredResult<>(10 * 1000L, "TimeOut");
CompletableFuture[] futures = new CompletableFuture[tasks];
for (int i=0;i
futures[i] = CompletableFuture.supplyAsync(this::getValue, executorService);
}
CompletableFuture.allOf(futures).thenRun( ()-> result.setResult("SUCCESS"));
return result;
}
private String getValue() {
sleepForMs(50);
return getCurrentTime();
}
}
請求 /many-thread/2000 ，查看棧信息：
存在 1729 個相似線程，如果在次加大 loop ，還可能會出現異常信息，有興趣可以自行測試。
3.3 CPU 過高
一般是大集合處理或死循環導致。
測試代碼如下：
@RestController
@RequestMapping("high-cpu")
public class HighCPUController {
private ExecutorService executorService = Executors.newFixedThreadPool(1, new BasicThreadFactory
.Builder()
.namingPattern("High-CPU-%d")
.build()
);
@RequestMapping("/{loop}")
public DeferredResult highCpu(@PathVariable long loop){
DeferredResult result = new DeferredResult<>(10 * 1000L, "TimeOut");
CompletableFuture.supplyAsync(()->{
for (int i=0;i
try {
Math.cos(i + 10);
}catch (Exception e){
}
}
return getCurrentTime();
}, executorService).thenAccept(r->result.setResult(r));
return result;
}
}
請求 /high-cpu/100000000000, CPU 會飆升。
3.3.1 多次線程棧對比
多次獲取線程棧，特定線程長期停留在一個運行代碼。
3.3.2 線程跟蹤
先得到高 CPU 線程，在通過 nid 與線程棧線程對應，從而定位問題線程。
top -Hp pid。獲取高 CPU 的線程號；
將線程號轉換為 16 進制；
在線程棧中通過 nid 查找對應的線程；
3.4 資源不足
各種 pool 最常見問題。
Pool 工作原理：
測試代碼如下：
@RestController
@RequestMapping("low-resource")
public class LowResourceController {
private ExecutorService executorService = Executors.newCachedThreadPool(new BasicThreadFactory
.Builder()
.namingPattern("Low-Resource-%d")
.build()
);
@Autowired
private StringRedisTemplate redisTemplate;
@RequestMapping("/{batch}")
public DeferredResult lowReource(@PathVariable int batch){
DeferredResult result = new DeferredResult<>(10 * 1000L, "TimeOut");
CompletableFuture[] futures = new CompletableFuture[batch];
for (int i=0;i
futures[i] = CompletableFuture.supplyAsync(this::getValue, executorService);
}
CompletableFuture.allOf(futures).thenRun( ()-> result.setResult("SUCCESS"));
return result;
}
private String getValue() {
try {
return redisTemplate.execute((RedisCallback)(redisConnection -> {
sleepForMs(5000);
return getCurrentTime() + redisConnection;
}));
}catch (Exception e){
e.printStackTrace();
}
return "ERROR";
}
}
請求 /low-resource/1000 超時后，查看堆棧信息：
可見，存在 998 個線程在等待 Jedis 資源。
3.5 鎖級聯
線程可以形成自己的依賴鏈條，增加問題排查的難度。
3.5.1 Future 級聯
代碼如下：
@RequestMapping("future")
public DeferredResult future(){
DeferredResult result = new DeferredResult<>(10 * 1000L, "TimeOut");
Future future = this.executorService.submit(()->{
sleepForMs(5000);
return getCurrentTime();
});
CompletableFuture[] futures = new CompletableFuture[CONCURRENT_COUNT];
for (int i=0;i
futures[i] = CompletableFuture.supplyAsync(()->{
try {
return future.get();
}catch (Exception e){
}
return "ERROR";
}, executorService);
}
CompletableFuture.allOf(futures).thenRun(()->result.setResult("SUCCESS"));
return result;
}
訪問 /wait-chain/future 后，查看線程棧信息：
共有 100 個線程在 future.get 處進行等待。
3.5.2 Guave Cache 級聯
Guava Cache 是最常用的 Local Cache，其內部做了并發處理，讓多個線程請求同一個 Key，會發生什么事情呢？
測試代碼如下：
private final LoadingCache cache;
public WaitChainController(){
cache = CacheBuilder.newBuilder()
.build(new CacheLoader() {
@Override
public String load(String s) throws Exception {
sleepForMs(5000);
return getCurrentTime();
}
});
}
@RequestMapping("guava-cache")
public DeferredResult guavaCache(){
DeferredResult result = new DeferredResult<>(10 * 1000L, "TimeOut");
CompletableFuture[] futures = new CompletableFuture[CONCURRENT_COUNT];
for (int i=0;i
futures[i] = CompletableFuture.supplyAsync(this::loadFromGuava, executorService);
}
CompletableFuture.allOf(futures).thenRun(()->result.setResult("SUCCESS"));
return result;
}
訪問 /wait-chain/guava-cache 后，查看線程棧信息：
可見有 98 個線程在 Sync.get 處等待，整個現象和 Future 非常相似。
3.5.3 Logger 級聯
日志是最常用的組件，也是最容易忽略的組件，如果多個線程同時訪問日志的寫操作，會產生什么精致的？
測試代碼如下：
@RequestMapping("logger")
public DeferredResult logger(){
DeferredResult result = new DeferredResult<>(10 * 1000L, "TimeOut");
CompletableFuture[] futures = new CompletableFuture[CONCURRENT_COUNT];
for (int i=0;i
futures[i] = CompletableFuture.supplyAsync(this::writeLogger, executorService);
}
CompletableFuture.allOf(futures).thenRun(()->result.setResult("SUCCESS"));
return result;
}
private String writeLogger(){
for (int i = 0;i<10000;i++){
LOGGER.info("{}", i);
}
return getCurrentTime();
}
訪問 /wait-chain/logger 后，查看線程棧信息.
寫堆棧:
從日志中可見，Wait-Chain-Thread-52 線程正在執行文件寫操作。
等待棧:
而有 98 個線程處于等待鎖的狀態。
4. 小結
Java 線程棧是線程運行時快照，可以幫助我們定位很多問題。掌握這一技能會讓我們在日常工作中得心應手。
最后附上 項目源碼
總結
以上是生活随笔為你收集整理的java线程卡住排查_基于 Java 线程栈 排查问题的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 线程等待通知 linux,Java 线程
- 下一篇： java美元兑换,（Java实现） 美元