Re: Bizarre performance in log4j2

[Remko Popma]

ot;,
>> Level.INFO, "com.TestMain", "true", arefs, null, config, null);
>> 
>>loggerConfig.addAppender(consoleAppender, Level.INFO, null);
>> 
>>config.addLogger("com.TestMain", loggerConfig);
>> 
>>Logger LOG = ctx.getLogger("com.TestMain");
>> 
>> }
>> 
>> *Log4j2.xml:*
>> 
>> 
>> 
>> 
>> 
>>
>> 
>>
>> 
>>
>> 
>>
>> 
>>
>> 
>>
>> 
>>
>> 
>>
>> 
>>
>> 
>>
>> 
>> 
>> 
>> 
>> I will call the appender in function_A as appender_API, and call the
>> appender from log4j2.xml as appender_XML.
>> 
>> Through my tests to print log using logger, named LOG, from function_A. I
>> found these phenomenons:
>> 
>> 1) just use the function_A and log4j2.xml above
>> 
>>logs will be printed by appender_API
>> 
>> 2) add > ref="Console"/> in tag  of log4j2.xml
>> 
>>logs will be printed by appender_XML twice although I have set
>> additivity="false" when I create logger in function_A
>> 
>> 3) add > additivity="false"> in tag 
>> of log4j2.xml
>> 
>>logs will be printed by appender_XML once
>> 
>> 
>> How can I explain these? All I can think is that the configuration of
>> logger from log4j2.xml covers the configuration from function_A. But
>> I'm little confusion about the load sequence between different loggers.
>> 
>> 
>> Besides, the configuration of logger named "com.TestMain" has location
>> information and it sets includeLocation="true".
>> 
>> To test async logger in log4j2, I just change  to 
>> comparing the 's configs of log4j2.xml from above and it turns out
>> a even worse performance in my early tests. Will the combination below
>> influence the performance if these two loggers print logs in the same file?
>> 
>> 1) sync logger, async appender and includeLocation="true" to print logs
>> from function_A
>> 
>> 2) asyncRoot, sync appender and includeLocation="false" to print other logs
>> 
>> Will it be difference if they print logs in two separate files?
>> 
>> 
>> Thank you very much.
>> 
>> Best regards,
>> 
>> Dylan Su
>> 
>> 
>> 
>> 
>> 
>>> On Fri, Oct 16, 2015 at 7:21 PM, Strong Su <lovelo...@gmail.com> wrote:
>>> 
>>> Hello everyone,
>>> 
>>> It takes me sometime to make sure that I have removed all log4j-1.2.16
>>> and slf4j-log4j12.
>>> It became better but not good enough.
>>> Since sync log4j2 has already performed much better than log4j1, we
>>> decided to use sync log4j2 first.
>>> And I will start a fresh test over async log4j2 from beginning to
>>> checkout where the problem is.
>>> 
>>> I will update this thread or link this problem to a new thread when the
>>> performance becomes normal.
>>> 
>>> Thank you very much for the advices during these days.
>>> 
>>> Best regards,
>>> Dylan Su
>>> 
>>>> On Wed, Oct 14, 2015 at 4:58 PM, Strong Su <lovelo...@gmail.com> wrote:
>>>> 
>>>> 
>>>> -- Forwarded message --
>>>> From: Gary Gregory <garydgreg...@gmail.com>
>>>> Date: Tue, Oct 13, 2015 at 9:58 PM
>>>> Subject: Re: Bizarre performance in log4j2
>>>> To: Log4J Users List <log4j-user@logging.apache.org>
>>>> 
>>>> 
>>>> You can check with:
>>>> 
>>>> mvn dependency:tree
>>>> 
>>>> Gary
>>>> 
>>>> On Tue, Oct 13, 2015 at 1:24 AM, Mikael Ståldal <
>>>> mikael.stal...@magine.com>
>>>> wrote:
>>>> 
>>>>> ...and make sure that no 3rd party dependencies brings them in.
>>>>> 
>>>>> On Tue, Oct 13, 2015 at 8:22 AM, Remko Popma <remko.po...@gmail.com>
>>>>> wrote:
>>>>> 
>>>>>> Please remove log4j-1.2.16 and replace it with log4j-1.2-api version
>>>> 2.3.
>>>>>> 
>>>>>> Also remove slf4j-log4j12 and add log4j-slf4j-impl version 2.3.
>>>>>> 
>>>>>> Sent from my iPhone
>>>>>> 
>>>>

Re: Bizarre performance in log4j2

[Strong Su]

nder_API
>
> 2) add  ref="Console"/> in tag  of log4j2.xml
>
> logs will be printed by appender_XML twice although I have set
> additivity="false" when I create logger in function_A
>
> 3) add  additivity="false"> in tag 
> of log4j2.xml
>
> logs will be printed by appender_XML once
>
>
> How can I explain these? All I can think is that the configuration of
> logger from log4j2.xml covers the configuration from function_A. But
> I'm little confusion about the load sequence between different loggers.
>
>
> Besides, the configuration of logger named "com.TestMain" has location
> information and it sets includeLocation="true".
>
> To test async logger in log4j2, I just change  to 
> comparing the 's configs of log4j2.xml from above and it turns out
> a even worse performance in my early tests. Will the combination below
> influence the performance if these two loggers print logs in the same file?
>
> 1) sync logger, async appender and includeLocation="true" to print logs
> from function_A
>
> 2) asyncRoot, sync appender and includeLocation="false" to print other logs
>
> Will it be difference if they print logs in two separate files?
>
>
> Thank you very much.
>
> Best regards,
>
> Dylan Su
>
>
>
>
>
> On Fri, Oct 16, 2015 at 7:21 PM, Strong Su <lovelo...@gmail.com> wrote:
>
>> Hello everyone,
>>
>> It takes me sometime to make sure that I have removed all log4j-1.2.16
>> and slf4j-log4j12.
>> It became better but not good enough.
>> Since sync log4j2 has already performed much better than log4j1, we
>> decided to use sync log4j2 first.
>> And I will start a fresh test over async log4j2 from beginning to
>> checkout where the problem is.
>>
>> I will update this thread or link this problem to a new thread when the
>> performance becomes normal.
>>
>> Thank you very much for the advices during these days.
>>
>> Best regards,
>> Dylan Su
>>
>> On Wed, Oct 14, 2015 at 4:58 PM, Strong Su <lovelo...@gmail.com> wrote:
>>
>>>
>>> -- Forwarded message --
>>> From: Gary Gregory <garydgreg...@gmail.com>
>>> Date: Tue, Oct 13, 2015 at 9:58 PM
>>> Subject: Re: Bizarre performance in log4j2
>>> To: Log4J Users List <log4j-user@logging.apache.org>
>>>
>>>
>>> You can check with:
>>>
>>> mvn dependency:tree
>>>
>>> Gary
>>>
>>> On Tue, Oct 13, 2015 at 1:24 AM, Mikael Ståldal <
>>> mikael.stal...@magine.com>
>>> wrote:
>>>
>>> > ...and make sure that no 3rd party dependencies brings them in.
>>> >
>>> > On Tue, Oct 13, 2015 at 8:22 AM, Remko Popma <remko.po...@gmail.com>
>>> > wrote:
>>> >
>>> > > Please remove log4j-1.2.16 and replace it with log4j-1.2-api version
>>> 2.3.
>>> > >
>>> > > Also remove slf4j-log4j12 and add log4j-slf4j-impl version 2.3.
>>> > >
>>> > > Sent from my iPhone
>>> > >
>>> > > > On 2015/10/13, at 14:39, Strong Su <lovelo...@gmail.com> wrote:
>>> > > >
>>> > > > Here is my pom.xml for logging:
>>> > > >
>>> > > > 
>>> > > >log4j
>>> > > >log4j
>>> > > >1.2.16
>>> > > > 
>>> > > > 
>>> > > >org.slf4j
>>> > > >slf4j-log4j12
>>> > > >1.5.11
>>> > > > 
>>> > > > 
>>> > > >org.slf4j
>>> > > >slf4j-api
>>> > > >1.5.11
>>> > > > 
>>> > > > 
>>> > > >org.apache.logging.log4j
>>> > > >log4j-api
>>> > > >2.3
>>> > > > 
>>> > > > 
>>> > > >org.apache.logging.log4j
>>> > > >log4j-core
>>> > > >2.3
>>> > > > 
>>> > > > 
>>> > > >org.apache.logging.log4j
>>> > > >log4j-web
>>> > > >2.3
>>> > > > 
>>> > > > 
>>> > > >com.lmax
>>> > > >disruptor
>>> > > >3.2.0
>>> > > > 
>>> > > >
>>> > > >
>>>

Re: Bizarre performance in log4j2

[Strong Su]

Hello everyone,
I take a deep look at our project and found one of our third dependencies
was using log4j2. It is using APIs of log4j2 instead of configuration files
but it can recognise and use my log4j2.xml.
I wrote a simple example to illustrate how log4j2 be added in the third
dependency.

*Function_A:*

public void function_A(){

LoggerContext ctx = (LoggerContext) LogManager.getContext(false);

Configuration config = ctx.getConfiguration();

Layout layout = PatternLayout.createLayout(

"%d{-MM-dd HH:mm:ss} [%t] %-5level %class{36} %L %M -
%msg%xEx%n", config, null, null, true, false, null, null);


ConsoleAppender consoleAppender = ConsoleAppender.createAppender(
layout, null, "SYSTEM_OUT", "consoleAppender", "false", "false");

AppenderRef consoleRef = AppenderRef.createAppenderRef(
"consoleAppender", Level.INFO, null);

AppenderRef[] crefs = new AppenderRef[] { consoleRef };

consoleAppender.start();

config.addAppender(consoleAppender);



AsyncAppender asyncAppender = AsyncAppender.createAppender(crefs,
null,

true, 128, "asyncAppender", false, null, config, false);

AppenderRef accessRef = AppenderRef.createAppenderRef(
"asyncAppender", Level.INFO, null);

AppenderRef[] arefs = new AppenderRef[] { accessRef };

asyncAppender.start();

config.addAppender(asyncAppender);


LoggerConfig loggerConfig = LoggerConfig.createLogger("false",
Level.INFO, "com.TestMain", "true", arefs, null, config, null);

loggerConfig.addAppender(consoleAppender, Level.INFO, null);

config.addLogger("com.TestMain", loggerConfig);

Logger LOG = ctx.getLogger("com.TestMain");

}

*Log4j2.xml:*




























I will call the appender in function_A as appender_API, and call the
appender from log4j2.xml as appender_XML.

Through my tests to print log using logger, named LOG, from function_A. I
found these phenomenons:

1) just use the function_A and log4j2.xml above

