手写链路追踪优化-全局API性能监控

原创已于 2025-09-18 01:01:25 修改 · 589 阅读

23 ·

CC 4.0 BY-SA版权

文章标签：

#java #spring boot #log4j

于 2025-09-18 00:56:41 首次发布

Java 专栏收录该内容

11 篇文章

订阅专栏

1. 前文回顾和优化需求分析

前面六篇文章已经让《手写链路追踪》完成了全链路用户信息追踪。
前文1：手写链路追踪
 前文2：手写链路追踪优化-自动全局追踪代替局部手动追踪
 前文3：手写链路追踪优化-多线程追踪
 前文4：手写链路追踪优化-MDC改造
 前文5：手写链路追踪优化-自定义用户信息追踪
 前文6：手写链路追踪优化-自定义用户信息异步追踪
过去，我看到很多朋友喜欢这样看看一个 API的耗时，观察一个API的请求日志，用结束的日志时间减去日志开始时间，这得多麻烦。
只要需要人工计算的地方我们何不交给代码来完成。
接下来我需要增加全局API性能监控的日志。我想在日志拦截器中实现全局API耗时的统计，自动识别API接口类型，返回状态。

2.代码实现

2.1 在MDC增加API请求开始时间和结束时间的记录

package com.sandwich.logtracing.util;

import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;

/**
 * @Author 公众号： IT三明治
 * @Date 2025/8/31
 * @Description: MDC工具类
 */
public class MdcUtils {
    public static final String TRACE_ID = "traceId";
    public static final String USER_ID = "userId";
    public static final String USER_NAME = "username";
    public static final String CLIENT_IP = "clientIp";

    public static final String START_TIME = "startTime";
    public static final String REQUEST_TIME = "requestTime";

    public static void setTraceId(String traceId) {
        if (StringUtils.isBlank(traceId)) {
            setTraceId();
            return;
        }
        MDC.put(TRACE_ID, traceId);
    }

    public static void setTraceId() {
        String traceId = RandomStrUtils.generateRandomString(15);
        MDC.put(TRACE_ID, traceId);
    }

    public static String getTraceId() {
        return MDC.get(TRACE_ID);
    }

    public static void removeTraceId() {
        MDC.remove(TRACE_ID);
    }

    public static void setUserId(String userId) {
        if (StringUtils.isBlank(userId)) {
            return;
        }
        MDC.put(USER_ID, userId);
    }

    public static String getUserId() {
        return MDC.get(USER_ID);
    }

    public static void setUserName(String userName) {
        if (StringUtils.isBlank(userName)) {
            return;
        }
        MDC.put(USER_NAME, userName);
    }

    public static String getUserName() {
        return MDC.get(USER_NAME);
    }


    public static void setClientIp(String clientIp) {
        if (StringUtils.isBlank(clientIp)) {
            return;
        }
        MDC.put(CLIENT_IP, clientIp);
    }

    public static String getClientIp() {
        return MDC.get(CLIENT_IP);
    }


    public static void setStartTime() {
        MDC.put(START_TIME, System.currentTimeMillis() + "");
    }

    public static String getStartTime() {
        return MDC.get(START_TIME);
    }

    public static void setRequestTime() {
        // 计算请求耗时
        String startTimeStr = MDC.get(START_TIME);
        if (startTimeStr != null) {
            long startTime = Long.parseLong(startTimeStr);
            long endTime = System.currentTimeMillis();
            long duration = endTime - startTime;
            MDC.put(REQUEST_TIME, String.valueOf(duration));
        }
    }

    public static String getRequestTime() {
        return MDC.get(REQUEST_TIME);
    }

    public static void clearAll() {
        MDC.clear();
    }
}

2.2 在拦截器添加时间处理和日志输出

在preHandle开始位置设置API开始时间到MDC

