stopwatch优雅打印执行时间

背景

在开发过程中, 有时需要记录一段代码的执行时间,或任务执行的时间.传统用法是在执行开始于结束各记录一次时间,两次时间相减就是执行时间.但这每次计算都需要设置两个变量放于首位.且随着业务改动,调整较大. 而目前有这么一类秒表工具类stopwatch.一次定义,多次使用. 提供者有spring-framework,apache与google.

简单方法

在业务开始与结束分别获取一次系统时间,并在最后两值相减获取执行时间,并按照自己的格式输出.

    public static void main(String[] args) throws InterruptedException {
        
        Long t1 = System.currentTimeMillis();
        // 业务模拟
        Thread.sleep(100);
        Long t2 = System.currentTimeMillis();
        System.out.println("A执行了" + (t2-t1) +"ms");


        Long t3 = System.currentTimeMillis();
        // 业务模拟
        Thread.sleep(100);
        Long t4 = System.currentTimeMillis();
        System.out.println("B执行了" + (t4-t3) +"ms");
     }

spring的stopwatch用法

在业务最开始创建stopwatch对象.

在不同的各个业务阶段调用start与stop方法来打上开始与结束时间标记.

在合适的地方打印业务的耗时与占比

import org.springframework.util.StopWatch;

public static void main(String[] args) throws InterruptedException {
        StopWatch stopwatch = new StopWatch();
        stopwatch.start("A");
        Map<String,Integer> params = new HashMap<>();
        Thread.sleep(100);
        stopwatch.stop();
        stopwatch.start("B");
        for (int i =0;i<1000;i++) {
            String salt = RandomUtil.randomString(10);
            String md5 = DigestUtils.md5Hex("" + salt).toUpperCase().substring(8, 24);
            Integer count = params.get(md5);
            if (count == null) count = 0;
            count ++;
            params.put(md5,count);
        }
        stopwatch.stop();
        stopwatch.start("C");
        params.entrySet().stream().filter(stringIntegerEntry -> stringIntegerEntry.getValue() > 1).collect(Collectors.toList());
        stopwatch.stop();
        System.out.println(stopwatch.prettyPrint());
    }

结果

StopWatch '': running time = 323037500 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
128886100  040%  A
126799900  039%  B
067351500  021%  C

更多方法

• getLastTaskTimeMillis() 获取最后一个任务的耗时
• getTotalTimeSeconds()获取总耗时秒，同时也有获取毫秒的方法；
• prettyPrint()优雅的格式打印结果，表格形式；
• shortSummary()返回简短的总耗时描述；
• getTaskCount()返回统计时间任务的数量；
• getLastTaskInfo().getTaskName()返回最后一个任务TaskInfo对象的名称；

apache的stopwatch用法

在业务最开始创建stopwatch对象.

在不同的各个业务阶段调用split来打上时间标记.

并紧接着输出开始到切点标记的运行时间.

public static void main(String[] args) throws InterruptedException {
    StopWatch stopWatch = new StopWatch();
    stopWatch.start();
    Map<String,Integer> params = new HashMap<>();
    Thread.sleep(100);
    stopWatch.split();
    System.out.println("统计从开始到第一个切入点运行时间：" + stopWatch.getSplitTime() + "ms");

    for (int i =0;i<1000;i++) {
        String salt = RandomUtil.randomString(10);
        String md5 = DigestUtils.md5Hex("" + salt).toUpperCase().substring(8, 24);
        Integer count = params.get(md5);
        if (count == null) count = 0;
        count ++;
        params.put(md5,count);
    }
    stopWatch.split();
    System.out.println("统计从开始到第二个切入点运行时间：" + stopWatch.getSplitTime() + "ms");

    params.entrySet().stream().filter(stringIntegerEntry -> stringIntegerEntry.getValue() > 1).collect(Collectors.toList());
    stopWatch.split();

    System.out.println("统计从开始到第三个切入点运行时间：" + stopWatch.getSplitTime() + "ms");
    stopWatch.stop();
}

执行结果

统计从开始到第一个切入点运行时间：102ms
统计从开始到第二个切入点运行时间：185ms
统计从开始到第三个切入点运行时间：259ms

guava的stopwatch用法

与其他两个不同,google的stopwatch创建使用的是createStarted静态类.在需要的时候创建.

切点的统计使用的是elapsed()方法,

存在reset()方法,但需要再次调用start才开始计时.

public static void main(String[] args) throws InterruptedException {
    Stopwatch stopwatch = Stopwatch.createStarted();

    Map<String,Integer> params = new HashMap<>();
    Thread.sleep(100);
    System.out.println("统计从开始到第一个切入点运行时间：" + stopwatch.elapsed() + "ms");

    for (int i =0;i<1000;i++) {
        String salt = RandomUtil.randomString(10);
        String md5 = DigestUtils.md5Hex("" + salt).toUpperCase().substring(8, 24);
        Integer count = params.get(md5);
        if (count == null) count = 0;
        count ++;
        params.put(md5,count);
    }
    System.out.println("统计从开始到第二个切入点运行时间：" + stopwatch.elapsed() + "ms");
    stopwatch.reset().start();
    params.entrySet().stream().filter(stringIntegerEntry -> stringIntegerEntry.getValue() > 1).collect(Collectors.toList());

    System.out.println("统计第三个业务运行时间：" + stopwatch.elapsed() + "ms");
}

结果

统计从开始到第一个切入点运行时间：PT0.1079573Sms
统计从开始到第二个切入点运行时间：PT0.1422942Sms
统计从开始到第三个切入点运行时间：PT0.0433762Sms