JVM抖动如何由没有对象分配的for循环引起？

Question

我已经对下面的代码进行了微观基准测试,我注意到一些有趣的东西,我希望有人可以更多地了解它.它导致一种情况,它看起来像一个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抖动的时候.为此,我启动一个后台守护程序线程,它休眠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上执行一个stop-the-world事件.在取消优化以前编译的代码时是否会这样做？

所以我对JVM内部专家的第一个问题是,我在这里走在正确的轨道上吗？2.5s延迟可能是因为将该方法标记为"未进入"; 如果是这样,为什么它会对其他线程产生如此极大的影响呢？如果这不太可能是原因,那么任何关于调查什么的想法都会很棒.

(为了完整性,这里是我用来测量抖动的代码)

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;
        }
    }
}

Answer 1

这需要一些挖掘才能找到吸烟枪,但这些教训很有价值; 特别是如何证明和隔离原因.所以我认为在这里记录它们很好.

JVM确实在等待举办Stop The World活动.Alexey Ragozin在http://blog.ragozin.info/2012/10/safepoints-in-hotspot-jvm.html上有关于这个主题的非常好的博客文章,这是让我走上正确轨道的帖子.他指出安全点在JNI方法边界和Java方法调用上.因此,我在这里的for循环没有安全点.

要了解在Java中停止世界事件,请使用以下JVM标志: -XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

第一个打印出停止世界事件的总持续时间,并不仅限于GC.在我的情况下打印出来:

Total time for which application threads were stopped: 2.5880809 seconds

这证明我遇到线程等待达到安全点的问题.接下来的两个参数打印出JVM想要等待达到全局安全点的原因.

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
4.144: EnableBiasedLocking              [      10          1              1    ]      [  2678     0  2678     0     0    ]  0   
Total time for which application threads were stopped: 2.6788891 seconds

因此,这表示JVM在尝试启用偏置锁定时等待了2678ms.为什么这是一个停止世界事件？值得庆幸的是Martin Thompson过去也遇到了这个问题,他在这里记录了这个问题.事实证明,Oracle JVM在启动期间存在相当多的线程争用,在此期间,偏置锁定具有非常高的成本,因此它延迟了将优化开启四秒钟.所以这里发生的事情是我的微基准测试超过4秒,然后它的循环没有安全点.因此,当JVM试图打开偏置锁定时,它必须等待.

对我有用的候选解决方案是:

1. -XX:-UseBiasedLocking(关闭偏置锁定)
2. -XX:BiasedLockingStartupDelay = 0(立即启用偏向锁定)
3. 更改循环以在其中包含安全点(例如,未优化或内联的方法调用)