如何在 Spring Boot 中记录 Rest Web 服务所花费的时间？

Posted 2023-02-27

【中文标题】如何在 Spring Boot 中记录 Rest Web 服务所花费的时间？

【英文标题】：How to log time taken by Rest web service in Spring Boot?

【发布时间】：2017-08-09 00:27:44

【问题描述】：

我正在使用 Spring Boot 编写一个 Web Rest web 服务。

我想记录我的网络服务处理请求所花费的时间。 我还想记录标题、方法和调用的 URI。

几个月前我在我的球衣网络服务中使用ContainerRequestFilter and ContainerResponseFilter filter() method.做了类似的事情

另外，AOP 更好还是过滤？

【问题讨论】：

你应该好好看看这个：docs.spring.io/spring-boot/docs/current/reference/html/…

添加spring-boot-actuator，它已经为您记录了。

正如 Martin 所说，使用执行器支架。您将免费获得所需的一切，还可以通过 REST、JMX 等公开统计数据，并能够将这些数据导出到其他地方。见docs.spring.io/spring-boot/docs/current/reference/html/…

【参考方案1】：

你试过这样的基本过滤器吗？

import java.io.IOException;
import javax.servlet.*;
import javax.servlet.annotation.WebFilter;
import javax.servlet.http.HttpServletRequest;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
@WebFilter("/*")
public class StatsFilter implements Filter 

    private static final Logger LOGGER = LoggerFactory.getLogger(StatsFilter.class);

    @Override
    public void init(FilterConfig filterConfig) throws ServletException 
        // empty
    

    @Override
    public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException 
        long time = System.currentTimeMillis();
        try 
            chain.doFilter(req, resp);
         finally 
            time = System.currentTimeMillis() - time;
            LOGGER.trace(":  ms ", ((HttpServletRequest) req).getRequestURI(),  time);
        
    

    @Override
    public void destroy() 
        // empty
    

已编辑：（感谢@suren-aznauryan） 现在，它使用Instant 和Duration 并避免System.currentTimeMillis()。

import java.io.IOException;
import java.time.Duration;
import java.time.Instant;
import javax.servlet.*;
import javax.servlet.annotation.WebFilter;
import javax.servlet.http.HttpServletRequest;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
@WebFilter("/*")
public class StatsFilter implements Filter 

    private static final Logger LOGGER = LoggerFactory.getLogger(StatsFilter.class);

    @Override
    public void init(FilterConfig filterConfig) throws ServletException 
        // empty
    

    @Override
    public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException 
        Instant start = Instant.now();
        try 
            chain.doFilter(req, resp);
         finally 
            Instant finish = Instant.now();
            long time = Duration.between(start, finish).toMillis();
            LOGGER.trace(":  ms ", ((HttpServletRequest) req).getRequestURI(),  time);
        
    

    @Override
    public void destroy() 
        // empty
    

【讨论】：

你在这里记录开始时间了吗？

@SeeKing 它只记录以毫秒为单位的总时间，但是如果您想知道开始时间和结束时间很容易。您必须保存初始时刻并对其进行跟踪。

@SeeKing 是一个组件，Spring 可以轻松做到这一点，但我更喜欢扫描它的包。

你需要把这个添加到类中：@Order(Ordered.HIGHEST_PRECEDENCE)docs.spring.io/spring-framework/docs/current/javadoc-api/org/…

使用System.currentTimeMillis() 不是测量经过时间的安全方法（请参阅this post）

【参考方案2】：

我们可以通过覆盖add()方法来使用Springboot InMemoryHttpTraceRepository

public class MyCustomTraceRepository extends InMemoryHttpTraceRepository 


    @Override
    public void add(HttpTrace trace) 
        log(trace);
        super.add(trace);
    

    //Log only you interested in
    public void log(HttpTrace trace) 
        Map<String, Object> traceMap = new LinkedHashMap<>();
        traceMap.put("status", trace.getResponse().getStatus());
        traceMap.put("method", trace.getRequest().getMethod());
        traceMap.put("uri", trace.getRequest().getUri().getPath());
        traceMap.put("timeTaken", trace.getTimeTaken());

        logger.info(traceMap)
    
    

//will Result into
status=<>, method=<>, uri=/<>, timeTaken=<>

@查看更多请求和响应跟踪选项：https://docs.spring.io/spring-boot/docs/current/actuator-api/html/#http-trace

【讨论】：

我可以知道为什么我们在覆盖 add 方法后调用 super.add(trace) 吗？

@manikantanvsr 那是因为需要此信息的跟踪执行器端点的默认实现是带有 add() 的 InMemoryHttpTraceRepository，现在由于我们要添加更多功能，我们正在编写我们的实现，然后调用 super 将添加执行器端点中的所有 API 和跟踪。现在，如果你不写，trace actuator 端点将不会有新的 API 信息

【参考方案3】：

Spring boot：日志拦截器

