11
\$\begingroup\$

Note -> Follow-on question posted here: YAuB - Micro Benchmark Follow-on

I recently answered this Beautiful String question, where the task is to maximize the value of a string by assigning each character a different value (from 1 to 26) in a way that the sum of all characters is maxmized.

A number of different solutions were presented, but, the question is, which one is fastest?

This inspired me to write yet another micro-benchmark system that allows you to run and get metrics on simple code runs, using some Java 8 tricks to make the invocation easy.

For example, in the question/answer set above, there are the following suggestions:

  • Legato has 2 implementations in his question
  • Janos has one
  • I have a few

That makes 6 implementations to sort through. It would be really nice to be able to do:

  1. create an instance of a benchmark system.
  2. add some tasks to run
  3. run the tasks with specified constraints
  4. get a report of the significant statistics for each task.

With that in mind, the goal is to allow the following:

final String line = "This is a test, including punctuation, and other words"
        + " and numbers like 1, UPPER, and Lower letters";
final int expect = 1574;

UBench uBench = new UBench("Beautiful");

uBench.addTask(Task.buildCheckedIntTask("Legato Java7", () -> getMaximumBeauty(line), expect));
uBench.addTask(Task.buildCheckedIntTask("Legato Java8", () -> getMaximumBeauty8(line), expect));
uBench.addTask(Task.buildCheckedIntTask("Janos Java7", () -> computeMaxBeauty(line), expect));
uBench.addTask(Task.buildCheckedIntTask("Rolfl Java7", () -> beautyMax7(line), expect));
uBench.addTask(Task.buildCheckedIntTask("Rolfl Java8Regex", () -> beautyMaxF(line), expect));
uBench.addTask(Task.buildCheckedIntTask("Rolfl Java8Filter", () -> beautyMax8(line), expect));


System.out.println("Warming up");
uBench.benchMark(5000).stream().forEach(System.out::println);
System.out.println("\n\nReal runs\n\n");
uBench.benchMark(10000).stream().sorted(Comparator.comparing(TaskStats::get95thPercentile))
        .forEach(System.out::println);

To that end, here is the code I would like reviewed. This code provides a mechanism to add tests, and benchmark them, in a Java-8 friendly way.

TaskStats

First, the results the tests provides. An example toString() looks like:

Task Janos Java7:
  Iterations  :         5000
  Fastest     :      0.00355ms
  Average     :      0.00792ms
  95Pctile    :      0.01934ms
  Slowest     :      3.26757ms
  TimeBlock   : 0.01600ms 0.00827ms 0.00796ms 0.00823ms 0.01392ms 0.00484ms 0.00504ms 0.00483ms 0.00534ms 0.00478ms
  FactorHisto :  2599  2072   291    31     5     0     1     0     0     1

The code is:

package net.tuis.ubench;

import java.util.Arrays;
import java.util.LongSummaryStatistics;
import java.util.stream.Collectors;
import java.util.stream.DoubleStream;
import java.util.stream.IntStream;
import java.util.stream.LongStream;

/**
 * Statistics representing the runs in this task.
 * <p>
 * Presents various statistics related to the run times that are useful for
 * interpreting the run performance.
 * 
 * @author rolf
 *
 */
public final class TaskStats {

    private static final double NANOxMILLI = 1000000.0;

    private final long[] results;
    private final long min;
    private final long max;
    private final double average;
    private final String name;

    /**
     * Construct statistics based on the nanosecond times of multiple runs.
     * 
     * @param name
     *            The name of the task that has been benchmarked
     * @param results
     *            The nano-second run times of each successful run.
     */
    public TaskStats(String name, long[] results) {
        this.name = name;
        this.results = results;
        LongSummaryStatistics lss = LongStream.of(results).summaryStatistics();
        min = lss.getMin();
        max = lss.getMax();
        average = lss.getAverage();
    }

    /**
     * Get the raw data the statistics are based off.
     * @return the individual test run times (in nanoseconds, and in order of execution).
     */
    public long[] getRawData() {
        return Arrays.copyOf(results, results.length);
    }

