Java Microbenchmark Harness (JMH) BufferedInputStream Test

Giriş

Elimizde BufferedInputStream işlevini sağlayan 3 tane sınıf vardı. Bunlardan 

- İki tanesi - yani Apache Common IO sınıfı ve Hazelcast'in kendi sınıfı - unsynchronized çalışıyor. 

- Bir tanesiyse - yani JDK ile gelen sınıf - synchronized çalışıyor. 

Merak ettiğimiz şey single threaded ortamda synchronized sınıfın read() metodunun maliyetinin çok fark yaratıp yaratmadığıydı

Not : JMH ile ölçüm yapan GitHub projesi burada

Sınıflar şöyle

1. java.io.BufferedInputStream;

2. com.hazelcast.internal.util.BufferingInputStream

3. org.apache.commons.io.input.UnsynchronizedBufferedInputStream;

Test kodu şöyle 

1. InputStream'den 100, 1000 ve 10_000 byte büyüklüğünde farklı bellek büyüklükleri ile okuma yappıyoruz

2. Girdi olarak kullanılan dosyada 30K satır var

// Only one forked process
@Fork(value = 1)
// Only one thread
@Threads(1)
// use the same instance of this class for the whole benchmark,
// so it is OK to have some member variables
@State(Scope.Benchmark)
// calculate the average time of one call
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
// 5 iterations to warm-up, that may last 20 milliseconds each
@Warmup(iterations = 5, time = 20, timeUnit = TimeUnit.MILLISECONDS)
// 20 iterations to measure, that may last 200 milliseconds each
@Measurement(iterations = 20, time = 200, timeUnit = TimeUnit.MILLISECONDS)
public class BufferedInputStreamJmh {
  @Param({"100", "1000", "10000"})
  private int readBufferSize;

  private BufferedInputStream bufferedInputStream;
  private BufferingInputStream bufferingInputStream;
  private UnsynchronizedBufferedInputStream unsynchronizedBufferedInputStream;

  public static void main(String[] args) throws Exception {
    org.openjdk.jmh.Main.main(args);
  }
  
  private int countNewLinesManually(InputStream inputStream, int customBytesToBuffer)
  throws IOException {
    byte[] buff = new byte[customBytesToBuffer];
    int count = 1;
    int bytesRead;
    while ((bytesRead = inputStream.read(buff)) != -1) {
      for (int i = 0; i < bytesRead; i++) {
        if (buff[i] == '\n') {
          count++;
        }
      }
    }
    return count;
  }
  ... 
}

@Setup ve @Teardown içinde her bir Invocation için yeni bir stream yaratıyoruz. Amaç sadece read() metodunun synchronized olup olmaması neyi değiştiriyor onu ölçmek. Bu yüzden test içine stream yaratma maliyetini dahil etmek istemedik. InputStream için 65536 byte büyüklüğünde oldukça büyük bir buffer kullanıyoruz

@Setup(Level.Invocation)
public void setup() throws IOException {
  final int streamInternalBufferSize = 1 << 16;
  bufferedInputStream = new BufferedInputStream(
    new FileInputStream("myfile.txt"), streamInternalBufferSize);
    
  bufferingInputStream = new BufferingInputStream(
      new FileInputStream("myfile.txt"), streamInternalBufferSize);
  unsynchronizedBufferedInputStream = new UnsynchronizedBufferedInputStream.Builder()
    .setInputStream(new FileInputStream("myfile.txt"))
    .setBufferSize(streamInternalBufferSize)
    .get();
}

@TearDown(Level.Invocation)
public void teardown() throws IOException {
  bufferedInputStream.close();
  bufferingInputStream.close();
  unsynchronizedBufferedInputStream.close();
}

Testler şöyle

@Benchmark
@OutputTimeUnit(TimeUnit.MILLISECONDS)
public int useBufferingInputStream() throws IOException {
  return countNewLinesManually(bufferingInputStream, readBufferSize);
  //assertThat(numberOfLines).isEqualTo(30_000);
}

@Benchmark
@OutputTimeUnit(TimeUnit.MILLISECONDS)
public int useBufferedInputStream() throws IOException {
  return countNewLinesManually(bufferedInputStream, readBufferSize);
  //assertThat(numberOfLines).isEqualTo(30_000);
}

