Я столкнулся с примером чрезвычайно неустойчивого профиля производительности очень простой операции отображения/сокращения на примитивных массивах. Вот мой тестовый код jmh:
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@BenchmarkMode(Mode.AverageTime)
@OperationsPerInvocation(Measure.ARRAY_SIZE)
@Warmup(iterations = 300, time = 200, timeUnit=MILLISECONDS)
@Measurement(iterations = 1, time = 1000, timeUnit=MILLISECONDS)
@State(Scope.Thread)
@Threads(1)
@Fork(1)
public class Measure
{
static final int ARRAY_SIZE = 1<<20;
final int[] ds = new int[ARRAY_SIZE];
private IntUnaryOperator mapper;
@Setup public void setup() {
setAll(ds, i->(int)(Math.random()*(1<<7)));
final int multiplier = (int)(Math.random()*10);
mapper = d -> multiplier*d;
}
@Benchmark public double multiply() {
return Arrays.stream(ds).map(mapper).sum();
}
}
И вот фрагменты типичного вывода:
# VM invoker: /Library/Java/JavaVirtualMachines/jdk1.8.0_20.jdk/Contents/Home/jre/bin/java
# VM options: <none>
# Warmup: 300 iterations, 200 ms each
# Measurement: 1 iterations, 1000 ms each
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: org.sample.Measure.multiply
# Run progress: 0,00% complete, ETA 00:01:01
# Fork: 1 of 1
# Warmup Iteration 1: 0,779 ns/op
# Warmup Iteration 2: 0,684 ns/op
# Warmup Iteration 3: 0,608 ns/op
# Warmup Iteration 4: 0,619 ns/op
# Warmup Iteration 5: 0,642 ns/op
# Warmup Iteration 6: 0,638 ns/op
# Warmup Iteration 7: 0,660 ns/op
# Warmup Iteration 8: 0,611 ns/op
# Warmup Iteration 9: 0,636 ns/op
# Warmup Iteration 10: 0,692 ns/op
# Warmup Iteration 11: 0,632 ns/op
# Warmup Iteration 12: 0,612 ns/op
# Warmup Iteration 13: 1,280 ns/op
# Warmup Iteration 14: 7,261 ns/op
# Warmup Iteration 15: 7,379 ns/op
# Warmup Iteration 16: 7,376 ns/op
# Warmup Iteration 17: 7,379 ns/op
# Warmup Iteration 18: 7,195 ns/op
# Warmup Iteration 19: 7,351 ns/op
# Warmup Iteration 20: 7,761 ns/op
....
....
....
# Warmup Iteration 100: 7,300 ns/op
# Warmup Iteration 101: 7,384 ns/op
# Warmup Iteration 102: 7,132 ns/op
# Warmup Iteration 103: 7,278 ns/op
# Warmup Iteration 104: 7,331 ns/op
# Warmup Iteration 105: 7,335 ns/op
# Warmup Iteration 106: 7,450 ns/op
# Warmup Iteration 107: 7,346 ns/op
# Warmup Iteration 108: 7,826 ns/op
# Warmup Iteration 109: 7,221 ns/op
# Warmup Iteration 110: 8,017 ns/op
# Warmup Iteration 111: 7,611 ns/op
# Warmup Iteration 112: 7,376 ns/op
# Warmup Iteration 113: 0,707 ns/op
# Warmup Iteration 114: 0,828 ns/op
# Warmup Iteration 115: 0,608 ns/op
# Warmup Iteration 116: 0,634 ns/op
# Warmup Iteration 117: 0,633 ns/op
# Warmup Iteration 118: 0,660 ns/op
# Warmup Iteration 119: 0,635 ns/op
# Warmup Iteration 120: 0,566 ns/op
Ключевые моменты происходят на итерациях 13 и 113: сначала производительность снижается в десять раз, а затем восстанавливается. Соответствующие времена составляют 2,5 и 22,5 секунды в тестовом прогоне. Время этих событий очень чувствительно к размеру массива, BTW.
Что может объяснить такое поведение? Компилятор JIT, вероятно, проделал свою работу в рамках первой итерации; о каких-либо действиях в ГК не говорится (подтверждено VisualVM)... Я полностью потерял всякое объяснение.
Моя версия Java (OS X):
$ java -version
java version "1.8.0_20"
Java(TM) SE Runtime Environment (build 1.8.0_20-b26)
Java HotSpot(TM) 64-Bit Server VM (build 25.20-b23, mixed mode)