@Override
public boolean preHandle(HttpServletRequest request, @NotNull HttpServletResponse response, @NotNull Object handler) {
MdcUtils.setStartTime();

在postHandle设置API请求时间到MDC

@Override
public void postHandle(@NotNull HttpServletRequest request, @NotNull HttpServletResponse response,
@NotNull Object handler, @NotNull ModelAndView modelAndView) {
// 请求处理完成后可以添加响应信息
MdcUtils.setRequestTime();
}

在afterCompletion开始后，MDC清理前，打印耗时，API URL, response code到日志

@Override
public void afterCompletion(@NotNull HttpServletRequest request, @NotNull HttpServletResponse response,
@NotNull Object handler, @Nullable Exception ex) {
log.info(“API [{}] process finished, request time [{}]ms, response code [{}]”,
request.getRequestURI(), MdcUtils.getRequestTime(), response.getStatus());
// 请求完全结束后清理MDC，防止内存泄漏
MdcUtils.clearAll();
}

完整代码如下

package com.sandwich.logtracing.interceptor;

import com.sandwich.logtracing.util.MdcUtils;
import com.sandwich.logtracing.util.RandomStrUtils;
import com.sandwich.logtracing.util.ThreadLocalContext;
import io.micrometer.common.util.StringUtils;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import lombok.extern.slf4j.Slf4j;
import org.apache.catalina.connector.RequestFacade;
import org.jetbrains.annotations.NotNull;
import org.slf4j.MDC;
import org.springframework.lang.NonNullApi;
import org.springframework.lang.Nullable;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;

/**
 * @Author 公众号： IT三明治
 * @Date 2025/9/9
 * @Description:
 */
@Slf4j
@Component
public class MDCInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, @NotNull HttpServletResponse response, @NotNull Object handler) {
        MdcUtils.setStartTime();
        // 从header中获取用户信息
        String traceId = request.getHeader("x-request-correlation-id");
        //if the request header don't have a trace id，then generate a random one
        if (StringUtils.isBlank(traceId)) {
            traceId = RandomStrUtils.generateRandomString(15);
        }
        MdcUtils.setTraceId(traceId);
        String userId = request.getHeader("X-User-ID");
        if (StringUtils.isNotBlank(userId)) {
            // 添加用户ID到MDC
            MdcUtils.setUserId(userId);
        }
        String username = request.getHeader("X-Username");

        if (StringUtils.isNotBlank(username)) {
            // 添加用户名到MDC
            MdcUtils.setUserName(username);
        }

        // 可以添加其他请求相关信息
        String clientIp = getClientIp( request);
        MdcUtils.setClientIp(clientIp);

        ThreadLocalContext.setTraceId(traceId);
        ThreadLocalContext.setUserId(userId);
        ThreadLocalContext.setUserName(username);
        ThreadLocalContext.setClientIp(clientIp);

        return true;
    }

    @Override
    public void postHandle(@NotNull HttpServletRequest request, @NotNull HttpServletResponse response,
                           @NotNull Object handler, @NotNull ModelAndView modelAndView) {
        // 请求处理完成后可以添加响应信息
        MdcUtils.setRequestTime();
    }

    @Override
    public void afterCompletion(@NotNull HttpServletRequest request, @NotNull HttpServletResponse response,
                                @NotNull Object handler, @Nullable Exception ex) {
        log.info("API [{}] process finished, request time [{}]ms, response code [{}]",
                request.getRequestURI(), MdcUtils.getRequestTime(), response.getStatus());
        // 请求完全结束后清理MDC，防止内存泄漏
        MdcUtils.clearAll();
    }

    private String getClientIp(HttpServletRequest request) {
        String ip = request.getHeader("X-Forwarded-For");
        if (ip == null || ip.isEmpty() || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getHeader("X-Real-IP");
        }
        if (ip == null || ip.isEmpty() || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getRemoteAddr();
        }
        return ip;
    }
}

2.3 调整日志pattern，修改输出顺序，让日志更好地左对齐

spring:
  application:
    name: log-tracing


# 日志配置
logging:
  level:
    com.sandwich.logtracing: DEBUG
    org.springframework: INFO
  pattern:
    console: "%d{yyyy-MM-dd HH:mm:ss.SSS} %X{traceId:-} %replace(%X{userId}){'^(?!$)(.+)$','[userId: $1] '}%replace(%X{username}){'^(?!$)(.+)$','[username: $1] '}%replace(%X{clientIp}){'^(?!$)(.+)$','[clientIp: $1] '}[%thread] %-5level %logger{50} - %msg%n"
    file: "%d{yyyy-MM-dd HH:mm:ss.SSS} %X{traceId:-} %replace(%X{userId}){'^(?!$)(.+)$','[userId: $1] '}%replace(%X{username}){'^(?!$)(.+)$','[username: $1] '}%replace(%X{clientIp}){'^(?!$)(.+)$','[clientIp: $1] '}[%thread] %-5level %logger{50} - %msg%n"
  file:
    name: ./logs/log-tracing.log
  logback:
    rollingpolicy:
      max-file-size: 100MB
      max-history: 30

3. 测试验证

启动项目
用shell客户端请求

