[jboss-jira] [JBoss JIRA] (JGRP-1693) log4j2: performance impact

[Bela Ban (JIRA)]

    [ https://issues.jboss.org/browse/JGRP-1693?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12804103#comment-12804103 ] 

Bela Ban edited comment on JGRP-1693 at 9/13/13 5:21 AM:
---------------------------------------------------------

Looks like the array creation is the biggest slowdown with varargs. The short-term solution is to use a log.isTraceEnabled() before a log.trace() statement in time critical code. A medium-term solution would be to create methods
{code}
log.trace(String format, Object arg1);
log.trace(String format, Object arg1, Object arg2);
log.trace(String format, Object arg1, Object arg2, Object arg3);
log.trace(String format, Object arg1, Object arg3, Object arg3, Object arg4);
log.trace(String format, Object arg1, Object arg2, Object arg3, Object arg4, Object arg5);
{code}

Most trace() calls in JGroups have between 1 and 4 argument, so these calls above would cover perhaps 95% of all cases, and bypass the need for a vargarg call. However, the problem is that these calls also need to be provided by the underlying logging framework, e.g. log42.
                
      was (Author: belaban):
    Looks like the array creation is the biggest slowdown with varargs. The current solution/suggestion is to use a log.isTraceEnabled() before a log.trace() statement in time critical code. A medium term solution would be to create methods
{code}
log.trace(String format, Object arg1);
log.trace(String format, Object arg1, Object arg2);
log.trace(String format, Object arg1, Object arg2, Object arg3);
log.trace(String format, Object arg1, Object arg3, Object arg3, Object arg4);
log.trace(String format, Object arg1, Object arg2, Object arg3, Object arg4, Object arg5);
{code}

Most trace() calls in JGroups have between 1 and 4 argument, so these calls above would cover perhaps 95% of all cases, and bypass the need for a vargarg call. However, the problem is that these calls also need to be provided by the underlying logging framework, e.g. log42.
                  
> log4j2: performance impact
> --------------------------
>
>                 Key: JGRP-1693
>                 URL: https://issues.jboss.org/browse/JGRP-1693
>             Project: JGroups
>          Issue Type: Task
>            Reporter: Bela Ban
>            Assignee: Bela Ban
>             Fix For: 3.4
>
>         Attachments: bla5.java, log4j2.xml
>
>
> I'm seeing sub-par performance with the program below, and thought maybe some of the bright folks on this list could help...
> The issue I'm having is that the new logging format log.trace("some string %s", string) is much slower than the old one if(log.isTraceEnabled()) log.trace("some string " + string).
> This is the case both with TRACE logging enabled and disabled !
> The logger here is basically a pass-through to log4j2.
> The test can be started with
> java org.jgroups.tests.bla5 10000 true // use the new format
>     or
> java org.jgroups.tests.bla5 10000 false / use the old format
> h3. Tracing disabled (org.jgroups.tests.bla5 = "warn"), 100000 iterations
> - OLD :5.0 M statements/sec
> - NEW: 2.7 M statements/sec
> h4. Questions / observations:
> - If I uncomment the log.isTraceEnabled() in NEW, I get the same perf (5 M) as with OLD, makes sense
> - If I remove the varargs, I get the same perf, too
> - Q: is it the creation of the vararg array and the copying of the args into it which takes so much time ?
> h3. Tracing enabled (org.jgroups.tests.bla5 = "trace"), 5000 iterations (prints to stdout)
> - OLD: 11'000 statements / sec
> - NEW:  7'200 statements / sec
> h4. Questions/observations:
> - If I don't pass the varargs, e.g. log.trace("static string"), the perf in NEW is 12'000 !
> - Q: is the parsing of the format string taking that much time, such that it is *slower* than the conversion of i into a string and the string concatenation/copying in the OLD version ?
> Some discussion on the core dwelt on the merits of using OLD versus NEW, and my take-away was that NEW was as fast as OLD. Is this not te case ?

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira