You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by ml...@mherrn.de on 2019/06/25 06:52:13 UTC
Logging with location information considerably slower than JUL
Hi,
according to https://logging.apache.org/log4j/2.x/performance.html logging
with location information should be roughly the same performance for JUL
and Log4j2.
However I made a few comparisons between Log4j2 and JUL and in this case
Log4j2 is much faster than JUL when omitting location information, but is
considerably slower when logging with location information.
Those are the results:
JUL without location information : 32.162s
JUL with location information : 21.682s
Log4j2 without location information: 4.168s
Log4j2 with location information : 59.000s
In each case I logged 1500000 simple log statements (only a fixed string)
and compared the timestamp of the first and the last generated log
statement. Above you see the time spent between the first and the last log
statement.
I did these tests several times and the results are equal each time.
In all cases I logged to a RollingFileAppender (or JULs equivalent).
I assume that JUL with location information is faster than JUL without
location information is because for JUL with location information I used a
custom Formatter that doesn't support any configuration whereas I was
using a SimpleFormatter with a specified formatstring for JUL without log
information.
It should be noted that I didn't use the Log4j2 API, but instead used the
JUL logging API and used the log4j-jul-bridge to actually use Log4j2
instead of the JUL implementation!
I want to pay special attention to the difference when logging with
location information, since I am puzzled that Log4j2 is that much slower
than JUL in that case.
The implementation of my custom Formatter is this:
public class OneLineFormatter extends Formatter {
private static final String LINE_SEPARATOR =
System.getProperty("line.separator");
private static final DateFormat DATE_FORMAT= new
SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSSS");
@Override
public String format(final LogRecord record) {
final StringBuilder sb = new StringBuilder();
final String dateString= DATE_FORMAT.format(new
Date(record.getMillis()));
sb.append(dateString)
.append(" ")
.append(getLogLevelString(record.getLevel()))
.append(" [")
.append(record.getSourceClassName())
.append("#")
.append(record.getSourceMethodName()).append("()")
.append("]")
.append(" - ")
.append(formatMessage(record))
.append(LINE_SEPARATOR);
if (record.getThrown() != null) {
try {
StringWriter sw = new StringWriter();
PrintWriter pw = new PrintWriter(sw);
record.getThrown().printStackTrace(pw);
pw.close();
sb.append(sw.toString());
} catch (Exception ex) {
// ignore
}
}
return sb.toString();
}
private String getLogLevelString(final Level level){
return String.format("%1$-7s", level.getName());
}
}
The log4j2 configuration I used is this:
<Configuration monitorinterval="30" status="info" strict="true">
<Properties>
<Property name="filename">logs/log4j2-with-method.log</Property>
<Property
name="filepattern">logs/log4j2-with-method.log.%i.gz</Property>
</Properties>
<Appenders>
<Appender type="RollingFile" name="File" fileName="${filename}"
filePattern="${filepattern}" bufferedIO="true">
<Policies>
<OnStartupTriggeringPolicy />
<SizeBasedTriggeringPolicy size="100mb"/>
</Policies>
<DefaultRolloverStrategy max="15" fileIndex="min" />
<Layout type="PatternLayout" pattern="%d %-6p [%C#%M] (%t) %m
%ex%n" />
</Appender>
</Appenders>
<Loggers>
<Root level="INFO">
<AppenderRef ref="File" />
</Root>
<Logger name="LPT_SIMPLE" level="ALL" />
</Loggers>
</Configuration>
I don't think there is anything special. Since when logging without
location information Log4j2 is much faster than JUL there must be a
difference between getting the location information. My above mentioned
custom formatter uses the methods java.util.LogRecord#getSourceClassName()
and java.util.LogRecord#getSourceMethodName() for obtaining that
information. I haven't looked into how Log4j2 does it, but it seems to be
much less efficient.
Can someone explain why Log4j2 is that much slower in that case?
Is there another way in Log4j2 to get the location information that
performs as fast as JUL?
Best regards
Marco
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging with location information considerably slower than JUL
Posted by Marco Herrn <ml...@mherrn.de>.
Hello Ralph,
I have done my tests with Java 8, but it seems that there is not different
behaviour when using Java 11.
I have created a JIRA ticket: https://issues.apache.org/jira/browse/LOG4J2-2644
My test code can be found at: https://github.com/hupfdule/LoggingPerformanceTest
Best regards
Marco
On Tue, Jun 25, 2019 at 09:41:38PM -0700, Ralph Goers wrote:
> Thanks for this info. I will take a look at your tests in the next few days. What version of Java were you running with? The method of getting the stack trace info changed for both JUL and Log4j in JDK 9.
>
> Ralph
>
> > On Jun 24, 2019, at 11:52 PM, ml@mherrn.de wrote:
> >
> > Hi,
> >
> > according to https://logging.apache.org/log4j/2.x/performance.html logging
> > with location information should be roughly the same performance for JUL
> > and Log4j2.
> >
> > However I made a few comparisons between Log4j2 and JUL and in this case
> > Log4j2 is much faster than JUL when omitting location information, but is
> > considerably slower when logging with location information.
> >
> > Those are the results:
> >
> > JUL without location information : 32.162s
> > JUL with location information : 21.682s
> > Log4j2 without location information: 4.168s
> > Log4j2 with location information : 59.000s
> >
> > In each case I logged 1500000 simple log statements (only a fixed string)
> > and compared the timestamp of the first and the last generated log
> > statement. Above you see the time spent between the first and the last log
> > statement.
> > I did these tests several times and the results are equal each time.
> >
> > In all cases I logged to a RollingFileAppender (or JULs equivalent).
> > I assume that JUL with location information is faster than JUL without
> > location information is because for JUL with location information I used a
> > custom Formatter that doesn't support any configuration whereas I was
> > using a SimpleFormatter with a specified formatstring for JUL without log
> > information.
> >
> > It should be noted that I didn't use the Log4j2 API, but instead used the
> > JUL logging API and used the log4j-jul-bridge to actually use Log4j2
> > instead of the JUL implementation!
> >
> > I want to pay special attention to the difference when logging with
> > location information, since I am puzzled that Log4j2 is that much slower
> > than JUL in that case.
> >
> > The implementation of my custom Formatter is this:
> >
> > public class OneLineFormatter extends Formatter {
> > private static final String LINE_SEPARATOR =
> > System.getProperty("line.separator");
> > private static final DateFormat DATE_FORMAT= new
> > SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSSS");
> >
> >
> > @Override
> > public String format(final LogRecord record) {
> > final StringBuilder sb = new StringBuilder();
> >
> > final String dateString= DATE_FORMAT.format(new
> > Date(record.getMillis()));
> >
> > sb.append(dateString)
> > .append(" ")
> > .append(getLogLevelString(record.getLevel()))
> > .append(" [")
> > .append(record.getSourceClassName())
> > .append("#")
> > .append(record.getSourceMethodName()).append("()")
> > .append("]")
> > .append(" - ")
> > .append(formatMessage(record))
> > .append(LINE_SEPARATOR);
> >
> > if (record.getThrown() != null) {
> > try {
> > StringWriter sw = new StringWriter();
> > PrintWriter pw = new PrintWriter(sw);
> > record.getThrown().printStackTrace(pw);
> > pw.close();
> > sb.append(sw.toString());
> > } catch (Exception ex) {
> > // ignore
> > }
> > }
> >
> > return sb.toString();
> > }
> >
> > private String getLogLevelString(final Level level){
> > return String.format("%1$-7s", level.getName());
> > }
> > }
> >
> > The log4j2 configuration I used is this:
> >
> > <Configuration monitorinterval="30" status="info" strict="true">
> > <Properties>
> > <Property name="filename">logs/log4j2-with-method.log</Property>
> > <Property
> > name="filepattern">logs/log4j2-with-method.log.%i.gz</Property>
> > </Properties>
> > <Appenders>
> > <Appender type="RollingFile" name="File" fileName="${filename}"
> > filePattern="${filepattern}" bufferedIO="true">
> > <Policies>
> > <OnStartupTriggeringPolicy />
> > <SizeBasedTriggeringPolicy size="100mb"/>
> > </Policies>
> > <DefaultRolloverStrategy max="15" fileIndex="min" />
> > <Layout type="PatternLayout" pattern="%d %-6p [%C#%M] (%t) %m
> > %ex%n" />
> > </Appender>
> > </Appenders>
> > <Loggers>
> > <Root level="INFO">
> > <AppenderRef ref="File" />
> > </Root>
> > <Logger name="LPT_SIMPLE" level="ALL" />
> > </Loggers>
> > </Configuration>
> >
> >
> > I don't think there is anything special. Since when logging without
> > location information Log4j2 is much faster than JUL there must be a
> > difference between getting the location information. My above mentioned
> > custom formatter uses the methods java.util.LogRecord#getSourceClassName()
> > and java.util.LogRecord#getSourceMethodName() for obtaining that
> > information. I haven't looked into how Log4j2 does it, but it seems to be
> > much less efficient.
> >
> > Can someone explain why Log4j2 is that much slower in that case?
> > Is there another way in Log4j2 to get the location information that
> > performs as fast as JUL?
> >
> >
> > Best regards
> > Marco
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
> >
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging with location information considerably slower than JUL
Posted by Ralph Goers <ra...@dslextreme.com>.
Thanks for this info. I will take a look at your tests in the next few days. What version of Java were you running with? The method of getting the stack trace info changed for both JUL and Log4j in JDK 9.
Ralph
> On Jun 24, 2019, at 11:52 PM, ml@mherrn.de wrote:
>
> Hi,
>
> according to https://logging.apache.org/log4j/2.x/performance.html logging
> with location information should be roughly the same performance for JUL
> and Log4j2.
>
> However I made a few comparisons between Log4j2 and JUL and in this case
> Log4j2 is much faster than JUL when omitting location information, but is
> considerably slower when logging with location information.
>
> Those are the results:
>
> JUL without location information : 32.162s
> JUL with location information : 21.682s
> Log4j2 without location information: 4.168s
> Log4j2 with location information : 59.000s
>
> In each case I logged 1500000 simple log statements (only a fixed string)
> and compared the timestamp of the first and the last generated log
> statement. Above you see the time spent between the first and the last log
> statement.
> I did these tests several times and the results are equal each time.
>
> In all cases I logged to a RollingFileAppender (or JULs equivalent).
> I assume that JUL with location information is faster than JUL without
> location information is because for JUL with location information I used a
> custom Formatter that doesn't support any configuration whereas I was
> using a SimpleFormatter with a specified formatstring for JUL without log
> information.
>
> It should be noted that I didn't use the Log4j2 API, but instead used the
> JUL logging API and used the log4j-jul-bridge to actually use Log4j2
> instead of the JUL implementation!
>
> I want to pay special attention to the difference when logging with
> location information, since I am puzzled that Log4j2 is that much slower
> than JUL in that case.
>
> The implementation of my custom Formatter is this:
>
> public class OneLineFormatter extends Formatter {
> private static final String LINE_SEPARATOR =
> System.getProperty("line.separator");
> private static final DateFormat DATE_FORMAT= new
> SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSSS");
>
>
> @Override
> public String format(final LogRecord record) {
> final StringBuilder sb = new StringBuilder();
>
> final String dateString= DATE_FORMAT.format(new
> Date(record.getMillis()));
>
> sb.append(dateString)
> .append(" ")
> .append(getLogLevelString(record.getLevel()))
> .append(" [")
> .append(record.getSourceClassName())
> .append("#")
> .append(record.getSourceMethodName()).append("()")
> .append("]")
> .append(" - ")
> .append(formatMessage(record))
> .append(LINE_SEPARATOR);
>
> if (record.getThrown() != null) {
> try {
> StringWriter sw = new StringWriter();
> PrintWriter pw = new PrintWriter(sw);
> record.getThrown().printStackTrace(pw);
> pw.close();
> sb.append(sw.toString());
> } catch (Exception ex) {
> // ignore
> }
> }
>
> return sb.toString();
> }
>
> private String getLogLevelString(final Level level){
> return String.format("%1$-7s", level.getName());
> }
> }
>
> The log4j2 configuration I used is this:
>
> <Configuration monitorinterval="30" status="info" strict="true">
> <Properties>
> <Property name="filename">logs/log4j2-with-method.log</Property>
> <Property
> name="filepattern">logs/log4j2-with-method.log.%i.gz</Property>
> </Properties>
> <Appenders>
> <Appender type="RollingFile" name="File" fileName="${filename}"
> filePattern="${filepattern}" bufferedIO="true">
> <Policies>
> <OnStartupTriggeringPolicy />
> <SizeBasedTriggeringPolicy size="100mb"/>
> </Policies>
> <DefaultRolloverStrategy max="15" fileIndex="min" />
> <Layout type="PatternLayout" pattern="%d %-6p [%C#%M] (%t) %m
> %ex%n" />
> </Appender>
> </Appenders>
> <Loggers>
> <Root level="INFO">
> <AppenderRef ref="File" />
> </Root>
> <Logger name="LPT_SIMPLE" level="ALL" />
> </Loggers>
> </Configuration>
>
>
> I don't think there is anything special. Since when logging without
> location information Log4j2 is much faster than JUL there must be a
> difference between getting the location information. My above mentioned
> custom formatter uses the methods java.util.LogRecord#getSourceClassName()
> and java.util.LogRecord#getSourceMethodName() for obtaining that
> information. I haven't looked into how Log4j2 does it, but it seems to be
> much less efficient.
>
> Can someone explain why Log4j2 is that much slower in that case?
> Is there another way in Log4j2 to get the location information that
> performs as fast as JUL?
>
>
> Best regards
> Marco
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging with location information considerably slower than JUL
Posted by Ralph Goers <ra...@dslextreme.com>.
Would it be possible for you to create a Jira issue and attach your sample project so I don’t have to reinvent the wheel? Or you could check it in to GitHub so I could clone it.
Ralph
> On Jun 24, 2019, at 11:52 PM, ml@mherrn.de wrote:
>
> Hi,
>
> according to https://logging.apache.org/log4j/2.x/performance.html logging
> with location information should be roughly the same performance for JUL
> and Log4j2.
>
> However I made a few comparisons between Log4j2 and JUL and in this case
> Log4j2 is much faster than JUL when omitting location information, but is
> considerably slower when logging with location information.
>
> Those are the results:
>
> JUL without location information : 32.162s
> JUL with location information : 21.682s
> Log4j2 without location information: 4.168s
> Log4j2 with location information : 59.000s
>
> In each case I logged 1500000 simple log statements (only a fixed string)
> and compared the timestamp of the first and the last generated log
> statement. Above you see the time spent between the first and the last log
> statement.
> I did these tests several times and the results are equal each time.
>
> In all cases I logged to a RollingFileAppender (or JULs equivalent).
> I assume that JUL with location information is faster than JUL without
> location information is because for JUL with location information I used a
> custom Formatter that doesn't support any configuration whereas I was
> using a SimpleFormatter with a specified formatstring for JUL without log
> information.
>
> It should be noted that I didn't use the Log4j2 API, but instead used the
> JUL logging API and used the log4j-jul-bridge to actually use Log4j2
> instead of the JUL implementation!
>
> I want to pay special attention to the difference when logging with
> location information, since I am puzzled that Log4j2 is that much slower
> than JUL in that case.
>
> The implementation of my custom Formatter is this:
>
> public class OneLineFormatter extends Formatter {
> private static final String LINE_SEPARATOR =
> System.getProperty("line.separator");
> private static final DateFormat DATE_FORMAT= new
> SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSSS");
>
>
> @Override
> public String format(final LogRecord record) {
> final StringBuilder sb = new StringBuilder();
>
> final String dateString= DATE_FORMAT.format(new
> Date(record.getMillis()));
>
> sb.append(dateString)
> .append(" ")
> .append(getLogLevelString(record.getLevel()))
> .append(" [")
> .append(record.getSourceClassName())
> .append("#")
> .append(record.getSourceMethodName()).append("()")
> .append("]")
> .append(" - ")
> .append(formatMessage(record))
> .append(LINE_SEPARATOR);
>
> if (record.getThrown() != null) {
> try {
> StringWriter sw = new StringWriter();
> PrintWriter pw = new PrintWriter(sw);
> record.getThrown().printStackTrace(pw);
> pw.close();
> sb.append(sw.toString());
> } catch (Exception ex) {
> // ignore
> }
> }
>
> return sb.toString();
> }
>
> private String getLogLevelString(final Level level){
> return String.format("%1$-7s", level.getName());
> }
> }
>
> The log4j2 configuration I used is this:
>
> <Configuration monitorinterval="30" status="info" strict="true">
> <Properties>
> <Property name="filename">logs/log4j2-with-method.log</Property>
> <Property
> name="filepattern">logs/log4j2-with-method.log.%i.gz</Property>
> </Properties>
> <Appenders>
> <Appender type="RollingFile" name="File" fileName="${filename}"
> filePattern="${filepattern}" bufferedIO="true">
> <Policies>
> <OnStartupTriggeringPolicy />
> <SizeBasedTriggeringPolicy size="100mb"/>
> </Policies>
> <DefaultRolloverStrategy max="15" fileIndex="min" />
> <Layout type="PatternLayout" pattern="%d %-6p [%C#%M] (%t) %m
> %ex%n" />
> </Appender>
> </Appenders>
> <Loggers>
> <Root level="INFO">
> <AppenderRef ref="File" />
> </Root>
> <Logger name="LPT_SIMPLE" level="ALL" />
> </Loggers>
> </Configuration>
>
>
> I don't think there is anything special. Since when logging without
> location information Log4j2 is much faster than JUL there must be a
> difference between getting the location information. My above mentioned
> custom formatter uses the methods java.util.LogRecord#getSourceClassName()
> and java.util.LogRecord#getSourceMethodName() for obtaining that
> information. I haven't looked into how Log4j2 does it, but it seems to be
> much less efficient.
>
> Can someone explain why Log4j2 is that much slower in that case?
> Is there another way in Log4j2 to get the location information that
> performs as fast as JUL?
>
>
> Best regards
> Marco
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org