Performance testing app in Java

Question

I wrote a basic app for measuring time it takes to execute any given block of code. What do you think?

@NoArgsConstructor
public class Measurer {
    private LoggingType loggingType = LoggingType.DISABLED;

    public Measurer(LoggingType loggingType) {
        this.loggingType = loggingType;
    }

    public long measure(MeasuredProcedure measuredProcedure) {
        long start = System.nanoTime();
        measuredProcedure.run();
        long finish = System.nanoTime();
        long nanosTaken = finish - start;
        if (loggingType.equals(LoggingType.ENABLED)) {
            logMeasurement(measuredProcedure, nanosTaken);
        }
        return nanosTaken;
    }

    public long compare(MeasuredProcedure firstProcedure, MeasuredProcedure secondProcedure) {
        long nanosTakenByFirstProcedure = measure(firstProcedure);
        long nanosTakenBySecondProcedure = measure(secondProcedure);
        long signedDifference = nanosTakenByFirstProcedure - nanosTakenBySecondProcedure;
        if (loggingType.equals(LoggingType.ENABLED)) {
            logDifferenceBetween(firstProcedure, nanosTakenByFirstProcedure)
                    .and(secondProcedure, nanosTakenBySecondProcedure);
        }
        return signedDifference;
    }

    private void logMeasurement(MeasuredProcedure measuredProcedure, long nanosTaken) {
        String timeTaken = renderReadable(nanosTaken);
        System.out.println(measuredProcedure + " took: " + timeTaken);
    }

    private ComparisonLoggingIntermediary logDifferenceBetween(MeasuredProcedure firstProcedure, long firstProcedureNanos) {
        return new ComparisonLoggingIntermediary(firstProcedure, firstProcedureNanos);
    }

    private static String renderReadable(long nanos) {
        var r = new NanoProcessor().process(nanos);
        TimeUnit[] timeUnits = {r.minutes(), r.seconds(), r.millis(), r.nanos()};
        var joiner = new StringJoiner(", ");
        for (int i = 0; i < timeUnits.length; i++) {
            TimeUnit unit = timeUnits[i];
            if (unit.value() == 0) {
                continue;
            }
            String suffix = (unit.value() % 10 == 1) ? "" : "s";
            joiner.add(unit.value() + " " + unit.name() + suffix);
        }
        return joiner.toString();
    }

    public enum LoggingType {
        ENABLED, DISABLED
    }

    static class NanoProcessor {
        NanoProcessingResult process(long nanos) {
            long minutes = extractLooseMinutes(nanos);
            long seconds = extractLooseSeconds(nanos);
            long milliseconds = extractLooseMilliseconds(nanos);
            long nanoseconds = extractLooseNanoseconds(nanos);
            return new NanoProcessingResult(
                    new TimeUnit(TimeUnitName.MINUTE, minutes),
                    new TimeUnit(TimeUnitName.SECOND, seconds),
                    new TimeUnit(TimeUnitName.MILLISECOND, milliseconds),
                    new TimeUnit(TimeUnitName.NANOSECOND, nanoseconds)
            );
        }

        private long extractLooseMinutes(long nanos) {
            return nanos / 60_000_000_000L;
        }

        private long extractLooseSeconds(long nanos) {
            return nanos % 60_000_000_000L / 1_000_000_000L;
        }

        private long extractLooseMilliseconds(long nanos) {
            return nanos % 1_000_000_000L / 1_000_000L;
        }

        private long extractLooseNanoseconds(long nanos) {
            return nanos % 1_000_000L;
        }

        record NanoProcessingResult(TimeUnit minutes, TimeUnit seconds,
                                    TimeUnit millis, TimeUnit nanos) {
        }

        record TimeUnit(TimeUnitName name, long value) {
            enum TimeUnitName {
                MINUTE, SECOND, MILLISECOND, NANOSECOND;

                @Override
                public String toString() {
                    return name().toLowerCase();
                }
            }
        }
    }

    private record ComparisonLoggingIntermediary(MeasuredProcedure firstProcedure,
                                                 long firstProcedureNanos) {
        void and(MeasuredProcedure secondProcedure, long secondProcedureNanos) {
            MeasuredProcedure fastestProcedure = (firstProcedureNanos < secondProcedureNanos) ?
                    firstProcedure : secondProcedure;
            MeasuredProcedure slowestProcedure = fastestProcedure.equals(firstProcedure) ?
                    secondProcedure : firstProcedure;
            long difference = Math.abs(firstProcedureNanos - secondProcedureNanos);
            long percentage = fastestProcedure.equals(firstProcedure) ?
                    difference / (secondProcedureNanos / 100) :
                    difference / (firstProcedureNanos / 100);
            String renderedDifference = renderReadable(difference);
            System.out.println(fastestProcedure + " has shown better performance: it is faster than " +
                    slowestProcedure + " by " + percentage + "% (" + renderedDifference + ")");
        }
    }
}

abstract class MeasuredProcedure {
    protected String name;
    protected MeasuredProcedure(String name) {
        this.name = name;
    }
    abstract void run();

    @Override
    public String toString() {
        return name;
    }
}

public final class MeasuredProcedureFactory {
    public static final MeasuredProcedure MILLION_INTS_TO_ARRLIST_NO_PREALLOCATION =
            new MeasuredProcedure("MILLION_INTS_TO_ARRLIST_NO_PREALLOCATION") {
                @Override
                public void run() {
                    int numOfElements = 1_000_000;
                    List<Integer> intList = new ArrayList<>();
                    addRandomInts(intList, numOfElements);
                }
            };
    public static final MeasuredProcedure MILLION_INTS_TO_ARRLIST_WITH_PREALLOCATION =
            new MeasuredProcedure("MILLION_INTS_TO_ARRLIST_WITH_PREALLOCATION") {
                @Override
                public void run() {
                    int numOfElements = 1_000_000;
                    List<Integer> intList = new ArrayList<>(numOfElements);
                    addRandomInts(intList, numOfElements);
                }
            };
    public static final MeasuredProcedure PLUS_CONCATENATION_OF_THOUSAND_LETTERS =
            new MeasuredProcedure("PLUS_CONCATENATION_OF_THOUSAND_LETTER") {
                @Override
                void run() {
                    String res = "";
                    String[] alphabet = "abcdefghijklmnopqrstuvwxyz".split("");
                    for(int i = 0; i < 1_000; i++) {
                        int randomIndex = Util.randomInt(alphabet.length);
                        res += alphabet[randomIndex];
                    }
                }
            };
    public static final MeasuredProcedure STRING_BUILDING_OF_THOUSAND_LETTERS =
            new MeasuredProcedure("STRING_BUILDING_OF_THOUSAND_LETTERS") {
                @Override
                void run() {
                    StringBuilder sb = new StringBuilder();
                    String[] alphabet = "abcdefghijklmnopqrstuvwxyz".split("");
                    for(int i = 0; i < 1_000; i++) {
                        int randomIndex = Util.randomInt(alphabet.length);
                        sb.append(alphabet[randomIndex]);
                    }
                    sb.toString();
                }
            };
    public static final MeasuredProcedure STRING_BUFFERING_OF_THOUSAND_LETTERS =
            new MeasuredProcedure("STRING_BUFFERING_OF_THOUSAND_LETTERS") {
                @Override
                void run() {
                    StringBuffer sb = new StringBuffer();
                    String[] alphabet = "abcdefghijklmnopqrstuvwxyz".split("");
                    for(int i = 0; i < 1_000; i++) {
                        int randomIndex = Util.randomInt(alphabet.length);
                        sb.append(alphabet[randomIndex]);
                    }
                    sb.toString();
                }
            };

    private MeasuredProcedureFactory() {
    }

    private static void addRandomInts(List<Integer> intList, int numOfElements) {
        for (int i = 0; i < numOfElements; i++) {
            int randomInt = Util.randomInt(numOfElements);
            intList.add(randomInt);
        }
    }
}

Example of usage:

public class App {
    public static void main(String[] args) {
        Measurer measurer = new Measurer(LoggingType.ENABLED);
        measurer.compare(
                MeasuredProcedureFactory.STRING_BUFFERING_OF_THOUSAND_LETTERS,
                MeasuredProcedureFactory.STRING_BUILDING_OF_THOUSAND_LETTERS
        );
    }
}

STRING_BUFFERING_OF_THOUSAND_LETTERS took: 2 milliseconds, 384700 nanoseconds

STRING_BUILDING_OF_THOUSAND_LETTERS took: 416800 nanoseconds

