利用ThreadLocal和StopWatch实现一个简单的埋点计时工具

---

前言

写代码的时候，我们有时候需要获取方法调用详细耗时。

一、一般做法

一般情况下，对于接口调用耗时，简单的做法都是通过System.currentTimeMillis()来获取时间，然后分别相减，获取某个代码块的执行耗时；

	public ApiResponseEntity exTest() {
        long start = System.currentTimeMillis();
        BizException bizException = new BizException("myTest");
        System.out.println("cost:" + (System.currentTimeMillis() - start));
        throw bizException;
    }

简单逻辑还好，但是如果我们的代码嵌套比较多，或者调用链路较长，该方法就显得不怎么合适了。

二、更优雅的做法

1. 考虑线程的概念

一般情况下，我们的方法调用都是发生在一个线程里，特别是一个网络请求。这样的话，咱们就可以考虑使用ThreadLocal来做这个事儿了。

2. 考虑如何计时

springboot启动的时候会显示花费了多少时间。跟代码进去发现，发现使用的StopWatch进行的计时。此处我们也使用StopWatch来进行计时。

3. 优化的计时方法类

public class StopWatchUtils {

    public static ThreadLocal<StopWatch> CURRENT_STOP_WATCH = new ThreadLocal<>();

    public static void start() {
        if (Objects.nonNull(CURRENT_STOP_WATCH.get())) {
            CURRENT_STOP_WATCH.remove();
        }
        StopWatch stopWatch = new StopWatch();
        stopWatch.start();
        CURRENT_STOP_WATCH.set(stopWatch);
        print(null);
    }

    public static void check() {
        if (Objects.nonNull(CURRENT_STOP_WATCH.get())) {
            StopWatch stopWatch = CURRENT_STOP_WATCH.get();
            stopWatch.stop();
            print(stopWatch);
        } else {
            print(null);
        }
        CURRENT_STOP_WATCH.remove();
        StopWatch newStopWatch = new StopWatch();
        newStopWatch.start();
        CURRENT_STOP_WATCH.set(newStopWatch);
    }

    public static void stop() {
        if (Objects.isNull(CURRENT_STOP_WATCH.get())) {
            return;
        }
        StopWatch stopWatch = CURRENT_STOP_WATCH.get();
        stopWatch.stop();
        print(stopWatch);
        CURRENT_STOP_WATCH.remove();
    }

    private static void print(StopWatch stopWatch) {
        Thread thread = Thread.currentThread();
        StackTraceElement[] stackTrace = thread.getStackTrace();
        StackTraceElement stackTraceElement = stackTrace[3];
        StringJoiner stringJoiner = new StringJoiner(":");
        stringJoiner.add(thread.getName())
                .add(stackTraceElement.getClassName())
                .add(String.valueOf(stackTraceElement.getLineNumber()));
        if (Objects.nonNull(stopWatch)) {
            stringJoiner.add(String.valueOf(stopWatch.getTotalTimeSeconds()));
        } else {
            stringJoiner.add("start");
        }
        System.out.println(stringJoiner.toString());
    }

}

使用工具类的小例子

public ApiResponseEntity<String> myTest() {
        StopWatchUtils.start();
        System.out.println("in");
        try {
            Thread.sleep(1200);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        new Thread(() ->{
            StopWatchUtils.check();
            try {
                Thread.sleep(1300);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            StopWatchUtils.check();
        }).start();
        StopWatchUtils.check();
        System.out.println("middle");
        try {
            Thread.sleep(1200);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        StopWatchUtils.check();
        System.out.println("in");
        try {
            Thread.sleep(1200);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        StopWatchUtils.stop();
        return ApiResponseEntity.ofSuccess("myTest");
    }

可以看到我在方法调用里专门起了一个新线程，不过在显示耗时的时候，由于我们打印了线程的name，所以可以根据线程的name来进行区分：

http-nio-7001-exec-1:com.xxxx.xxxx.xxxx.test.TestController:24:start
in
Thread-242:com.xxxx.xxxx.xxxx.test.TestController:32:start
http-nio-7001-exec-1:com.xxxx.xxxx.xxxx.test.TestController:40:1.206
middle
http-nio-7001-exec-1:com.xxxx.xxxx.xxxx.test.TestController:47:1.202
in
Thread-242:com.xxxx.xxxx.xxxx.test.TestController:38:1.303
http-nio-7001-exec-1:com.xxxx.xxxx.xxxx.test.TestController:54:1.202

1. 如果光看线程http-nio-7001-exec-1对应的记录，可以发现每次距离上次调用微微大于了1.2秒，也符合我们让线程sleep了1.2秒的逻辑。
2. 如果光看线程Thread-242对应的记录，可以发现每次距离上次调用微微大于了1.3秒，也符合我们让线程sleep了1.3秒的逻辑。

总结

1. 不要害怕ThreadLocal，放心大胆的用。
2. ThreadLocal还有个比较常用的场景，就是自定义interceptor，然后在preHandle方法里set一下ThreadLocal，然后在afterCompletion中remove掉ThreadLocal。（不可大意，线上外包写的代码出现过这个漏洞，被黑客攻击来着，还好没有影响数据）