线程级耗时统计工具类TimeWatcher

线程级耗时统计工具类TimeWatcher

先看效果

• 假设我们的业务代码逻辑是这样的
  

• 那么最终的日志打印效果为（注：此为美化输出，也可设置为常规一行输出，还可自定义）

  2024-11-08T23:48:53.390+08:00  INFO 31472 --- [nio-8080-exec-1] c.i.c.filter.TimeWatcherFilter           : consume time -> 
  1....................................987ms @ request-uri -> /user-info
  |--1.1...............................964ms @ TestController#userInfo
  |--|--1.1.1..........................961ms @ 查询用户
  |--|--|--1.1.1.1.....................158ms @ 查询用户基本信息
  |--|--|--1.1.1.2......................84ms @ 查询用户安全信息
  |--|--|--1.1.1.3.....................171ms @ 查询用户拥有的角色
  |--|--|--1.1.1.4.....................206ms @ 根据角色查询api权限
  |--|--|--|--1.1.1.4.1.................53ms @ 查询角色关联的菜单
  |--|--|--|--1.1.1.4.2................152ms @ 查询菜单关联的api权限
  |--|--|--1.1.1.5.....................125ms @ 查询用户直接关联的api权限
  |--|--|--1.1.1.6.....................156ms @ 组装数据
  |--|--|--1.1.1.7......................56ms @ 加密数据
  

工具类获取方式一：使用作者的常用工具包

提示：如果你不想引入作者的工具包，那么你可以直接看获取方式二

第一步：引入作者的常用工具包

<!-- 作者常用工具包 -->
<dependency>
    <groupId>com.idea-aedi</groupId>
    <artifactId>common-spring</artifactId>
    <version>2100.10.7.LTS17</version> <!--jdk17-->
    <!--<version>2100.10.7.LTS8</version>--> <!--jdk8-->
</dependency>

<!-- aop（因为作者还封装了个注解进行支持，要用注解的话需要引入aop） -->
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

第二步：启用耗时统计器

/**
 * 开启耗时监控
 * <pre>
 * 注：默认情况下，会：
 *    1.对所有被{@link WatchTime}注解标注的方法进行耗时统计
 *    2.对所有Controller类下的方法进行耗时统计
 *    
 *    当然这些你都可以通过在这里通过指定{@link TimeWatcher}注解的相关属性来进行修改
 * </pre>
 */
@EnableFeature(
        enableTimeWatcher = @TimeWatcher 
)
@SpringBootApplication
public class StartUp {
    
    public static void main(String[] args) {
        SpringApplication.run(StartUp.class, args);
    }
}

第三步：使用耗时器统计器

• 使用方式一：通过注解（示例）

   @WatchTime(taskName = "查询用户拥有的角色")
   public Collection<Long> queryRole(Long userId) {
       ...
   }
  

• 使用方式二：使用工具类（示例）

  // 示例一
  try {
      WatchTimeUtil.start("查询用户基本信息");
      mockLogic();
  } finally {
      WatchTimeUtil.stop();
  }
  
  // 示例二
  WatchTimeUtil.voidWatch("查询用户安全信息", () -> mockLogic()); // 方法无返回值
  //Object returnVal = WatchTimeUtil.watch("查询用户安全信息", () -> mockLogic()); // 方法有返回值
  

获取方式二：直接使用工具类

第一步：复制此核心工具类进自己的项目

import com.alibaba.fastjson2.JSON;
import org.apache.commons.lang3.StringUtils;

import javax.annotation.Nonnull;
import java.util.ArrayList;
import java.util.LinkedList;
import java.util.List;
import java.util.Objects;
import java.util.function.Consumer;
import java.util.function.Function;


/**
 * 耗时统计工具
 *
 * @author <font size = "20" color = "#3CAA3C"><a href="https://gitee.com/JustryDeng">JustryDeng</a></font> <img
 * src="https://gitee.com/JustryDeng/shared-files/raw/master/JustryDeng/avatar.jpg" />
 * @since 2100.10.7.LTS17
 */
public final class WatchTimeUtil {
    
    /** 初始化标识 */
    private static final ThreadLocal<Boolean> initThreadLocal = ThreadLocal.withInitial(() -> false);
    
    /** 存放执行中任务的ThreadLocal */
    private static final ThreadLocal<LinkedList<TaskInfo>> runningTaskThreadLocal = new ThreadLocal<>();
    
    /** 存放已结束任务的ThreadLocal */
    private static final ThreadLocal<LinkedList<TaskInfo>> endTaskThreadLocal = new ThreadLocal<>();
    
