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
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