    /**
     * Summarize the time-progression of the run time for each iteration, in
     * order of execution (in milliseconds).
     * <p>
     * An example helps. If there are 200 results, and a request for 10 zones,
     * then return 10 double values representing the average time of the first
     * 20 runs, then the next 20, and so on, until the 10th zone contains the
     * average time of the last 20 runs.
     * <p>
     * This is a good way to see the effects of warm-up times and different
     * compile levels
     * 
     * @param zoneCount
     * @return
     */
    public final double[] getZoneTimesMilli(int zoneCount) {
        double[] ret = new double[Math.min(zoneCount, results.length)];
        int perblock = results.length / ret.length;
        int overflow = results.length % ret.length;
        int pos = 0;
        for (int block = 0; block < ret.length; block++) {
            int count = perblock + (block < overflow ? 1 : 0);
            int limit = pos + count;
            long nanos = 0;
            while (pos < limit) {
                nanos += results[pos];
                pos++;
            }
            ret[block] = (nanos / NANOxMILLI) / count;
        }
        return ret;
    }

    /**
     * Compute a log-2-based histogram relative to the fastest run in the data
     * set.
     * <p>
     * This gives a sense of what the general shape of the runs are in terms of
     * distribution of run times. The histogram is based on the fastest run.
     * <p>
     * By way of an example, the output: <code>100, 50, 10, 1, 0, 1</code> would
     * suggest that:
     * <ul>
     * <li>100 runs were between 1 times and 2 times as slow as the fastest.
     * <li>50 runs were between 2 and 4 times slower than the fastest.
     * <li>10 runs were between 4 and 8 times slower
     * <li>1 run was between 8 and 16 times slower
     * <li>1 run was between 32 and 64 times slower
     * 
     * @return
     */
    public final int[] getHistogramByDoublingFactor() {
        int count = (int) (max / min);
        int[] histo = new int[Integer.numberOfTrailingZeros(Integer.highestOneBit(count)) + 1];
        LongStream.of(results).mapToInt(t -> Integer.numberOfTrailingZeros(Integer.highestOneBit((int) (t / min))))
                .forEach(i -> histo[i]++);
        return histo;
    }

    /**
     * Compute the 95<sup>th</sup> percentile of runtimes (in milliseconds).
     * <p>
     * 95% of all runs completed in this time, or faster.
     * 
     * @return the millisecond time of the 95<sup>th</sup> percentile.
     */
    public final double get95thPercentile() {
        if (results.length < 100) {
            return getSlowest();
        }
        long limit = ((results.length + 1) * 95) / 100;
        return LongStream.of(results).sorted().limit(limit).max().getAsLong() / NANOxMILLI;
    }

    /**
     * Compute the average time of all runs (in milliseconds).
     * 
     * @return the average time (in milliseconds)
     */
    public final double getAverage() {
        return average / NANOxMILLI;
    }

    /**
     * Compute the slowest run (in milliseconds).
     * 
     * @return The slowest run time (in milliseconds).
     */
    public final double getSlowest() {
        return max / NANOxMILLI;
    }

    /**
     * Compute the fastest run (in milliseconds).
     * 
     * @return The fastest run time (in milliseconds).
     */
    public final double getFastest() {
        return min / NANOxMILLI;
    }

    @Override
    public String toString() {
        return String.format("Task %s:\n" +
                             "  Iterations  : %12d\n" + 
                             "  Fastest     : %12.5fms\n" + 
                             "  Average     : %12.5fms\n" + 
                             "  95Pctile    : %12.5fms\n" + 
                             "  Slowest     : %12.5fms\n" + 
                             "  TimeBlock   : %s\n" + 
                             "  FactorHisto : %s\n", 
                name, results.length, getFastest(), getAverage(),
                get95thPercentile(), getSlowest(), formatMillis(getZoneTimesMilli(10)),
                formatHisto(getHistogramByDoublingFactor()));
    }

    private String formatHisto(int[] histogramByXFactor) {
        return IntStream.of(histogramByXFactor).mapToObj(i -> String.format("%5d", i)).collect(Collectors.joining(" "));
    }

    private String formatMillis(double[] zoneTimesMilli) {
        return DoubleStream.of(zoneTimesMilli).mapToObj(d -> String.format("%.5fms", d))
                .collect(Collectors.joining(" "));
    }

}

Task

