[
https://issues.apache.org/jira/browse/LOG4J2-2157?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Malte Skoruppa updated LOG4J2-2157:
-----------------------------------
Description:
We recently added a
{{return traceExit(retvalue);}}
to a given method in our project, where before we simply had
{{return retvalue;}}
We then noticed that the running time of our software skyrocketed because of
this change (the given method that this traceExit call was added to is called
_very_ often). On a particular test case, the execution time grew from 3
minutes to 15 minutes.
The surprising thing: *This happened even when logging at TRACE level was
disabled.*
After profiling, we found out that traceExit(R) _always_ internally generates a
message, even when logging at TRACE level is disabled. This can become
extremely costly when traceExit(R) is called very often, and it doesn't make
any sense because these messages are not logged anyway.
+Technical explanation:+
Essentially, in org.apache.logging.log4j.spi.AbstractLogger, the method
traceExit(final R result) calls the method exit(final String fqcn, final String
format, final R result), which in turn makes the call logIfEnabled(fqcn,
Level.TRACE, EXIT_MARKER, exitMsg(format, result), null).
This means that exitMsg(format, result) is always called, even when logging on
TRACE level is disabled. Thus, a StringBuilder is invoked every time, which
constructs a String and then throws it away because logging is disabled anyway.
This implies that traceExit(R) can only be used for methods that are not called
very often. For methods that are called often, calling traceExit(R) cannot be
sensibly used because it utterly kills performance.
Could you fix this? It seems unnecessary to call exitMsg(final String format,
final Object result) when logging is disabled anyway.
was:
We recently added a
{{return traceExit(retvalue);}}
to a given method in our project, where before we simply had
{{return retvalue;}}
We then noticed that the running time of our software skyrocketed because of
this change (the given method that this traceExit call was added to is called
_very_ often). On a particular test case, the execution time grew from 3
minutes to 15 minutes.
The surprising thing: *This happened even when logging at TRACE level was
disabled.*
After profiling, we found out that traceExit(R) _always_ internally generates a
message, even when logging at TRACE level is disabled. This can become
extremely costly when traceExit(R) is called very often, and it doesn't make
any sense because these messages are not logged anyway.
+Technical explanation:+
Essentially, in org.apache.logging.log4j.spi.AbstractLogger, the method
traceExit(final R result) calls the method exit(final String fqcn, final String
format, final R result), which in turn makes the call logIfEnabled(fqcn,
Level.TRACE, EXIT_MARKER, exitMsg(format, result), null).
This means that exitMsg(format, result) is always called, even when logging on
TRACE level is disabled. Thus, a StringBuilder is invoked every time, which
constructs a String and then throws it away because logging is disabled anyway.
This implies that traceExit(R) can only be used for methods that are not called
very often. For methods that are called often, calling traceExit(R) cannot be
sensibly used.
Could you fix this? It seems unnecessary to call exitMsg(final String format,
final Object result) when logging is disabled anyway.
> Don't create exit message in traceExit(R) when logging is disabled
> ------------------------------------------------------------------
>
> Key: LOG4J2-2157
> URL: https://issues.apache.org/jira/browse/LOG4J2-2157
> Project: Log4j 2
> Issue Type: Improvement
> Affects Versions: 2.10.0
> Reporter: Malte Skoruppa
> Labels: performance
>
> We recently added a
>
> {{return traceExit(retvalue);}}
> to a given method in our project, where before we simply had
> {{return retvalue;}}
> We then noticed that the running time of our software skyrocketed because of
> this change (the given method that this traceExit call was added to is called
> _very_ often). On a particular test case, the execution time grew from 3
> minutes to 15 minutes.
> The surprising thing: *This happened even when logging at TRACE level was
> disabled.*
> After profiling, we found out that traceExit(R) _always_ internally generates
> a message, even when logging at TRACE level is disabled. This can become
> extremely costly when traceExit(R) is called very often, and it doesn't make
> any sense because these messages are not logged anyway.
> +Technical explanation:+
> Essentially, in org.apache.logging.log4j.spi.AbstractLogger, the method
> traceExit(final R result) calls the method exit(final String fqcn, final
> String format, final R result), which in turn makes the call
> logIfEnabled(fqcn, Level.TRACE, EXIT_MARKER, exitMsg(format, result), null).
> This means that exitMsg(format, result) is always called, even when logging
> on TRACE level is disabled. Thus, a StringBuilder is invoked every time,
> which constructs a String and then throws it away because logging is disabled
> anyway.
> This implies that traceExit(R) can only be used for methods that are not
> called very often. For methods that are called often, calling traceExit(R)
> cannot be sensibly used because it utterly kills performance.
> Could you fix this? It seems unnecessary to call exitMsg(final String format,
> final Object result) when logging is disabled anyway.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