Administrator@USER-20230930SH MINGW64 /d/git/java/log-tracing/shell (master)
$ ./login.sh 
Generated traceId from client side: A4LnbakJlqHVcMl
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   144    0   100  100    44    121     53 --:--:-- --:--:-- --:--:--   175
Response from login API:
{
    "responseCode": 200,
    "message": "success",
    "data": "Sandwich login success",
    "traceId": "A4LnbakJlqHVcMl"
}

用traceId： A4LnbakJlqHVcMl追踪日志

2025-09-17 22:29:23.764  [main] INFO  o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 1004 ms
2025-09-17 22:29:24.202  [main] INFO  o.s.boot.web.embedded.tomcat.TomcatWebServer - Tomcat started on port 8080 (http) with context path '/'
2025-09-17 22:29:24.209  [main] INFO  com.sandwich.logtracing.LogTracingApplication - Started LogTracingApplication in 1.928 seconds (process running for 2.476)
2025-09-17 22:30:02.702  [http-nio-8080-exec-2] INFO  o.a.c.core.ContainerBase.[Tomcat].[localhost].[/] - Initializing Spring DispatcherServlet 'dispatcherServlet'
2025-09-17 22:30:02.702  [http-nio-8080-exec-2] INFO  org.springframework.web.servlet.DispatcherServlet - Initializing Servlet 'dispatcherServlet'
2025-09-17 22:30:02.703  [http-nio-8080-exec-2] INFO  org.springframework.web.servlet.DispatcherServlet - Completed initialization in 1 ms
2025-09-17 22:30:02.807 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 1 done
2025-09-17 22:30:02.816 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 1 done
2025-09-17 22:30:02.861 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 2 done
2025-09-17 22:30:02.877 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 2 done
2025-09-17 22:30:02.925 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 3 done
2025-09-17 22:30:02.940 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 3 done
2025-09-17 22:30:02.987 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 4 done
2025-09-17 22:30:03.003 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 4 done
2025-09-17 22:30:03.051 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 5 done
2025-09-17 22:30:03.066 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 5 done
2025-09-17 22:30:03.112 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 6 done
2025-09-17 22:30:03.128 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 6 done
2025-09-17 22:30:03.175 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 7 done
2025-09-17 22:30:03.190 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 7 done
2025-09-17 22:30:03.236 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 8 done
2025-09-17 22:30:03.252 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 8 done
2025-09-17 22:30:03.299 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 9 done
2025-09-17 22:30:03.315 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 9 done
2025-09-17 22:30:03.361 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing login for user Sandwich, login step 10 done
2025-09-17 22:30:03.377 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  c.s.logtracing.service.impl.LoginServiceImpl - processing async login for user Sandwich, login step 10 done
2025-09-17 22:30:03.423 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.sandwich.logtracing.controller.LoginController - user Sandwich login success
2025-09-17 22:30:03.439 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  com.sandwich.logtracing.util.ThreadLocalContext - traceId removed from thread local
2025-09-17 22:30:03.439 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  com.sandwich.logtracing.util.ThreadLocalContext - user id removed from thread local
2025-09-17 22:30:03.439 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  com.sandwich.logtracing.util.ThreadLocalContext - user name removed from thread local
2025-09-17 22:30:03.439 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [async-thread-1] INFO  com.sandwich.logtracing.util.ThreadLocalContext - client ip removed from thread local
2025-09-17 22:30:03.456 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO  c.sandwich.logtracing.interceptor.MDCInterceptor - API [/test/login] process finished, request time [735]ms, response code [200]

注意最后的日志

2025-09-17 22:30:03.456 A4LnbakJlqHVcMl [userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1] [http-nio-8080-exec-2] INFO c.sandwich.logtracing.interceptor.MDCInterceptor - API [/test/login] process finished, request time [735]ms, response code [200]

这个日志包含了API接口/test/login, 耗时735ms, response code: 200。
如果我们需要像用户信息一样[userId: 123456] [username: Sandwich] [clientIp: 0:0:0:0:0:0:0:1]这样子打印到日志也是可以的，只是这样打印是需要在日志的pattern做条件判断的，有一定性能损耗，而API耗时这种数据，一个请求只需要打印一次，所以我没有沿用这种方式打印出来。以日志msg的方式打印，灵活性也更高，调整更方便。

4.总结

本文主要在拦截器完成了全局API性能监控。由于这是在拦截器打印出来的，以后所有的API请求都会自动在结束前打印这个日志，为我们对哪个API请求，耗时多少，请求状态的监控提供便利。如果结合Prometheus+Grafana或者InfluxDB+Grafana监控效果更佳。如果您有更好的建议，请在评论区给我留言。请关注我，后面我们继续研究，谢谢。