Error benchmarking log statements

[Sean Patrick Floyd]

Hi. I would like to benchmark log4j over slf4j logging with and without line numbers, since according to Log4j docs the "l" location flag is "extremely slow".

So I came up with this benchmark:

public class PatternLayoutBenchmark {
  private static final org.apache.log4j.Level LEVEL = org.apache.log4j.Level.INFO;

  @Param private LayoutProvider layoutProvider;

  private org.slf4j.Logger logger;

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

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

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

      }

    };
    abstract org.apache.log4j.PatternLayout createLayout();

    public final org.slf4j.Logger getLogger() throws Exception {
      org.apache.log4j.spi.RootLogger log4jLogger = new org.apache.log4j.spi.RootLogger(LEVEL);
      org.apache.log4j.Hierarchy h = new org.apache.log4j.Hierarchy(log4jLogger);
      new org.apache.log4j.spi.DefaultRepositorySelector(h);
      log4jLogger.addAppender(new org.apache.log4j.WriterAppender(createLayout(), new StringWriter()));
      final Constructor<org.slf4j.impl.Log4jLoggerAdapter> constructor =

            org.slf4j.impl.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); }
}

But when I run it, I get this error:

Experiment selection: 
  Instruments:   [allocation, runtime]
  User parameters:   {layoutProvider=[WITH_LINE_INFO, WITH_RECOMMENDED_PATTERN]}
  Virtual machines:  [default]
  Selection type:    Full cartesian product
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:
java.lang.IllegalStateException: Your benchmark appears to have non-deterministic allocation behavior. Observed 1 instance(s) of char[376] (768 bytes) 
at java.util.Arrays.copyOf(Arrays.java:2367)
at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:130)
at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:114)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:415)
at java.lang.StringBuffer.append(StringBuffer.java:237)
at java.io.StringWriter.write(StringWriter.java:101)
at org.apache.log4j.helpers.QuietWriter.write(QuietWriter.java:48)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
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)

The non-deterministic allocation behavior is probably something that has to be expected from a logging framework, so is there anything I can do to ignore that check?

I am using the latest caliper source, and

Java version "1.7.0_45"

Java(TM) SE Runtime Environment (build 1.7.0_45-b18)

Java HotSpot(TM) 64-Bit Server VM (build 24.45-b08, mixed mode)

on Ubuntu (64)

Thanks in advance, Sean

[Luke Sandberg]

-Cinstrument.allocation. trackAllocations=false

Should disable fine grained tracking which may get you past the error.  Otherwise you will need to disable the allocation instrument altogether.

(phone)

--
--
guava-...@googlegroups.com
Project site: http://caliper.googlecode.com
This group: http://groups.google.com/group/caliper
 
This list is for general discussion.
To report an issue: http://code.google.com/p/caliper/issues/entry
To get help: http://stackoverflow.com/questions/ask (use the tag "caliper")
 
---
You received this message because you are subscribed to the Google Groups "caliper" group.
To unsubscribe from this group and stop receiving emails from it, send an email to caliper+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Gregory Kick]

You're hitting https://code.google.com/p/caliper/issues/detail?id=273 .   If you don't care about allocations, the simplest thing to do is just to disable that instrument: -i runtime.

Otherwise, you need to get all of the code initialized such that each rep allocates the same amount.  Typically, it's things like lazy initialization that cause issues.  Invoking your benchmark method with some reps from the setup method usually seems to work for that.

HTH.

--

--
guava-...@googlegroups.com
Project site: http://caliper.googlecode.com
This group: http://groups.google.com/group/caliper
 
This list is for general discussion.
To report an issue: http://code.google.com/p/caliper/issues/entry
To get help: http://stackoverflow.com/questions/ask (use the tag "caliper")
 
---
You received this message because you are subscribed to the Google Groups "caliper" group.
To unsubscribe from this group and stop receiving emails from it, send an email to caliper+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

--
Greg Kick
Java Core Libraries Team

[Sean Patrick Floyd]

Thanks. both "-Cinstrument.allocation.trackAllocations=false" and "-i runtime" worked.

[Gregory Kick]

I just pushed some changes today that might help resolve some of these allocation measurement issues.  If anybody wants to build caliper from HEAD and give it a try that'd be appreciated.

On Tue, Jan 7, 2014 at 3:02 AM, Sean Patrick Floyd <seanp...@googlemail.com> wrote:

Thanks. both "-Cinstrument.allocation.trackAllocations=false" and "-i runtime" worked.

--
--
guava-...@googlegroups.com
Project site: http://caliper.googlecode.com
This group: http://groups.google.com/group/caliper
 
This list is for general discussion.
To report an issue: http://code.google.com/p/caliper/issues/entry
To get help: http://stackoverflow.com/questions/ask (use the tag "caliper")
 
---
You received this message because you are subscribed to the Google Groups "caliper" group.
To unsubscribe from this group and stop receiving emails from it, send an email to caliper+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.