STRING_BUILDING_OF_THOUSAND_LETTERS has shown better performance: it is faster than STRING_BUFFERING_OF_THOUSAND_LETTERS by 82% (1 millisecond, 967900 nanoseconds)

Answer 1

It seems like a very complex way to make what is essentially "toy code" to test how long an algorithm runs. I would perhaps concentrate on writing the algorithms first in a usefule manner and then figure out a way to measure their running time so that minimal changes to the algorithm is needed in order to measure it. Along the lines of what Martin Frank already suggested, maybe wrap the code to be measured in a lambda and pass that to the timer.

But as an exercise in how to write a library, let's see...

Managing logging levels should not be a concern of your library. Use a logging framework and let the caller worry about setting the logging level in the configuration. Since you are already using Lombok, consider @Slf4j.

ComparisonLoggingIntermediary breaks the record contract. A record is a data container that shouldn't contain complex logic. It breaks the single responsibility principle since it's a record for one measurement result, a comparator for two measurement results and an output formatter. That's three responsibilities. The and method adds another way to represent measurement results, the method parameters. What if you want to add another metric to the results? You would have to change both the record class and the method signature. That's a sign of duplicate code. My suggestion is to remove the and method, it's name is fairly bad as it doesn't tell anything about what it does and rename the class to MeasurementResult.

Maybe consider changing the compare method so that instead of two, it can accept any number of methods to measure (using varargs for example). That will force you to rethink your methods and data structures so that they become more generic and making mistakes like the ComparisonLoggingIntermediary becomes easier to spot as the code would be a lot more complicated. To remove the need to have a dedicated class just for providing a procedure name, maybe separate the registration of procedures and the measurement to separate methods. If you like fluent interfaces and builders, maybe something like:

final List<MeasurementResult> result = Masurer.builder()
    .register("NO PREALLOCATION", new NoPreallocation())
    .register("WITH PREALLOCATION", new WithPreallocation())
    .measure();

There's a bit of redundancy in the registration methods there and you could use class names too, but if you want to use functional interfaces and lambdas, then class names aren't very useful.

Follow single responsibility principle. Make the Measurer only responsible for measuring the execution time. Create a MeasurementResultComparator for sorting out a collection of MeasurementResult objects. Then you can make another comparator if you want to sort them by longest time or some other metric you decide to collect later.

Then for outputting the results, create a class for printing out a set of results to a PrintStream. You might not always be using a console so incorporating the concole output to your library would place unnecessary restrictions on the users who want to use your library from a graphical user interface.

And for measuring algorithm performance, simply taking the start and end time from a single execution is very error prone and will not produce useful results. It allows other processes to interfere with the execution. You may have a garbage collector running during one measurement but not the other. You should be running the measured code multiple times and recording statics from the execution times. Calculate average and mean times, etc (that's the kind of information you could put in the MeasurementResult record).

Answer 2

misleading requirements

"I wrote a basic app for measuring time [..]. What do you think?"

when i look into your example,

Measurer measurer = new Measurer(..);
measurer.compare(...) );

it is not so obvious, where you are measuring. i had to look deeper into your code and see, what compare really does:

1. measure procedures and
2. compare them.

Additionally to disguises what you are really doing, this approach violates the single responsibility principle.

misleading requirements pt.2

"[..] to execute any given block of code. What do you think?"

honestly, when i read first this title i was expecting that your code somehow wraps the test code into its own runner. that was slightly confusing for me - but that may be an foreigner issue, i am not native english hahaha:-)

minor issues

1. shoot sparrows with cannons: an enum for an boolean seems to me (imho) slighty too much since you could create the same semantic with an boolean if (loggingType.equals(LoggingType.ENABLED)) vs. if(isLoggingEnabled) - that said under the premise that i refuse any primitive obsession!
2. talking of logging, you forgot some System.out.print on e.g. Measurer.logMeasurement - write them into the log.
3. missing class: Util - sorry did i miss something?
4. duplicate code:

StringBuffer sb = new StringBuffer();
String[] alphabet = "abcdefghijklmnopqrstuvwxyz".split("");
for(int i = 0; i < 1_000; i++) {
    int randomIndex = Util.randomInt(alphabet.length);
    sb.append(alphabet[randomIndex]);
}
sb.toString();

summary

