Я провел микротестирование следующего кода и заметил кое-что интересное, на что я надеюсь, кто-нибудь сможет пролить больше света. Это приводит к ситуации, когда кажется, что цикл 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-ядерном ноутбуке Intel Sandy Bridged/i7 с тактовой частотой 2 ГГц под управлением Java 6 (Oracle JVM) на OSX. Этот код неоднократно запускается для
2,626852686364034 несогласованных байтовых массива чтений/нс [totalTestRun=3806,837 мс]
(Я отбраковал повторные прогоны, используемые для разогрева JVM)
Этот результат кажется мне разумным.
Это стало интересным, когда я начал измерять джиттер JVM. Для этого я запускаю поток фонового демона, который спит в течение 1 мс, а затем выясняю, насколько дольше 1 мс он действительно спал. И я изменил отчет, чтобы распечатать максимальный джиттер для каждого повторного запуска теста.
2,6109858273078306 несогласованных байтовых массивов чтений/нс [maxJitter=0,411 мс totalTestRun=3829,971 мс]
Чтобы получить представление о «нормальном» джиттере для моей среды, перед запуском фактических тестовых прогонов я отслеживаю джиттер без какой-либо работы, и показания, подобные приведенным ниже, являются типичными (все в мс). Таким образом, джиттер в 0,411 мс является нормальным и не столь интересным.
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;
}
}
}