public class ApiLogger extends HandlerInterceptorAdapter 
  private static final Logger logger = LoggerFactory
    .getLogger(ApiLogger.class);

  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception 
    String requestId = UUID.randomUUID().toString();
    log(request,response, requestId);
    long startTime = System.currentTimeMillis();
    request.setAttribute("startTime", startTime);
    request.setAttribute("requestId", requestId);
      return true;
  

  @Override
  public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception 
    super.afterCompletion(request, response, handler, ex);
    long startTime = (Long)request.getAttribute("startTime");    
    long endTime = System.currentTimeMillis();
    long executeTime = endTime - startTime;
    logger.info("requestId , Handle : , request take time: ",request.getAttribute("requestId"), handler, executeTime);
  

  private void log(HttpServletRequest request, HttpServletResponse response, String requestId) 
    logger.info("requestId , host   HttpMethod: , URI : ",requestId, request.getHeader("host"),
      request.getMethod(), request.getRequestURI() );
  

注册拦截器：

@Configuration
@EnableWebMvc
public class AppConfig extends WebMvcConfigurerAdapter 
  @Override
  public void addInterceptors(InterceptorRegistry registry) 
    registry.addInterceptor(new ApiLogger()).addPathPatterns("/api/v1/*");
  

【讨论】：

应该是"/api/v1/**"

@aadidasu 是的，实际上它取决于要求，它不限制任何模式。

这种方法对异步调用也有效吗？请求线程将立即返回，因此不会记录整个 Async 线程所用的实际时间。

@aadidasu 是的，这种方法对异步调用无效，你是对的，如果异步调用将创建一个新的线程并且实际线程将完成它的工作，并且其中不包括异步线程工作时间请求。

这对我们有用！我还是想知道有没有性能方面的考虑.....

【参考方案4】：

如果您的控制器是异步的，请使用 Aspect 获得正确且完整的执行时间。

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;
import java.util.Arrays;
import java.util.UUID;

@Aspect
@Component
public class LoggingAspect 

  static Logger log = LoggerFactory.getLogger(LoggingAspect.class);

  @Around("execution(* com.aakchoo.api.controller..*(..))")
  public Object profileExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable 

    long start = System.currentTimeMillis();
    String className = joinPoint.getSignature().getDeclaringTypeName();
    String methodName = joinPoint.getSignature().getName();
    String apiName = className + "."+ methodName;
    HttpServletRequest request =
        ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();
    String requestId = UUID.randomUUID().toString();
    log.info("----->>>>>\nREQUESTED_ID: \nHOST:  HttpMethod: \nURI: \nAPI: \nArguments: \n",
        requestId,
        request.getHeader("host"),
        request.getMethod(),
        request.getRequestURI(),
        apiName,
        Arrays.toString(joinPoint.getArgs()));

    Object result = joinPoint.proceed();
    long elapsedTime = System.currentTimeMillis() - start;
    log.info("<<<<<-----\nExecution Time:  ms [REQUESTED_ID: ] [API: ]", elapsedTime,requestId,apiName);

    return result;
  

将@EnableAspectJAutoProxy 添加到您的应用程序类

@EnableAsync
@SpringBootApplication
@EnableAspectJAutoProxy
public class Application 
  public static void main(String[] args) 
    SpringApplication.run(Application.class, args);
  

您的 build.gradle 将需要以下内容

compile 'org.aspectj:aspectjweaver:1.8.10'
compile 'org.springframework.boot:spring-boot-starter-aop'

【讨论】：

如果joinPoint.proceed() 抛出异常怎么办？

【参考方案5】：

David 的回答是正确的 - 过滤器是在 Spring Boot 中实现此类功能的好方法。

Spring Boot 有一个 built-in endpoint，它返回有关最近 100 个请求的信息，如下所示：

[
    "timestamp": 1394343677415,
    "info": 
        "method": "GET",
        "path": "/trace",
        "headers": 
            "request": 
                "Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8",
                "Connection": "keep-alive",
                "Accept-Encoding": "gzip, deflate",
                "User-Agent": "Mozilla/5.0 Gecko/Firefox",
                "Accept-Language": "en-US,en;q=0.5",
                "Cookie": "_ga=GA1.1.827067509.1390890128; ..."
                "Authorization": "Basic ...",
                "Host": "localhost:8080"
            ,
            "response": 
                "Strict-Transport-Security": "max-age=31536000 ; includeSubDomains",
                "X-Application-Context": "application:8080",
                "Content-Type": "application/json;charset=UTF-8",
                "status": "200"
            
        
    
,
    "timestamp": 1394343684465,
    ...
]

如果您的应用程序正在调用其他服务或查询数据库，请考虑使用Sniffy 进行分析 - 它不仅会显示您在服务器上花费的时间，还会显示调用下游系统所花费的时间。观看现场演示 here（检查顶部底部角落的黑色小部件）。

免责声明：我是Sniffy的作者

【讨论】：

这不是一个糟糕的答案，但它没有回答所提出的问题，而且由于 Sniffy 是您的产品，因此有点自我满足。如果你要插入你的东西，至少可以考虑提一下。 “我创建了 Sniffy，它有帮助....”。

@Gregg 很公平 - 我添加了免责声明