您将如何分解并记录应用程序不同部分的执行时间？

Question

我们构建了一个 Web 应用程序，它接受 SOAP 消息、进行一些处理、调用另一个 Web 服务、处理响应并将其发送回原始调用者。

我们希望在一行中记录这些不同步骤的不同执行时间。 我们将 log4j 与 JBossWS 堆栈结合使用。 换句话说，我们希望日志输出看起来像这样：

2009-06-10T16:19:31.487 3336/2449/861

其中 3336ms 是服务请求所花费的总时间，2449ms 是等待 Web 服务响应所花费的时间，861ms 是内部处理数据所花费的时间。

这些不同的计算发生在代码中的不同位置，我们不能只对每个计算进行计时并在单个方法结束时调用记录器。 我们中的一个人建议使用 log4j 的 MDC 作为一组穷人的全局变量来跟踪不同的执行时间。

所以我的问题如下：

1. 这是否是对民主变革运动主要意图的可怕滥用？
2. 如果是，否则你会怎么做？

Answer 1

请查看 SLF4J 分析器。 够有趣的。 tt 的开发是为了满足完全相同的需求，即测量和改进 SOAP 调用的性能。

Answer 2

听起来像是 Perf4J 的工作。

Answer 3

我会执行以下操作：

1. 创建一个 PerformanceTimer 类，该类公开：
   • recordWaitedForWebServerReponse(操作Id，时间);
   • recordMassgedData(操作Id, 时间);
   • 其他方法（如果需要）
2. 在需要的地方注入该类；
3. 让 PerformanceTimer 维护一个 OperationId 的并发映射 -> 操作计时数据；
4. 在已知的最后一个方法调用上，使用所需的输出调用 Log4j。

Answer 4

虽然这肯定会起作用，但我也对这个想法感到畏缩。 我的建议是为此目的创建一个计时类，它使用 ThreadLocal 为每个请求创建一个变量。

当请求到来时，您创建变量（带有开始时间的long）。 当变量已经存在时，您无需管它。 当结果发送回客户端时，您可以计算持续时间并记录下来。

Answer 5

我会使用 Spring 和面向方面的编程来做到这一点。 好处是我只需编写一次逻辑，然后在需要的地方以声明方式应用它。

Answer 6

一种简单的方法是使用 System.currentTimeMillis() ，它返回以毫秒为单位的时间。
方法开始时的毫秒数与方法结束时的毫秒数之间的差异将给出执行该特定方法所需的毫秒数。
希望System.currentTimeMillis()能够帮助您。

Answer 7

我们只是在第一个请求过滤器中使用它：

logger.trace("Init");
long start = System.currentTimeMillis();

//do stuff here 

long stop = System.currentTimeMillis();
String time = Util.getTimeDifferenceInSec(start, stop);
logger.trace("Complete in " + time + " sec");