The task code allows you to create tasks that can be added to the benchmark, and reported on later. The main consideration here is that the code that checks the result should not be counted toward the performance of the code that produces any result. Here's the code, with some factory methods for creating common Tasks. Note that the class is abstract, and that the factory methods create concrete, specialized instances, but users are free to create their own implementations too.

package net.tuis.ubench;

import java.util.Objects;
import java.util.function.IntSupplier;
import java.util.function.Supplier;

/**
 * Tasks represent actions which can be benchmarked on the MicroBench tool.
 * <p>
 * This class encompasses the concept of running code, timing that run, and
 * being aware that the code may need to check the result outside of the timed
 * portion. The calling code will effectively perform:
 * 
 * <pre>
 * R result = perform()
 * if (!check(result)) {
 *     throw new IllegalStateException(...);
 * }
 * </pre>
 * 
 * but the <code>perform()</code> call will be timed.
 * 
 * 
 * @author rolf
 *
 * @param <S>
 *            The type of data that can be created before each task is run.
 * @param <R>
 *            The type of the result that the task produces.
 */
public abstract class Task<R> {

    /**
     * Build a task that ensures the function produces the correct result
     * (result is compared with the equivalent of
     * <code>Objects.equals(expect, function.get())</code> )
     * 
     * @param name
     *            The task name
     * @param benchmark
     *            The supplier that produces a result, the item that is
     *            benchmarked.
     * @param expect
     *            the value the benchmarked code is expected to produce
     * @return the Task ready to be added to the MicroBench tool.
     */
    public static final <T> Task<T> buildCheckedTask(final String name, final Supplier<T> benchmark, final T expect) {
        return new Task<T>(name) {

            @Override
            protected T perform() throws Exception {
                return benchmark.get();
            }

            @Override
            protected boolean check(T result) {
                return Objects.equals(expect, result);
            }

        };
    }

    /**
     * Build a task that ensures the function produces the correct result
     * (result is compared with the equivalent of
     * <code>function.getAsInt() == expect</code> )
     * 
     * @param name
     *            The task name
     * @param benchmark
     *            The supplier that produces a result, the item that is
     *            benchmarked.
     * @param expect
     *            the value the benchmarked code is expected to produce
     * @return the Task ready to be added to the MicroBench tool.
     */
    public static final Task<?> buildCheckedIntTask(final String name, final IntSupplier benchmark, final int expect) {
        return new Task<Boolean>(name) {

            @Override
            protected Boolean perform() throws Exception {
                int got = benchmark.getAsInt();
                return Boolean.valueOf(expect == got);
            }

            @Override
            protected boolean check(Boolean result) {
                return result.booleanValue();
            }

        };
    }

    /**
     * Build a task that just runs the benchmark code.
     * 
     * @param name
     *            The task name
     * @param benchmark
     *            The supplier that produces a result, the item that is
     *            benchmarked.
     * @return the Task ready to be added to the MicroBench tool.
     */

    public static final Task<?> buildVoidTask(final String name, final Runnable function) {
        return new Task<Object>(name) {

            @Override
            protected Object perform() throws Exception {
                function.run();
                return null;
            }

            @Override
            protected boolean check(Object result) {
                return true;
            }

        };
    }

    private final String name;

    /**
     * Create a new Task instance (expected to inherit this class).
     * 
     * @param name
     *            The task name (used in reports).
     */
    public Task(String name) {
        this.name = name;
    }

    /**
     * The task's name
     * 
     * @return the name this task was created with.
     */
    public final String getName() {
        return name;
    }

    /**
     * Execute one iteration of the task, producing a result useful for
     * statistics.
     * 
     * @return The runtime results of the task.
     * @throws IllegalStateException
     *             if the task being tested throws an exception, or does not
     *             match the expected value.
     */
    final long compute() {
        try {

            long start = System.nanoTime();

            R r = perform();

            long done = System.nanoTime();

            if (!check(r)) {
                throw new IllegalStateException(String.format("Unexpected result in task %s -> %s", name, r));
            }

            return done - start;
        } catch (Exception e) {
            throw new IllegalStateException(String.format("Failed execution in %s with %s", name, e.getMessage()), e);
        }
    }

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

    /**
     * Perform the benchmarked code. This is the time-critical aspect.
     * 
     * @return the value the benchmark should produce
     * @throws Exception
     *             if there is an execution problem
     */
    protected abstract R perform() throws Exception;

