non-deterministic allocation behavior in caliper benchmark

Question

I am trying to benchmark the performance of two different log4j Pattern layouts when used via slf4j. I am using caliper (current HEAD version).

Here's my benchmark class:

public class PatternLayoutBenchmark {

    // fully qualified names wherever there would otherwise be confusion btw
    // log4j and slf4j
    private static final org.apache.log4j.Level LEVEL = INFO;

    @Param
    private LayoutProvider layoutProvider;
    private org.slf4j.Logger logger;

    @BeforeExperiment
    public void setup() throws Exception { logger = layoutProvider.getLogger(); }

    @Benchmark
    public int timeLogging(final int repetitions) {
        int ct = 0;
        for (int i = 0; i < repetitions; i++) {
            logger.info("Now let's see the big difference this makes");
            ct++;
        }
        return ct;
    }

    enum LayoutProvider {
        WITH_LINE_INFO {
            @Override
            PatternLayout createLayout() {
                return new PatternLayout("%d %x %p %t %l: %m%n");
            }
        },
        WITH_RECOMMENDED_PATTERN {
            @Override
            PatternLayout createLayout() {
                return new PatternLayout("%d %x %p %t %c: %m%n");
            }
        };
        abstract PatternLayout createLayout();

        public final org.slf4j.Logger getLogger() throws Exception {
            RootLogger log4jLogger = new RootLogger(LEVEL);
            Hierarchy h = new Hierarchy(log4jLogger);
            new DefaultRepositorySelector(h);
            log4jLogger.addAppender(new WriterAppender(createLayout(), new StringWriter()));

            final Constructor<Log4jLoggerAdapter> constructor = 
                    Log4jLoggerAdapter.class.getDeclaredConstructor(org.apache.log4j.Logger.class);
            constructor.setAccessible(true);
            return constructor.newInstance(log4jLogger);
        }
    }

    public static void main(final String[] args) {
        CaliperMain.main(PatternLayoutBenchmark.class, args);
    }

}

When I run it, I get this error:

This selection yields 4 experiments.
Starting experiment 1 of 4: {instrument=allocation, benchmarkMethod=timeLogging, vm=default, parameters={layoutProvider=WITH_LINE_INFO}}… 
com.google.caliper.runner.ProxyWorkerException: An exception occurred in a worker process.  The stack trace is as follows:
An unexpected exception has been thrown by the caliper runner.
    java.lang.IllegalStateException: Your benchmark appears to have non-deterministic allocation behavior. Observed 1 instance(s) of char[376] (768 bytes) 
Please see https://sites.google.com/site/caliperusers/issues
    at java.util.Arrays.copyOf(Arrays.java:2367)
    at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:130)
    at org.apache.log4j.Category.callAppenders(Category.java:206)
    ...
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)
    at some.pckg.name.PatternLayoutBenchmark.timeLogging(PatternLayoutBenchmark.java:37) in the baseline but only 0 in the actual measurement

Is there some configuration I need to add to my benchmark? Or how can I solve this problem?

Answer 1

I got the correct answer from the caliper forum:

the solution was to disable the allocation instrumentation by adding the flag

-i runtime

Another suggestion that also worked was:

-Cinstrument.allocation.trackAllocations=false