执行方法堆栈中的所有方法所花费的时间答案

【问题标题】：Time taken to execute all methods in a method stack执行方法堆栈中的所有方法所花费的时间
【发布时间】：2015-05-01 13:26:56
【问题描述】：

很多时候，在编写应用程序时，我希望在 stacktrace 中分析和测量所有方法所花费的时间。我的意思是说：

Method A --> Method B --> Method C ...

A 方法在内部调用B，它可能会调用另一个。我想知道在每个方法中执行所花费的时间。这样在 Web 应用程序中，我可以准确地知道代码的哪一部分所消耗的时间百分比。

为了进一步解释，在 Spring 应用程序的大多数时候，我编写了一个切面，它为类的每个方法调用收集信息。最后给了我总结。但我讨厌这样做，它重复且冗长，需要不断更改正则表达式以适应不同的类。相反，我想要这样：

@Monitor
public void generateReport(int id){
...
}

在方法上添加一些注释将触发检测 api 收集此方法和以后调用的任何方法所用时间的所有统计信息。并且当这个方法退出时，它会停止收集信息。我认为这应该相对容易实现。

问题是：是否有任何合理的替代方案可以让我为一般的 java 代码做到这一点？或任何快速收集此信息的方法。甚至是 Spring 应用程序的 Spring 插件？

PS：与XRebel 完全一样，它会生成漂亮的安全、dao、服务等部分代码所花费的时间摘要。但它需要一个炸弹。如果你买得起，你一定要买。

【问题讨论】：

记录在这里。如果 B 和它的被调用者消耗了 50% 的时间，那么 B 有 50% 的时间在堆栈上。如果 B 调用 C 使用 40% 的时间，那么堆栈有 40% 的时间将 B 在 C 之上。无论您想知道什么时间信息，作为运行时间的一小部分，您可以通过查看 10 or so random stacks 获得。它不会向您展示不需要太多时间的东西；我敢打赌，您正在寻找需要大量时间的东西。

标签： java spring profiling

【解决方案1】：

你想写一个Java agent。这样的代理允许您在加载类时重新定义它。这样，您可以在不污染源代码的情况下实现方面。我写了一个库，Byte Buddy，这使得这很容易。

对于您的监视器示例，您可以按如下方式使用 Byte Buddy：

