第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 {@Overridepublic 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;}@Overridepublic void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) {System.err.println("***LogInterceptor.postHandle***");// 获取请求开始时间}@Overridepublic 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步:细枝末节功能介绍
3.1、引入LogContext收纳上下文数据
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLong;public class LogContext {private static ThreadLocal<AtomicInteger> sql_count = new InheritableThreadLocal<>();private static ThreadLocal<AtomicLong> sql_cost = new InheritableThreadLocal<>();private static ThreadLocal<String> traceid = new InheritableThreadLocal<>();private static ThreadLocal<Long> acclocated_memory = new InheritableThreadLocal<>();private static ThreadLocal<Long> total_cpu_cost = new InheritableThreadLocal<>();private static ThreadLocal<Long> 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: trueallocated_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;@Overridepublic 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<String, Object> 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***