第1步：基本配置了解

Further Reading ： SpringBoot 统计API接口用时该使用过滤器还是拦截器?

第2步：通过LogInterceptor来统计信息

日志打印放afterCompletion是为了兼容异常场景也可以记录日志

import com.zhangziwa.practisesvr.utils.log.LogContext;
import com.zhangziwa.practisesvr.utils.log.ThreadMXBeanUtils;
import com.zhangziwa.practisesvr.utils.log.logUtils;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;
import java.time.Instant;
@Component
@Slf4j
public class LogInterceptor implements HandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        System.err.println("***LogInterceptor.preHandle***");
        LogContext.setTraceId(logUtils.genUUID());
        LogContext.initSqlCost();
        LogContext.initSqlCost();
        if (Boolean.TRUE.equals(ThreadMXBeanUtils.isThreadCpuTimeEnabled())) {
            LogContext.initCurrentThreadTime();
            LogContext.initCurrentThreadUserTime();
        }
        if (Boolean.TRUE.equals(ThreadMXBeanUtils.isThreadAllocatedMemoryEnabled())) {
            LogContext.initAllocatedBytes();
        }
        long startTime = Instant.now().toEpochMilli();
        request.setAttribute("startTime", startTime);
        log.warn("LogInterceptor.postHandle: Start processing request at {} - {}", Instant.now(), request.getRequestURI());
        return true;
    }
    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) {
        System.err.println("***LogInterceptor.postHandle***");
    }
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        System.err.println("***LogInterceptor.afterCompletion***");
        // 获取请求开始时间
        Long startTime = (Long) request.getAttribute("startTime");
        long executionCost = 0L;
        if (startTime != null) {
            executionCost = Instant.now().toEpochMilli() - startTime;
            int statusCode = response.getStatus();
            log.warn("LogInterceptor.postHandle: Finished processing request at {} - {} in {} ms. Status code: {}", Instant.now(), request.getRequestURI(), executionCost, statusCode);
        }
        String apiJson = logUtils.buildApiJsonLog(request, response, executionCost);
        log.info(apiJson);
        LogContext.clear();
    }
}

第3步：LogInterceptor用到的方法横展开

3.1、引入LogContext收纳上下文数据

import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLong;
public class LogContext {
    private static ThreadLocal sql_count = new InheritableThreadLocal<>();
    private static ThreadLocal sql_cost = new InheritableThreadLocal<>();
    private static ThreadLocal traceid = new InheritableThreadLocal<>();
    private static ThreadLocal acclocated_memory = new InheritableThreadLocal<>();
    private static ThreadLocal total_cpu_cost = new InheritableThreadLocal<>();
    private static ThreadLocal user_cpu_cost = new InheritableThreadLocal<>();
    public static void initSqlCount() {
        sql_count.set(new AtomicInteger(0));
    }
    public static void incrementSqlCount() {
        if (sql_count.get() == null) {
            sql_count.set(new AtomicInteger(0));
        }
        sql_count.get().incrementAndGet();
    }
    public static int getSqlCount() {
        return sql_count.get().intValue();
    }
    public static void initSqlCost() {
        sql_cost.set(new AtomicLong(0));
    }
    public static void incrementSqlCost(Long sqlCost) {
        if (sql_cost.get() == null) {
            sql_cost.set(new AtomicLong(0));
        }
        sql_cost.get().addAndGet(sqlCost);
    }
    public static Long getSqlCost() {
        return sql_cost.get().longValue();
    }
    public static void setTraceId(String traceId) {
        if (traceid.get() == null) {
            traceid.set(traceId);
        }
    }
    public static String getTraceId() {
        return traceid.get();
    }
    public static void initAllocatedBytes() {
        acclocated_memory.set(ThreadMXBeanUtils.getCurrentThreadAllocatedBytes());
    }
    public static void initCurrentThreadTime() {
        total_cpu_cost.set(ThreadMXBeanUtils.getCurrentThreadTime());
    }
    public static void initCurrentThreadUserTime() {
        user_cpu_cost.set(ThreadMXBeanUtils.getCurrentThreadUserTime());
    }
    public static void clear() {
        sql_count.remove();
        sql_cost.remove();
        traceid.remove();
        acclocated_memory.remove();
        total_cpu_cost.remove();
        user_cpu_cost.remove();
    }
}

3.2、引入CPU使用统计

配置文件可以配置是否开启统计

thread:
  cpu_time_enabled: true
  allocated_memory_enabled: true

import org.springframework.beans.factory.InitializingBean;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.stereotype.Component;
@Component
public class ThreadMXBeanConfig implements InitializingBean {
    @Value("${thread.cpu_time_enabled:true}")
    private static boolean isThreadCpuTimeEnabled;
    @Value("${thread.allocated_memory_enabled:true}")
    private static boolean isThreadAllocatedMemoryEnabled;
    @Override
    public void afterPropertiesSet() throws Exception {
        if (isThreadCpuTimeEnabled) {
            ThreadMXBeanUtils.setThreadCpuTimeEnabled(true);
        }
        if (isThreadAllocatedMemoryEnabled) {
            ThreadMXBeanUtils.setThreadAllocatedMemoryEnabled(true);
        }
    }
}