    /** 存放最大序号的ThreadLocal */
    private static final ThreadLocal<String> maxTaskNoThreadLocal = new ThreadLocal<>();
    
    /**
     * 管理器
     */
    public static class Manager {
    
        /**
         * 初始化
         */
        public static void init() {
            if (initThreadLocal.get()) {
                throw new IllegalStateException("It has already been initialized, please do not initialize it repeatedly.");
            }
            initThreadLocal.set(true);
            runningTaskThreadLocal.set(new LinkedList<>());
            endTaskThreadLocal.set(new LinkedList<>());
        }
    
        /**
         * 初始化
         */
        public static void initSilence() {
            if (initThreadLocal.get()) {
                return;
            }
            initThreadLocal.set(true);
            runningTaskThreadLocal.set(new LinkedList<>());
            endTaskThreadLocal.set(new LinkedList<>());
        }
    
        /**
         * 所有耗时统计任务当前是否都已结束
         */
        public static boolean currIsEnd() {
            LinkedList<TaskInfo> list = runningTaskThreadLocal.get();
            return list == null || list.size() == 0;
        }
    
        /**
         * 获取已完成的任务集合
         */
        public static List<TaskInfo> getEndTaskList() {
            return new ArrayList<>(endTaskThreadLocal.get());
        }
    
        /**
         * 获取进行中的任务集合
         */
        public static List<TaskInfo> getIngTaskList() {
            return new ArrayList<>(runningTaskThreadLocal.get());
        }
        
        /**
         * 清空
         */
        public static void clear() {
            runningTaskThreadLocal.remove();
            endTaskThreadLocal.remove();
            maxTaskNoThreadLocal.remove();
            initThreadLocal.remove();
        }
        
        /**
         * 获取下一个执行序号
         */
        public static String nextNo() {
            TaskInfo taskInfo = runningTaskThreadLocal.get().peekFirst();
            String maxNo = maxTaskNoThreadLocal.get();
            String nextNo;
            if (taskInfo == null) {
                if (maxNo == null) {
                    nextNo = "1";
                } else {
                    nextNo = String.valueOf(Long.parseLong(maxNo.split("\\.")[0]) + 1);
                }
            } else {
                Objects.requireNonNull(maxNo, "maxNo should not be null.");
                String parentNo = taskInfo.getTaskNo();
                String[] parentNoArr = parentNo.split("\\.");
                String[] maxNoArr = maxNo.split("\\.");
                long subNo;
                if (maxNoArr.length > parentNoArr.length) {
                    subNo = Long.parseLong(maxNoArr[parentNoArr.length]) + 1;
                } else {
                    subNo = 1;
                }
                nextNo = parentNo + "." + subNo;
            }
            return nextNo;
        }
    
        /**
         * 按照任务序号排序
         */
        public static void sortByTaskNo(List<TaskInfo> taskInfoList) {
            if (taskInfoList == null) {
                return;
            }
            taskInfoList.sort(
                    (x, y) -> {
                        String xNo = x.getTaskNo();
                        String yNo = y.getTaskNo();
                        String[] xNoArr = xNo.split("\\.");
                        String[] yNoArr = yNo.split("\\.");
                        int minLength = Math.min(xNoArr.length, yNoArr.length);
                        for (int i = 0; i < minLength; i++) {
                            long xVal = Long.parseLong(xNoArr[i]);
                            long yVal = Long.parseLong(yNoArr[i]);
                            if (xVal < yVal) {
                                return -1;
                            }
                            if (xVal > yVal) {
                                return 1;
                            }
                        }
                        return Integer.compare(xNoArr.length, yNoArr.length);
                    }
            );
        }
        
        /**
         * 耗时信息
         */
        public static String prettyResult(@Nonnull List<TaskInfo> endTaskList) {
            StringBuilder sb = new StringBuilder();
            int size = endTaskList.size();
            if (size == 0) {
                sb.append("no tasks time info.");
                return sb.toString();
            }
            if (size == 1) {
                TaskInfo taskInfo = endTaskList.get(0);
                long consumeMilli = (taskInfo.getEndTime() - taskInfo.getStartTime()) / 1000000;
                return consumeMilli + "ms @ " + taskInfo.getTaskName();
            }
            Manager.sortByTaskNo(endTaskList);
            for (TaskInfo taskInfo : endTaskList) {
                String no = taskInfo.getTaskNo();
                String[] noArr = no.split("\\.");
                sb.append("\n");
                sb.append(StringUtils.rightPad("|--".repeat(Math.max(0, noArr.length - 1)) + no, 4, "."));
                long consumeMilli = (taskInfo.getEndTime() - taskInfo.getStartTime()) / 1000000;
                sb.append(StringUtils.leftPad(consumeMilli + "", 6, "."))
                        .append("ms")
                        .append(" @ ")
                        .append(taskInfo.getTaskName());
            }
            return sb.toString();
        }
        
        /**
         * 耗时信息
         */
        public static String result(@Nonnull List<TaskInfo> endTaskList) {
            int size = endTaskList.size();
            if (size == 0) {
                return "no tasks time info.";
            }
            if (size == 1) {
                TaskInfo taskInfo = endTaskList.get(0);
                long consumeMilli = (taskInfo.getEndTime() - taskInfo.getStartTime()) / 1000000;
                return consumeMilli + "ms @ " + taskInfo.getTaskName();
            }
            Manager.sortByTaskNo(endTaskList);
            List<String> list = new ArrayList<>();
            for (TaskInfo taskInfo : endTaskList) {
                StringBuilder sb = new StringBuilder();
                String no = taskInfo.getTaskNo();
                sb.append("taskNo: ");
                sb.append(no);
                sb.append(", ");
                long consumeMilli = (taskInfo.getEndTime() - taskInfo.getStartTime()) / 1000000;
                sb.append("consumeTime: ");
                sb.append(consumeMilli)
                        .append("ms, ")
                        .append("taskName: ")
                        .append(taskInfo.getTaskName());
                list.add(sb.toString());
            }
            return JSON.toJSONString(list);
        }
    }
    
    /**
     * 开始统计
     * <pre>
     * 若计时器尚未初始化，则会静默忽略当前操作
     * </pre>
     *
     * @param taskName 任务名
     */
    public static void start(String taskName) {
        if (!initThreadLocal.get()) {
            return;
        }
        TaskInfo taskInfo = new TaskInfo();
        String no = Manager.nextNo();
        taskInfo.setTaskNo(no);
        taskInfo.setTaskName(taskName);
        taskInfo.setStartTime(System.nanoTime());
        runningTaskThreadLocal.get().addFirst(taskInfo);
        maxTaskNoThreadLocal.set(no);
    }
    
    /**
     * 结束统计
     * <pre>
     * 若计时器尚未初始化，则会静默忽略当前操作
     * </pre>
     */
    public static void stop() {
        if (!initThreadLocal.get()) {
            return;
        }
        LinkedList<TaskInfo> runningTaskDeque = runningTaskThreadLocal.get();
        if (runningTaskDeque.size() == 0) {
            return;
        }
        TaskInfo taskInfo = runningTaskDeque.pollFirst();
        taskInfo.setEndTime(System.nanoTime());
        endTaskThreadLocal.get().addLast(taskInfo);
    }
    
    /**
     * 执行
     *
     * @param taskName 任务名
     * @param function 业务逻辑块
     * @param param 参数
     *
     * @return 逻辑执行结果
     */
    public static <P, R> R watch(@Nonnull String taskName, Function<P, R> function, P param) {
        try {
            start(taskName);
            return function.apply(param);
        } finally {
            stop();
        }
    }
    
    /**
     * 执行
     *
     * @param taskName 任务名
     * @param function 业务逻辑块
     *
     * @return 执行结果
     */
    public static <R> R watch(@Nonnull String taskName, InnerNoArgFunction<R> function) {
        try {
            start(taskName);
            return function.apply();
        } finally {
            stop();
        }
    }
    
    /**
     * 执行
     *
     * @param taskName 任务名
     * @param consumer 业务逻辑块
     * @param param 参数
     */
    public static <P> void voidWatch(@Nonnull String taskName, Consumer<P> consumer, P param) {
        try {
            start(taskName);
            consumer.accept(param);
        } finally {
            stop();
        }
    }
    
    /**
     * 执行
     *
     * @param taskName 任务名
     * @param consumer 业务逻辑块
     */
    public static void voidWatch(@Nonnull String taskName, InnerNoArgConsumer consumer) {
        try {
            start(taskName);
            consumer.accept();
        } finally {
            stop();
        }
    }
    
    /**
     * 耗时信息
     */
    public static String prettyResult() {
        if (!initThreadLocal.get()) {
            throw new IllegalStateException("Not initialized yet. You could do it by 'TimeWatchUtil.Manager.init()', "
                    + "and don't forget to clear him last by 'TimeWatchUtil.Manager.clear()'");
        }
        if (!Manager.currIsEnd()) {
            throw new IllegalStateException("There are also running tasks. " + Manager.getIngTaskList());
        }
        List<TaskInfo> endTaskList = Manager.getEndTaskList();
        return Manager.prettyResult(endTaskList);
    }
    
    /**
     * 耗时信息
     */
    public static String result() {
        if (!initThreadLocal.get()) {
            throw new IllegalStateException("Not initialized yet. You could do it by 'TimeWatchUtil.Manager.init()', "
                    + "and don't forget to clear him last by 'TimeWatchUtil.Manager.clear()'");
        }
        if (!Manager.currIsEnd()) {
            throw new IllegalStateException("There are also running tasks. " + Manager.getIngTaskList());
        }
        List<TaskInfo> endTaskList = Manager.getEndTaskList();
        return Manager.result(endTaskList);
    }
    
    /**
     * 任务信息
     */
    public static class TaskInfo {
        
        /** 执行序号（格式形如：xxx.xxx.xxx） */
        private String taskNo;
        
        /** 任务名 */
        private String taskName;
        
        /** 开始时间（纳秒） */
        private long startTime;
        
        /** 结束时间（纳秒） */
        private long endTime;
    
        public String getTaskNo() {
            return taskNo;
        }
    
        public void setTaskNo(String taskNo) {
            this.taskNo = taskNo;
        }
    
        public String getTaskName() {
            return taskName;
        }
    
        public void setTaskName(String taskName) {
            this.taskName = taskName;
        }
    
        public long getStartTime() {
            return startTime;
        }
    
        public void setStartTime(long startTime) {
            this.startTime = startTime;
        }
    
        public long getEndTime() {
            return endTime;
        }
    
        public void setEndTime(long endTime) {
            this.endTime = endTime;
        }
    
        @Override
        public String toString() {
            return "TaskInfo{" +
                    "no='" + taskNo + '\'' +
                    ", taskName='" + taskName + '\'' +
                    ", startTime=" + startTime +
                    ", endTime=" + endTime +
                    '}';
        }
    }
    
    /**
     * (non-javadoc)
     */
    @FunctionalInterface
    public interface InnerNoArgFunction<R> {
        R apply();
    }
    
    /**
     * (non-javadoc)
     */
    @FunctionalInterface
    public interface InnerNoArgConsumer {
        void accept();
    }
    
}

第二步：配置总开关过滤器（示例）

@Component
public class TimeWatcherDemoFilter implements Filter {
    
    private final boolean prettyResult = true;
    
    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException,
            ServletException {
        HttpServletRequest httpServletRequest = null;
        if (request instanceof HttpServletRequest) {
            httpServletRequest = (HttpServletRequest)request;
        }
        try {
            WatchTimeUtil.Manager.init();
            String requestUri = "";
            if (httpServletRequest != null) {
                requestUri = httpServletRequest.getRequestURI();
            }
            WatchTimeUtil.start("request-uri -> " + requestUri);
            chain.doFilter(request, response);
        } finally {
            try {
                WatchTimeUtil.stop();
                if (log.isInfoEnabled()) {
                      log.info("consume time -> {}", prettyResult ? WatchTimeUtil.prettyResult() : WatchTimeUtil.result());
                 }
            } catch (Exception e) {
                log.warn("WatchTimeUtil.stop occur exception. e.getMessage() -> {}", e.getMessage());
            }
            WatchTimeUtil.Manager.clear();
        }
    }
}

第三步（可选）：自定义aop注解

// 这里仅给出切面类核心逻辑demo
 try {
     String taskName;
     if (useDefaultAnnoValue || StringUtils.isBlank(annotation.value())) {
         taskName = clazzSimpleName + "#" + methodName;
     } else {
         taskName = annotation.value();
     }
     WatchTimeUtil.start(taskName);
     obj = methodInvocation.proceed();
 } finally {
     WatchTimeUtil.stop();
 }

第四步：使用耗时器统计器

• 使用方式一：通过注解（假设你自定义的注解名为@WatchTime）

   @WatchTime(taskName = "查询用户拥有的角色")
   public Collection<Long> queryRole(Long userId) {
       ...
   }
  

• 使用方式二：使用工具类（示例）

  // 示例一
  try {
      WatchTimeUtil.start("查询用户基本信息");
      mockLogic();
  } finally {
      WatchTimeUtil.stop();
  }
  
  // 示例二
  WatchTimeUtil.voidWatch("查询用户安全信息", () -> mockLogic()); // 方法无返回值
  //Object returnVal = WatchTimeUtil.watch("查询用户安全信息", () -> mockLogic()); // 方法有返回值
  

相关资料

• 基于获取方式一的示例代码（timewatcher/demo分支）