[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:all-tabpanel ]

Bela Ban updated JGRP-1693:
---------------------------

    Description: 
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 ?


  was:
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

1. Tracing disabled (org.jgroups.tests.bla5 = "warn"), 100000 iterations
============================================
- OLD :5.0 M statements/sec
- NEW: 2.7 M statements/sec

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 ?

2. Tracing enabled (org.jgroups.tests.bla5 = "trace"), 5000 iterations (prints to stdout)
=====================================================

- OLD: 11'000 statements / sec
- NEW:  7'200 statements / sec

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 ?



    
> 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