大家好，又见面了，我是你们的朋友全栈君。

一、传统计算耗时方式

一般采用 System.currentTimeMillis() 来获取时间，然后打印当前时间与任务开始执行时间的差值。

• 记录开始时间点
• 记录结束时间点
• 输出当前时间与任务开始执行时间的差值

代码如下：

    public static void main(String[] args) throws InterruptedException { 
   
        long startTime = System.currentTimeMillis();

        // do something
        TimeUnit.SECONDS.sleep(5);

        System.out.println("执行耗时：" + (System.currentTimeMillis() - startTime) + "ms");
    }

二、使用 Spring 计时器 StopWatch

StopWatch是位于 org.springframework.util包下的一个工具类，通过它可方便的对程序部分代码进行计时(ns级别),可以很方便的计算出任务的耗时.
commons工具包下也有的实现可以直接使用 (org.apache.commons.lang3.time.StopWatch) ，功能差不多。

1、StopWatch使用

通过创建 StopWatch对象，然后调用它的start、stop方法来区分执行任务区间，基于 System.nanoTime()获得时间。 通过 getTotalTimeMillis()方法获得总耗时。

StopWatch的其他方法：

• prettyPrint()方法，可以优雅的打印出统计分析信息；
• getTotalTimeMillis()方法，打印出总耗时；
• getLastTaskName()方法，打印最后一个任务名称；
• getLastTaskInfo()方法，获得最后一个任务的TaskInfo，进而获得更多相关信息；
• getTaskCount()方法，获得任务数；

demo1：单业务模块使用

    public static void main(String[] args) throws InterruptedException { 
   
        StopWatch sw = new StopWatch("xx任务的耗时");

        sw.start();
        // do something
        TimeUnit.SECONDS.sleep(5);
        sw.stop();

        System.out.println(sw.getId() + ":"  + sw.getTotalTimeMillis() + "ms");
        System.out.println(sw.getLastTaskName());
        System.out.println(sw.getLastTaskInfo());
        System.out.println(sw.getTaskCount());
        System.out.println(sw.prettyPrint());
    }

demo2：多业务模块使用

    public static void main(String[] args) throws InterruptedException { 
   
        StopWatch sw = new StopWatch("xx任务的耗时");
        
        sw.start("业务1");
        TimeUnit.SECONDS.sleep(2);
        sw.stop();

        sw.start("业务2");
        TimeUnit.SECONDS.sleep(5);
        sw.stop();

        sw.start("业务3");
        TimeUnit.SECONDS.sleep(3);
        sw.stop();

        System.out.println(sw.getId() + ":"  + sw.getTotalTimeMillis() + "ms");
        System.out.println(sw.prettyPrint());
    }

StopWatch优缺点：
优点：

• Spring自带工具类，可直接使用，代码实现简单，使用更简单
  通过多组start、stop方法，将业务代码块进行区分，可获得不同代码块的执行耗时
  统一归纳，展示每项任务耗时与占用总时间的百分比，展示结果直观。
• 性能消耗相对较小，并且最大程度的保证了start与stop之间的时间记录的准确性

缺点：

• 一个StopWatch实例一次只能开启一个task，start和stop要成对使用。若要一次开启多个
  task，需要new不同的StopWatch实例
• 代码侵入式使用，需要改动多处代码

2、Spring中StopWatch源码

该工具类中源码实现也极其简单，通过 start与stop方法分别记录开始时间与结束时间，其中在记录结束时间时，会维护一个链表类型的 tasklist属性，从而使该类可记录多个任务，最后的输出也仅仅是对之前记录的信息做了一个统一的归纳输出，从而使结果更加直观的展示出来。

• StopWatch也封装了一个记录任务名、结束时间操作的 TaskInfo内部类。
• 在 start方法中记录了任务名称和任务执行的时间，基于 System.nanoTime()获得时间。
• 在 stop方法中，通过两个时间戳相减获得 lastTime，也就是一个任务的执行时间；lastTime累计相加获得总的执行时间；同时记录任务列表、任务数统计。

StopWatch源码如下:

package org.springframework.util;

import java.text.NumberFormat;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.TimeUnit;
import org.springframework.lang.Nullable;

public class StopWatch { 
   
    private final String id;
    private boolean keepTaskList;
    private final List<StopWatch.TaskInfo> taskList;
    private long startTimeNanos;
    @Nullable
    private String currentTaskName;
    @Nullable
    private StopWatch.TaskInfo lastTaskInfo;
    private int taskCount;
    private long totalTimeNanos;

    public StopWatch() { 
   
        this("");
    }

    public StopWatch(String id) { 
   
        this.keepTaskList = true;
        this.taskList = new ArrayList(1);
        this.id = id;
    }

    public String getId() { 
   
        return this.id;
    }

    public void setKeepTaskList(boolean keepTaskList) { 
   
        this.keepTaskList = keepTaskList;
    }

    public void start() throws IllegalStateException { 
   
        this.start("");
    }

    public void start(String taskName) throws IllegalStateException { 
   
        if (this.currentTaskName != null) { 
   
            throw new IllegalStateException("Can't start StopWatch: it's already running");
        } else { 
   
            this.currentTaskName = taskName;
            this.startTimeNanos = System.nanoTime();
        }
    }

