JAVA如何优雅的计算函数执行时间_java 如何优雅的打印执行时间

优雅的实现 PK 传统的实现

优雅实现

加一个注解即可，如@TimeIt 

@TimeIt
public ReturnJson getNavigationConfigEntity() {
...}

传统实现

public ReturnJson getNavigationConfigEntity() {
    long startTime = System.currentTimeMillis();
    ...
    log.info("getNavigationConfigEntity costs: {}", System.currentTimeMillis() - startTime);
}

优雅的实现，不入侵原有函数实现，且代码量小。

如何做出计时效果的注解？

核心技术：AspectJ 和 AOP

步骤0，定义一个注解TimeIt

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface TimeIt {
}

步骤1，定义切面

@Aspect
@Component   //不要用configuration, 会导致bean启动太晚，出现  Advice must be declared inside an aspect type的错误
@Slf4j
public class AspectAnnotation {
    @Around("@annotation(com.pingan.pivot.manage.annotation.TimeIt)")
    public Object recordPerformance(ProceedingJoinPoint pjp) throws Throwable {
        StopWatch stopWatch = new StopWatch();
        stopWatch.start();
        Object ret = pjp.proceed(pjp.getArgs());
        stopWatch.stop();
        log.info("{} costs: {} ms", ((MethodSignature)pjp.getSignature()).getMethod().getName(), stopWatch.getLastTaskInfo().getTimeMillis());
        return ret;
    }
}

@Around 属于aspect内的advice，能力很强，可以在原函数前面或后面添加其他功能，也可以修改入参和返回结果。

下面这句就是原函数的执行。

Object ret = pjp.proceed(pjp.getArgs())

这里，在原函数之前加入计时，函数之后停止计时，即可起到计算原函数执行时间的效果。

@Around内的描述，就是将这个切面和注解TimeIt进行关联，凡是被TimeIt注解的函数，都会执行这个方法而实现计时功能。

要打印函数运行时间，就必须显示是函数名，如何做到一个通用的功能，注解在哪个函数上面，就显示那个函数的名字？

采用下面的方式可以获取函数签名从而显示函数名。

((MethodSignature)pjp.getSignature()).getMethod().getName()

注意：

这个类的要使用 @Component 而不是 @Configuration （否则会出现错误）

因为spring boot的启动中，会故意延迟Configuration注解的Bean的启动时机。

拓展知识

微服务主函数的使用的注解 @SpringBootApplication的定义里有

@ComponentScan(

excludeFilters = {@Filter(

type = FilterType.CUSTOM,

classes = {TypeExcludeFilter.class}

), @Filter(

type = FilterType.CUSTOM,

classes = {AutoConfigurationExcludeFilter.class}

)}

)

从这个描述可知，配置类的注解会故意不scan，等其他bean完成后，再进行Bean创建

步骤2，引入aspectj-maven-plugin 实现静态代理

通过引入aspectj-maven-plugin，让mvn编译时，加入AspectJ的静态编织能力，从而实现在原函数外面加上静态proxy。

<plugin>
    <groupId>org.codehaus.mojo</groupId>
    <artifactId>aspectj-maven-plugin</artifactId>
    <version>1.14.0</version>
    <configuration>
        <complianceLevel>1.8</complianceLevel>
        <source>1.8</source>
        <target>1.8</target>
        <showWeaveInfo>true</showWeaveInfo>
        <verbose>true</verbose>
        <Xlint>ignore</Xlint>
        <encoding>UTF-8 </encoding>
        <forceAjcCompile>true</forceAjcCompile>
        <sources/>
        <weaveDirectories>
            <weaveDirectory>${project.build.directory}/classes</weaveDirectory>
        </weaveDirectories>
    </configuration>
    <executions>
        <execution>
            <goals>
                <!-- use this goal to weave all your main classes -->
                <goal>compile</goal>
            </goals>
        </execution>
    </executions>
</plugin>

这里特别关键的是：

        <sources/>
        <weaveDirectories>
            <weaveDirectory>${project.build.directory}/classes</weaveDirectory>
        </weaveDirectories>

如果不添加这个，会出现无法找到各种get和set函数的问题。

为什么会有这个问题？

因为get和set目前基本都由lombok在编译阶段自动生成。

aspectj和lombok都属于编译阶段引入的静态代理。

必须要让aspectj在lombok完成之后再进行静态代理。

因此，将weaveDirectory设置为${project.build.directory}/classes，这样，aspectJ就会去lombok生成后的.class文件里去作用，从而实现先lombok后aspectj的工作顺序。

（${project.build.directory} 是系统变量，直接写即可，无需额外定义）

另外，<sources/> 等价于 <sources></sources>，即不使用任何java代码

如何不使用注解，批量的让函数打印执行时间？

上面注解的方式，非常方便的精确打印具体的函数。

但是，如果需要打印的函数数量很多，且具有聚集效应，如都在一个类或包里等，每个函数写一个注解是低效的，可以采用如下方式实现批量动作。

@Aspect
@Component   //不要用configuration, 会导致bean启动太晚，出现  Advice must be declared inside an aspect type的错误
@Slf4j
public class AspectAnnotation {
    @Pointcut("execution(* com.pingan.pivot.manage.service.impl.NavigationRobotServiceImpl.*(..))")
    public void logRunTime(){
    }
 
    //@Around("@annotation(com.pingan.pivot.manage.annotation.TimeIt)")
    @Around("logRunTime()")
    public Object recordPerformance(ProceedingJoinPoint pjp) throws Throwable {
        StopWatch stopWatch = new StopWatch();
        stopWatch.start();
        Object ret = pjp.proceed(pjp.getArgs());
        stopWatch.stop();
        log.info("{} costs: {} ms", ((MethodSignature)pjp.getSignature()).getMethod().getName(), stopWatch.getLastTaskInfo().getTimeMillis());
        return ret;
    }
}

制作一个切点Pointcut，作用范围为：

NavigationRobotServiceImpl 这个类下的任何方法

其中，execution右边的*代表任意返回值的函数，最右边的(..)代表任意入参，2个结合在一起，就是不根据入参和返回值进行过滤。

将这个Pointcut和切面函数关联在一起，即可让这个类的所有方法都具备计时打印的功能。

背景文档：

Introduction to Spring AOP | Baeldung