this is a fine & nice piece of code - i it was very readable and good to understand!

Answer 3

Only one measurement is taken without any preparation, which means your measurement can be polluted by:

• Slower execution of methods that have not been JIT-compiled yet, or have been JIT-compiled at a low optimization level (due to tiered compilation).
• CPU frequency changes (typically starts slow, when the computer goes from idle to running a program).
• Allocating and accessing memory for the first time, while the JVM still has to ask the OS for memory and the OS is still lazily allocating it.
• Any transient event that occurs exactly while you are measuring.

When taking one measurement (or too few measurements in general), the middle two things in particular will tend to favour the second and later benchmarks unfairly over the first one, which is most impacted by those effects.

So I recommend at least take multiple measurements, and I would discard some of the initial results entirely: the extra slowdown experienced by the initial runs is not a property of the code, but of the environment within which it runs.

Unfortunately I could not quickly find how a Java benchmarking framework can ensure that the measurement it's taking reflects properly optimized code, which I suppose could either work by discarding measurements until the frameworks knows that the method has been optimized (how can it query that?) or by the framework forcing the JVM to optimize a given method (is there an API for that?). Surely there is some way, otherwise benchmarking Java would be essentially impossible, but Java benchmarking frameworks exist.

You may also need some way to safely "sink" results in way that guarantees that a result will be computed, to prevent the JVM from optimizing code into nothingness when it detects that the result is not used.

Answer 4

If your reference material tells you never to use booleans, you need new reference material. But anyway: whether to "log or not" shouldn't be a property of your class; you should just be able to decide whether or not to print the results after a measurement run.

Measurer is too vague; consider instead PerfTimer.

compare is hard-coded for only two methods, which is not useful. You should refactor to support an arbitrary number of methods.

All of the intermediary, factory and processor stuff is too complicated and should go away. Facetiously, this is "peak Java".

Whatever Util is doing, it needs to be deleted and replaced with java.util.Random.nextInt.

For all of the time conversion trouble you go through, the return value of measure() is left ambiguous - it's in nanos, but the caller wouldn't know that unless they read the source. Use Duration instead for your public interface.

Perhaps more importantly, this utility is fairly poor at doing the one thing it's supposed to do, which is to measure execution time. Never - especially for very short code - measure a single execution time. You're on a scheduled OS, which introduces a fair amount of jitter to any and all timing results. The timed procedures themselves need to be made longer, and they should be iterated at least ~1000 times and some summary statistics shown.

Suggested

PerfTimer.java

import java.io.PrintStream;
import java.time.Duration;
import java.util.Collection;
import java.util.Comparator;
import java.util.List;
import java.util.stream.Collectors;

import static java.lang.System.nanoTime;


public class PerfTimer {
    public record Method(String name, Runnable fun) {
        @Override
        public String toString() { return name; }
    }

    public static class Result {
        public final Method method;
        private long min = Long.MAX_VALUE,
                     max = Long.MIN_VALUE,
                     n = 0;
        private double sum = 0;

        private Result(Method method) {
            this.method = method;
        }

        private void run() {
            long start = nanoTime();
            method.fun().run();
            long dur = nanoTime() - start;
            min = Long.min(min, dur);
            max = Long.max(max, dur);
            sum += dur;
            n++;
        }

        private double order() { return sum; }
        public Duration min() { return Duration.ofNanos(min); }
        public Duration max() { return Duration.ofNanos(max); }
        public Duration mean() { return Duration.ofNanos((long)(sum / n)); }

        @Override
        public String toString() {
            return "%s took %s (mean)".formatted(method, mean());
        }
    }

    public record ResultSet(Collection<Result> results) {
        private static double toMicros(Duration dur) { return dur.toNanos() * 1e-3; }

        public void print(PrintStream out) {
            out.printf("%20s %10s %10s %10s%n", "method", "min_us", "mean_us", "max_us");

            for (Result result: results)
                out.printf("%20s %10.2f %10.2f %10.2f%n", result.method,
                    toMicros(result.min()), toMicros(result.mean()), toMicros(result.max()));
        }
    }

    private static final Comparator<Result> byMean = Comparator.comparingDouble(Result::order);

    private final Collection<Method> methods;

    public PerfTimer(Collection<Method> methods) {
        this.methods = methods;
    }

