What is Microbenchmarking?
Microbenchmarking measures the performance of small piece of code.
For example, to measure the execution time of a method, we record the time when the method is about to start the actual execution (ex: say it is time1) and we record the time (say it is time2) when the method finish execution.
long time1 = System.currentTimeMillis();
......
......
......
long time2 = System.currentTimeMillis();
(time2-time1) return the total execution time of a method. Result may not be accurate for one iteration, to get the better accurate result, we need to run the test several times, ignore the warmup time, get the throughput, average execution time etc.,
Apart from this, you definitely expect following features from a benchmarking.
a. We may need to store the benchmarking statistics to external destination like a file,
b. we may want to publish these statistics in json or csv format etc.,
c. Want to get the benchmarking results in different time units like nanoseconds, milliseconds, seconds etc.,
d. Run the benchmarking with different parameters
e. We may want to maintain the state across given trail of execution.
f. We may want to ignore warmup executions from statistics calculation etc.,
What if I say, there is a tool JMH, that has all these features. Cool isn’t it…..
Let’s write a simple hello world application and try to understand JMH basics.
Step 1: Create a benchmark using @Benchmark annotation.
@Benchmark
@BenchmarkMode(Mode.AverageTime)
public String randString() throws InterruptedException {
// Some intentional delay
TimeUnit.MILLISECONDS.sleep(10);
final StringBuilder sb = new StringBuilder(RAND_STR_LENGTH);
for (int i = 0; i < RAND_STR_LENGTH; i++)
sb.append(INPUT_CHARS.charAt(SECURE_RANDOM.nextInt(INPUT_CHARS.length())));
return sb.toString();
}
Step 2: Start the benchmarking process by calling org.openjdk.jmh.Main.main method.
public static void main(String[] args) throws IOException {
org.openjdk.jmh.Main.main(args);
}
Find the below working application.
HelloWorld.java
package com.sample.app;
import java.io.IOException;
import java.security.SecureRandom;
import java.util.concurrent.TimeUnit;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Mode;
public class HelloWorld {
private static final String INPUT_CHARS = "0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz";
private static SecureRandom SECURE_RANDOM = new SecureRandom();
private static final int RAND_STR_LENGTH = 16;
@Benchmark
@BenchmarkMode(Mode.AverageTime)
public String randString() throws InterruptedException {
// Some intentional delay
TimeUnit.MILLISECONDS.sleep(10);
final StringBuilder sb = new StringBuilder(RAND_STR_LENGTH);
for (int i = 0; i < RAND_STR_LENGTH; i++)
sb.append(INPUT_CHARS.charAt(SECURE_RANDOM.nextInt(INPUT_CHARS.length())));
return sb.toString();
}
public static void main(String[] args) throws IOException {
org.openjdk.jmh.Main.main(args);
}
}
Output
# JMH version: 1.35
# VM version: JDK 15.0.2, Java HotSpot(TM) 64-Bit Server VM, 15.0.2+7-27
# VM invoker: /Library/Java/JavaVirtualMachines/jdk-15.0.2.jdk/Contents/Home/bin/java
# VM options: -Dfile.encoding=UTF-8 -XX:+ShowCodeDetailsInExceptionMessages
# Blackhole mode: full + dont-inline hint (auto-detected, use -Djmh.blackhole.autoDetect=false to disable)
# Warmup: 5 iterations, 10 s each
# Measurement: 5 iterations, 10 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: com.sample.app.HelloWorld.randString
# Run progress: 0.00% complete, ETA 00:08:20
# Fork: 1 of 5
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
# Warmup Iteration 3: 0.011 s/op
# Warmup Iteration 4: 0.011 s/op
# Warmup Iteration 5: 0.011 s/op
Iteration 1: 0.011 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
# Run progress: 20.00% complete, ETA 00:07:01
# Fork: 2 of 5
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
# Warmup Iteration 3: 0.011 s/op
# Warmup Iteration 4: 0.011 s/op
# Warmup Iteration 5: 0.011 s/op
Iteration 1: 0.011 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
# Run progress: 40.00% complete, ETA 00:05:16
# Fork: 3 of 5
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
# Warmup Iteration 3: 0.011 s/op
# Warmup Iteration 4: 0.011 s/op
# Warmup Iteration 5: 0.011 s/op
Iteration 1: 0.011 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
# Run progress: 60.00% complete, ETA 00:03:30
# Fork: 4 of 5
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
# Warmup Iteration 3: 0.011 s/op
# Warmup Iteration 4: 0.011 s/op
# Warmup Iteration 5: 0.011 s/op
Iteration 1: 0.011 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
# Run progress: 80.00% complete, ETA 00:01:45
# Fork: 5 of 5
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
# Warmup Iteration 3: 0.011 s/op
# Warmup Iteration 4: 0.011 s/op
# Warmup Iteration 5: 0.011 s/op
Iteration 1: 0.011 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
Result "com.sample.app.HelloWorld.randString":
0.011 ±(99.9%) 0.001 s/op [Average]
(min, avg, max) = (0.011, 0.011, 0.011), stdev = 0.001
CI (99.9%): [0.011, 0.011] (assumes normal distribution)
# Run complete. Total time: 00:08:47
REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.
Benchmark Mode Cnt Score Error Units
HelloWorld.randString avgt 25 0.011 ± 0.001 s/op
In the above output, you can see that it took 8 minutes to calculate the average execution time of randString method. It did five forks with 5 warmup iterations and 5 actual iterations. From those results, it's concluding an output by taking the average of all execution. So the result is almost accurate here.
Now let’s understand the JMH concepts in depth.
Fork
Fork represent a trail, where each trail has m warmup iterations and n actual iterations. In the above example, JMH perform 5 trails. You can customize the number of forks using either @Fork annotation or with OptionBuilder.
@Benchmark
@Fork(2)
@BenchmarkMode(Mode.AverageTime)
public String randString() throws InterruptedException {
......
......
}
Above snippet configure 2 trails to benchmark the method randString().
Warmup
The warmup iterations are used to ensure your application reaches a steady state before recording sample values. You can configure the number of warmup iterations for each fork using @Warmup annotation.
@Benchmark
@Fork(value = 2)
@Warmup(iterations = 2)
@BenchmarkMode(Mode.AverageTime)
public String randString() throws InterruptedException {
..........
..........
}
Console output for above configuration.
# Benchmark: com.sample.app.HelloWorld.randString
# Run progress: 0.00% complete, ETA 00:02:20
# Fork: 1 of 2
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
Iteration 1: 0.012 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
# Run progress: 50.00% complete, ETA 00:01:10
# Fork: 2 of 2
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
Iteration 1: 0.011 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
Actual iterations
Actual iterations to calculate the benchmark are set with the help of @Measurement annotation.@Benchmark
@Fork(value = 2)
@Warmup(iterations = 2)
@Measurement(iterations = 8)
@BenchmarkMode(Mode.AverageTime)
public String randString() throws InterruptedException {
......
......
}
Above snippet sets number of warmup iterations to 2, and number of actual iterations to 8 for each fork.
Console output for above configuration.
# Benchmark: com.sample.app.HelloWorld.randString
# Run progress: 0.00% complete, ETA 00:03:20
# Fork: 1 of 2
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
Iteration 1: 0.011 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
Iteration 6: 0.011 s/op
Iteration 7: 0.012 s/op
Iteration 8: 0.011 s/op
# Run progress: 50.00% complete, ETA 00:01:40
# Fork: 2 of 2
# Warmup Iteration 1: 0.011 s/op
# Warmup Iteration 2: 0.011 s/op
Iteration 1: 0.011 s/op
Iteration 2: 0.011 s/op
Iteration 3: 0.011 s/op
Iteration 4: 0.011 s/op
Iteration 5: 0.011 s/op
Iteration 6: 0.011 s/op
Iteration 7: 0.011 s/op
Iteration 8: 0.011 s/op
Note that, JMH forks the JVM multiple times during benchmarking in order to discard any profiles built up by the just-in-time (JIT) profiling performed by the JVM during execution.
No comments:
Post a Comment