基於 Java 線程棧的問題排查

時間  2020-04-24
標籤 基於 java 線程 問題 排查 欄目 Java 简体版
原文   原文鏈接
除日誌外，還有沒有別的方式跟蹤線上服務問題呢？或者，跟蹤並排除日誌裏沒法發現的問題？

方法固然是有的，就是經過現場快照定位並發現問題。咱們所說的現場，主要指這兩方面：git

  1. Java 線程棧。線程棧是Java線程工做的快照，能夠得到當前線程在作什麼；
  2. Java 內存堆。堆是JVM的內存快照，能夠獲取內存分配相關信息。

今天，咱們從 Java 線程角度，研究下基於線程棧若是排除問題。redis

1. Java 線程狀態變換

在正式介紹線程棧以前，有必要先了解下 Java 線程的相關狀態。

image

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 獲取棧

  1. jstack pid
  2. kill -3 pid
強烈建議使用 jstack 命令！一者，方便重定向；兩者，最大限度的避免 kill 這種高危命令的使用。

3.2 棧信息

image

核心信息：併發

  • 線程名。務必給線程起一個優雅的名字；
  • Java 線程 id。全局惟一，16進制顯示；
  • Native 線程 id。OS 線程id，16進制，與系統資源對應起來；
  • 狀態。線程所處狀態，最關心 RUNNABLE 狀態，實實在在消耗 CPU；
  • 鎖信息。獲取鎖、等待鎖；
  • 調用棧信息。方法調用鏈，類、方法、代碼行號，問題排查關鍵；

3.3 線程棧視角

從線程中獲取信息，有兩個視角。

  1. 單次線程棧app

    • 總線程數量
    • 是否發生死鎖
    • 線程所處狀態
    • 線程調用棧

  2. 屢次線程棧ide

    • 是否一直執行同一段代碼
    • 是否一直等待同一個鎖
通常會導出多份線程棧，共 10 份，每一個 2s 打一份。

3. 問題排查

線程棧不一樣於日誌，是程序運行時的快照，能夠定位不少詭異問題。

3.1 死鎖

死鎖是程序最爲嚴重的問題，致使進程 hold 在那，沒法處理正常請求。

image

死鎖發生存在幾個條件：oop

  1. 存在互斥條件；
  2. 保持並請求資源；
  3. 不能剝奪資源；
  4. 出現環路等待
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<String> object(){
    DeferredResult<String> result = new DeferredResult<>(10 * 1000L, "TimeOut");
    CompletableFuture<String> r1 = CompletableFuture.supplyAsync(this::objectMethod1, this.deadlockExecutor);
    CompletableFuture<String> r2 = CompletableFuture.supplyAsync(this::objectMethod2, this.deadlockExecutor);
    CompletableFuture.allOf(r1, r2).thenRun( ()-> result.setResult("SUCCESS"));
    return result;
}

請求 /deadlock/object 返回超時，打印 Java 棧信息，發生死鎖：
image測試

從棧信息中，咱們能夠得到如下信息：ui

  1. 發生死鎖現象
  2. 發生死鎖的相關線程
  3. 線程獲取哪一個鎖，又再等待什麼鎖
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<String> lock(){
    DeferredResult<String> result = new DeferredResult<>(10 * 1000L, "TimeOut");
    CompletableFuture<String> r1 = CompletableFuture.supplyAsync(this::lockMethod1, this.deadlockExecutor);
    CompletableFuture<String> r2 = CompletableFuture.supplyAsync(this::lockMethod2, this.deadlockExecutor);
    CompletableFuture.allOf(r1, r2).thenRun( ()-> result.setResult("SUCCESS"));
    return result;
}

請求 /deadlock/lock 返回超時，打印 Java 棧信息，發生死鎖：
image