    public ResultSet measure(int n) {
        List<Result> results = methods.stream().map(Result::new).collect(Collectors.toList());

        for (int i = 0; i < n; i++)
            for (Result result: results)
                result.run();

        results.sort(byMean);
        return new ResultSet(results);
    }
}

Main.java

import java.util.ArrayList;
import java.util.List;
import java.util.Random;

public class Main {
    private final Random rand = new Random(0);

    private void addRandomInts(List<Integer> dest, long n) {
        for (long i = 0; i < n; i++)
            dest.add(rand.nextInt());
    }

    private List<Integer> intsToArrNoPrealloc() {
        long n = 100_000;
        List<Integer> ints = new ArrayList<>();
        addRandomInts(ints, n);
        return ints;
    }

    private List<Integer> intsToArrPrealloc() {
        int n = 100_000;
        List<Integer> ints = new ArrayList<>(n);
        addRandomInts(ints, n);
        return ints;
    }

    private String plusConcatAlphabet() {
        String res = "";
        String[] alphabet = "abcdefghijklmnopqrstuvwxyz".split("");
        for(int i = 0; i < 2_000; i++) {
            int randomIndex = rand.nextInt(alphabet.length);
            res += alphabet[randomIndex];
        }
        return res;
    }

    private String strBuildAlphabet() {
        StringBuilder sb = new StringBuilder();
        String[] alphabet = "abcdefghijklmnopqrstuvwxyz".split("");
        for(int i = 0; i < 2_000; i++) {
            int randomIndex = rand.nextInt(alphabet.length);
            sb.append(alphabet[randomIndex]);
        }
        return sb.toString();
    }

    private String strBufferAlphabet() {
        StringBuffer sb = new StringBuffer();
        String[] alphabet = "abcdefghijklmnopqrstuvwxyz".split("");
        for(int i = 0; i < 2_000; i++) {
            int randomIndex = rand.nextInt(alphabet.length);
            sb.append(alphabet[randomIndex]);
        }
        return sb.toString();
    }

    public void demo() {
        PerfTimer timer = new PerfTimer(List.of(
            new PerfTimer.Method("intsToArrNoPrealloc", this::intsToArrNoPrealloc),
            new PerfTimer.Method("intsToArrPrealloc", this::intsToArrPrealloc)
        ));
        timer.measure(1_000).print(System.out);
        System.out.println();

        timer = new PerfTimer(List.of(
            new PerfTimer.Method("plusConcatAlphabet", this::plusConcatAlphabet),
            new PerfTimer.Method("strBuildAlphabet", this::strBuildAlphabet),
            new PerfTimer.Method("strBufferAlphabet", this::strBufferAlphabet)
        ));
        timer.measure(1_000).print(System.out);
    }

    public static void main(String[] args) {
        new Main().demo();
    }
}

Output

              method     min_us    mean_us     max_us
   intsToArrPrealloc     969.60    1095.73    4885.60
 intsToArrNoPrealloc    1044.20    1209.09    8096.80

              method     min_us    mean_us     max_us
    strBuildAlphabet      31.00      43.99     623.50
   strBufferAlphabet      30.80      47.42    1240.30
  plusConcatAlphabet     164.60     233.00    2193.00

Answer 5

Focusing on a single aspect, the MeasuredProcedure:

in general: abstract classes are useless, and composition is better than inheritance.

In this case, composition lets you define the thing you want to instrument separately, without having to create a dedicated class just for that thing.

Expanding on that:

Assuming an existing class

public class Frombulator {

  // ...

  public void frombulate() {
    // This is what you measure
  }

}

you could have this:

public class MeasuredProcedure implements Callable {
    private String name;
    private Callable systemUnderTest;
    publi MeasuredProcedure(String name, Callable systemUnderTest) {
        this.name = name;
        this.systemUnderTest = systemUnderTest;
    }

    public void call() {
        this.systemUnderTest.call();
    }

    @Override
    public String toString() {
        return name;
    }
}

Then you use it as:

Frombulator f = ...;

MeasuredProcedure mp = new MeasuredProcedure("foobar", f.frombulate);

long time = measurer.measure(mp);

At this point, you can also just ditch the MeasuredProcedure altogether, and simply take a Callable, Runnable, Function, or whatever is cool nowadays in the Java functional world as input to your measurer.

This keeps a clear distinction between the measurer and the measured.