Stop Watch - java获取方法的具体执行时间

大家都知道java中，如果想查看一个方法执行具体的时间，最简单的方法就是在方法执行前后使用long  System.currentTimeMillis()获取当前的时间，再用时间相减。其实这样获取的时间是相对不精确的。例如在下面的程序中： 

long startTime = System.currentTimeMillis();

method();

long endTime = System.currentTimeMillis();

executeTime = endTime - startTime

其实method可以是一个很简单的方法也可以是一个很复杂的方法，在method中，我们可以去修改各种各样的信息，可以去和第三方的jar包进行交互，这样其实他的执行时间有可能会取决于和第三方的交互时间，而第三方的执行时间，有可能还有各种网络连接，数据库连接等相关，所以我们往往是不能很精确的获取这个时间的，最精确的办法是用反射的原理，利用Spring的AOP编程，逐步地去查看每个方法的执行细节所花费的时间，但这样往往很复杂，实际上，Apache中的common框架中的一个工具类org.apache.commons.lang.time StopWatch 可以很好的模拟了秒表，通过它的split方法和getSplitTime方法，可以很好地看出各分步骤对性能下降的贡献值来。

1. 简单的模拟：

 watch.start();

        logger.info("Start to get information from VCenter: " + vCenter);

        try {

            vc = inventory.getVCenterInfo();

        } catch (Exception e) {

            logger.error("cannot get VCenter info: " + vCenter , e);

            return;

        }

        watch.stop();

logger.info(String.format("End to get information from VCenter: %s, spend time:%s(ms) ", vCenter, watch.getTime()));

 

2. 更加精确的模拟：

stWatch.start();



step1();



stWatch.split();



System.out.println("Time consumed by step1: "+stWatch.getSplitTime());



step2();



stWatch.split();



System.out.println("Time consumed by step1 and step2: "+stWatch.getSplitTime());



stWatch.stop();

 

但如上的代码有些许不足： 每次getSplitTime得到的值都是当前所有步骤的总和，而不是当前这个步骤的耗时值，以上面代码为例，它没有直接地得出step1和step2两个步骤的各自耗。

 

于是原来基础上加了两个方法(加了方法的源码见附件)： splitAndSaveTime和getSplitTimeByStep。这样的演示代码如下：

 

评论

1 楼 freezingsky 2013-07-03  

只是简单的介绍API就没什么意思了。如果能进一步的说明，二者的差异性，以及后者的实现方式，相信会更好！