[ http://jira.qos.ch/browse/LBCORE-88?page=com.atlassian.jira.plugin.system.is... ] Vadim Mironov updated LBCORE-88: -------------------------------- Attachment: screenshot-1.jpg
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 Attachments: screenshot-1.jpg
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