logs will be printed by appender_API

2) add  in tag  of log4j2.xml

logs will be printed by appender_XML twice although I have set
additivity="false" when I create logger in function_A

3) add  in tag 
of log4j2.xml

logs will be printed by appender_XML once


How can I explain these? All I can think is that the configuration of
logger from log4j2.xml covers the configuration from function_A. But
I'm little confusion about the load sequence between different loggers.


Besides, the configuration of logger named "com.TestMain" has location
information and it sets includeLocation="true".

To test async logger in log4j2, I just change  to 
comparing the 's configs of log4j2.xml from above and it turns out
a even worse performance in my early tests. Will the combination below
influence the performance if these two loggers print logs in the same file?

1) sync logger, async appender and includeLocation="true" to print logs
from function_A

2) asyncRoot, sync appender and includeLocation="false" to print other logs

Will it be difference if they print logs in two separate files?


Thank you very much.

Best regards,

Dylan Su





On Fri, Oct 16, 2015 at 7:21 PM, Strong Su <lovelo...@gmail.com> wrote:

> Hello everyone,
>
> It takes me sometime to make sure that I have removed all log4j-1.2.16 and
> slf4j-log4j12.
> It became better but not good enough.
> Since sync log4j2 has already performed much better than log4j1, we
> decided to use sync log4j2 first.
> And I will start a fresh test over async log4j2 from beginning to
> checkout where the problem is.
>
> I will update this thread or link this problem to a new thread when the
> performance becomes normal.
>
> Thank you very much for the advices during these days.
>
> Best regards,
> Dylan Su
>
> On Wed, Oct 14, 2015 at 4:58 PM, Strong Su <lovelo...@gmail.com> wrote:
>
>>
>> -- Forwarded message --
>> From: Gary Gregory <garydgreg...@gmail.com>
>> Date: Tue, Oct 13, 2015 at 9:58 PM
>> Subject: Re: Bizarre performance in log4j2
>> To: Log4J Users List <log4j-user@logging.apache.org>
>>
>>
>> You can check with:
>>
>> mvn dependency:tree
>>
>> Gary
>>
>> On Tue, Oct 13, 2015 at 1:24 AM, Mikael Ståldal <
>> mikael.stal...@magine.com>
>> wrote:
>>
>> > ...and make sure that no 3rd party dependencies brings them in.
>> >
>> > On Tue, Oct 13, 2015 at 8:22 AM, Remko Popma <remko.po...@gmail.com>
>&

Re: Bizarre performance in log4j2

[Strong Su]

Hello everyone,

It takes me sometime to make sure that I have removed all log4j-1.2.16 and
slf4j-log4j12.
It became better but not good enough.
Since sync log4j2 has already performed much better than log4j1, we decided
to use sync log4j2 first.
And I will start a fresh test over async log4j2 from beginning to checkout
where the problem is.

I will update this thread or link this problem to a new thread when the
performance becomes normal.

Thank you very much for the advices during these days.

Best regards,
Dylan Su

On Wed, Oct 14, 2015 at 4:58 PM, Strong Su <lovelo...@gmail.com> wrote:

>
> -- Forwarded message --
> From: Gary Gregory <garydgreg...@gmail.com>
> Date: Tue, Oct 13, 2015 at 9:58 PM
> Subject: Re: Bizarre performance in log4j2
> To: Log4J Users List <log4j-user@logging.apache.org>
>
>
> You can check with:
>
> mvn dependency:tree
>
> Gary
>
> On Tue, Oct 13, 2015 at 1:24 AM, Mikael Ståldal <mikael.stal...@magine.com
> >
> wrote:
>
> > ...and make sure that no 3rd party dependencies brings them in.
> >
> > On Tue, Oct 13, 2015 at 8:22 AM, Remko Popma <remko.po...@gmail.com>
> > wrote:
> >
> > > Please remove log4j-1.2.16 and replace it with log4j-1.2-api version
> 2.3.
> > >
> > > Also remove slf4j-log4j12 and add log4j-slf4j-impl version 2.3.
> > >
> > > Sent from my iPhone
> > >
> > > > On 2015/10/13, at 14:39, Strong Su <lovelo...@gmail.com> wrote:
> > > >
> > > > Here is my pom.xml for logging:
> > > >
> > > > 
> > > >log4j
> > > >log4j
> > > >1.2.16
> > > > 
> > > > 
> > > >org.slf4j
> > > >slf4j-log4j12
> > > >1.5.11
> > > > 
> > > > 
> > > >org.slf4j
> > > >slf4j-api
> > > >1.5.11
> > > > 
> > > > 
> > > >org.apache.logging.log4j
> > > >log4j-api
> > > >2.3
> > > > 
> > > > 
> > > >org.apache.logging.log4j
> > > >log4j-core
> > > >2.3
> > > > 
> > > > 
> > > >org.apache.logging.log4j
> > > >log4j-web
> > > >2.3
> > > > 
> > > > 
> > > >com.lmax
> > > >disruptor
> > > >3.2.0
> > > > 
> > > >
> > > >
> > > >> On Tue, Oct 13, 2015 at 12:22 PM, Remko Popma <
> remko.po...@gmail.com>
> > > wrote:
> > > >>
> > > >> For log4j1, are you using the log4j-1.2-api-2.x.jar? And similarly
> the
> > > >> log4j-slf4j-impl-2.x.jar for SLF4J? (Just checking...)
> > > >>
> > > >> Sent from my iPhone
> > > >>
> > > >>> On 2015/10/13, at 11:43, Gary Gregory <garydgreg...@gmail.com>
> > wrote:
> > > >>>
> > > >>> Can you use 2.4?
> > > >>>
> > > >>> Gary
> > > >>>
> > > >>>> On Mon, Oct 12, 2015 at 6:56 PM, Strong Su <lovelo...@gmail.com>
> > > wrote:
> > > >>>>
> > > >>>> I'm using Log4j 2.3 and Disruptor 3.2.
> > > >>>> Because of third party package like spring, I have to use Log4j
> 1.2
> > > and
> > > >>>> slf4j 1.5 too.
> > > >>>>
> > > >>>>
> > > >>>> On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma <
> remko.po...@gmail.com
> > >
> > > >>>> wrote:
> > > >>>>
> > > >>>>> Output looks ok.
> > > >>>>> Sleep was the default wait strategy but has been changed to
> Block a
> > > >> long
> > > >>>>> time ago. Looks like the docs are out of date. Thanks for drawing
> > my
> > > >>>>> attention to this.
> > > >>>>>
> > > >>>>> I don't understand why changing the includeLocation does not
> make a
> > > >>>>> difference in performance. You should see a large improvement.
> > > >>>>> Which Log4j version are you using?
> > > >>>>>
> > > >>>>>
> > > >>>>>
> > > >>>>>> On Mon, Oct 12, 2015 at 12:58 PM, Strong Su <
> lovelo...@gmail.com>

Re: Bizarre performance in log4j2

[Mikael Ståldal]

...and make sure that no 3rd party dependencies brings them in.

On Tue, Oct 13, 2015 at 8:22 AM, Remko Popma  wrote:

> Please remove log4j-1.2.16 and replace it with log4j-1.2-api version 2.3.
>
> Also remove slf4j-log4j12 and add log4j-slf4j-impl version 2.3.
>
> Sent from my iPhone
>
> > On 2015/10/13, at 14:39, Strong Su  wrote:
> >
> > Here is my pom.xml for logging:
> >
> > 
> >log4j
> >log4j
> >1.2.16
> > 
> > 
> >org.slf4j
> >slf4j-log4j12
> >1.5.11
> > 
> > 
> >org.slf4j
> >slf4j-api
> >1.5.11
> > 
> > 
> >org.apache.logging.log4j
> >log4j-api
> >2.3
> > 
> > 
> >org.apache.logging.log4j
> >log4j-core
> >2.3
> > 
> > 
> >org.apache.logging.log4j
> >log4j-web
> >2.3
> > 
> > 
> >com.lmax
> >disruptor
> >3.2.0
> > 
> >
> >
> >> On Tue, Oct 13, 2015 at 12:22 PM, Remko Popma 
> wrote:
> >>
> >> For log4j1, are you using the log4j-1.2-api-2.x.jar? And similarly the
> >> log4j-slf4j-impl-2.x.jar for SLF4J? (Just checking...)
> >>
> >> Sent from my iPhone
> >>
> >>> On 2015/10/13, at 11:43, Gary Gregory  wrote:
> >>>
> >>> Can you use 2.4?
> >>>
> >>> Gary
> >>>
>  On Mon, Oct 12, 2015 at 6:56 PM, Strong Su 
> wrote:
> 
>  I'm using Log4j 2.3 and Disruptor 3.2.
>  Because of third party package like spring, I have to use Log4j 1.2
> and
>  slf4j 1.5 too.
> 
> 
>  On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma 
>  wrote:
> 
> > Output looks ok.
> > Sleep was the default wait strategy but has been changed to Block a
> >> long
> > time ago. Looks like the docs are out of date. Thanks for drawing my
> > attention to this.
> >
> > I don't understand why changing the includeLocation does not make a
> > difference in performance. You should see a large improvement.
> > Which Log4j version are you using?
> >
> >
> >
> >> On Mon, Oct 12, 2015 at 12:58 PM, Strong Su 
> >> wrote:
> >>
> >> Here is my console debug with status="trace".
> >> I found that log4j2 didn't get SleepWaitingStrategy by default and I
> > didn't
> >> find includeLocation in console.
> >>
> >>
> >> 2015-10-12 18:55:25,424 DEBUG Starting
> LoggerContext[name=2090228673]
> > from
> >> configuration at jndi:/localhost/WEB-INF/log4j2.xml
> >> 2015-10-12 18:55:25,425 DEBUG Starting
> LoggerContext[name=2090228673,
> >> org.apache.logging.log4j.core.LoggerContext@4347ede7] with
>  configuration
> >> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
> >> 2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a
> new
> > one.
> >> 2015-10-12 18:55:25,430 DEBUG Starting configuration
> >> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
> >> 2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70 plugins
> >> 2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0 plugins
> >> 2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11
> plugins
> >> 2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
> >> class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching
>  for
> >> builder factory method...
> >> 2015-10-12 18:55:25,445 DEBUG Found builder factory method
>  [newBuilder]:
> >> public static
>  org.apache.logging.log4j.core.layout.PatternLayout$Builder
> >> org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
> >> 2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
> >> 2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found 21
> >> plugins
> >> 2015-10-12 18:55:25,480 DEBUG Calling build() on class class
> >> org.apache.logging.log4j.core.layout.PatternLayout$Builder for
> element
> >> PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
> >> Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null,
> name="null",
> >> name="null", name="null", name="null", name="null")
> >> 2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33
>  plugins
> >> 2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from
> >> builder
> >> factory method.
> >> 2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
> >> class=org.apache.logging.log4j.core.appender.FileAppender].
> Searching
>  for
> >> builder factory method...
> >> 2015-10-12 18:55:25,485 DEBUG No builder factory method found in
> class
> >> org.apache.logging.log4j.core.appender.FileAppender. Going to try
> > finding a
> >> factory method instead.
> >> 2015-10-12 18:55:25,486 DEBUG Still building Plugin[name=appender,
> >> class=org.apache.logging.log4j.core.appender.FileAppender].
> Searching
>  for
> >> factory method...
> >> 