    /**
     * Check the results of execution. Simply return true for unchecked runs.
     * The timing of this code is not critical
     * 
     * @param result
     *            The result from the perform method
     * @return true if the check passed.
     */
    protected abstract boolean check(R result);

}

UBench itself

Finally, the class that controls the admission, and running of the benchmarks.

package net.tuis.ubench;

import java.util.ArrayList;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.TimeUnit;

/**
 * The UBench class encompasses a suite of tasks that are to be compared...
 * possibly relative to each other.
 * <p>
 * Each task can be added to the suite. Once you have the tasks you need, then
 * all tasks can be benchmarked according to limits given in the run.
 * 
 * @author rolf
 *
 */
public class UBench {

    private final List<Task<?>> tasks = new ArrayList<>();
    private final String suiteName;

    public UBench(String suiteName) {
        this.suiteName = suiteName;
    }

    /**
     * Add a task to the suite.
     * <p>
     * Note that there are helper methods on the Task class to help you build
     * task instances.
     * 
     * @param task
     *            the task to add to this suite.
     */
    public void addTask(Task<?> task) {
        synchronized (tasks) {
            tasks.add(task);
        }
    }

    /**
     * Benchmark a task until it completes the desired iterations, exceeds the
     * time limit, or reaches stability, whichever comes first.
     * 
     * @param iterations
     *            maximum number of iterations to run.
     * @param minStabilityLen
     *            If this many iterations in a row are all within the
     *            maxVariance, then the benchmark ends.
     * @param maxVariance
     *            Expressed as a percent from 0.0 to 100.0, and so on
     * @return the results of all completed tasks.
     */
    public List<TaskStats> benchMark(final int iterations, final int minStabilityLen, final double maxVariance,
            final long timeLimit, final TimeUnit timeUnit) {

        List<Task<?>> mytasks = getTasks();
        TaskStats[] ret = new TaskStats[mytasks.size()];
        int i = 0;
        for (Task<?> task : mytasks) {
            ret[i++] = runTask(task, iterations, minStabilityLen, 1 + (maxVariance / 100.0), timeLimit, timeUnit);
        }

        return Arrays.asList(ret);
    }

    /**
     * Benchmark all tasks until it they complete the desired elapsed time
     * 
     * @param iterations
     *            number of iterations to run.
     * @return the results of all completed tasks.
     */
    public List<TaskStats> benchMark(final long timeLimit, final TimeUnit timeUnit) {
        return benchMark(Integer.MAX_VALUE, 0, 100, timeLimit, timeUnit);
    }

    /**
     * Benchmark all tasks until it they complete the desired iteration count
     * 
     * @param iterations
     *            number of iterations to run.
     * @return the results of all completed tasks.
     */
    public List<TaskStats> benchMark(final int iterations) {
        return benchMark(iterations, 0, 100, 1000, TimeUnit.DAYS);
    }

    private List<Task<?>> getTasks() {
        synchronized (tasks) {
            return new ArrayList<>(tasks);
        }
    }

    private TaskStats runTask(final Task<?> task, final int iterations, final int minStability, final double maxLimit,
            final long timeLimit, final TimeUnit timeUnit) {
        long[] results = new long[Math.min(iterations, 10000)];
        long[] recents = new long[Math.min(minStability, iterations)];
        int rPos = 0;

        long limit = System.currentTimeMillis() + timeUnit.toMillis(timeLimit);

        for (int i = 0; i < iterations; i++) {
            long res = Math.max(task.compute(), 1);
            if (rPos >= results.length) {
                results = Arrays.copyOf(results, expandTo(results.length));
            }
            if (minStability > 0) {
                recents[rPos % recents.length] = res;
            }
            results[rPos++] = res;
            if ((timeLimit > 0 && System.currentTimeMillis() >= limit)
                    || (minStability > 0 && rPos >= recents.length && inBounds(recents, maxLimit))) {
                return new TaskStats(task.getName(), Arrays.copyOf(results, rPos));
            }
        }
        return new TaskStats(task.getName(), Arrays.copyOf(results, rPos));
    }

