AspectJ计算执行时间

如何解决AspectJ计算执行时间

在这种情况下，method1呼叫method2。

在每个方法执行中都定义了切入点和建议，以计算该方法所花费的时间。所以，

   advice of `method1` prints 10 seconds; 

   advice of `method2` prints 6 seconds;

我想打印method1所花费的时间，而不包括method2所花费的时间。那就是我想要10-6 = 4 seconds作为结果

如何使用方面实现这一目标？

预计：4秒

代码段：

public int method1( String input ){
   User user = null;
   // something .. 
   method2(input,input2);
   return 100;
}

这是方面组件中的检查方法：

@pointcut("....something correct")
public void endpoint (ProceedingJoinPoint pjp) throws Throwable {

@Around("endpoint")
public void tiMetaken(ProceedingJoinPoint pjp) throws Throwable {
     
     //code to calcualte start time
     pjp.proceed();
     printf("the total time " : currentTime - startTime);
}

解决方法

通过AOP模拟探查器可能是可行的，但很复杂。原因是您需要计算方法调用树，并将其与执行时间一起记录在单独的数据结构中。记录日志时，必须从测量的时间中减去子树中所有内容的执行时间。这将花费CPU周期，内存和大量维护工作。另一个问题是异步代码，即多线程。

我的建议是退后一步，想一想为什么您甚至认为自己需要这个。唯一的原因是您的method1混合了（费时的）逻辑和调用也包含（费时的）逻辑的其他方法。

您听说过Integration Operation Segregation Principle (IOSP)吗？它基本上指出有两种类型的方法：

操作包含逻辑
集成仅调用操作

如果将此原理应用于自己的代码，则会间接产生您感兴趣的数字。

因此，如果您运行此方面

package de.scrum_master.aspect;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;

@Aspect
public class TimerAspect {
  @Around("execution(* *(..)) && within(de.scrum_master..*) && !within(TimerAspect)")
  public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
    long startTime = System.nanoTime();
    try {
      return joinPoint.proceed();
    }
    finally {
      System.out.println(joinPoint + " -> " + (System.nanoTime() - startTime) / 1000000 + " ms");
    }
  }
}

针对此应用程序

package de.scrum_master.app;

public class Application {
  public static void main(String[] args) throws InterruptedException {
    new Application().method1("foo");
  }

  public int method1(String input) throws InterruptedException {
    Thread.sleep(300);
    method2(input,11);
    Thread.sleep(100);
    return 100;
  }

  public void method2(String input,int i) throws InterruptedException {
    Thread.sleep(600);
  }
}

您得到不想要的有问题的输出：

execution(void de.scrum_master.app.Application.method2(String,int)) -> 604 ms
execution(int de.scrum_master.app.Application.method1(String)) -> 1009 ms
execution(void de.scrum_master.app.Application.main(String[])) -> 1010 ms

但是如果您按照这样的IOSP重构应用程序代码

package de.scrum_master.app;

public class Application {
  public static void main(String[] args) throws InterruptedException {
    new Application().integration("foo");
  }

  public int integration(String input) throws InterruptedException {
    operation1();
    operation2(input,11);
    operation3();
    return 100;
  }

  private void operation1() throws InterruptedException {
    Thread.sleep(300);
  }

  public void operation2(String input,int i) throws InterruptedException {
    Thread.sleep(600);
  }

  private void operation3() throws InterruptedException {
    Thread.sleep(100);
  }
}

应用程序仍会执行相同的操作，但是所有逻辑操作和可能昂贵的操作都将分解为它们自己的方法。 operation2与之前的method2相同，operation1是发生在逻辑之前，operation3是发生在逻辑之后，operation2。现在，不仅integration（以前为method1）更加整洁，易于阅读，而且每次操作都获得了单独的计时日志：

execution(void de.scrum_master.app.Application.operation1()) -> 302 ms
execution(void de.scrum_master.app.Application.operation2(String,int)) -> 599 ms
execution(void de.scrum_master.app.Application.operation3()) -> 100 ms
execution(int de.scrum_master.app.Application.integration(String)) -> 1005 ms
execution(void de.scrum_master.app.Application.main(String[])) -> 1005 ms

当然，Thread.sleep操作只是您可能具有的任何应用程序逻辑的符号表示形式：if或switch - case语句，循环，外部资源（文件，数据库）处理，复杂计算等等。

底线：重构！如果您想计时，测试，重构，请不要混合使用它们。或者，使用探查器。