[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<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 栈信息，发生死锁：

从栈信息中，我们可以获得以下信息：

发生死锁现象
发生死锁的相关线程
线程获取哪个锁，又再等待什么锁

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 栈信息，发生死锁：

和上个栈信息非常相似，发生了死锁现象。但，丢失了很重要的一个信息“线程获得哪个锁，又在申请哪个锁”，这可能就是 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 ，查看栈信息：

存在 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 多次线程栈对比

多次获取线程栈，特定线程长期停留在一个运行代码。

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<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 超时后，查看堆栈信息：

可见，存在 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 后，查看线程栈信息：

共有 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 后，查看线程栈信息：

可见有 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();
}