我一直在对以下代码进行微基准测试,我注意到一些有趣的东西,我希望有人能对此有所了解。这导致了一种情况,看起来 for 循环可以继续快速运行,同时阻塞 JVM 中的其他线程。如果这是真的,那么我想了解为什么,如果不是真的,那么任何对我可能遗漏的东西的见解都会受到赞赏。
为了建立这种情况,让我带您了解我正在运行的基准测试及其结果。
代码非常简单,遍历数组中的每个元素,对其内容求和。重复“targetCount”次。
public class UncontendedByteArrayReadBM extends Benchmark {
private int arraySize;
private byte[] array;
public UncontendedByteArrayReadBM( int arraySize ) {
super( "array reads" );
this.arraySize = arraySize;
}
@Override
public void setUp() {
super.setUp();
array = new byte[arraySize];
}
@Override
public void tearDown() {
array = null;
}
@Override
public BenchmarkResult invoke( int targetCount ) {
long sum = 0;
for ( int i=0; i<targetCount; i++ ) {
for ( int j=0; j<arraySize; j++ ) {
sum += array[j];
}
}
return new BenchmarkResult( ((long)targetCount)*arraySize, "uncontended byte array reads", sum );
}
}
在我的 4 核 - 2Ghz Intel Sandy Bridged/i7 笔记本电脑上,在 OSX 上运行 Java 6 (Oracle JVM)。此代码反复运行到
2.626852686364034 非竞争字节数组读取/ns [totalTestRun=3806.837ms]
(我已经剔除了用于加热 JVM 的重复运行)
这个结果在我看来是合理的。
当我开始测量 JVM Jitter 时,这很有趣。为此,我启动了一个休眠 1ms 的后台守护线程,然后计算出它真正休眠的时间比 1ms 长了多少。我更改了报告以打印出每次重复测试运行的最大抖动。
2.6109858273078306 非竞争字节数组读取/ns [maxJitter=0.411ms totalTestRun=3829.971ms]
为了了解我的环境的“正常”抖动,在开始实际测试运行之前,我在没有任何工作的情况下监控抖动,并且以下读数是典型的(均以毫秒为单位)。因此,0.411ms 的抖动是正常的,并不那么有趣。
getMaxJitterMillis() = 0.599
getMaxJitterMillis() = 0.37
getMaxJitterMillis() = 0.352
我在这个问题的结尾包含了我如何测量抖动的代码。
然而有趣的部分,是的,它确实发生在“JVM预热”期间,因此不“正常”,但我想更详细地了解以下内容:
2.4519521584902644 uncontended byte array reads/ns [maxJitter=2561.222ms totalTestRun=4078.383ms]
请注意,抖动超过 2.5 秒。通常我会把它归结为GC。但是,我确实在测试运行之前触发了 System.gc(),并且 -XX:+PrintGCDetails 此时没有显示 GC。事实上,在任何测试运行期间都没有 GC,因为在这个总结预分配字节的测试中几乎没有发生对象分配。每次我运行新测试时也会发生这种情况,因此我不怀疑它是来自其他随机发生的进程的干扰。
我的好奇心猛增,因为当我注意到总运行时间的抖动非常高时,实际上每纳秒读取数组元素的数量或多或少保持不变。因此,在这种情况下,一个线程在 4 核机器上严重滞后,而工作线程本身并没有滞后,也没有 GC 进行。
进一步调查,我查看了 Hotspot 编译器在做什么,并通过 -XX:+PrintCompilation 找到以下内容:
2632 2% com.mosaic.benchmark.datastructures.array.UncontendedByteArrayReadBM::invoke @ 14 (65 bytes)
6709 2% made not entrant com.mosaic.benchmark.datastructures.array.UncontendedByteArrayReadBM::invoke @ -2 (65 bytes)
打印出来的这两行之间的延迟约为 2.5 秒。就在包含大 for 循环的方法已将其优化代码标记为不再进入时。
我的理解是 Hotspot 在后台线程上运行,当它准备好换入新版本的代码时,它会等待已经运行的代码到达安全点,然后再换入。如果是一个大的 for 循环,位于每个循环体的末尾(可能已经展开了一些)。我预计不会有 2.5 秒的延迟,除非此换出必须在 JVM 中执行停止世界事件。在去优化以前编译的代码时会这样做吗?
所以我对 JVM 内部专家的第一个问题是,我是否走在正确的轨道上?2.5 秒的延迟是否是由于将该方法标记为“未进入”?如果是这样,为什么它会对其他线程产生如此极端的影响?如果这不太可能是原因,那么任何关于其他调查内容的想法都会很棒。
(为了完整起见,这里是我用来测量抖动的代码)
private static class MeasureJitter extends Thread {
private AtomicLong maxJitterWitnessedNS = new AtomicLong(0);
public MeasureJitter() {
setDaemon( true );
}
public void reset() {
maxJitterWitnessedNS.set( 0 );
}
public double getMaxJitterMillis() {
return maxJitterWitnessedNS.get()/1000000.0;
}
public void printMaxJitterMillis() {
System.out.println( "getMaxJitterMillis() = " + getMaxJitterMillis() );
}
@Override
public void run() {
super.run();
long preSleepNS = System.nanoTime();
while( true ) {
try {
Thread.sleep( 1 );
} catch (InterruptedException e) {
e.printStackTrace();
}
long wakeupNS = System.nanoTime();
long jitterNS = Math.max(0, wakeupNS - (preSleepNS+1000000));
long max = Math.max( maxJitterWitnessedNS.get(), jitterNS );
maxJitterWitnessedNS.lazySet( max );
preSleepNS = wakeupNS;
}
}
}