@Benchmark
@OutputTimeUnit(TimeUnit.MILLISECONDS)
public int useUnsynchronizedBufferedInputStream() throws IOException {
  return countNewLinesManually(unsynchronizedBufferedInputStream, readBufferSize);
  //assertThat(numberOfLines).isEqualTo(30_000);
}

Test sonuçları şöyle. 

- Java 11'de hem MacOS hem de Windows 11'de BufferingInputStream daha iyi sonuç verdi. 

- JDK BufferednputStream ikinci. 

- UnsynchronizedBufferedInputStream sınıfı unsynchronized kod kullanmasına rağmen üçüncü sırada. Üstelik UnsynchronizedBufferedInputStream sınıfı 100 byte okumada çok kötü sonuç veriyor.

Java 11 MacOs

Benchmark                                                    (readBufferSize)  Mode  Cnt  Score   Error  Units
BufferedInputStreamJmh.useBufferedInputStream                             100  avgt   20  0.276 ± 0.003  ms/op
BufferedInputStreamJmh.useBufferedInputStream                            1000  avgt   20  0.229 ± 0.003  ms/op
BufferedInputStreamJmh.useBufferedInputStream                           10000  avgt   20  0.236 ± 0.003  ms/op
BufferedInputStreamJmh.useBufferingInputStream                            100  avgt   20  0.268 ± 0.004  ms/op
BufferedInputStreamJmh.useBufferingInputStream                           1000  avgt   20  0.226 ± 0.001  ms/op
BufferedInputStreamJmh.useBufferingInputStream                          10000  avgt   20  0.227 ± 0.002  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream               100  avgt   20  4.163 ± 0.018  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream              1000  avgt   20  0.594 ± 0.002  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream             10000  avgt   20  0.240 ± 0.001  ms/op

Java 11 Windows

Benchmark                                                    (readBufferSize)  Mode  Cnt  Score   Error  Units
BufferedInputStreamJmh.useBufferedInputStream                             100  avgt   20  0,336 ± 0,009  ms/op
BufferedInputStreamJmh.useBufferedInputStream                            1000  avgt   20  0,267 ± 0,009  ms/op
BufferedInputStreamJmh.useBufferedInputStream                           10000  avgt   20  0,264 ± 0,014  ms/op
BufferedInputStreamJmh.useBufferingInputStream                            100  avgt   20  0,283 ± 0,008  ms/op
BufferedInputStreamJmh.useBufferingInputStream                           1000  avgt   20  0,245 ± 0,006  ms/op
BufferedInputStreamJmh.useBufferingInputStream                          10000  avgt   20  0,234 ± 0,008  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream               100  avgt   20  8,785 ± 0,135  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream              1000  avgt   20  1,076 ± 0,016  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream             10000  avgt   20  0,308 ± 0,014  ms/op

Java 17'de sonuç aynı. JDK 15 ile artık biased locking artık yok. Yani kodda synchronized varsa bile artık hep etkin.  Buna rağmen BufferedInputStream etkilenmiyor

Java 17 MacOs

Benchmark                                                    (readBufferSize)  Mode  Cnt  Score   Error  Units
BufferedInputStreamJmh.useBufferedInputStream                             100  avgt   20  0.277 ± 0.001  ms/op
BufferedInputStreamJmh.useBufferedInputStream                            1000  avgt   20  0.224 ± 0.001  ms/op
BufferedInputStreamJmh.useBufferedInputStream                           10000  avgt   20  0.231 ± 0.004  ms/op
BufferedInputStreamJmh.useBufferingInputStream                            100  avgt   20  0.268 ± 0.002  ms/op
BufferedInputStreamJmh.useBufferingInputStream                           1000  avgt   20  0.216 ± 0.001  ms/op
BufferedInputStreamJmh.useBufferingInputStream                          10000  avgt   20  0.223 ± 0.003  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream               100  avgt   20  3.582 ± 0.008  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream              1000  avgt   20  0.536 ± 0.005  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream             10000  avgt   20  0.231 ± 0.003  ms/op

Java 17 Windows

