java - 没有对象分配的 for 循环如何导致 JVM 抖动？

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 抖动时。为此，我启动了一个 hibernate 1 毫秒的后台守护进程线程，然后计算出它真正 hibernate 的时间比 1 毫秒长多少。我更改了报告以打印出每次重复测试运行的最大抖动。

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

Answer 1

这需要一些挖掘才能找到确凿的证据，但经验教训很有值(value)；特别是关于如何证明和隔离原因。所以我认为在这里记录它们很好。

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

要了解 Java 中的 stop the world 事件，请使用以下 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 在尝试启用偏置锁定时等待了 2678 毫秒。为什么这是一个停止世界事件？值得庆幸的是，Martin Thompson 过去也遇到过这个问题，并且他已将其记录在案 here .事实证明，Oracle JVM 在启动期间有相当多的线程争用，在此期间，偏向锁定的成本非常高，因此它延迟了 4 秒开启优化。所以这里发生的事情是我的微基准测试超过了四秒钟，然后它的循环中没有安全点。因此，当 JVM 尝试开启偏置锁定时，它不得不等待。

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

-XX:-UseBiasedLocking(关闭偏置锁定)

-XX:BiasedLockingStartupDelay=0(立即启用偏置锁定)

更改循环以在其中包含一个安全点(例如，未优化或内联的方法调用)