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

[Vadim Mironov (JIRA)]

    [ http://jira.qos.ch/browse/LBCORE-88?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11056#action_11056 ] 

Vadim Mironov commented on LBCORE-88:
-------------------------------------

Hmm, how then i can achieve log file names with current timestamp that are rolled every 2MB?

> 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