使用stopwatch监控代码耗时

在日常开发中，我们对于一些代码想要知道它执行消耗的时间，可能会根据执行开始时间和结束时间进行计算。比较常见的就是

System.currentTimeMillis()。这种方法比较适合单一节点的监控，比如在某一个方法中，我只需要知道其中一个节点所消耗的时间。

如果是在一个接口中，我不确定哪一步代码更耗时，想要知道多个节点的耗时该怎么办呢，使用多个System.currentTimeMillis()打印的话也是可以的，但是比较麻烦。这里给大家介绍一下Stopwatch码表。

StopWatch的优势在于对于多个代码块的计算。它可以提供单独的任务执行时间，以及任务的汇总时间，现在我们以计算三个代码块执行时间为例：

@Test
     void test4() throws InterruptedException {
         StopWatch stopWatch = new StopWatch("代码耗时测试一组");
         stopWatch.start("代码块1");
         Thread.sleep(1000);
         stopWatch.stop();
         stopWatch.start("代码块2");
         Thread.sleep(2000);
         stopWatch.stop();
         stopWatch.start("代码块3");
         Thread.sleep(3000);
         stopWatch.stop();
         System.out.println(stopWatch.prettyPrint());
     }

StopWatch stopWatch = new StopWatch("代码耗时测试一组");这段代码会new一个StopWatch对象，并且给这个StopWatch设置一个名称，这样可以增加易读性，并且在打印日志时会把这个名称打印出来方便查询。

stopWatch.start("代码块1");start方法实际执行的是System.nanoTime()获取当前时间纳秒，参数代码块1是当前任务的名称，和码表名称一样，增加易读性，并可以打印。下面是start方法的源码：

stopWatch.stop();方法就是获取当前时间并计算消耗时间了，下面是stop方法的源码：

由start方法和stop方法的源码可以看出，start和stop一定要成对出现，否则currentTaskName判断那里就会抛出异常。

System.out.println(stopWatch.prettyPrint());这行代码是用来打印日志的，贴出源码看一下：

for循环里面就是遍历StopWatch里面的任务，打印每个任务执行耗时和所占百分比。

我们来看下执行结果：

可以看到，日志打印出来了总的执行耗时、每个节点的耗时和耗时占比。但是不太美观的是，这个时间默认的时间单位是纳秒，不太方便阅读。我们来重写一下日志打印方法，把时间单位改完秒。

public static String prettyPrintBySecond(StopWatch stopWatch) {
         StopWatch.TaskInfo[] taskInfos = stopWatch.getTaskInfo();
         StringBuilder sb = new StringBuilder();
         sb.append('\n');
         sb.append("StopWatch '").append(stopWatch.getId()).append("': running time = ").append(stopWatch.getTotalTimeSeconds()).append(" s");
         sb.append('\n');
         if (taskInfos.length < 1) {
             sb.append("No task info kept");
         } else {
             sb.append("---------------------------------------------\n");
             sb.append("s         %     Task name\n");
             sb.append("---------------------------------------------\n");
             NumberFormat nf = NumberFormat.getNumberInstance();
             nf.setMinimumFractionDigits(3);
             nf.setGroupingUsed(false);
             NumberFormat pf = NumberFormat.getPercentInstance();
             pf.setMinimumIntegerDigits(2);
             pf.setMinimumFractionDigits(2);
             pf.setGroupingUsed(false);
             for (StopWatch.TaskInfo task : taskInfos) {
                 sb.append(nf.format(task.getTimeSeconds())).append("  ");
                 sb.append(pf.format((double) task.getTimeNanos() / stopWatch.getTotalTimeNanos())).append("  ");
                 sb.append(task.getTaskName()).append("\n");
             }
         }
         return sb.toString();
     }

@Test
     void test4() throws InterruptedException {
         StopWatch stopWatch = new StopWatch("代码耗时测试一组");
         stopWatch.start("代码块1");
         Thread.sleep(1000);
         stopWatch.stop();
         stopWatch.start("代码块2");
         Thread.sleep(2000);
         stopWatch.stop();
         stopWatch.start("代码块3");
         Thread.sleep(3000);
         stopWatch.stop();
         System.out.println(StopWatchUtil.prettyPrintBySecond(stopWatch));
     }

来看一下美化后的执行结果：

我们现在是在一个方法中监控时间消耗，那如果是嵌套方法的情况下，需要在嵌套方法中监控时间消耗该怎么做呢？其实和上面一样，在嵌套方法中

new Stopwatch()，并进行start、stop打印日志。唯一不同的就是码表名称，和任务名称了。下面看下多码表的执行效果：