This section provides a tutorial example on how to write empty loop test method. The benchmark test result shows impacts of JIT compilation and the garbage collection threads
After finishing the benchmark runner program, I wrote this simple empty loop test method:
/**
* BenchmarkLoopTest.java
* Copyright (c) 2010 by Dr. Herong Yang, herongyang.com
*/
class BenchmarkLoopTest {
// The empty loop benchmark test method
public static long emptyLoop(int steps, BenchmarkRunner runner) {
long result = 0;
long i = 0;
runner.startTimer();
for (i=0; i<steps; i++) {
}
runner.stopTimer();
result = i;
return result;
}
}
Here my first benchmark test run to make sure everything is working:
C:\herong\jvm>javac BenchmarkRunner.java
C:\herong\jvm>javac BenchmarkLoopTest.java
C:\herong\jvm>java BenchmarkRunner BenchmarkLoopTest emptyLoop 3 3 3
Are you ready?
y
Waking up the JIT compiler...
Run: 1, Time: 6146, Test returns: 3
Run: 2, Time: 3631, Test returns: 3
Run: 3, Time: 3352, Test returns: 3
Starting benchmark test runs...
Run: 1, Time: 3353, Test returns: 3
Run: 2, Time: 3352, Test returns: 3
Run: 3, Time: 3353, Test returns: 3
Benchmark test time report...
Runs: 3, Ave: 1117, Min: 1117, Max: 1117 - Per step in nanoseconds
Runs: 3, Ave: 3352, Min: 3352, Max: 3353 - All steps in nanoseconds
Runs: 3, Ave: 0, Min: 0, Max: 0 - All steps in milliseconds
Runs: 3, Ave: 0, Min: 0, Max: 0 - All steps in seconds
Cool. My program is working! The empty loop test code took about 6146 nanoseconds
to executed for the first call. After, the code was executed fast, about 3352 nanoseconds.
To figure out the impact of the JIT compiler in HotSpot Client JVM, version 1.6.0_06,
I did test with a large "warmups" value, 1000000. The test result is listed below with some comments:
C:\herong\jvm>java BenchmarkRunner
BenchmarkLoopTest emptyLoop 1000000 3 3
Are you ready?
y
Waking up the JIT compiler...
Run: 1, Time: 6146, Test returns: 3
Run: 2, Time: 3632, Test returns: 3 // Drop #1
Run: 3, Time: 3353, Test returns: 3
...
Run: 386, Time: 3352, Test returns: 3
Run: 387, Time: 3352, Test returns: 3
Run: 388, Time: 3631, Test returns: 3
Run: 389, Time: 2794, Test returns: 3 // Drop #2
Run: 390, Time: 2514, Test returns: 3
Run: 391, Time: 2514, Test returns: 3
Run: 392, Time: 2514, Test returns: 3
...
Run: 1159, Time: 2514, Test returns: 3
Run: 1160, Time: 2514, Test returns: 3
Run: 1161, Time: 17879, Test returns: 3 // Interruption #1
Run: 1162, Time: 2514, Test returns: 3
Run: 1163, Time: 2514, Test returns: 3
...
Run: 1828, Time: 2235, Test returns: 3
Run: 1829, Time: 2235, Test returns: 3
Run: 1830, Time: 2235, Test returns: 3
Run: 1831, Time: 1956, Test returns: 3 // Drop #3
Run: 1832, Time: 1955, Test returns: 3
Run: 1833, Time: 1956, Test returns: 3
...
Run: 2528, Time: 1956, Test returns: 3
Run: 2529, Time: 1955, Test returns: 3
Run: 2530, Time: 25981, Test returns: 3 // Interruption #2
Run: 2531, Time: 2794, Test returns: 3
Run: 2532, Time: 1956, Test returns: 3
...
Run: 3126, Time: 1676, Test returns: 3
Run: 3127, Time: 11733, Test returns: 3 // Interruption #3
Run: 3128, Time: 1955, Test returns: 3
...
Run: 4478, Time: 1956, Test returns: 3
Run: 4479, Time: 10057, Test returns: 3 // Interruption #4
Run: 4480, Time: 1956, Test returns: 3
...
Run: 11178, Time: 1955, Test returns: 3
Run: 11179, Time: 13689, Test returns: 3 // Interruption #5
Run: 11180, Time: 1955, Test returns: 3
...
... More Interruptions
...
Run: 999266, Time: 1955, Test returns: 3
Run: 999267, Time: 22069, Test returns: 3 // Interruption #?
Run: 999268, Time: 1956, Test returns: 3
...
Run: 999998, Time: 1955, Test returns: 3
Run: 999999, Time: 1956, Test returns: 3
Run: 1000000, Time: 1956, Test returns: 3
By looking at the test result, it seems that the JIT compiler was able to recompile codes
to speed up the empty loop execution 3 times. The execution time went down
from 6146 to 3352, to 2514, then to 1956 nanoseconds.
Once a while the execution time of the empty loop took much longer. This was probably caused
by the garbage collection threads in the JVM.