和上個棧信息很是類似，發生了死鎖現象。但，丟失了很重要的一個信息「線程得到哪一個鎖，又在申請哪一個鎖」，這可能就是 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<String> manyThreads(@PathVariable int tasks){
        DeferredResult<String> result = new DeferredResult<>(10 * 1000L, "TimeOut");
        CompletableFuture<String>[] futures = new CompletableFuture[tasks];
        for (int i=0;i<tasks;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 ，查看棧信息：
image

存在 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<String> highCpu(@PathVariable long loop){
        DeferredResult<String> result = new DeferredResult<>(10 * 1000L, "TimeOut");
        CompletableFuture.supplyAsync(()->{
            for (int i=0;i<loop;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 屢次線程棧對比
屢次獲取線程棧，特定線程長期停留在一個運行代碼。

image

3.3.2 線程跟蹤
先獲得高 CPU 線程，在經過 nid 與線程棧線程對應，從而定位問題線程。
  1. top -Hp pid。獲取高 CPU 的線程號；
  2. 將線程號轉換爲 16 進制；
  3. 在線程棧中經過 nid 查找對應的線程；

3.4 資源不足

各類 pool 最多見問題。

Pool 工做原理：
image

測試代碼以下：

@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<String> lowReource(@PathVariable int batch){
        DeferredResult<String> result = new DeferredResult<>(10 * 1000L, "TimeOut");
        CompletableFuture<String>[] futures = new CompletableFuture[batch];
        for (int i=0;i<batch;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<String>)(redisConnection -> {
                sleepForMs(5000);
                return getCurrentTime() + redisConnection;
            }));
        }catch (Exception e){
            e.printStackTrace();
        }
        return "ERROR";

    }
}

請求 /low-resource/1000 超時後，查看堆棧信息：
image

可見，存在 998 個線程在等待 Jedis 資源。

3.5 鎖級聯

線程能夠造成本身的依賴鏈條，增長問題排查的難度。
3.5.1 Future 級聯

代碼以下：

@RequestMapping("future")
public DeferredResult<String> future(){
    DeferredResult<String> result = new DeferredResult<>(10 * 1000L, "TimeOut");

    Future<String> future = this.executorService.submit(()->{
        sleepForMs(5000);
        return getCurrentTime();
    });

    CompletableFuture<String>[] futures = new CompletableFuture[CONCURRENT_COUNT];
    for (int i=0;i<CONCURRENT_COUNT;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 後，查看線程棧信息：

image

共有 100 個線程在 future.get 處進行等待。

3.5.2 Guave Cache 級聯
Guava Cache 是最經常使用的 Local Cache，其內部作了併發處理，讓多個線程請求同一個 Key，會發生什麼事情呢？

測試代碼以下：

private final LoadingCache<String, String> cache;

public WaitChainController(){
    cache = CacheBuilder.newBuilder()
            .build(new CacheLoader<String, String>() {
                @Override
                public String load(String s) throws Exception {
                    sleepForMs(5000);
                    return getCurrentTime();
                }
            });
}
@RequestMapping("guava-cache")
public DeferredResult<String> guavaCache(){
    DeferredResult<String> result = new DeferredResult<>(10 * 1000L, "TimeOut");
    CompletableFuture<String>[] futures = new CompletableFuture[CONCURRENT_COUNT];
    for (int i=0;i<CONCURRENT_COUNT;i++){
        futures[i] = CompletableFuture.supplyAsync(this::loadFromGuava, executorService);
    }
    CompletableFuture.allOf(futures).thenRun(()->result.setResult("SUCCESS"));
    return result;
}

訪問 /wait-chain/guava-cache 後，查看線程棧信息：
image

可見有 98 個線程在 Sync.get 處等待，整個現象和 Future 很是類似。

3.5.3 Logger 級聯
日誌是最經常使用的組件，也是最容易忽略的組件，若是多個線程同時訪問日誌的寫操做，會產生什麼精緻的？

測試代碼以下：

@RequestMapping("logger")
public DeferredResult<String> logger(){
    DeferredResult<String> result = new DeferredResult<>(10 * 1000L, "TimeOut");
    CompletableFuture<String>[] futures = new CompletableFuture[CONCURRENT_COUNT];
    for (int i=0;i<CONCURRENT_COUNT;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 後，查看線程棧信息.

寫堆棧:
image
從日誌中可見，Wait-Chain-Thread-52 線程正在執行文件寫操做。

等待棧:
image
而有 98 個線程處於等待鎖的狀態。

4. 小結

Java 線程棧是線程運行時快照，能夠幫助咱們定位不少問題。掌握這一技能會讓咱們在平常工做中駕輕就熟。

最後附上 項目源碼

我的微信

掃一掃，添加個人微信，一塊兒交流共同成長（備註爲技術學習）

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程