[logback-dev] [JIRA] Created: (LBCORE-88) RollingFileAppender constantly reopens log file which leads to very poor performance

[Vadim Mironov (JIRA)]

RollingFileAppender constantly reopens log file which leads to very poor performance
------------------------------------------------------------------------------------

                 Key: LBCORE-88
                 URL: http://jira.qos.ch/browse/LBCORE-88
             Project: logback-core
          Issue Type: Bug
          Components: Appender
    Affects Versions: 0.9.15
         Environment: win-xp SP2, logback-0.9.15, sun java-1.6.0_12
            Reporter: Vadim Mironov
            Assignee: Logback dev list
            Priority: Critical


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. 

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira