如何知道代码跑得多慢？

1. 测算耗时

背景

程序员经常需要知道一段代码的执行耗时。典型的例如查询数据库，不同参数查询到不同的数据量，耗时相差很大。如果一个操作总体耗时较大，包含了几次数据库操作，自然就想知道哪一次操作是长耗时的主要原因，甚至每一个的耗时是多少。从而可以有的放矢地做优化。

使用要简单

测算一段代码的耗时，通常就是用stop watch（秒表）。在执行的开始点开始计时，在执行的结束点停止计时，并把耗时输出到日志。虽然代码也就几行，但每个地方都这么写，会显得很啰嗦，编码效率也低。
所以我把这个功能封装成一个实用工具类。用起来大概是这样子:

MonitorUtil.time(() -> {
    // 一个耗时操作，如查询数据库
}, "给这个操作起个名");

它会这样输出到日志：

[WARN] 2023-05-19T08:26:00.007 xx-project com.xxx.util.MonitorUtil 给这个操作起个名 elapsed 3,140 ms. warning

末尾的warning会在某些终端上显示为黄色，显眼。

输出要简洁

在线上运行时，也希望能知道耗时比较大的代码。但如果每处测算耗时的地方都输出日志，日志就会太多，而我们只关注那些长耗时。所以我规定：少于500毫秒的，不输出。

暂停与继续

有一种场景，在一个代码范围内，只期望计算一部分操作的累计耗时，而忽略其它操作的耗时。
比如，处理一批文件，每个文件要解析后将结果存为另一个文件。这里只关心解析的时间，而忽略写文件的耗时。所以MonitorUtil提供了暂停和继续的功能。在写文件时，暂停计时，写文件后开始解析另一个文件时继续计时。
最终会输出累计的耗时以及累计等待耗时。累计等待耗时，即是从暂停到继续的时长的总和。
代码：

MonitorUtil.time(monitor -> {
    for (...) {
        // 文件解析
        monitor.pause();
        // 其它操作
        monitor.continue();
    }
}, "仅算文件解析");

输出如下：

[WARN] 2023-05-19T08:26:00.008 xx-project com.xxx.util.MonitorUtil 仅算文件解析 elapsed 1,140 ms，waited 2,000ms. warning
这样就能知道那段代码是工作的时间多还是等待的时间多了。

2. 显示进度

说另一个问题，也是跟时间有关的。有些功能耗时比较长，比如循环处理数据。或许是10秒，或许是10分钟。对着没有什么输出的屏幕，显得很无助。此时如果能知道剩下大概需要多少时间，无疑对做决策有大帮助。如，是中断还是继续等。

当然了，进度百分比，只有业务代码才知道。但业务代码难以把握如何输出这个进度。密了则输出一大堆，干扰视线。疏了又是漫长无助的等待。所以，是由业务代码报告进度，由这个工具决定要不要输出。
代码：

MonitorUtil.time(monitor -> {
    for (...) {
        // 一些操作
        monitor.process(proc);     // proc 是[0,1]区间的浮点数，表示进度
    }
}, "给这个操作起个名");

要做到输出不能太密，不能太疏。所以MonitorUtil内部的规则如下：

1. 5秒内不输出两次
2. 5~10秒，前进至少3%才输出
3. 10~15秒，前进至少1%才输出
4. 大于15秒，无论进度如何都输出
   这里说的多少秒，是相对于上一次输出的时间而言。前进也是相对于上一次输出。
   输出：

[INFO] 2023-05-19T08:26:00.009 xx-project com.xxx.util.MonitorUtil 给这个操作起个名 7% 30% 61% 98% 100%`

嵌套使用

假如有两个进度测试的代码嵌套在一起，如

MonitorUtil.time(monitor -> {
    for (...) {
        // 一些操作
        abc();
        // 一些操作
        monitor.process(proc);     // proc 是[0,1]区间的浮点数，表示进度
    }
}, "大功能名");

void abc() {
    MonitorUtil.time(monitor -> {
        for (...) {
            // 一些操作
            monitor.process(proc);     // proc 是[0,1]区间的浮点数，表示进度
        }
    }, "小功能名");
}

由于日志只有一份，两个进度的输出就会混在一起，很乱，看不清。所以解决这个问题，我规定当发生进度测算嵌套时，只有最外层的有效，即只有最外层的会输出。好像也没有更好的办法了，如果您有更好的建议，请留言。感谢。

3. 这个工具的优势

高性能

• 它的输出都是被动的。即只在被测代码开始、结束、主动调用process方法时，才执行逻辑，才有可能输出。如果process方法没有被调用，就算过了15秒，也不会有进度输出。所以，在应用的时候，可以偏频繁一些地调用process方法。调了不一定有输出，不调一定不会输出。
• 它的内部是顺序的判断，没有循环，更没有复杂算法，非常高效。
• 它并没有创建新的线程(单线程)，而是与业务代码工作在同一个线程。它消耗的资源非常少，包括内存消耗很少。在除了“开始、结束、process方法被调用时”之外，消耗的CPU为零。用它来测算时间，成本极低，可以大量使用。

支持异常

业务代码发生异常时，它还能不能测算出耗时？可以的。回调方法（lambda表达式）如果发生的异常，它也能计算耗时，并在耗时超过500毫秒时输出。异常也是结束的一种。

测算的目标形式

如前面所见，它测算的目标形式是代码块，而代码块是最灵活的表现形式。它可以是一行代码，可以是多行。可以是一个函数的完整代码，也可以是函数的一部分代码。

4. 实现原理简介

它的内部实现原理并不难。测算时间，就是记录(用变量保存)开始时间，并在结束时计算一下时间差。进度功能，则是记录上一次的输出时间和进度，下次输出时作对比。暂停功能，则是用两个变量分别记录工作和等待的耗时累加值。至于如何知道自己是不是“最外层”，则是用一个static变量来保存当前的层数。如果是0就是最外层。
它的每一处实现，都是平淡无奇。借用棋类的话，就是“通盘无妙手”。关键是实用。