还在用new Date计算任务执行时间?强烈建议使用这个API

在实践过程中,我们经常需要记录一个任务执行的耗时,这是评价代码好坏,评测代码性能,排查业务执行问题的重要操作。那么,你是如何来获取并计算任务执行耗时的呢?通过new Date获得时间进行换算?还是有更好的方案?本文给你答案。

获取任务耗时通常做法

获取任务耗时,最简单的方式就是打印当前时间与任务开始执行时间的差值,实例代码如下:

  @Test
  public void testElapsedTimes() throws InterruptedException {
    long startTime = new Date().getTime();

    // do something
    Thread.sleep(1000);

    System.out.println("执行耗时:" + (new Date().getTime() - startTime) + "ms");
  }

上述方式实现简单,逻辑也比较直观。但如果执行大量测试,测试中还有不同的代码逻辑块,那么需要改动的地方就比较多。

改进做法

在上述代码中,如果IDE安装有代码检查工具,则会提示采用System.currentTimeMillis()来获取时间,而不是new Date().getTime()的方式。

改造之后,实现代码如下:

  @Test
  public void testElapsedTimes1() throws InterruptedException {
    long startTime = System.currentTimeMillis();

    // do something
    Thread.sleep(1000);

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

在这样的场景下(无需获取更多Date相关信息)也推荐使用System.currentTimeMillis()来获取时间戳。至于为什么,看一下Date的源码实现就知道了。

Date的构造方法:

public Date() {
    this(System.currentTimeMillis());
}

Date在构造时,本质上也是先获得了System.currentTimeMillis(),然后再初始化其他信息。既然我们只需要时间戳,那就没必要再构建Date对象了。从性能层面来说,能优化则优化。

Spring的StopWatch

上述两种方式虽然性能和写法有所区别,但本质是一样的。下面我们来讲讲Spring提供的StopWatch类,它不仅可实现上述功能,而且还可以做类似任务执行时间控制,也就是封装了一个对开始时间、结束时间记录操作的Java类。

先通过StopWatch类来实现一下上述功能:

  @Test
  public void testStopWatch() throws InterruptedException {
    StopWatch sw = new StopWatch();

    sw.start("开始执行业务");
    // do something
    Thread.sleep(1000);
    sw.stop();

    System.out.println(sw.getTotalTimeMillis());
  }

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

乍一看,代码好像还比之前的方式多了,体现不出来什么优势啊!下面我们再来看一个复杂点的示例:

  @Test
  public void testStopWatch1() throws InterruptedException {
    StopWatch sw = new StopWatch();

    sw.start("起床");
    Thread.sleep(1000);
    sw.stop();

    sw.start("洗漱");
    Thread.sleep(2000);
    sw.stop();

    sw.start("锁门");
    Thread.sleep(500);
    sw.stop();

    System.out.println(sw.prettyPrint());
    System.out.println(sw.getTotalTimeMillis());
    System.out.println(sw.getLastTaskName());
    System.out.println(sw.getLastTaskInfo());
    System.out.println(sw.getTaskCount());
  }

执行上述测试示例,打印结果如下:

StopWatch '': running time = 3509166972 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
1003330360  029%  起床
2001421734  057%  洗漱
504414878  014%  锁门

3509
锁门
org.springframework.util.StopWatch$TaskInfo@12f40c25
3

此时,看到StopWatch的魅力所在了吗?

  • 通过多组start、stop方法,将业务代码块进行区分,可获得不同代码块的执行耗时;
  • 可以通过start方法传入taskName,对每个代码块进行命名;
  • 可以对总任务耗时、每个任务耗时进行统计分析;
  • prettyPrint()方法,可以优雅的打印出统计分析信息;
  • getTotalTimeMillis()方法,打印出总耗时;
  • getLastTaskName()方法,打印最后一个任务名称;
  • getLastTaskInfo()方法,获得最后一个任务的TaskInfo,进而获得更多相关信息;
  • getTaskCount()方法,获得任务数;

现在再看,使用StopWatch是不是可以获得更多有用的信息?

StopWatch的实现原理

最后呢,我们再来看一眼源码,了解一下StopWatch的实现机制。

先看StopWatch的start方法实现:

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

start方法中记录了任务名称和任务执行的时间,基于System.nanoTime()获得。

stop方法实现如下:

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

在stop方法中,通过两个时间戳相减获得lastTime,也就是一个任务的执行时间;lastTime累计相加获得总的执行时间;同时,记录任务列表、任务数统计。

而其他get方法,则是对start、stop中获取的数据的进一步统计、分析、格式化输出而已。

小结

有些功能当我们使用习惯了,可能就固守于一个实现方式,但如果去参考学习其他框架中类似功能的实现,往往会有些新的突破。如果你在使用Spring的框架,建议你尝试一下StopWatch这个API,可以让你的时间统计日志更加高端大气。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 213,014评论 6 492
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,796评论 3 386
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 158,484评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,830评论 1 285
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,946评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,114评论 1 292
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,182评论 3 412
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,927评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,369评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,678评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,832评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,533评论 4 335
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,166评论 3 317
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,885评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,128评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,659评论 2 362
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,738评论 2 351

推荐阅读更多精彩内容