第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步：细枝末节功能介绍
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: 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<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***