如何知道代码跑得多慢?

博客 分享
0 295
张三
张三 2023-05-22 09:55:51
悬赏:0 积分 收藏

如何知道代码跑得多慢?

分享一下,我自研的一个代码块耗时测算实用工具类。它主要包含以下的功能:

  1. 测算耗时
  2. 显示进度

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就是最外层。
它的每一处实现,都是平淡无奇。借用棋类的话,就是“通盘无妙手”。关键是实用。

posted @ 2023-05-22 09:05  BillySir  阅读(84)  评论(1编辑  收藏  举报
回帖
    张三

    张三 (王者 段位)

    921 积分 (2)粉丝 (41)源码

     

    温馨提示

    亦奇源码

    最新会员