Re: Bizarre performance in log4j2

[Remko Popma]

Very strange...

Can we try something else? Instead of using  or ,
just use  and  in the configuration, and make all loggers
asynchronous by setting system property
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

(But keep includeLocation="false".)


On Tue, Oct 13, 2015 at 8:47 PM, Strong Su  wrote:

> I change them to log4j-1.2-api and log4j-slf4j-impl. But it didn't change
> better.
>
> On Tue, Oct 13, 2015 at 4:24 PM, Mikael Ståldal  >
> wrote:
>
> > ...and make sure that no 3rd party dependencies brings them in.
> >
> > On Tue, Oct 13, 2015 at 8:22 AM, Remko Popma 
> > wrote:
> >
> > > Please remove log4j-1.2.16 and replace it with log4j-1.2-api version
> 2.3.
> > >
> > > Also remove slf4j-log4j12 and add log4j-slf4j-impl version 2.3.
> > >
> > > Sent from my iPhone
> > >
> > > > On 2015/10/13, at 14:39, Strong Su  wrote:
> > > >
> > > > Here is my pom.xml for logging:
> > > >
> > > > 
> > > >log4j
> > > >log4j
> > > >1.2.16
> > > > 
> > > > 
> > > >org.slf4j
> > > >slf4j-log4j12
> > > >1.5.11
> > > > 
> > > > 
> > > >org.slf4j
> > > >slf4j-api
> > > >1.5.11
> > > > 
> > > > 
> > > >org.apache.logging.log4j
> > > >log4j-api
> > > >2.3
> > > > 
> > > > 
> > > >org.apache.logging.log4j
> > > >log4j-core
> > > >2.3
> > > > 
> > > > 
> > > >org.apache.logging.log4j
> > > >log4j-web
> > > >2.3
> > > > 
> > > > 
> > > >com.lmax
> > > >disruptor
> > > >3.2.0
> > > > 
> > > >
> > > >
> > > >> On Tue, Oct 13, 2015 at 12:22 PM, Remko Popma <
> remko.po...@gmail.com>
> > > wrote:
> > > >>
> > > >> For log4j1, are you using the log4j-1.2-api-2.x.jar? And similarly
> the
> > > >> log4j-slf4j-impl-2.x.jar for SLF4J? (Just checking...)
> > > >>
> > > >> Sent from my iPhone
> > > >>
> > > >>> On 2015/10/13, at 11:43, Gary Gregory 
> > wrote:
> > > >>>
> > > >>> Can you use 2.4?
> > > >>>
> > > >>> Gary
> > > >>>
> > >  On Mon, Oct 12, 2015 at 6:56 PM, Strong Su 
> > > wrote:
> > > 
> > >  I'm using Log4j 2.3 and Disruptor 3.2.
> > >  Because of third party package like spring, I have to use Log4j
> 1.2
> > > and
> > >  slf4j 1.5 too.
> > > 
> > > 
> > >  On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma <
> remko.po...@gmail.com
> > >
> > >  wrote:
> > > 
> > > > Output looks ok.
> > > > Sleep was the default wait strategy but has been changed to
> Block a
> > > >> long
> > > > time ago. Looks like the docs are out of date. Thanks for drawing
> > my
> > > > attention to this.
> > > >
> > > > I don't understand why changing the includeLocation does not
> make a
> > > > difference in performance. You should see a large improvement.
> > > > Which Log4j version are you using?
> > > >
> > > >
> > > >
> > > >> On Mon, Oct 12, 2015 at 12:58 PM, Strong Su <
> lovelo...@gmail.com>
> > > >> wrote:
> > > >>
> > > >> Here is my console debug with status="trace".
> > > >> I found that log4j2 didn't get SleepWaitingStrategy by default
> > and I
> > > > didn't
> > > >> find includeLocation in console.
> > > >>
> > > >>
> > > >> 2015-10-12 18:55:25,424 DEBUG Starting
> > > LoggerContext[name=2090228673]
> > > > from
> > > >> configuration at jndi:/localhost/WEB-INF/log4j2.xml
> > > >> 2015-10-12 18:55:25,425 DEBUG Starting
> > > LoggerContext[name=2090228673,
> > > >> org.apache.logging.log4j.core.LoggerContext@4347ede7] with
> > >  configuration
> > > >> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
> > > >> 2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled.
> Registering a
> > > new
> > > > one.
> > > >> 2015-10-12 18:55:25,430 DEBUG Starting configuration
> > > >> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
> > > >> 2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70
> > plugins
> > > >> 2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0
> > plugins
> > > >> 2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11
> > > plugins
> > > >> 2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
> > > >> class=org.apache.logging.log4j.core.layout.PatternLayout].
> > Searching
> > >  for
> > > >> builder factory method...
> > > >> 2015-10-12 18:55:25,445 DEBUG Found builder factory method
> > >  [newBuilder]:
> > > >> public static
> > >  org.apache.logging.log4j.core.layout.PatternLayout$Builder
> > > >> org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
> > > >> 2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry
> initializing.
> > > >> 2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter'
> found
> > 21
> > > >> plugins
> > > >> 2015-10-12 18:55:25,480 DEBUG Calling build() on 

Re: Bizarre performance in log4j2

[Strong Su]

I change them to log4j-1.2-api and log4j-slf4j-impl. But it didn't change
better.

On Tue, Oct 13, 2015 at 4:24 PM, Mikael Ståldal 
wrote:

> ...and make sure that no 3rd party dependencies brings them in.
>
> On Tue, Oct 13, 2015 at 8:22 AM, Remko Popma 
> wrote:
>
> > Please remove log4j-1.2.16 and replace it with log4j-1.2-api version 2.3.
> >
> > Also remove slf4j-log4j12 and add log4j-slf4j-impl version 2.3.
> >
> > Sent from my iPhone
> >
> > > On 2015/10/13, at 14:39, Strong Su  wrote:
> > >
> > > Here is my pom.xml for logging:
> > >
> > > 
> > >log4j
> > >log4j
> > >1.2.16
> > > 
> > > 
> > >org.slf4j
> > >slf4j-log4j12
> > >1.5.11
> > > 
> > > 
> > >org.slf4j
> > >slf4j-api
> > >1.5.11
> > > 
> > > 
> > >org.apache.logging.log4j
> > >log4j-api
> > >2.3
> > > 
> > > 
> > >org.apache.logging.log4j
> > >log4j-core
> > >2.3
> > > 
> > > 
> > >org.apache.logging.log4j
> > >log4j-web
> > >2.3
> > > 
> > > 
> > >com.lmax
> > >disruptor
> > >3.2.0
> > > 
> > >
> > >
> > >> On Tue, Oct 13, 2015 at 12:22 PM, Remko Popma 
> > wrote:
> > >>
> > >> For log4j1, are you using the log4j-1.2-api-2.x.jar? And similarly the
> > >> log4j-slf4j-impl-2.x.jar for SLF4J? (Just checking...)
> > >>
> > >> Sent from my iPhone
> > >>
> > >>> On 2015/10/13, at 11:43, Gary Gregory 
> wrote:
> > >>>
> > >>> Can you use 2.4?
> > >>>
> > >>> Gary
> > >>>
> >  On Mon, Oct 12, 2015 at 6:56 PM, Strong Su 
> > wrote:
> > 
> >  I'm using Log4j 2.3 and Disruptor 3.2.
> >  Because of third party package like spring, I have to use Log4j 1.2
> > and
> >  slf4j 1.5 too.
> > 
> > 
> >  On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma  >
> >  wrote:
> > 
> > > Output looks ok.
> > > Sleep was the default wait strategy but has been changed to Block a
> > >> long
> > > time ago. Looks like the docs are out of date. Thanks for drawing
> my
> > > attention to this.
> > >
> > > I don't understand why changing the includeLocation does not make a
> > > difference in performance. You should see a large improvement.
> > > Which Log4j version are you using?
> > >
> > >
> > >
> > >> On Mon, Oct 12, 2015 at 12:58 PM, Strong Su 
> > >> wrote:
> > >>
> > >> Here is my console debug with status="trace".
> > >> I found that log4j2 didn't get SleepWaitingStrategy by default
> and I
> > > didn't
> > >> find includeLocation in console.
> > >>
> > >>
> > >> 2015-10-12 18:55:25,424 DEBUG Starting
> > LoggerContext[name=2090228673]
> > > from
> > >> configuration at jndi:/localhost/WEB-INF/log4j2.xml
> > >> 2015-10-12 18:55:25,425 DEBUG Starting
> > LoggerContext[name=2090228673,
> > >> org.apache.logging.log4j.core.LoggerContext@4347ede7] with
> >  configuration
> > >> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
> > >> 2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a
> > new
> > > one.
> > >> 2015-10-12 18:55:25,430 DEBUG Starting configuration
> > >> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
> > >> 2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70
> plugins
> > >> 2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0
> plugins
> > >> 2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11
> > plugins
> > >> 2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
> > >> class=org.apache.logging.log4j.core.layout.PatternLayout].
> Searching
> >  for
> > >> builder factory method...
> > >> 2015-10-12 18:55:25,445 DEBUG Found builder factory method
> >  [newBuilder]:
> > >> public static
> >  org.apache.logging.log4j.core.layout.PatternLayout$Builder
> > >> org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
> > >> 2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
> > >> 2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found
> 21
> > >> plugins
> > >> 2015-10-12 18:55:25,480 DEBUG Calling build() on class class
> > >> org.apache.logging.log4j.core.layout.PatternLayout$Builder for
> > element
> > >> PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
> > >> Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null,
> > name="null",
> > >> name="null", name="null", name="null", name="null")
> > >> 2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33
> >  plugins
> > >> 2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from
> > >> builder
> > >> factory method.
> > >> 2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
> > >> class=org.apache.logging.log4j.core.appender.FileAppender].
> > 

