[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=11052#action_11052 ] 

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

>From the screenshot you can see that for 10000 log statements there were 3321 invocations of Writer.close (though in reality there was only one file created) with corresponding 3321 invocations of FileOutputStream.open. Unless there is a real need to reopen the very same file for each third log statement, I'm inclined to think that this one is a big performance issue.

> 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