    private int expandTo(int length) {
        // add 25% + 100 - limit to Integer.Max
        int toAdd = 100 + (length >> 2);
        toAdd = Math.min(Integer.MAX_VALUE - length, toAdd);
        return toAdd + length;
    }

    @Override
    public String toString() {
        return String.format("%s with tasks: %s", suiteName, tasks.toString());
    }

    /**
     * Compute whether any of the values in times exceed the given bound,
     * realtive to the minimum value in times.
     * 
     * @param times
     *            the times to compute the bounds on
     * @param bound
     *            the bound is represented as a value like 1.10 for 10% greater
     *            than the minimum
     * @return true if all values are in bounds.
     */
    private static final boolean inBounds(long[] times, double bound) {
        long min = times[0];
        long max = times[0];
        long limit = (long) (min * bound);
        for (int i = 1; i < times.length; i++) {
            if (times[i] < min) {
                min = times[i];
                limit = (long) (min * bound);
                if (max > limit) {
                    return false;
                }
            }
            if (times[i] > max) {
                max = times[i];
                // new max, is it slower than the worst allowed?
                if (max > limit) {
                    return false;
                }
            }
        }
        return true;
    }

}

Requests

All of this code is available on GitHub, in my MicroBench repository. The code presented here is this commit.

I am particularly interested in getting suggestions for how to improve the code from a usability perspective, as well as any suggestions for better ways to collect, and manage the timing results.

By the way

Going the full circle back to the Beautiful Strings... here's the full version of the tests I ran for which function is fastest:

Task Rolfl Java7:
  Iterations  :        10000
  Fastest     :      0.00079ms
  Average     :      0.00171ms
  95Pctile    :      0.00276ms
  Slowest     :      0.04382ms
  TimeBlock   : 0.00291ms 0.00283ms 0.00298ms 0.00201ms 0.00153ms 0.00099ms 0.00097ms 0.00097ms 0.00094ms 0.00095ms
  FactorHisto :  5429  4244   282    15    10    20

Task Rolfl Java8Filter:
  Iterations  :        10000
  Fastest     :      0.00237ms
  Average     :      0.00431ms
  95Pctile    :      0.00592ms
  Slowest     :      0.07105ms
  TimeBlock   : 0.00509ms 0.00298ms 0.00313ms 0.00528ms 0.00575ms 0.00582ms 0.00534ms 0.00424ms 0.00272ms 0.00272ms
  FactorHisto :  4804  5132    51     9     4

Task Janos Java7:
  Iterations  :        10000
  Fastest     :      0.00276ms
  Average     :      0.00420ms
  95Pctile    :      0.00790ms
  Slowest     :      0.09276ms
  TimeBlock   : 0.00682ms 0.00753ms 0.00482ms 0.00323ms 0.00316ms 0.00314ms 0.00316ms 0.00318ms 0.00316ms 0.00383ms
  FactorHisto :  7751  2168    61    15     4     1

Task Legato Java7:
  Iterations  :        10000
  Fastest     :      0.00434ms
  Average     :      0.00644ms
  95Pctile    :      0.00947ms
  Slowest     :      2.81442ms
  TimeBlock   : 0.00740ms 0.00625ms 0.00633ms 0.00595ms 0.01058ms 0.00846ms 0.00490ms 0.00483ms 0.00482ms 0.00482ms
  FactorHisto :  9369   596    19     7     6     0     1     0     1     1

Task Rolfl Java8Regex:
  Iterations  :        10000
  Fastest     :      0.00474ms
  Average     :      0.00744ms
  95Pctile    :      0.01145ms
  Slowest     :      0.11052ms
  TimeBlock   : 0.00644ms 0.00573ms 0.00570ms 0.00804ms 0.00591ms 0.00538ms 0.00924ms 0.01090ms 0.00701ms 0.01002ms
  FactorHisto :  6519  3449    26     4     2

Task Legato Java8:
  Iterations  :        10000
  Fastest     :      0.00553ms
  Average     :      0.01247ms
  95Pctile    :      0.03671ms
  Slowest     :      1.39734ms
  TimeBlock   : 0.03745ms 0.02690ms 0.00881ms 0.00764ms 0.00934ms 0.00889ms 0.00812ms 0.00576ms 0.00580ms 0.00597ms
  FactorHisto :  7247  1209  1175   354    12     1     1     1
\$\endgroup\$
6
\$\begingroup\$

From a usability perspective, this is a bit weird...

public static final Task<?> buildCheckedIntTask(final String name, final IntSupplier benchmark, final int expect) {
    return new Task<Boolean>(name) {

There's not really any need for a Task<Boolean> here, it could just as well be Task<Integer>.

Additionally, as you know what type it returns, I see no reason to return Task<?>. It would be beneficial to return Task<Integer> here IMO.

I would expect the checking to be done within the check method, and not within perform(), like the following:

public static final Task<Integer> buildCheckedIntTask(final String name, final IntSupplier benchmark, final int expect) {
    return new Task<Integer>(name) {
            @Override
            protected Integer perform() throws Exception {
                int got = benchmark.getAsInt();
                return got;
            }

            @Override
            protected boolean check(Integer result) {
                return result == expect;
            }

About this buildVoidTask, why use the Object type when you can use the Void type?

public static final Task<Void> buildVoidTask(final String name, final Runnable function) {
    return new Task<Void>(name) {
        @Override
        protected Void perform() throws Exception {
            function.run();
            return null;
        }

        @Override
        protected boolean check(Object result) {
            return true;
        }

When it comes to abstract classes, I sometimes move the abstract methods themselves to an interface, make the abstract class a concrete class, and pass it an object of the interface. Like the following:

public interface TaskCaller<R> {
    R getResult() throws Exception;
    boolean checkResult(R result);
}

Although this can easily be separated into ThrowingSupplier<R> (you'd have to make that one) and Predicate<R>

public class Task<R> {
    private final ThrowingSupplier<R> supplier;
    private final Predicate<R> checker;

    public Task(String name, ThrowingSupplier<R> supplier, Predicate<R> predicate) {
        this.name = name;
        this.supplier = supplier;
        this.checker = predicate;
    }
    ...
}

It is good that you at the moment allow extending Task<R>, but you haven't provided an easy way to use a Predicate<R> for the checking. Let's say you have a PrimeNumberGenerator for example. It's not possible to provide a single Long expected to that. It is however possible to verify that the generated numbers is prime.

If you were to use this, your separate build methods could be drastically shortened:

    public static final <T> Task<T> buildCheckedTask(final String name, final Supplier<T> benchmark, final T expect) {
        return new Task<T>(name, benchmark, r -> Objects.equals(r, expect));
    }

private final List<Task<?>> tasks = new ArrayList<>();

It might just be me, but I believe instead of using the synchronization throughout your class you could wrap this one in Collections.synchronizedList (although you know more about multi-threaded things than I do, there might be a significant performance drawback by using this?)


/**
 * Benchmark all tasks until it they complete the desired elapsed time
 * @param iterations
 *            number of iterations to run.
 * @return the results of all completed tasks.
 */
public List<TaskStats> benchMark(final long timeLimit, final TimeUnit timeUnit) {
  1. Avoid grammatical errors in JavaDoc. That's not useful ;) until it they...
  2. The @param does not match the actual parameters for this method

} catch (Exception e) {
    throw new IllegalStateException(String.format("Failed execution in %s with %s", name, e.getMessage()), e);
}

Rethrowing an exception, good, nothing wrong with that... but... Let's say that a simple new RuntimeException() is thrown somewhere inside the code. Then the message for this IllegalStateException will be:

Failed execution in MyTask with null

That's right. With what? Instead of using e.getMessage(), it is a lot more helpful to simply use e.

Consider this code:

System.out.println(new RuntimeException("test error"));
System.out.println(new RuntimeException("test error").getMessage());

System.out.println(new RuntimeException());
System.out.println(new RuntimeException().getMessage());

The output here is:

java.lang.RuntimeException: test error
test error
java.lang.RuntimeException
null

Using .getMessage() drastically reduces the usefulness when used in a string.


Other micro-benchmark frameworks have a feature for scanning a class for @Benchmark annotations. [meta-tag:feature-request]

Also, probably the most important thing with regards to usability, make it easy to use your library as a dependency! At the moment, there does not seem to be a build.gradle, pom.xml or similar for your project. If there was a Maven dependency available for your project, doesn't necessarily have to be on Maven Central, anyone could use it in an easy way.

\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.