Benchmark                                                    (readBufferSize)  Mode  Cnt  Score   Error  Units
BufferedInputStreamJmh.useBufferedInputStream                             100  avgt   20  0,422 ± 0,012  ms/op
BufferedInputStreamJmh.useBufferedInputStream                            1000  avgt   20  0,302 ± 0,008  ms/op
BufferedInputStreamJmh.useBufferedInputStream                           10000  avgt   20  0,256 ± 0,008  ms/op
BufferedInputStreamJmh.useBufferingInputStream                            100  avgt   20  0,299 ± 0,004  ms/op
BufferedInputStreamJmh.useBufferingInputStream                           1000  avgt   20  0,273 ± 0,004  ms/op
BufferedInputStreamJmh.useBufferingInputStream                          10000  avgt   20  0,237 ± 0,005  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream               100  avgt   20  8,624 ± 0,184  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream              1000  avgt   20  1,076 ± 0,041  ms/op
BufferedInputStreamJmh.useUnsynchronizedBufferedInputStream             10000  avgt   20  0,300 ± 0,006  ms/op

Java Microbenchmark Harness (JMH) Kullanımı

Gradle

Şu satırı dahil ederiz

plugins {
  ...
  id "me.champeau.gradle.jmh" version "0.5.3"
  ...
}

Çalıştırmak için şöyle yaparız

gradle jmh

@State Anotasyonu

Scope.Benchmark

Açıklaması şöyle. Tek bir nesneyi multi-threaded olarak test etmek içindir

By using benchmark scope, all of the threads used on the benchmark scope will share the same object. 

@OutputTimeUnit Anotasyonu

Açıklaması şöyle.

We would like our results to be reported in microseconds, therefore we shall use @OutputTimeUnit(TimeUnit.MICROSECONDS)

@BenchmarkMode Anotasyonu

Açıklaması şöyle.

On JMH, we have various benchmark modes depending on what we want to measure.

Throughput is when we want to measure the number of operations per unit of time.

AverageTime is when we want to measure the average time per operation.

SampleTime is when we want to sample the time for each operation including min, max time, and more than just the average.

SingleShotTime is when we want to measure the time for a single operation. This can help when we want to identify how the operation will do on a cold start.

All We also have the option to measure all of the above with @BenchmarkMode(Mode.All)

@Threads Anotasyonu

Kaç thread ile koşacağını belirtir

@Warmup Anotasyonu

Kaç defa ısınma yapılacağını belirtir

@Fork Anotasyonu

Benchmark testin kaç defa yapılacağını belirtir

@Measurement

Kaç yineleme yapılacağını belirtir. Çıktıda count sütununda gösterilir.

Kullanım

Örnek

Şöyle yaparız. Test sonucu nano saniyedir ve ortalaması alınır. Multi-threaded test yapar. Test 2 defa fork edilir ve her birisi 2 yineleme yapar. 

@OutputTimeUnit(TimeUnit.NANOSECONDS)
@BenchmarkMode(Mode.AverageTime)
@State(Scope.Benchmark)
@Fork(value = 2)
@Measurement(iterations = 2)
@Warmup(iterations = 1)
public class MyBenchmark {

  @Benchmark
  public long foo() {
   ...
  }

  @Benchmark
  public long bar() {
      ...
  }
}

Örnek

Şöyle yaparız

import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.infra.Blackhole;
import org.openjdk.jmh.profile.GCProfiler;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;

@State(Scope.Benchmark)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
@BenchmarkMode(Mode.All)
public class RateLimiterBenchmark {
  private static final int FORK_COUNT = 2;
  private static final int WARMUP_COUNT = 10;
  private static final int ITERATION_COUNT = 10;
  private static final int THREAD_COUNT = 2;
 
  public static void main(String[] args) throws RunnerException {
    Options options = new OptionsBuilder().addProfiler(GCProfiler.class).build();
     new Runner(options).run();
  }
 
  @Setup
  public void setUp() {
    ...
  }
 
  @Benchmark
  @Threads(value = THREAD_COUNT)
  @Warmup(iterations = WARMUP_COUNT)
  @Fork(value = FORK_COUNT)
  @Measurement(iterations = ITERATION_COUNT)
  public String refillPermission() {
    ...
  }
}

Çıktı şöyle. Score sütunu değeri daha düşük olan daha hızlıdır

Benchmark                                                         Mode       Cnt      Score   Error   Units
RateLimiterBenchmark.refillPermission                            thrpt        20     13.594 ± 0.217  ops/us
RateLimiterBenchmark.refillPermission                             avgt        20      0.147 ± 0.002   us/op
RateLimiterBenchmark.refillPermission                           sample  10754462      0.711 ± 0.025   us/op
RateLimiterBenchmark.refillPermission:refillPermission·p0.00    sample                  ≈ 0           us/op
RateLimiterBenchmark.refillPermission:refillPermission·p0.50    sample                0.084           us/op
RateLimiterBenchmark.refillPermission:refillPermission·p0.90    sample                0.125           us/op
RateLimiterBenchmark.refillPermission:refillPermission·p0.95    sample                0.125           us/op
RateLimiterBenchmark.refillPermission:refillPermission·p0.99    sample                0.209           us/op
RateLimiterBenchmark.refillPermission:refillPermission·p0.999   sample              139.008           us/op
RateLimiterBenchmark.refillPermission:refillPermission·p0.9999  sample              935.936           us/op
RateLimiterBenchmark.refillPermission:refillPermission·p1.00    sample            20709.376           us/op
RateLimiterBenchmark.refillPermission    

Cnt ile kaç yineleme yapıldığı belirtilir.@Measurement ile count yani iteration/yineleme değeri belirtilir. Açıklaması şöyle

Count is the number of iterations. Apart from throughput where we measure the operations by time, the rest is the time per operation. Throughput, Average, and Single shot are straightforward. Sample lists the percentiles. Error is the margin of error.

Örnek

Şöyle yaparız. Burada @Warmup ile @Setup ile işaretli kod çalıştırılıyor

import org.openjdk.jmh.annotations.Benchmark;

import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.infra.Blackhole;

import java.util.HashMap;
import java.util.Map;
import java.util.concurrent.TimeUnit;

@State(Scope.Benchmark)
@Warmup(iterations = 5, time = 1)
@Measurement(iterations = 20, time = 1)
@Fork(1)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@OperationsPerInvocation
public class MapBenchmark {
  private static final int SIZE = 10;

  private Map<Integer, String> mapOf;
  private Map<Integer, String> hashMap;

  @Setup
  public void setup() {
    mapOf = Map.of(
                0, "value0",
                1, "value1",
                2, "value2",
                3, "value3",
                4, "value4",
                5, "value5",
                6, "value6",
                7, "value7",
                8, "value8",
                9, "value9"
    );
    hashMap = new HashMap<>();
    hashMap.put(0, "value0");
    hashMap.put(1, "value1");
    hashMap.put(2, "value2");
    hashMap.put(3, "value3");
    hashMap.put(4, "value4");
    hashMap.put(5, "value5");
    hashMap.put(6, "value6");
    hashMap.put(7, "value7");
    hashMap.put(8, "value8");
    hashMap.put(9, "value9");
  }
  @Benchmark
  public void testMapOf(Blackhole blackhole) {
    Map<Integer, String> map = Map.of(
                0, "value0",
                1, "value1",
                2, "value2",
                3, "value3",
                4, "value4",
                5, "value5",
                6, "value6",
                7, "value7",
                8, "value8",
                9, "value9"
    );
    blackhole.consume(map);
  }
  @Benchmark
  public void testHashMap(Blackhole blackhole) {
    Map<Integer, String> hashMap = new HashMap<>();
    hashMap.put(0, "value0");
    hashMap.put(1, "value1");
    hashMap.put(2, "value2");
    hashMap.put(3, "value3");
    hashMap.put(4, "value4");
    hashMap.put(5, "value5");
    hashMap.put(6, "value6");
    hashMap.put(7, "value7");
    hashMap.put(8, "value8");
    hashMap.put(9, "value9");
    blackhole.consume(hashMap);
  }
  @Benchmark
  public void testGetMapOf() {
    for (int i = 0; i < 10; i++) {
      mapOf.get(i);
    }
  }
  @Benchmark
  public void testGetHashMap() {
    for (int i = 0; i < SIZE; i++) {
      hashMap.get(i);
    }
  }
}

Çıktı şöyle. Score sütunu değeri daha düşük olan daha hızlıdır

Benchmark                    Mode  Cnt   Score   Error  Units
MapBenchmark.testGetHashMap  avgt   20  14.999 ± 0.433  ns/op
MapBenchmark.testGetMapOf    avgt   20  16.327 ± 0.119  ns/op
MapBenchmark.testHashMap     avgt   20  84.920 ± 1.737  ns/op
MapBenchmark.testMapOf       avgt   20  83.290 ± 0.471  ns/op