Why this matters
Engineers often ask "is the new version faster?" The usual answer is a single timing: run the old code, run the new code, compare two numbers. That answer is often wrong. The first run of Java code is slower than the later runs. A background program can add a few milliseconds to one run and not the next. A compiler can remove the work you wanted to time, which makes the number look excellent.
This lesson shows how to measure code so that the number means something. You will see the effects that make one timing unreliable, write small programs that show each effect, and build a rule set you can follow. The programs are in Java and C++, because those two languages show the effects most clearly. The lesson does not teach the growth-rate ideas from the previous lessons in this module. It teaches how to check that a measured difference is real.
A few terms first. A benchmark is a program whose only job is to time some code. A timing is one measured elapsed time, in milliseconds or nanoseconds. A run is one execution of the timed code. A measurement is a set of runs and the numbers you get from them. Keep those four words separate in your head, because the rest of the lesson uses them.
One timing is a guess
Here is the simplest Java benchmark. The method work adds up a value for each number from 0 to n - 1. The main method runs it eight times and prints the time for each run.
System.nanoTime() returns a clock reading in nanoseconds. A nanosecond is one billionth of a second. The difference between two readings is the elapsed time. Dividing by 1,000,000 gives milliseconds.
The variable sink deserves a note now and gets its own section later. It adds up every result, and the program prints it at the end. Without that, the compiler could decide the result is not used and skip the work. The printed sink value shows the work was really done.
The output from two separate launches of the program:
run 1: 19 ms
run 2: 17 ms
run 3: 18 ms
run 4: 18 ms
run 5: 18 ms
run 6: 17 ms
run 7: 20 ms
run 8: 18 ms
sink=320000008run 1: 19 ms
run 2: 17 ms
run 3: 18 ms
run 4: 18 ms
run 5: 19 ms
run 6: 17 ms
run 7: 17 ms
run 8: 18 ms
sink=320000008Look at the first launch alone. Run 2 took 17 ms and run 7 took 20 ms. The same code, on the same input, differed by 3 ms, which is about 18 percent of the smaller number. If you had timed only run 2 for the old code and only run 7 for the new code, you could report a change that is pure noise. The second launch has a different spread, and its values are not the same as the first. Neither launch tells you anything about a change in the code, because nothing in the code changed.
Run the same program again and the numbers move. That movement is normal. It comes from the operating system switching between programs, from the processor changing its speed, and from the Java runtime doing its own work in the background. A single timing hides all of this.
Java warms up
The usual Java setup does not compile the code to machine code before the program starts. The javac compiler first turns the code into bytecode, which is a simpler form that a Java virtual machine runs. The JVM (Java virtual machine) starts by interpreting that bytecode, which means it reads and runs one instruction at a time. While the program runs, the JVM watches which methods are used the most, and compiles those to machine code. This is called just-in-time compilation, or JIT. The compiled version runs much faster.
So the first calls to a method are slow, and later calls are fast. The JIT takes time to decide and compile, and during that time the code runs the slow way. This effect is called warm-up.
The next program shows warm-up directly. It calls work with a smaller input, 50,000, many times. It groups the calls into batches of 100 and prints the time for each batch.
The output of the first of three launches:
batch 1 (100 calls): 6312 us
batch 2 (100 calls): 4474 us
batch 3 (100 calls): 4381 us
batch 4 (100 calls): 4349 us
batch 5 (100 calls): 4428 us
batch 6 (100 calls): 4424 us
batch 7 (100 calls): 4391 us
batch 8 (100 calls): 4427 us
batch 9 (100 calls): 4428 us
batch 10 (100 calls): 4399 us
sink=100001000Batch 1 took about 6.3 milliseconds (6312 microseconds, where a microsecond is one millionth of a second). From batch 3 on, the batches take about 4.4 milliseconds. Across three launches, the first batch was between 40 and 70 percent slower than the steady batches. The steady number is the number that tells you how fast the code really is. The first batch tells you how long the program takes to get going, which matters for a short-lived program but is a different question.
The next command turns the JIT off, with the -Xint flag, which means "interpret only". It shows how much the compiled code gains. It runs the original Bench program, compiled with javac Bench.java:
java -Xint -cp . Benchrun 1: 151 ms
run 2: 149 ms
run 3: 152 ms
run 4: 149 ms
run 5: 156 ms
run 6: 154 ms
run 7: 149 ms
run 8: 148 ms
sink=320000008The same work took about 150 milliseconds without the JIT, and about 18 milliseconds with it. That is roughly eight times slower. This tells you the JIT is doing most of the work for this loop, so a benchmark that runs only the interpreter measures something very different from the code you ship.
The practical rule follows from this. Run the code a number of times before you start measuring, and throw those runs away. These are called warm-up runs. The measured runs come after them.
Step 1: warm up, then measure many runs
A measurement needs enough runs to show the spread. The next program does the rest of the recipe for one function. It runs five warm-up calls and discards them. Then it runs ten measured calls with a larger input, and it reports the smallest, the median and the largest time. The median is the middle value when the numbers are sorted in order. If there is an even count, it is the average of the two middle values.
Three launches of this program gave:
measured runs (ms): [1.822133, 2.146267, 2.3291, 1.803177, 1.825559, 1.82084, 1.804559, 1.813647, 1.823516, 1.806343]
min=1.80 median=1.82 max=2.33
sink=59999955measured runs (ms): [1.846688, 2.022206, 1.994659, 1.762882, 1.771318, 1.7998, 1.759976, 1.760537, 2.122223, 2.01885]
min=1.76 median=1.82 max=2.12
sink=59999955measured runs (ms): [2.132974, 2.014522, 1.787568, 1.78862, 1.781307, 1.821572, 1.755448, 1.768482, 1.826319, 1.949215]
min=1.76 median=1.81 max=2.13
sink=59999955The median is 1.81 to 1.82 milliseconds in all three launches. The slowest single run was up to about 28 percent above the median, in the first launch, and the fastest was up to about 3 percent below it. The median is the number to report, because one slow run from a background task does not move it much. The minimum is useful as a sign of how fast the code can go on a quiet machine, and the maximum shows how noisy the machine was.
Notice what the reading does not tell you. It does not say the program is fast, because you have no other program to compare with. A benchmark gives a number for one thing, and a comparison needs two numbers measured the same way.
Step 2: compare two versions on the same terms
Suppose you want to know whether a list of boxed numbers is slower to add up than a plain array. In Java, int[] stores the numbers directly. List<Integer> stores each number as an object (a separate small box that holds the number), and reading it takes an extra step. The next program measures both on the same million values with the same timing code.
Each version gets the same warm-up, the same number of measured runs, and the same input. The two measured runs alternate, so both versions see the same background conditions over time. Here are three launches:
int[] array min=0.06 ms median=0.07 ms max=0.13 ms
ArrayList min=0.30 ms median=0.30 ms max=0.46 ms
sink=2475000000int[] array min=0.05 ms median=0.06 ms max=0.11 ms
ArrayList min=0.29 ms median=0.30 ms max=0.78 ms
sink=2475000000int[] array min=0.08 ms median=0.11 ms max=0.31 ms
ArrayList min=0.29 ms median=0.32 ms max=1.19 ms
sink=2475000000The list version's median is about three to five times the array version's median in all three launches. The medians across launches do not overlap: the array medians were 0.06 to 0.11 ms, and the list medians were 0.30 to 0.32 ms. One array run reached 0.31 ms in the third launch, so single runs do overlap, which is why the comparison uses the medians of several launches.
The honest way to write the result is: "In three separate launches on this machine, summing 1,000,000 values with a list took a median of 0.30 to 0.32 ms, and summing the same values in an array took a median of 0.06 to 0.11 ms." The sentence names the input size, the number of launches, the machine, and gives a range instead of one number. A reader can judge it, and a reader can rerun it.
Step 3: a compiler can remove work you did not use
A benchmark times the work you ask for. If the result of that work is not used, a compiler may decide the work does nothing useful and remove it. Then the timer measures nothing, and the number looks excellent.
This happens in C++ very clearly. The next program is the C++ version of the same kind of loop. The function work adds (i * i) % 7 for each value of i below n. The main function runs it five times, and it can call the function with or without using the result. The USE_RESULT macro switches between the two forms. A macro here is a name the compiler replaces with text before it compiles, so #ifdef USE_RESULT means "if the name USE_RESULT was defined at compile time".
#include <chrono>
#include <cstdint>
#include <cstdio>
static uint64_t work(uint64_t n) {
uint64_t total = 0;
for (uint64_t i = 0; i < n; i++) {
total += (i * i) % 7;
}
return total;
}
int main() {
const uint64_t n = 50000000ULL;
const int runs = 5;
uint64_t sink = 0;
for (int r = 1; r <= runs; r++) {
auto start = std::chrono::steady_clock::now();
#ifdef USE_RESULT
uint64_t v = work(n);
sink += v;
asm volatile("" : : "r"(sink) : "memory");
#else
work(n);
#endif
auto end = std::chrono::steady_clock::now();
double ms = std::chrono::duration<double, std::milli>(end - start).count();
std::printf("run %d: %.3f ms\n", r, ms);
}
std::printf("sink=%llu\n", (unsigned long long)sink);
return 0;
}The line asm volatile("" : : "r"(sink) : "memory"); is a marker for the compiler. It says that the value of sink must be kept up to date at that point. It does nothing when the program runs, and it is the usual way to stop a compiler from removing work in a C++ benchmark loop. The std::chrono::steady_clock is a clock that never goes backwards, which is what a timer needs. The next commands compile the program three ways and run each one.
g++ -O0 -std=c++17 -o b_o0 bench.cpp
g++ -O2 -std=c++17 -o b_o2 bench.cpp
g++ -O2 -DUSE_RESULT -std=c++17 -o b_o2_used bench.cpp
./b_o0
./b_o2
./b_o2_usedThe -O0 flag asks for no optimisation, and -O2 asks for the usual optimisation level for release builds. The -DUSE_RESULT flag defines the macro, so the program keeps the result. The compiler used was g++ 15.2.0 on the machine that wrote this lesson.
run 1: 43.146 ms
run 2: 44.194 ms
run 3: 43.908 ms
run 4: 44.162 ms
run 5: 44.785 ms
sink=0run 1: 0.000 ms
run 2: 0.000 ms
run 3: 0.000 ms
run 4: 0.000 ms
run 5: 0.000 ms
sink=0run 1: 39.462 ms
run 2: 39.515 ms
run 3: 38.613 ms
run 4: 39.173 ms
run 5: 39.864 ms
sink=499999990The middle block is the important one. With -O2 and the result unused, every run took 0.000 milliseconds. That is not a fast loop. It is a loop the compiler deleted, because nothing in the program read its result. The third block shows the same optimised code when the result is used: about 39 milliseconds per run.
The first block shows that the -O0 build, with no optimisation, takes about 44 milliseconds even though the result is unused, which is slower than the -O2 build that uses its result. Removing the work changes it to zero, which is far more than any choice of flag. A benchmark that reports zero for work that should take milliseconds has not measured the work.
C++ has no warm-up in the Java sense. The compiler produces machine code before the program starts, so the first run is not slow for that reason. The first run in the first block was about the same as the rest. The steady-state rule still applies, though: run several times, look at the spread, and report the median.
Step 4: a rule set you can use
The examples above show one or two effects each. Put them together, and the rules for an honest measurement are:
- Run the same input on the same machine, with the same compiler or runtime version and the same flags, for both versions you compare.
- Warm up first. In Java, run the code several times and throw those runs away.
- Keep the result of the work and use it at the end, so the compiler cannot remove it.
- Make each timed run long enough to be measured well. A run that takes a few microseconds can be mostly timer overhead and noise. Batch many calls into one timed run when a single call is very short.
- Keep setup out of the timed part. Creating the input inside the timer adds its cost to the result.
- Keep printing out of the timed part. A
printlninside the timer measures the terminal, not your code. - Run many times. Report the median, plus the minimum and maximum so the spread is visible.
- Write down the setup: language, version, flags, input size, number of warm-up and measured runs, and the machine.
A timing is an estimate, and an estimate has a range. When two medians differ by less than the spread, there is no clear winner, and the honest report is "no measurable difference at this input size".
Common mistakes
Trusting one run. The first Java launch above showed run 2 at 17 ms and run 7 at 20 ms for the same code. Comparing a single run of an old version to a single run of a new version can show a change of 10 to 20 percent that is only noise. Run each version many times and compare medians.
Timing the warm-up. The first batch of the Warm program took 40 to 70 percent longer than the steady batches. A benchmark that does not warm up reports the cost of starting the JVM, the interpreter, and the first compilation, not the cost of the code.
Keeping no result. The C++ -O2 build with the result unused printed 0.000 ms for every run. The timer measured nothing. Java's JIT can, in principle, also remove work whose result is never used, so keep a value such as sink that is printed at the end.
Forgetting a required header. A C++ benchmark needs #include <chrono> for std::chrono. This file leaves that line out:
#include <cstdio>
int main() {
auto start = std::chrono::steady_clock::now();
std::printf("%d\n", 1);
return 0;
}Compiling it gives this message:
g++ -std=c++17 -o no_include no_include.cppno_include.cpp: In function ‘int main()’:
no_include.cpp:4:23: error: ‘std::chrono’ has not been declared
4 | auto start = std::chrono::steady_clock::now();
| ^~~~~~The message names the file, the line and the column, and it names the missing name std::chrono. The fix is to add #include <chrono> at the top of the file. The benchmark earlier in this lesson already has that line.
Comparing unlike builds. The Java -Xint run was about eight times slower than the JIT run, and the -O0 build was slower than the -O2 build. Comparing an interpreted run to a compiled run, or a debug build to a release build, says nothing about your code. Use the same flags for both sides.
Practice
Exercise 1. Version A took 17, 18, 18 and 19 ms in four runs. Version B took 16, 21, 17 and 22 ms in four runs. Which is faster?
Show the answer
The median of A is 18 ms. The sorted values of B are 16, 17, 21 and 22, so its median is 19 ms. The medians differ by 1 ms, and B's values spread from 16 to 22 ms. The data does not show a clear winner. The honest report is that the difference is inside the noise. Run more times, or use a larger input, before drawing a conclusion.
Exercise 2. The Warm program discards batch 1 when it reads the steady speed. Why is that right, and what does batch 1 measure?
Show the answer
Batch 1 includes the time the JVM spends interpreting the code and compiling it to machine code. That time is real, and it matters for a short program that runs the code once. It does not describe how fast the code runs once it is warm. For a steady speed, use the later batches. For a start-up cost, use batch 1.
Exercise 3. The C++ build with -O2 and an unused result printed 0.000 ms for each run. Explain what happened, and give the change that fixes the benchmark.
Show the answer
The compiler saw that nothing read the result of work(n), so it removed the loop. The timer then measured an empty statement. The fix is to add the result to sink, and to put a barrier such as asm volatile("" : : "r"(sink) : "memory") after it, so the compiler keeps the value. With that change the same build took about 39 ms per run.
Exercise 4. One call to a function takes about 0.5 ms. You want each timed run to last about 100 ms. How many calls should one timed run contain, and what does the answer depend on?
Show the answer
About 200 calls, because 200 times 0.5 ms is 100 ms. The answer assumes the call takes the same time each time, which is only true when the input and the cache state stay the same. If the time per call changes, measure one batch first and then choose the count from that measurement.
Exercise 5. A report says: "The new version is 9 percent faster, from a median of 1.10 ms to 1.00 ms, measured in one launch with 3 runs." List what is missing from this report.
Show the answer
The report has one launch and three runs, which is too few to show the spread. It does not say the input size, the language version, the flags, the number of warm-up runs, or the machine. It does not say whether the old and new versions ran under the same conditions. A better report gives the median and range over at least three launches, each with a fixed input and the setup listed, so a reader can rerun it.
Summary
- One timing is one sample. Measure many runs and report the median with the minimum and maximum.
- Java runs slowly at first while the JIT compiles the code. Run warm-up calls first and throw them away.
- Keep the result of the work and use it at the end, so the compiler cannot remove the work you want to time.
- Compare two versions only with the same input, machine, flags and harness, and call a difference real only when it is larger than the spread.
- Write down the setup with every number, so the result can be checked.