import com.sun.management.ThreadMXBean;
import java.lang.management.ManagementFactory;
public class ThreadMXBeanUtils {
    private static final ThreadMXBean threadMXBean = (ThreadMXBean) ManagementFactory.getThreadMXBean();
    public static void setThreadCpuTimeEnabled(boolean enabled) {
        threadMXBean.setThreadCpuTimeEnabled(enabled);
    }
    public static void setThreadAllocatedMemoryEnabled(boolean enabled) {
        threadMXBean.setThreadAllocatedMemoryEnabled(enabled);
    }
    public static Boolean isThreadCpuTimeEnabled() {
        return threadMXBean.isThreadCpuTimeEnabled();
    }
    public static Boolean isThreadAllocatedMemoryEnabled() {
        return threadMXBean.isThreadAllocatedMemoryEnabled();
    }
    public static long getCurrentThreadTime() {
        return threadMXBean.getCurrentThreadCpuTime() / 1_000_000L;
    }
    public static long getCurrentThreadUserTime() {
        return threadMXBean.getCurrentThreadUserTime() / 1_000_000L;
    }
    public static long getCurrentThreadAllocatedBytes() {
        return threadMXBean.getCurrentThreadAllocatedBytes();
    }
}

3.3、拼接日志信息

import com.zhangziwa.practisesvr.utils.JsonUtils;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import java.time.ZonedDateTime;
import java.time.format.DateTimeFormatter;
import java.util.LinkedHashMap;
import java.util.Map;
import java.util.UUID;
public class logUtils {
    public static String genUUID() {
        return UUID.randomUUID().toString().replace("-", "");
    }
    public static String buildApiJsonLog(HttpServletRequest request, HttpServletResponse response, long cost) {
        Map apiJsonMap = new LinkedHashMap<>();
        apiJsonMap.put("traceId", LogContext.getTraceId());
        apiJsonMap.put("end_date", DateTimeFormatter.ISO_ZONED_DATE_TIME.format(ZonedDateTime.now()));
        apiJsonMap.put("cost", cost);
        apiJsonMap.put("remoteHost", request.getRemoteHost());
        apiJsonMap.put("remoteAddr", request.getRemoteAddr());
        apiJsonMap.put("remotePort", request.getRemotePort());
        apiJsonMap.put("method", request.getMethod());
        apiJsonMap.put("requestURI", request.getRequestURI());
        apiJsonMap.put("status", response.getStatus());
        apiJsonMap.put("requestContentLength", request.getContentLengthLong());
        apiJsonMap.put("sql_count", LogContext.getSqlCost());
        if (Boolean.TRUE.equals(ThreadMXBeanUtils.isThreadCpuTimeEnabled())) {
            apiJsonMap.put("currentThreadTime", ThreadMXBeanUtils.getCurrentThreadTime());
            apiJsonMap.put("currentThreadUserTime", ThreadMXBeanUtils.getCurrentThreadUserTime());
        }
        if (Boolean.TRUE.equals(ThreadMXBeanUtils.isThreadAllocatedMemoryEnabled())) {
            apiJsonMap.put("currentThreadAllocatedBytes", ThreadMXBeanUtils.getCurrentThreadAllocatedBytes());
        }
        return JsonUtils.toJson(apiJsonMap);
    }
}

第4步：使用

[2024-01-22 23:59:54.392_392] [WARN ] [http-nio-8080-exec-3] [LogFilter.java:21] → [LogFilter.doFilter: Start processing request at 2024-01-22T15:59:54.392746300Z - /students]
***LogFilter.doFilter.start***
***RequestHeaderCheckFilter.doFilter.start***
***ResponsePostInterceptor.preHandle***
***LogInterceptor.preHandle***
[2024-01-22 23:59:54.414_414] [WARN ] [http-nio-8080-exec-3] [LogInterceptor.java:36] → [LogInterceptor.postHandle: Start processing request at 2024-01-22T15:59:54.414364Z - /students]
***StudentController.edit***
[2024-01-22 23:59:56.589_589] [INFO ] [http-nio-8080-exec-3] [HikariDataSource.java:110] → [practisedb - Starting...]
[2024-01-22 23:59:56.730_730] [INFO ] [http-nio-8080-exec-3] [HikariPool.java:565] → [practisedb - Added connection com.mysql.cj.jdbc.ConnectionImpl@1e073db7]
[2024-01-22 23:59:56.732_732] [INFO ] [http-nio-8080-exec-3] [HikariDataSource.java:123] → [practisedb - Start completed.]
***ResponsePostAdvice.supports***
***ResponsePostAdvice.beforeBodyWrite***
***LogInterceptor.postHandle***
***ResponsePostInterceptor.postHandle***
***LogInterceptor.afterCompletion***
[2024-01-22 23:59:57.328_328] [WARN ] [http-nio-8080-exec-3] [LogInterceptor.java:56] → [LogInterceptor.postHandle: Finished processing request at 2024-01-22T15:59:57.328849300Z - /students in 2914 ms. Status code: 200]
[2024-01-22 23:59:57.715_715] [INFO ] [http-nio-8080-exec-3] [LogInterceptor.java:60] → [{"traceId":"5fef66027b0b45b1a509b7c1c4388b28","end_date":"2024-01-22T23:59:57.5332642+08:00[Asia/Shanghai]","cost":2914,"remoteHost":"0:0:0:0:0:0:0:1","remoteAddr":"0:0:0:0:0:0:0:1","remotePort":8263,"method":"PUT","requestURI":"/students","status":200,"requestContentLength":180,"sql_count":0,"currentThreadTime":109,"currentThreadUserTime":93,"currentThreadAllocatedBytes":29778776}]
[2024-01-22 23:59:57.715_715] [WARN ] [http-nio-8080-exec-3] [LogFilter.java:30] → [LogFilter.doFilter: Finished processing request at 2024-01-22T15:59:57.715645Z - /students in 3323 ms. Status code: 200]
***ResponsePostInterceptor.afterCompletion***
***RequestHeaderCheckFilter.doFilter.end***
***LogFilter.doFilter.end***