发现一个 Java 代码耗时统计的问题

This topic created in 1349 days ago, the information mentioned may be changed or developed.

一个方法的执行时间耗时比较高，用以下的代码统计耗时发现整个方法耗时长，但是单次循环的耗时又很小。整个方法 for 循环外没有其他代码，代码如下，某次耗时如下。并非每次都这样，但都是 cost 比 cost1 加起来要大，循环次数不会很大，1-10 次左右。环境：jdk1.8,IDEA2021

		fun(){
			long st = System.currentTimeMillis();
			for(xxx){
				long st1 = System.currentTimeMillis();
				xxxxx
				long et1 = System.currentTimeMillis();
				System.out.println("cost1:" + (et1-st1));
			}
			long et = System.currentTimeMillis();
			System.out.println("cost:" + (et-st));
		}
		cost1:16
		cost1:13
		cost1:16
		cost1:2
		cost:168

12 replies • 2022-09-05 15:12:58 +08:00

AlkTTT

Sep 5, 2022

System.out.println();
控制台打印是走 IO 的，也有耗时

CodeXx

Sep 5, 2022

@AlkTTT 会耗时这么高吗

lllllliiii

Sep 5, 2022

@AlkTTT #1
```
long et = System.currentTimeMillis();
```
这一行已经把时间算出来了。跟`print`没关系把。

Jooooooooo

Sep 5, 2022

java 有 jit 和 gc 的, 没法这么简单的算耗时. 至少你的循环次数不够.

timethinker

Sep 5, 2022

@fzdwx 之前的时间都是单纯的计算两个时间差，并没有把每次的输出计算在内，但是最后的输出包含了循环内的 println 语句，所以总时间跟之前的时间存在悬殊。

timethinker

Sep 5, 2022

建议楼主先把计算的结果缓存到一个数组内，最后再打印出来数组内的结果，看看是否可以得到心中想要的答案，就能确定问题出在什么地方了。

chendy

Sep 5, 2022

因为有 GC ，JIT ，以及系统资源调度等等等的问题导致时间不稳定
需要做足够的 warmup ，跑比较多的次数才能得到一个相对准确的时间
测性能的话，推荐使用 jmh https://github.com/openjdk/jmh

340244120w

Sep 5, 2022 via iPhone

把 print 去掉程序最后一行再 print 看看最终结果。楼上几位说 jit 的，审题不仔细啊

yiqunz

Sep 5, 2022

··· java
public static void main(String[] args) throws InterruptedException {
int times = 10;
long[] s1 = new long[times];
long[] s2 = new long[times];
long start = System.currentTimeMillis();
for (int i = 0; i < times; i++) {
s1[i] = System.currentTimeMillis();
Thread.sleep(10);
s2[i] = System.currentTimeMillis();
}
long end = System.currentTimeMillis();
System.out.println(end - start);
long all = 0;
for (int i = 0; i < times; i++) {
System.out.println(s2[i] - s1[i]);
all += s2[i] - s1[i];
}
System.out.println(all);
}

```
实测就是相同的

yiqunz

Sep 5, 2022

``` java
public static void main(String[] args) throws InterruptedException {
int times = 10;
long[] s1 = new long[times];
long[] s2 = new long[times];
long start = System.currentTimeMillis();
for (int i = 0; i < times; i++) {
s1[i] = System.currentTimeMillis();
Thread.sleep(10);
s2[i] = System.currentTimeMillis();
}
long end = System.currentTimeMillis();
System.out.println(end - start);
long all = 0;
for (int i = 0; i < times; i++) {
System.out.println(s2[i] - s1[i]);
all += s2[i] - s1[i];
}
System.out.println(all);
}

```
实测就是相同的

CodeXx

Sep 5, 2022

感谢以上回复。本人疏忽，for 里面有些条件 continue 了，导致的时间对不上。。应该要在 for 开头打印上次执行完到这次开始执行的时间的

AS4694lAS4808

Sep 5, 2022

有 continue 不写出来不是在忽悠楼上的大神们[狗头]