Snippets: Java: Spring: Log Method Execution Time

 20th August 2020 at 2:19pm

如何在 Spring Boot 中纪录函数的执行耗时。这利用了 Spring 的 AOP 特性,但是我还不完全整理 AOP,所以这篇 tiddler 的标题不是 AOP。

下面这个示例中,com.tencent.tsf.resource.proxy 中有大量访问外部服务的 API Helper,如:

[onlyice@onlyicelin-PC8 proxy]$ tree .
.
├── api
│   ├── AlaudaApiHelper.java
│   ├── ApiHelper.java
│   ├── ContainerApiHelper.java
│   ├── ContainerMasterApiHelper.java
│   ├── ContainerRegistryApiHelper.java
│   ├── DockerRegistryApiHelper.java
│   └── HarborApiHelper.java
├── cloudapi
│   ├── CAMCredentialCache.java
│   ├── CAMRoleCredential.java
│   ├── CAMRoleHandler.java
│   ├── CloudAPIHandler.java

因此用了 * com.tencent.tsf.resource.proxy..*.*(..)) 来匹配这些函数(抄的别人的,具体的匹配规则我也没深究)。

package com.tencent.tsf.resource.aop;

@Aspect
@Component
public class CommonLog {
    private static final Logger log = LoggerFactory.getLogger(CommonLog.class);

    @Around("execution(* com.tencent.tsf.resource.proxy..*.*(..))")
    public Object trackResourceRPCTime(ProceedingJoinPoint point) throws Throwable {
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();// 获取request
        long beginTime = System.currentTimeMillis();
        // 执行方法
        try {
            Object result = point.proceed();
            return result;
        } catch (Throwable t) {
            throw t;
        } finally {
            long time = System.currentTimeMillis() - beginTime;
            String message = String.format("Trace RPC time, RequestId: %s, %s used %dms",
                    request.getHeader(TSF.REQUEST_ID_HEADER_KEY), point.toString(), time);
            log.info(message);
        }
    }
}