Re: Bizarre performance in log4j2

[Remko Popma]

Please remove log4j-1.2.16 and replace it with log4j-1.2-api version 2.3.

Also remove slf4j-log4j12 and add log4j-slf4j-impl version 2.3.

Sent from my iPhone

> On 2015/10/13, at 14:39, Strong Su  wrote:
> 
> Here is my pom.xml for logging:
> 
> 
>log4j
>log4j
>1.2.16
> 
> 
>org.slf4j
>slf4j-log4j12
>1.5.11
> 
> 
>org.slf4j
>slf4j-api
>1.5.11
> 
> 
>org.apache.logging.log4j
>log4j-api
>2.3
> 
> 
>org.apache.logging.log4j
>log4j-core
>2.3
> 
> 
>org.apache.logging.log4j
>log4j-web
>2.3
> 
> 
>com.lmax
>disruptor
>3.2.0
> 
> 
> 
>> On Tue, Oct 13, 2015 at 12:22 PM, Remko Popma  wrote:
>> 
>> For log4j1, are you using the log4j-1.2-api-2.x.jar? And similarly the
>> log4j-slf4j-impl-2.x.jar for SLF4J? (Just checking...)
>> 
>> Sent from my iPhone
>> 
>>> On 2015/10/13, at 11:43, Gary Gregory  wrote:
>>> 
>>> Can you use 2.4?
>>> 
>>> Gary
>>> 
 On Mon, Oct 12, 2015 at 6:56 PM, Strong Su  wrote:
 
 I'm using Log4j 2.3 and Disruptor 3.2.
 Because of third party package like spring, I have to use Log4j 1.2 and
 slf4j 1.5 too.
 
 
 On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma 
 wrote:
 
> Output looks ok.
> Sleep was the default wait strategy but has been changed to Block a
>> long
> time ago. Looks like the docs are out of date. Thanks for drawing my
> attention to this.
> 
> I don't understand why changing the includeLocation does not make a
> difference in performance. You should see a large improvement.
> Which Log4j version are you using?
> 
> 
> 
>> On Mon, Oct 12, 2015 at 12:58 PM, Strong Su 
>> wrote:
>> 
>> Here is my console debug with status="trace".
>> I found that log4j2 didn't get SleepWaitingStrategy by default and I
> didn't
>> find includeLocation in console.
>> 
>> 
>> 2015-10-12 18:55:25,424 DEBUG Starting LoggerContext[name=2090228673]
> from
>> configuration at jndi:/localhost/WEB-INF/log4j2.xml
>> 2015-10-12 18:55:25,425 DEBUG Starting LoggerContext[name=2090228673,
>> org.apache.logging.log4j.core.LoggerContext@4347ede7] with
 configuration
>> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
>> 2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a new
> one.
>> 2015-10-12 18:55:25,430 DEBUG Starting configuration
>> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
>> 2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70 plugins
>> 2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0 plugins
>> 2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11 plugins
>> 2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
>> class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching
 for
>> builder factory method...
>> 2015-10-12 18:55:25,445 DEBUG Found builder factory method
 [newBuilder]:
>> public static
 org.apache.logging.log4j.core.layout.PatternLayout$Builder
>> org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
>> 2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
>> 2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found 21
>> plugins
>> 2015-10-12 18:55:25,480 DEBUG Calling build() on class class
>> org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
>> PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
>> Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
>> name="null", name="null", name="null", name="null")
>> 2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33
 plugins
>> 2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from
>> builder
>> factory method.
>> 2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
>> class=org.apache.logging.log4j.core.appender.FileAppender]. Searching
 for
>> builder factory method...
>> 2015-10-12 18:55:25,485 DEBUG No builder factory method found in class
>> org.apache.logging.log4j.core.appender.FileAppender. Going to try
> finding a
>> factory method instead.
>> 2015-10-12 18:55:25,486 DEBUG Still building Plugin[name=appender,
>> class=org.apache.logging.log4j.core.appender.FileAppender]. Searching
 for
>> factory method...
>> 2015-10-12 18:55:25,486 DEBUG Found factory method [createAppender]:
> public
>> static org.apache.logging.log4j.core.appender.FileAppender
>> 

Re: Bizarre performance in log4j2

[Strong Su]

Here is my console debug with status="trace".
I found that log4j2 didn't get SleepWaitingStrategy by default and I didn't
find includeLocation in console.


2015-10-12 18:55:25,424 DEBUG Starting LoggerContext[name=2090228673] from
configuration at jndi:/localhost/WEB-INF/log4j2.xml
2015-10-12 18:55:25,425 DEBUG Starting LoggerContext[name=2090228673,
org.apache.logging.log4j.core.LoggerContext@4347ede7] with configuration
XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a new one.
2015-10-12 18:55:25,430 DEBUG Starting configuration
XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70 plugins
2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0 plugins
2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11 plugins
2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching for
builder factory method...
2015-10-12 18:55:25,445 DEBUG Found builder factory method [newBuilder]:
public static org.apache.logging.log4j.core.layout.PatternLayout$Builder
org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found 21 plugins
2015-10-12 18:55:25,480 DEBUG Calling build() on class class
org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
name="null", name="null", name="null", name="null")
2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33 plugins
2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from builder
factory method.
2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
class=org.apache.logging.log4j.core.appender.FileAppender]. Searching for
builder factory method...
2015-10-12 18:55:25,485 DEBUG No builder factory method found in class
org.apache.logging.log4j.core.appender.FileAppender. Going to try finding a
factory method instead.
2015-10-12 18:55:25,486 DEBUG Still building Plugin[name=appender,
class=org.apache.logging.log4j.core.appender.FileAppender]. Searching for
factory method...
2015-10-12 18:55:25,486 DEBUG Found factory method [createAppender]: public
static org.apache.logging.log4j.core.appender.FileAppender
org.apache.logging.log4j.core.appender.FileAppender.createAppender(java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,org.apache.logging.log4j.core.Layout,org.apache.logging.log4j.core.Filter,java.lang.String,java.lang.String,org.apache.logging.log4j.core.config.Configuration).
2015-10-12 18:55:25,500 DEBUG Calling createAppender on class
org.apache.logging.log4j.core.appender.FileAppender for element File with
params(name="/data/applogs/data-proxy/logs/app.log", name="false",
name="null", name="File", name="false", name="null", name="null",
name="null", PatternLayout(%d %-5p [%c{2}] %m%n), null, name="null",
name="null", Configuration(jndi:/localhost/WEB-INF/log4j2.xml))
2015-10-12 18:55:25,504 DEBUG Starting FileManager
/data/applogs/data-proxy/logs/app.log
2015-10-12 18:55:25,505 DEBUG Built Plugin[name=appender] OK from factory
method.
2015-10-12 18:55:25,505 DEBUG Building Plugin[name=layout,
class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching for
builder factory method...
2015-10-12 18:55:25,505 DEBUG Found builder factory method [newBuilder]:
public static org.apache.logging.log4j.core.layout.PatternLayout$Builder
org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
2015-10-12 18:55:25,507 DEBUG Calling build() on class class
org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
name="null", name="null", name="null", name="null")
2015-10-12 18:55:25,508 DEBUG Built Plugin[name=layout] OK from builder
factory method.
2015-10-12 18:55:25,508 DEBUG Building Plugin[name=appender,
class=org.apache.logging.log4j.core.appender.ConsoleAppender]. Searching
for builder factory method...
2015-10-12 18:55:25,510 DEBUG PluginManager 'Converter' found 33 plugins
2015-10-12 18:55:25,512 DEBUG Found builder factory method [newBuilder]:
public static
org.apache.logging.log4j.core.appender.ConsoleAppender$Builder
org.apache.logging.log4j.core.appender.ConsoleAppender.newBuilder().
2015-10-12 18:55:25,519 DEBUG No PluginVisitorStrategy found on annotation
[interface
org.apache.logging.log4j.core.config.plugins.validation.constraints.Required].
Ignoring.
2015-10-12 18:55:25,520 DEBUG Encountered type
[org.apache.logging.log4j.core.layout.PatternLayout] which can only be
checked for null.
2015-10-12 18:55:25,522 DEBUG 

Re: Bizarre performance in log4j2

[Remko Popma]

Can you change the configuration to start with
 On 2015/10/12, at 15:22, Strong Su  wrote:
> 
> Hi Remko. Thanks for the reply.
> I changed includeLocation to false and re-run the test.
> But it didn't change better. QPS is still about 5000.
> 
> I found user occupies CPU for about 70% when I run sync log4j1 and sync
> log4j2.
> But when I run async log4j2, it's only about 30% and system occupies for
> about 70%.
> All of them(include sync log4j2 and async log4j2) are under very high load
> average.
> Are these normal numbers?
> 
>> On Sun, Oct 11, 2015 at 7:56 PM, Remko Popma  wrote:
>> 
>> See also http://logging.apache.org/log4j/2.x/manual/async.html#Location
>> and
>> 
>> http://logging.apache.org/log4j/2.x/manual/async.html#Throughput_of_Logging_With_Location_includeLocationtrue
>> 
>> On Sun, Oct 11, 2015 at 1:54 PM, Remko Popma 
>> wrote:
>> 
>>> The problem with the strange performance result is because of the
>>> configuration:
>>> You have includeLocation=true. This will force Log4j to take a snapshot
>> of
>>> the stack and is very slow.
>>> 
>>> Your layouts do not actually use this information, and this explains why
>>> synchronous logging is faster: synchronous logging will _only_ take a
>>> snapshot of the stack when the layout needs it. In your case this is
>> never,
>>> so you get fast performance.
>>> 
>>> The solution is to change your config to
>>> 
>>> 
>>> If you test this with async loggers you should see a performance
>>> improvement immediately.
>>> 
 On Sun, Oct 11, 2015 at 12:21 PM, Strong Su  wrote:
 
 My log4j2 sync configuration is:
 
 
 


>>> immediateFlush="false" append="false">






 






 
 
 
 And async configuration change  to 
 
 On Sun, Oct 11, 2015 at 10:51 AM, Remko Popma 
 wrote:
 
> Can you post your log4j2 configuration?
> 
> Sent from my iPhone
> 
>> On 2015/10/10, at 21:58, Strong Su  wrote:
>> 
>> I insert a log in a http request function on server side. And I
>> start
>> requests continually on client side through hundreds of threads.
>> I measure the performance through QPS because server has to print a
 log
>> whenever it receive a request. The time delayed by logging will
 influence
>> QPS heavily.
>> When I didn't insert a log in the request function, QPS was about
 2.
>> When I inserted a log4j1 log, QPS was about 1.
>> When I inserted a log4j2 sync log, QPS was about 18000.
>> But when I inserted a log4j2 asycn log, QPS was only about 5000.
>> 
>>> On Sat, Oct 10, 2015 at 8:34 PM, Remko Popma <
>> remko.po...@gmail.com>
> wrote:
>>> 
>>> How did you measure the good performance (with sync logging) and
>> the
 bad
>>> performance (with async)? What happens exactly when "it turns
 terrible"?
>>> 
 On Saturday, 10 October 2015, Strong Su 
 wrote:
 
 Hello everyone,
 I'm still testing log4j2 on our projects.
 When using it, I find it has a beautiful performance when using
>> sync
 log4j2.
 But it turns terrible when I add -DLog4jContextSelector or change
> 
>>> to
  in log4j2.xml to use async log4j2.
 I don't even have a clue on explaining this.What could cause this
> bizarre
 problem?
 
 Thank you.
 Best regards,
 Dylan Su
>>> 
> 
> -
> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> For additional commands, e-mail: log4j-user-h...@logging.apache.org
> 
> 
 
>>> 
>>> 
>> 

-
To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-user-h...@logging.apache.org

Re: Bizarre performance in log4j2

[Strong Su]

Hi Remko. Thanks for the reply.
I changed includeLocation to false and re-run the test.
But it didn't change better. QPS is still about 5000.

I found user occupies CPU for about 70% when I run sync log4j1 and sync
log4j2.
But when I run async log4j2, it's only about 30% and system occupies for
about 70%.
All of them(include sync log4j2 and async log4j2) are under very high load
average.
Are these normal numbers?

On Sun, Oct 11, 2015 at 7:56 PM, Remko Popma  wrote:

> See also http://logging.apache.org/log4j/2.x/manual/async.html#Location
> and
>
> http://logging.apache.org/log4j/2.x/manual/async.html#Throughput_of_Logging_With_Location_includeLocationtrue
>
> On Sun, Oct 11, 2015 at 1:54 PM, Remko Popma 
> wrote:
>
> > The problem with the strange performance result is because of the
> > configuration:
> > You have includeLocation=true. This will force Log4j to take a snapshot
> of
> > the stack and is very slow.
> >
> > Your layouts do not actually use this information, and this explains why
> > synchronous logging is faster: synchronous logging will _only_ take a
> > snapshot of the stack when the layout needs it. In your case this is
> never,
> > so you get fast performance.
> >
> > The solution is to change your config to
> > 
> >
> > If you test this with async loggers you should see a performance
> > improvement immediately.
> >
> > On Sun, Oct 11, 2015 at 12:21 PM, Strong Su  wrote:
> >
> >> My log4j2 sync configuration is:
> >>
> >> 
> >> 
> >> 
> >> 
> >>  >> immediateFlush="false" append="false">
> >> 
> >> 
> >> 
> >> 
> >> 
> >> 
> >>
> >> 
> >> 
> >> 
> >> 
> >> 
> >> 
> >>
> >> 
> >>
> >> And async configuration change  to 
> >>
> >> On Sun, Oct 11, 2015 at 10:51 AM, Remko Popma 
> >> wrote:
> >>
> >> > Can you post your log4j2 configuration?
> >> >
> >> > Sent from my iPhone
> >> >
> >> > > On 2015/10/10, at 21:58, Strong Su  wrote:
> >> > >
> >> > > I insert a log in a http request function on server side. And I
> start
> >> > > requests continually on client side through hundreds of threads.
> >> > > I measure the performance through QPS because server has to print a
> >> log
> >> > > whenever it receive a request. The time delayed by logging will
> >> influence
> >> > > QPS heavily.
> >> > > When I didn't insert a log in the request function, QPS was about
> >> 2.
> >> > > When I inserted a log4j1 log, QPS was about 1.
> >> > > When I inserted a log4j2 sync log, QPS was about 18000.
> >> > > But when I inserted a log4j2 asycn log, QPS was only about 5000.
> >> > >
> >> > >> On Sat, Oct 10, 2015 at 8:34 PM, Remko Popma <
> remko.po...@gmail.com>
> >> > wrote:
> >> > >>
> >> > >> How did you measure the good performance (with sync logging) and
> the
> >> bad
> >> > >> performance (with async)? What happens exactly when "it turns
> >> terrible"?
> >> > >>
> >> > >>> On Saturday, 10 October 2015, Strong Su 
> >> wrote:
> >> > >>>
> >> > >>> Hello everyone,
> >> > >>> I'm still testing log4j2 on our projects.
> >> > >>> When using it, I find it has a beautiful performance when using
> sync
> >> > >>> log4j2.
> >> > >>> But it turns terrible when I add -DLog4jContextSelector or change
> >> > 
> >> > >> to
> >> > >>>  in log4j2.xml to use async log4j2.
> >> > >>> I don't even have a clue on explaining this.What could cause this
> >> > bizarre
> >> > >>> problem?
> >> > >>>
> >> > >>> Thank you.
> >> > >>> Best regards,
> >> > >>> Dylan Su
> >> > >>
> >> >
> >> > -
> >> > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> >> > For additional commands, e-mail: log4j-user-h...@logging.apache.org
> >> >
> >> >
> >>
> >
> >
>

Re: Bizarre performance in log4j2

[Strong Su]

I'm using Log4j 2.3 and Disruptor 3.2.
Because of third party package like spring, I have to use Log4j 1.2 and
slf4j 1.5 too.


On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma  wrote:

> Output looks ok.
> Sleep was the default wait strategy but has been changed to Block a long
> time ago. Looks like the docs are out of date. Thanks for drawing my
> attention to this.
>
> I don't understand why changing the includeLocation does not make a
> difference in performance. You should see a large improvement.
> Which Log4j version are you using?
>
>
>
> On Mon, Oct 12, 2015 at 12:58 PM, Strong Su  wrote:
>
> > Here is my console debug with status="trace".
> > I found that log4j2 didn't get SleepWaitingStrategy by default and I
> didn't
> > find includeLocation in console.
> >
> >
> > 2015-10-12 18:55:25,424 DEBUG Starting LoggerContext[name=2090228673]
> from
> > configuration at jndi:/localhost/WEB-INF/log4j2.xml
> > 2015-10-12 18:55:25,425 DEBUG Starting LoggerContext[name=2090228673,
> > org.apache.logging.log4j.core.LoggerContext@4347ede7] with configuration
> > XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
> > 2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a new
> one.
> > 2015-10-12 18:55:25,430 DEBUG Starting configuration
> > XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
> > 2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70 plugins
> > 2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0 plugins
> > 2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11 plugins
> > 2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
> > class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching for
> > builder factory method...
> > 2015-10-12 18:55:25,445 DEBUG Found builder factory method [newBuilder]:
> > public static org.apache.logging.log4j.core.layout.PatternLayout$Builder
> > org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
> > 2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
> > 2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found 21
> > plugins
> > 2015-10-12 18:55:25,480 DEBUG Calling build() on class class
> > org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
> > PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
> > Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
> > name="null", name="null", name="null", name="null")
> > 2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33 plugins
> > 2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from builder
> > factory method.
> > 2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
> > class=org.apache.logging.log4j.core.appender.FileAppender]. Searching for
> > builder factory method...
> > 2015-10-12 18:55:25,485 DEBUG No builder factory method found in class
> > org.apache.logging.log4j.core.appender.FileAppender. Going to try
> finding a
> > factory method instead.
> > 2015-10-12 18:55:25,486 DEBUG Still building Plugin[name=appender,
> > class=org.apache.logging.log4j.core.appender.FileAppender]. Searching for
> > factory method...
> > 2015-10-12 18:55:25,486 DEBUG Found factory method [createAppender]:
> public
> > static org.apache.logging.log4j.core.appender.FileAppender
> >
> >
> org.apache.logging.log4j.core.appender.FileAppender.createAppender(java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,org.apache.logging.log4j.core.Layout,org.apache.logging.log4j.core.Filter,java.lang.String,java.lang.String,org.apache.logging.log4j.core.config.Configuration).
> > 2015-10-12 18:55:25,500 DEBUG Calling createAppender on class
> > org.apache.logging.log4j.core.appender.FileAppender for element File with
> > params(name="/data/applogs/data-proxy/logs/app.log", name="false",
> > name="null", name="File", name="false", name="null", name="null",
> > name="null", PatternLayout(%d %-5p [%c{2}] %m%n), null, name="null",
> > name="null", Configuration(jndi:/localhost/WEB-INF/log4j2.xml))
> > 2015-10-12 18:55:25,504 DEBUG Starting FileManager
> > /data/applogs/data-proxy/logs/app.log
> > 2015-10-12 18:55:25,505 DEBUG Built Plugin[name=appender] OK from factory
> > method.
> > 2015-10-12 18:55:25,505 DEBUG Building Plugin[name=layout,
> > class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching for
> > builder factory method...
> > 2015-10-12 18:55:25,505 DEBUG Found builder factory method [newBuilder]:
> > public static org.apache.logging.log4j.core.layout.PatternLayout$Builder
> > org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
> > 2015-10-12 18:55:25,507 DEBUG Calling build() on class class
> > org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
> > PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
> > Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
> > name="null", 

Re: Bizarre performance in log4j2

[Remko Popma]

Output looks ok.
Sleep was the default wait strategy but has been changed to Block a long
time ago. Looks like the docs are out of date. Thanks for drawing my
attention to this.

I don't understand why changing the includeLocation does not make a
difference in performance. You should see a large improvement.
Which Log4j version are you using?



On Mon, Oct 12, 2015 at 12:58 PM, Strong Su  wrote:

> Here is my console debug with status="trace".
> I found that log4j2 didn't get SleepWaitingStrategy by default and I didn't
> find includeLocation in console.
>
>
> 2015-10-12 18:55:25,424 DEBUG Starting LoggerContext[name=2090228673] from
> configuration at jndi:/localhost/WEB-INF/log4j2.xml
> 2015-10-12 18:55:25,425 DEBUG Starting LoggerContext[name=2090228673,
> org.apache.logging.log4j.core.LoggerContext@4347ede7] with configuration
> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
> 2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a new one.
> 2015-10-12 18:55:25,430 DEBUG Starting configuration
> XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
> 2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70 plugins
> 2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0 plugins
> 2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11 plugins
> 2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
> class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching for
> builder factory method...
> 2015-10-12 18:55:25,445 DEBUG Found builder factory method [newBuilder]:
> public static org.apache.logging.log4j.core.layout.PatternLayout$Builder
> org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
> 2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
> 2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found 21
> plugins
> 2015-10-12 18:55:25,480 DEBUG Calling build() on class class
> org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
> PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
> Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
> name="null", name="null", name="null", name="null")
> 2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33 plugins
> 2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from builder
> factory method.
> 2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
> class=org.apache.logging.log4j.core.appender.FileAppender]. Searching for
> builder factory method...
> 2015-10-12 18:55:25,485 DEBUG No builder factory method found in class
> org.apache.logging.log4j.core.appender.FileAppender. Going to try finding a
> factory method instead.
> 2015-10-12 18:55:25,486 DEBUG Still building Plugin[name=appender,
> class=org.apache.logging.log4j.core.appender.FileAppender]. Searching for
> factory method...
> 2015-10-12 18:55:25,486 DEBUG Found factory method [createAppender]: public
> static org.apache.logging.log4j.core.appender.FileAppender
>
> org.apache.logging.log4j.core.appender.FileAppender.createAppender(java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,org.apache.logging.log4j.core.Layout,org.apache.logging.log4j.core.Filter,java.lang.String,java.lang.String,org.apache.logging.log4j.core.config.Configuration).
> 2015-10-12 18:55:25,500 DEBUG Calling createAppender on class
> org.apache.logging.log4j.core.appender.FileAppender for element File with
> params(name="/data/applogs/data-proxy/logs/app.log", name="false",
> name="null", name="File", name="false", name="null", name="null",
> name="null", PatternLayout(%d %-5p [%c{2}] %m%n), null, name="null",
> name="null", Configuration(jndi:/localhost/WEB-INF/log4j2.xml))
> 2015-10-12 18:55:25,504 DEBUG Starting FileManager
> /data/applogs/data-proxy/logs/app.log
> 2015-10-12 18:55:25,505 DEBUG Built Plugin[name=appender] OK from factory
> method.
> 2015-10-12 18:55:25,505 DEBUG Building Plugin[name=layout,
> class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching for
> builder factory method...
> 2015-10-12 18:55:25,505 DEBUG Found builder factory method [newBuilder]:
> public static org.apache.logging.log4j.core.layout.PatternLayout$Builder
> org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
> 2015-10-12 18:55:25,507 DEBUG Calling build() on class class
> org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
> PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
> Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
> name="null", name="null", name="null", name="null")
> 2015-10-12 18:55:25,508 DEBUG Built Plugin[name=layout] OK from builder
> factory method.
> 2015-10-12 18:55:25,508 DEBUG Building Plugin[name=appender,
> class=org.apache.logging.log4j.core.appender.ConsoleAppender]. Searching
> for builder factory method...
> 2015-10-12 18:55:25,510 DEBUG PluginManager 'Converter' found 33 

Re: Bizarre performance in log4j2

[Remko Popma]

For log4j1, are you using the log4j-1.2-api-2.x.jar? And similarly the 
log4j-slf4j-impl-2.x.jar for SLF4J? (Just checking...)

Sent from my iPhone

> On 2015/10/13, at 11:43, Gary Gregory  wrote:
> 
> Can you use 2.4?
> 
> Gary
> 
>> On Mon, Oct 12, 2015 at 6:56 PM, Strong Su  wrote:
>> 
>> I'm using Log4j 2.3 and Disruptor 3.2.
>> Because of third party package like spring, I have to use Log4j 1.2 and
>> slf4j 1.5 too.
>> 
>> 
>> On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma 
>> wrote:
>> 
>>> Output looks ok.
>>> Sleep was the default wait strategy but has been changed to Block a long
>>> time ago. Looks like the docs are out of date. Thanks for drawing my
>>> attention to this.
>>> 
>>> I don't understand why changing the includeLocation does not make a
>>> difference in performance. You should see a large improvement.
>>> Which Log4j version are you using?
>>> 
>>> 
>>> 
 On Mon, Oct 12, 2015 at 12:58 PM, Strong Su  wrote:
 
 Here is my console debug with status="trace".
 I found that log4j2 didn't get SleepWaitingStrategy by default and I
>>> didn't
 find includeLocation in console.
 
 
 2015-10-12 18:55:25,424 DEBUG Starting LoggerContext[name=2090228673]
>>> from
 configuration at jndi:/localhost/WEB-INF/log4j2.xml
 2015-10-12 18:55:25,425 DEBUG Starting LoggerContext[name=2090228673,
 org.apache.logging.log4j.core.LoggerContext@4347ede7] with
>> configuration
 XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
 2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a new
>>> one.
 2015-10-12 18:55:25,430 DEBUG Starting configuration
 XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
 2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70 plugins
 2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0 plugins
 2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11 plugins
 2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
 class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching
>> for
 builder factory method...
 2015-10-12 18:55:25,445 DEBUG Found builder factory method
>> [newBuilder]:
 public static
>> org.apache.logging.log4j.core.layout.PatternLayout$Builder
 org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
 2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
 2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found 21
 plugins
 2015-10-12 18:55:25,480 DEBUG Calling build() on class class
 org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
 PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
 Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
 name="null", name="null", name="null", name="null")
 2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33
>> plugins
 2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from builder
 factory method.
 2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
 class=org.apache.logging.log4j.core.appender.FileAppender]. Searching
>> for
 builder factory method...
 2015-10-12 18:55:25,485 DEBUG No builder factory method found in class
 org.apache.logging.log4j.core.appender.FileAppender. Going to try
>>> finding a
 factory method instead.
 2015-10-12 18:55:25,486 DEBUG Still building Plugin[name=appender,
 class=org.apache.logging.log4j.core.appender.FileAppender]. Searching
>> for
 factory method...
 2015-10-12 18:55:25,486 DEBUG Found factory method [createAppender]:
>>> public
 static org.apache.logging.log4j.core.appender.FileAppender
>> org.apache.logging.log4j.core.appender.FileAppender.createAppender(java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,org.apache.logging.log4j.core.Layout,org.apache.logging.log4j.core.Filter,java.lang.String,java.lang.String,org.apache.logging.log4j.core.config.Configuration).
 2015-10-12 18:55:25,500 DEBUG Calling createAppender on class
 org.apache.logging.log4j.core.appender.FileAppender for element File
>> with
 params(name="/data/applogs/data-proxy/logs/app.log", name="false",
 name="null", name="File", name="false", name="null", name="null",
 name="null", PatternLayout(%d %-5p [%c{2}] %m%n), null, name="null",
 name="null", Configuration(jndi:/localhost/WEB-INF/log4j2.xml))
 2015-10-12 18:55:25,504 DEBUG Starting FileManager
 /data/applogs/data-proxy/logs/app.log
 2015-10-12 18:55:25,505 DEBUG Built Plugin[name=appender] OK from
>> factory
 method.
 2015-10-12 18:55:25,505 DEBUG Building Plugin[name=layout,
 class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching
>> for
 builder factory method...
 2015-10-12 18:55:25,505 

Re: Bizarre performance in log4j2

[Strong Su]

Using 2.4 will have some difficulties cause we are still using Java 1.6.
May the problem be I'm using an older version of log4j?

By the way, here is how I log in the request function:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

{...}

private static final Logger LOG= LogManager.getLogger(A.class);

{...}

LOG.info("Log4j_TEST");



On Tue, Oct 13, 2015 at 10:43 AM, Gary Gregory 
wrote:

> Can you use 2.4?
>
> Gary
>
> On Mon, Oct 12, 2015 at 6:56 PM, Strong Su  wrote:
>
> > I'm using Log4j 2.3 and Disruptor 3.2.
> > Because of third party package like spring, I have to use Log4j 1.2 and
> > slf4j 1.5 too.
> >
> >
> > On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma 
> > wrote:
> >
> > > Output looks ok.
> > > Sleep was the default wait strategy but has been changed to Block a
> long
> > > time ago. Looks like the docs are out of date. Thanks for drawing my
> > > attention to this.
> > >
> > > I don't understand why changing the includeLocation does not make a
> > > difference in performance. You should see a large improvement.
> > > Which Log4j version are you using?
> > >
> > >
> > >
> > > On Mon, Oct 12, 2015 at 12:58 PM, Strong Su 
> wrote:
> > >
> > > > Here is my console debug with status="trace".
> > > > I found that log4j2 didn't get SleepWaitingStrategy by default and I
> > > didn't
> > > > find includeLocation in console.
> > > >
> > > >
> > > > 2015-10-12 18:55:25,424 DEBUG Starting LoggerContext[name=2090228673]
> > > from
> > > > configuration at jndi:/localhost/WEB-INF/log4j2.xml
> > > > 2015-10-12 18:55:25,425 DEBUG Starting LoggerContext[name=2090228673,
> > > > org.apache.logging.log4j.core.LoggerContext@4347ede7] with
> > configuration
> > > > XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
> > > > 2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a
> new
> > > one.
> > > > 2015-10-12 18:55:25,430 DEBUG Starting configuration
> > > > XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
> > > > 2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70 plugins
> > > > 2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0 plugins
> > > > 2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11 plugins
> > > > 2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
> > > > class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching
> > for
> > > > builder factory method...
> > > > 2015-10-12 18:55:25,445 DEBUG Found builder factory method
> > [newBuilder]:
> > > > public static
> > org.apache.logging.log4j.core.layout.PatternLayout$Builder
> > > > org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
> > > > 2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
> > > > 2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found 21
> > > > plugins
> > > > 2015-10-12 18:55:25,480 DEBUG Calling build() on class class
> > > > org.apache.logging.log4j.core.layout.PatternLayout$Builder for
> element
> > > > PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
> > > > Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
> > > > name="null", name="null", name="null", name="null")
> > > > 2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33
> > plugins
> > > > 2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from
> builder
> > > > factory method.
> > > > 2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
> > > > class=org.apache.logging.log4j.core.appender.FileAppender]. Searching
> > for
> > > > builder factory method...
> > > > 2015-10-12 18:55:25,485 DEBUG No builder factory method found in
> class
> > > > org.apache.logging.log4j.core.appender.FileAppender. Going to try
> > > finding a
> > > > factory method instead.
> > > > 2015-10-12 18:55:25,486 DEBUG Still building Plugin[name=appender,
> > > > class=org.apache.logging.log4j.core.appender.FileAppender]. Searching
> > for
> > > > factory method...
> > > > 2015-10-12 18:55:25,486 DEBUG Found factory method [createAppender]:
> > > public
> > > > static org.apache.logging.log4j.core.appender.FileAppender
> > > >
> > > >
> > >
> >
> org.apache.logging.log4j.core.appender.FileAppender.createAppender(java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,org.apache.logging.log4j.core.Layout,org.apache.logging.log4j.core.Filter,java.lang.String,java.lang.String,org.apache.logging.log4j.core.config.Configuration).
> > > > 2015-10-12 18:55:25,500 DEBUG Calling createAppender on class
> > > > org.apache.logging.log4j.core.appender.FileAppender for element File
> > with
> > > > params(name="/data/applogs/data-proxy/logs/app.log", name="false",
> > > > name="null", name="File", name="false", name="null", name="null",
> > > > name="null", PatternLayout(%d %-5p [%c{2}] %m%n), null, name="null",
> > > > 

Re: Bizarre performance in log4j2

[Strong Su]

Here is my pom.xml for logging:


log4j
log4j
1.2.16


org.slf4j
slf4j-log4j12
1.5.11


org.slf4j
slf4j-api
1.5.11


org.apache.logging.log4j
log4j-api
2.3


org.apache.logging.log4j
log4j-core
2.3


org.apache.logging.log4j
log4j-web
2.3


com.lmax
disruptor
3.2.0



On Tue, Oct 13, 2015 at 12:22 PM, Remko Popma  wrote:

> For log4j1, are you using the log4j-1.2-api-2.x.jar? And similarly the
> log4j-slf4j-impl-2.x.jar for SLF4J? (Just checking...)
>
> Sent from my iPhone
>
> > On 2015/10/13, at 11:43, Gary Gregory  wrote:
> >
> > Can you use 2.4?
> >
> > Gary
> >
> >> On Mon, Oct 12, 2015 at 6:56 PM, Strong Su  wrote:
> >>
> >> I'm using Log4j 2.3 and Disruptor 3.2.
> >> Because of third party package like spring, I have to use Log4j 1.2 and
> >> slf4j 1.5 too.
> >>
> >>
> >> On Tue, Oct 13, 2015 at 7:15 AM, Remko Popma 
> >> wrote:
> >>
> >>> Output looks ok.
> >>> Sleep was the default wait strategy but has been changed to Block a
> long
> >>> time ago. Looks like the docs are out of date. Thanks for drawing my
> >>> attention to this.
> >>>
> >>> I don't understand why changing the includeLocation does not make a
> >>> difference in performance. You should see a large improvement.
> >>> Which Log4j version are you using?
> >>>
> >>>
> >>>
>  On Mon, Oct 12, 2015 at 12:58 PM, Strong Su 
> wrote:
> 
>  Here is my console debug with status="trace".
>  I found that log4j2 didn't get SleepWaitingStrategy by default and I
> >>> didn't
>  find includeLocation in console.
> 
> 
>  2015-10-12 18:55:25,424 DEBUG Starting LoggerContext[name=2090228673]
> >>> from
>  configuration at jndi:/localhost/WEB-INF/log4j2.xml
>  2015-10-12 18:55:25,425 DEBUG Starting LoggerContext[name=2090228673,
>  org.apache.logging.log4j.core.LoggerContext@4347ede7] with
> >> configuration
>  XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]...
>  2015-10-12 18:55:25,427 DEBUG Shutdown hook enabled. Registering a new
> >>> one.
>  2015-10-12 18:55:25,430 DEBUG Starting configuration
>  XmlConfiguration[location=jndi:/localhost/WEB-INF/log4j2.xml]
>  2015-10-12 18:55:25,432 DEBUG PluginManager 'Core' found 70 plugins
>  2015-10-12 18:55:25,433 DEBUG PluginManager 'Level' found 0 plugins
>  2015-10-12 18:55:25,438 DEBUG PluginManager 'Lookup' found 11 plugins
>  2015-10-12 18:55:25,441 DEBUG Building Plugin[name=layout,
>  class=org.apache.logging.log4j.core.layout.PatternLayout]. Searching
> >> for
>  builder factory method...
>  2015-10-12 18:55:25,445 DEBUG Found builder factory method
> >> [newBuilder]:
>  public static
> >> org.apache.logging.log4j.core.layout.PatternLayout$Builder
>  org.apache.logging.log4j.core.layout.PatternLayout.newBuilder().
>  2015-10-12 18:55:25,458 DEBUG TypeConverterRegistry initializing.
>  2015-10-12 18:55:25,458 DEBUG PluginManager 'TypeConverter' found 21
>  plugins
>  2015-10-12 18:55:25,480 DEBUG Calling build() on class class
>  org.apache.logging.log4j.core.layout.PatternLayout$Builder for element
>  PatternLayout with params(name="%d %-5p [%c{2}] %m%n",
>  Configuration(jndi:/localhost/WEB-INF/log4j2.xml), null, name="null",
>  name="null", name="null", name="null", name="null")
>  2015-10-12 18:55:25,481 DEBUG PluginManager 'Converter' found 33
> >> plugins
>  2015-10-12 18:55:25,482 DEBUG Built Plugin[name=layout] OK from
> builder
>  factory method.
>  2015-10-12 18:55:25,483 DEBUG Building Plugin[name=appender,
>  class=org.apache.logging.log4j.core.appender.FileAppender]. Searching
> >> for
>  builder factory method...
>  2015-10-12 18:55:25,485 DEBUG No builder factory method found in class
>  org.apache.logging.log4j.core.appender.FileAppender. Going to try
> >>> finding a
>  factory method instead.
>  2015-10-12 18:55:25,486 DEBUG Still building Plugin[name=appender,
>  class=org.apache.logging.log4j.core.appender.FileAppender]. Searching
> >> for
>  factory method...
>  2015-10-12 18:55:25,486 DEBUG Found factory method [createAppender]:
> >>> public
>  static org.apache.logging.log4j.core.appender.FileAppender
> >>
> org.apache.logging.log4j.core.appender.FileAppender.createAppender(java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,org.apache.logging.log4j.core.Layout,org.apache.logging.log4j.core.Filter,java.lang.String,java.lang.String,org.apache.logging.log4j.core.config.Configuration).
>  2015-10-12 18:55:25,500 DEBUG Calling createAppender on class
>  org.apache.logging.log4j.core.appender.FileAppender for element File
> >> with
>  params(name="/data/applogs/data-proxy/logs/app.log", name="false",

Re: Bizarre performance in log4j2

[Strong Su]

My log4j2 sync configuration is:






















And async configuration change  to 

On Sun, Oct 11, 2015 at 10:51 AM, Remko Popma  wrote:

> Can you post your log4j2 configuration?
>
> Sent from my iPhone
>
> > On 2015/10/10, at 21:58, Strong Su  wrote:
> >
> > I insert a log in a http request function on server side. And I start
> > requests continually on client side through hundreds of threads.
> > I measure the performance through QPS because server has to print a log
> > whenever it receive a request. The time delayed by logging will influence
> > QPS heavily.
> > When I didn't insert a log in the request function, QPS was about 2.
> > When I inserted a log4j1 log, QPS was about 1.
> > When I inserted a log4j2 sync log, QPS was about 18000.
> > But when I inserted a log4j2 asycn log, QPS was only about 5000.
> >
> >> On Sat, Oct 10, 2015 at 8:34 PM, Remko Popma 
> wrote:
> >>
> >> How did you measure the good performance (with sync logging) and the bad
> >> performance (with async)? What happens exactly when "it turns terrible"?
> >>
> >>> On Saturday, 10 October 2015, Strong Su  wrote:
> >>>
> >>> Hello everyone,
> >>> I'm still testing log4j2 on our projects.
> >>> When using it, I find it has a beautiful performance when using sync
> >>> log4j2.
> >>> But it turns terrible when I add -DLog4jContextSelector or change
> 
> >> to
> >>>  in log4j2.xml to use async log4j2.
> >>> I don't even have a clue on explaining this.What could cause this
> bizarre
> >>> problem?
> >>>
> >>> Thank you.
> >>> Best regards,
> >>> Dylan Su
> >>
>
> -
> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>
>

Re: Bizarre performance in log4j2

[Strong Su]

I was mean to run sync logger and sync appender to compare the basic
performance of log4j2.
But when I run command:
jstack -F  | grep log
and command:
jstack -F  | grep disruptor
I found many messages after command1 and they have the word of
AsyncAppender but nothing after command2.
Is that means my log4j2.xml was using async appender and sync logger?
If so, which property opens async appender by default?
And will using async logger and async appender at the same time reduce the
performance?


On Sun, Oct 11, 2015 at 6:21 PM, Strong Su  wrote:

> My log4j2 sync configuration is:
>
> 
> 
> 
> 
>  append="false">
> 
> 
> 
> 
> 
> 
>
> 
> 
> 
> 
> 
> 
>
> 
>
> And async configuration change  to 
>
> On Sun, Oct 11, 2015 at 10:51 AM, Remko Popma 
> wrote:
>
>> Can you post your log4j2 configuration?
>>
>> Sent from my iPhone
>>
>> > On 2015/10/10, at 21:58, Strong Su  wrote:
>> >
>> > I insert a log in a http request function on server side. And I start
>> > requests continually on client side through hundreds of threads.
>> > I measure the performance through QPS because server has to print a log
>> > whenever it receive a request. The time delayed by logging will
>> influence
>> > QPS heavily.
>> > When I didn't insert a log in the request function, QPS was about 2.
>> > When I inserted a log4j1 log, QPS was about 1.
>> > When I inserted a log4j2 sync log, QPS was about 18000.
>> > But when I inserted a log4j2 asycn log, QPS was only about 5000.
>> >
>> >> On Sat, Oct 10, 2015 at 8:34 PM, Remko Popma 
>> wrote:
>> >>
>> >> How did you measure the good performance (with sync logging) and the
>> bad
>> >> performance (with async)? What happens exactly when "it turns
>> terrible"?
>> >>
>> >>> On Saturday, 10 October 2015, Strong Su  wrote:
>> >>>
>> >>> Hello everyone,
>> >>> I'm still testing log4j2 on our projects.
>> >>> When using it, I find it has a beautiful performance when using sync
>> >>> log4j2.
>> >>> But it turns terrible when I add -DLog4jContextSelector or change
>> 
>> >> to
>> >>>  in log4j2.xml to use async log4j2.
>> >>> I don't even have a clue on explaining this.What could cause this
>> bizarre
>> >>> problem?
>> >>>
>> >>> Thank you.
>> >>> Best regards,
>> >>> Dylan Su
>> >>
>>
>> -
>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
>> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>>
>>
>

Re: Bizarre performance in log4j2

[Remko Popma]

See also http://logging.apache.org/log4j/2.x/manual/async.html#Location
and
http://logging.apache.org/log4j/2.x/manual/async.html#Throughput_of_Logging_With_Location_includeLocationtrue

On Sun, Oct 11, 2015 at 1:54 PM, Remko Popma  wrote:

> The problem with the strange performance result is because of the
> configuration:
> You have includeLocation=true. This will force Log4j to take a snapshot of
> the stack and is very slow.
>
> Your layouts do not actually use this information, and this explains why
> synchronous logging is faster: synchronous logging will _only_ take a
> snapshot of the stack when the layout needs it. In your case this is never,
> so you get fast performance.
>
> The solution is to change your config to
> 
>
> If you test this with async loggers you should see a performance
> improvement immediately.
>
> On Sun, Oct 11, 2015 at 12:21 PM, Strong Su  wrote:
>
>> My log4j2 sync configuration is:
>>
>> 
>> 
>> 
>> 
>> > immediateFlush="false" append="false">
>> 
>> 
>> 
>> 
>> 
>> 
>>
>> 
>> 
>> 
>> 
>> 
>> 
>>
>> 
>>
>> And async configuration change  to 
>>
>> On Sun, Oct 11, 2015 at 10:51 AM, Remko Popma 
>> wrote:
>>
>> > Can you post your log4j2 configuration?
>> >
>> > Sent from my iPhone
>> >
>> > > On 2015/10/10, at 21:58, Strong Su  wrote:
>> > >
>> > > I insert a log in a http request function on server side. And I start
>> > > requests continually on client side through hundreds of threads.
>> > > I measure the performance through QPS because server has to print a
>> log
>> > > whenever it receive a request. The time delayed by logging will
>> influence
>> > > QPS heavily.
>> > > When I didn't insert a log in the request function, QPS was about
>> 2.
>> > > When I inserted a log4j1 log, QPS was about 1.
>> > > When I inserted a log4j2 sync log, QPS was about 18000.
>> > > But when I inserted a log4j2 asycn log, QPS was only about 5000.
>> > >
>> > >> On Sat, Oct 10, 2015 at 8:34 PM, Remko Popma 
>> > wrote:
>> > >>
>> > >> How did you measure the good performance (with sync logging) and the
>> bad
>> > >> performance (with async)? What happens exactly when "it turns
>> terrible"?
>> > >>
>> > >>> On Saturday, 10 October 2015, Strong Su 
>> wrote:
>> > >>>
>> > >>> Hello everyone,
>> > >>> I'm still testing log4j2 on our projects.
>> > >>> When using it, I find it has a beautiful performance when using sync
>> > >>> log4j2.
>> > >>> But it turns terrible when I add -DLog4jContextSelector or change
>> > 
>> > >> to
>> > >>>  in log4j2.xml to use async log4j2.
>> > >>> I don't even have a clue on explaining this.What could cause this
>> > bizarre
>> > >>> problem?
>> > >>>
>> > >>> Thank you.
>> > >>> Best regards,
>> > >>> Dylan Su
>> > >>
>> >
>> > -
>> > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
>> > For additional commands, e-mail: log4j-user-h...@logging.apache.org
>> >
>> >
>>
>
>

Re: Bizarre performance in log4j2

[Ralph Goers]

What does your server look like? Specifically, how many cores? Are they hyper 
threaded? How much memory?

If you don’t have YourKit or some other profiler installed to identify the 
bottleneck, one of my favorite tricks is to just take several thread dumps 
10-15 seconds apart and then compare them. If they consistently show the same 
piece of code being executed then that is likely a bottleneck.

Ralph

> On Oct 10, 2015, at 5:58 AM, Strong Su  wrote:
> 
> I insert a log in a http request function on server side. And I start
> requests continually on client side through hundreds of threads.
> I measure the performance through QPS because server has to print a log
> whenever it receive a request. The time delayed by logging will influence
> QPS heavily.
> When I didn't insert a log in the request function, QPS was about 2.
> When I inserted a log4j1 log, QPS was about 1.
> When I inserted a log4j2 sync log, QPS was about 18000.
> But when I inserted a log4j2 asycn log, QPS was only about 5000.
> 
> On Sat, Oct 10, 2015 at 8:34 PM, Remko Popma  wrote:
> 
>> How did you measure the good performance (with sync logging) and the bad
>> performance (with async)? What happens exactly when "it turns terrible"?
>> 
>> On Saturday, 10 October 2015, Strong Su  wrote:
>> 
>>> Hello everyone,
>>> I'm still testing log4j2 on our projects.
>>> When using it, I find it has a beautiful performance when using sync
>>> log4j2.
>>> But it turns terrible when I add -DLog4jContextSelector or change 
>> to
>>>  in log4j2.xml to use async log4j2.
>>> I don't even have a clue on explaining this.What could cause this bizarre
>>> problem?
>>> 
>>> Thank you.
>>> Best regards,
>>> Dylan Su
>>> 
>> 



-
To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-user-h...@logging.apache.org

Bizarre performance in log4j2

[Strong Su]

Hello everyone,
 I'm still testing log4j2 on our projects.
When using it, I find it has a beautiful performance when using sync log4j2.
But it turns terrible when I add -DLog4jContextSelector or change  to
 in log4j2.xml to use async log4j2.
I don't even have a clue on explaining this.What could cause this bizarre
problem?

Thank you.
Best regards,
Dylan Su

Re: Bizarre performance in log4j2

[Remko Popma]

How did you measure the good performance (with sync logging) and the bad
performance (with async)? What happens exactly when "it turns terrible"?

On Saturday, 10 October 2015, Strong Su  wrote:

> Hello everyone,
>  I'm still testing log4j2 on our projects.
> When using it, I find it has a beautiful performance when using sync
> log4j2.
> But it turns terrible when I add -DLog4jContextSelector or change  to
>  in log4j2.xml to use async log4j2.
> I don't even have a clue on explaining this.What could cause this bizarre
> problem?
>
> Thank you.
> Best regards,
> Dylan Su
>

Re: Bizarre performance in log4j2

[Strong Su]

I insert a log in a http request function on server side. And I start
requests continually on client side through hundreds of threads.
I measure the performance through QPS because server has to print a log
whenever it receive a request. The time delayed by logging will influence
QPS heavily.
When I didn't insert a log in the request function, QPS was about 2.
When I inserted a log4j1 log, QPS was about 1.
When I inserted a log4j2 sync log, QPS was about 18000.
But when I inserted a log4j2 asycn log, QPS was only about 5000.

On Sat, Oct 10, 2015 at 8:34 PM, Remko Popma  wrote:

> How did you measure the good performance (with sync logging) and the bad
> performance (with async)? What happens exactly when "it turns terrible"?
>
> On Saturday, 10 October 2015, Strong Su  wrote:
>
> > Hello everyone,
> >  I'm still testing log4j2 on our projects.
> > When using it, I find it has a beautiful performance when using sync
> > log4j2.
> > But it turns terrible when I add -DLog4jContextSelector or change 
> to
> >  in log4j2.xml to use async log4j2.
> > I don't even have a clue on explaining this.What could cause this bizarre
> > problem?
> >
> > Thank you.
> > Best regards,
> > Dylan Su
> >
>