new AgentBuilder.Default()
 .rebase(declaresMethod(isAnnotatedWith(Monitor.class))
 .transform( (builder, type) ->
   builder
     .method(isAnnotatedWith(Monitor.class))
     .intercept(MethodDelegation.to(MonitorInterceptor.class);
  );

class MonitorInterceptor {
  @RuntimeType
  Object intercept(@Origin String method,
                                @SuperCall Callable<?> zuper)
      throws Exception {
    long start = System.currentTimeMillis();
    try {
       return zuper.call();
     } finally {
       System.out.println(method + " took " + (System.currentTimeMillis() - start);
     }
   }
}

上述构建的代理可以安装在提供给任何 Java 代理的检测接口的实例上。

作为使用 Spring 的一个优势，上述代理将适用于任何 Java 实例，而不仅适用于 Spring bean。

【讨论】：

我用 0.6.8 版本试了一下。但它什么也没打印。有最新版本的类似文档吗？
两个快速检查：您的Monitor 注释是否声明RetentionType.RUNTIME？您是否注册了AgentBuilder.Listener 以查看潜在错误？此外，您应该使用最新版本。 0.6.8 真的很老了。
感谢您的快速回复:)。这是代码的链接：pastebin.com/jZnNkgUk 使用 0.6.8，因为上面的代码没有用 1.x 系列编译。谢谢。是监视器声明：@Target({ElementType.METHOD}) @Retention(RetentionPolicy.RUNTIME)
您的main 方法是在您正在拦截的类中定义的。因此，在附加代理之前已经加载了该类。将您的主要方法放入另一个类中，一切都应该正常工作。当前版本的唯一 API 变化是 rebase 被重命名为 type。
谢谢。它现在工作了:)。需要另一个帮助：我需要找出我的 @Monitor 注释方法在内部调用的所有方法的时间。从上面，我只拦截使用@Monitor 调用的方法。

【解决方案2】：

我不知道是否已经有一个库在做这件事，也不能给你一个现成的代码。但我可以给你一个描述，你可以如何自己实现它。

首先，我认为将 AspectJ 包含到您的项目中没有问题。比创建注释 f.e. @Monitor 充当您喜欢的任何时间测量的标记。比创建一个简单的数据结构来保存您想要跟踪的信息。一个例子如下：

public class OperationMonitoring {
    boolean active=false;
    List<MethodExecution> methodExecutions = new ArrayList<>();
}

public class MethodExecution {
    MethodExcecution invoker;
    List<MethodExeuction> invocations = new ArrayList<>();
    long startTime;
    long endTime;
}

比为所有方法创建一个环绕建议。在执行时检查被调用的方法是否用您的 Monitoring 注释进行了注释。如果是，则开始监视此线程中的每个方法执行。一个简单的示例代码如下所示：

@Aspect
public class MonitoringAspect {

    private ThreadLocal<OperationMonitoring> operationMonitorings = new ThreadLocal<>();

    @Around("execution(* *.*(..))")
    public void monitoring(ProceedingJoinPoint pjp) {  
        Method method = extractMethod(pjp);
        if (method != null) {
            OperationMonitoring monitoring = null;
            if(method.isAnnotationPresent(Monitoring.class){
                 monitoring = operationMonitorings.get();
                 if(monitoring!=null){
                     if(!monitoring.active) {
                          monitoring.active=true;
                     }
                 } else {
                     // Create new OperationMonitoring object and set it
                 }
            }
            if(monitoring == null){
                 // this method is not annotated but is the tracking already active?
                 monitoring = operationMonitoring.get();
            }
            if(monitoring!=null && monitoring.active){
               // do monitoring stuff and invoke the called method
            } else {
               // invoke the called method without monitoring
            }
            // Stop the monitoring by setting monitoring.active=false if this method was annotated with Monitoring (and it started the monitoring).
        }
    }


    private Method extractMethod(JoinPoint joinPoint) {
         if (joinPoint.getKind().equals(JoinPoint.METHOD_EXECUTION) && joinPoint.getSignature() instanceof MethodSignature) {
              return ((MethodSignature) joinPoint.getSignature()).getMethod();
         }
         return null;
    }
}

上面的代码只是一个方法。我也会重组代码，但我已经将它写在一个文本字段中，所以请注意架构缺陷。正如最后的评论所提到的。此解决方案不支持沿途的多个注释方法。但是添加它很容易。这种方法的一个限制是，当您在跟踪路径期间启动其他线程时它会失败。在受监控的线程中添加对启动新线程的支持并不是那么容易。这也是为什么 IoC 框架有自己的特性来处理线程以便能够跟踪它的原因。

我希望您了解这个的一般概念，如果不欢迎进一步提问。

【讨论】：

【解决方案3】：

这就是我构建开源工具stagemonitor 的确切原因，该工具使用 Byte Buddy 插入分析代码。如果您想监控 Web 应用程序，您不必更改或注释您的代码。如果您有独立的应用程序，则可以使用 @MonitorRequests 注释。

【讨论】：

感谢您的回答。巧合的是，我什至使用 bytebuddy 为自己构建了它 :)。谢谢，周末试试。

【解决方案4】：

你说你想知道堆栈上每个例程所花费的时间百分比。

我假设您的意思是包含时间。

我还假设您的意思是 wall-clock 时间，理论上，如果其中一个较低级别的被调用者碰巧进行了一些 I/O、锁定等，您不希望对此视而不见。

因此，在挂钟时间进行采样的堆栈采样分析器将获得正确的信息。

A 所用时间的百分比是包含 A 的样本的百分比，对于 B 等也是如此。

要获得 B 使用 A 的时间的百分比，它是包含 A 的样本恰好在下面的下一个级别有 B 的百分比。

所有信息都在堆栈样本中，但可能很难让分析器仅提取您想要的信息。

你还说你想要精确百分比。这意味着您还需要大量堆栈样本。例如，如果您想将测量的不确定性缩小 10 倍，则需要 100 倍的样本。

根据我发现性能问题的经验，我愿意容忍 10% 或更多的不确定性，因为我的目标是找出大的浪费，而不是精确地知道它有多糟糕。所以我手动取样，然后手动查看。事实上，如果你看统计数据，你只需要在少到两个个样本上看到一些浪费的东西就知道它是坏的，而且你在看到它之前抽取的样本越少，它就越糟糕. （示例：如果问题浪费了 30% 的时间，则平均需要 2/30% = 6.67 个样本才能看到两次。如果浪费了 90% 的时间，则平均只需要 2.2 个样本。）

【讨论】：