分享一下,我自研的一个代码块耗时测算实用工具类。它主要包含以下的功能:
- 测算耗时
- 显示进度
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内部的规则如下:
- 5秒内不输出两次
- 5~10秒,前进至少3%才输出
- 10~15秒,前进至少1%才输出
- 大于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就是最外层。
它的每一处实现,都是平淡无奇。借用棋类的话,就是“通盘无妙手”。关键是实用。