    public void stop() throws IllegalStateException { 
   
        if (this.currentTaskName == null) { 
   
            throw new IllegalStateException("Can't stop StopWatch: it's not running");
        } else { 
   
            long lastTime = System.nanoTime() - this.startTimeNanos;
            this.totalTimeNanos += lastTime;
            this.lastTaskInfo = new StopWatch.TaskInfo(this.currentTaskName, lastTime);
            if (this.keepTaskList) { 
   
                this.taskList.add(this.lastTaskInfo);
            }

            ++this.taskCount;
            this.currentTaskName = null;
        }
    }

    public boolean isRunning() { 
   
        return this.currentTaskName != null;
    }

    @Nullable
    public String currentTaskName() { 
   
        return this.currentTaskName;
    }

    public long getLastTaskTimeNanos() throws IllegalStateException { 
   
        if (this.lastTaskInfo == null) { 
   
            throw new IllegalStateException("No tasks run: can't get last task interval");
        } else { 
   
            return this.lastTaskInfo.getTimeNanos();
        }
    }

    public long getLastTaskTimeMillis() throws IllegalStateException { 
   
        if (this.lastTaskInfo == null) { 
   
            throw new IllegalStateException("No tasks run: can't get last task interval");
        } else { 
   
            return this.lastTaskInfo.getTimeMillis();
        }
    }

    public String getLastTaskName() throws IllegalStateException { 
   
        if (this.lastTaskInfo == null) { 
   
            throw new IllegalStateException("No tasks run: can't get last task name");
        } else { 
   
            return this.lastTaskInfo.getTaskName();
        }
    }

    public StopWatch.TaskInfo getLastTaskInfo() throws IllegalStateException { 
   
        if (this.lastTaskInfo == null) { 
   
            throw new IllegalStateException("No tasks run: can't get last task info");
        } else { 
   
            return this.lastTaskInfo;
        }
    }

    public long getTotalTimeNanos() { 
   
        return this.totalTimeNanos;
    }

    public long getTotalTimeMillis() { 
   
        return nanosToMillis(this.totalTimeNanos);
    }

    public double getTotalTimeSeconds() { 
   
        return nanosToSeconds(this.totalTimeNanos);
    }

    public int getTaskCount() { 
   
        return this.taskCount;
    }

    public StopWatch.TaskInfo[] getTaskInfo() { 
   
        if (!this.keepTaskList) { 
   
            throw new UnsupportedOperationException("Task info is not being kept!");
        } else { 
   
            return (StopWatch.TaskInfo[])this.taskList.toArray(new StopWatch.TaskInfo[0]);
        }
    }

    public String shortSummary() { 
   
        return "StopWatch '" + this.getId() + "': running time = " + this.getTotalTimeNanos() + " ns";
    }

    public String prettyPrint() { 
   
        StringBuilder sb = new StringBuilder(this.shortSummary());
        sb.append('\n');
        if (!this.keepTaskList) { 
   
            sb.append("No task info kept");
        } else { 
   
            sb.append("---------------------------------------------\n");
            sb.append("ns % Task name\n");
            sb.append("---------------------------------------------\n");
            NumberFormat nf = NumberFormat.getNumberInstance();
            nf.setMinimumIntegerDigits(9);
            nf.setGroupingUsed(false);
            NumberFormat pf = NumberFormat.getPercentInstance();
            pf.setMinimumIntegerDigits(3);
            pf.setGroupingUsed(false);
            StopWatch.TaskInfo[] var4 = this.getTaskInfo();
            int var5 = var4.length;

            for(int var6 = 0; var6 < var5; ++var6) { 
   
                StopWatch.TaskInfo task = var4[var6];
                sb.append(nf.format(task.getTimeNanos())).append(" ");
                sb.append(pf.format((double)task.getTimeNanos() / (double)this.getTotalTimeNanos())).append(" ");
                sb.append(task.getTaskName()).append("\n");
            }
        }

        return sb.toString();
    }

    public String toString() { 
   
        StringBuilder sb = new StringBuilder(this.shortSummary());
        if (this.keepTaskList) { 
   
            StopWatch.TaskInfo[] var2 = this.getTaskInfo();
            int var3 = var2.length;

            for(int var4 = 0; var4 < var3; ++var4) { 
   
                StopWatch.TaskInfo task = var2[var4];
                sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeNanos()).append(" ns");
                long percent = Math.round(100.0D * (double)task.getTimeNanos() / (double)this.getTotalTimeNanos());
                sb.append(" = ").append(percent).append("%");
            }
        } else { 
   
            sb.append("; no task info kept");
        }

        return sb.toString();
    }

    private static long nanosToMillis(long duration) { 
   
        return TimeUnit.NANOSECONDS.toMillis(duration);
    }

    private static double nanosToSeconds(long duration) { 
   
        return (double)duration / 1.0E9D;
    }

    public static final class TaskInfo { 
   
        private final String taskName;
        private final long timeNanos;

        TaskInfo(String taskName, long timeNanos) { 
   
            this.taskName = taskName;
            this.timeNanos = timeNanos;
        }

        public String getTaskName() { 
   
            return this.taskName;
        }

        public long getTimeNanos() { 
   
            return this.timeNanos;
        }

        public long getTimeMillis() { 
   
            return StopWatch.nanosToMillis(this.timeNanos);
        }

        public double getTimeSeconds() { 
   
            return StopWatch.nanosToSeconds(this.timeNanos);
        }
    }
}

– 求知若饥，虚心若愚。