I was looking on the sample test program trying to compare some inhouse logging system vs logback/slf4j and noticed really poor performance when using rolling file appender. Here is the sample program:

public class LoggerTest {

private static final int NUMBER_OF_LOG_STMTS = 10000;

private static final String FIRST_PART = "Some lengthy log statement which includes string concatenation. Here it goes: int = [";
private static final String WHOLE_STRING = "Some lengthy log statement which includes string concatenation. Here it goes: int = [{}], bd = [{}], complexType = [{}]";

static class ComplexType {

private String s1;
private String s2;
private String s3;

public ComplexType(String s1, String s2, String s3)

{ this.s1 = s1; this.s2 = s2; this.s3 = s3; }

@Override
public String toString()

{ return "Complex type toString: s1 = [" + s1 + "], s2 = [" + s2 + "], s3 = [" + s3 + "]"; }

}

@SuppressWarnings("unchecked")
public static void main(String[] args) {
Integer someInt = new Integer(500);
BigDecimal decimal = new BigDecimal(10000.67458239);
ComplexType type = new ComplexType("info", "another info", "yet another useless statement");

ensureFullGC();
System.err.println("STARTING LOGGER SIM");
for (int i = 0; i < NUMBER_OF_LOG_STMTS; i++)

{ Logger.log( FIRST_PART + someInt + "], bd = [" + decimal + "], complexType = [" + type + "]"); }

ensureFullGC();

Logger log = LoggerFactory.getLogger(LoggerTest.class);
ensureFullGC();
System.err.println("STARTING SLF4J SIM");
for (int i = 0; i < NUMBER_OF_LOG_STMTS; i++) {
log.info(WHOLE_STRING, new Object[]

{someInt, decimal, type}

);
}
ensureFullGC();

synchronized(LoggerTest.class) {
try

{ LoggerTest.class.wait(); }

catch (InterruptedException e)

{ e.printStackTrace(); }

}
}

private static void ensureFullGC() {
for (int i = 0; i < 4; i++)

{ System.gc(); }

}
}

What it does is just runs log statements 10000 times with both systems using rollover policies (of some kind). First one is the inhouse logger which is just a wrapper over printstream/messageformatter and the second one is logback via slf4j.

When i start this program with GC debug parameters, i've noticed that cycle with logback logger took 12 times more then for inhouse logger. Detailed perf analysis is in the image attached.