计算执行时间的AspectJ

Question

在这个场景中，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);
}

Answer 1

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

我的建议是后退一步，想想为什么你会觉得自己需要这个。唯一的原因是您的method1将(耗时)逻辑与调用其他方法(也包含(耗时)逻辑)混合在一起。

您是否听说过集成操作隔离原则(IOSP)(https://clean-code-developer.com/grades/grade-1-red/#:%7E:text=Integration%20Operation%20Segregation%20Principle%20(IOSP%29,-Why%3F&text=IOSP%20calls%20for%20a%20clear,control%20structures%20or%20API%20invocations.&text=Or%20a%20method%20does%20not,methods%20within%20its%20code%20basis)? )，它基本上说有两种方法：

• operations只包含logic
• integrations调用操作

如果将此原则应用于自己的代码，则间接获得您感兴趣的数字，作为副作用。

所以如果你运行这个方面

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语句、循环、外部资源(文件、数据库)处理、复杂计算或其他什么。

底线：Go重构！不要混合操作和集成，如果你想要时间，测试，重构，单独使用它们。或者，使用分析器。