You are viewing a plain text version of this content. The canonical link for it is here.

Posted to log4j-user@logging.apache.org by "SMITH, CURTIS" <cs...@att.com> on 2013/07/29 16:08:49 UTC

reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Hi guys,  I mentioned this observation last week, that my embedded single core env, the VM also does not support reflection.  Is reflection used in the hot path of logging that might be affecting my testing of V2 using more CPU than v1?

>>> LOGGER.debug("sun.reflect.Reflection is not installed");   // ----------------------------

I get this log at VM startup time.

Curt
------------------------


package org.apache.logging.log4j.core.selector;

public class ClassLoaderContextSelector implements ContextSelector {

private static void setupCallerCheck() {
223         try {
224             final ClassLoader loader = Loader.getClassLoader();
225             final Class clazz = loader.loadClass("sun.reflect.Reflection");
226             final Method[] methods = clazz.getMethods();
227             for (final Method method : methods) {
228                 final int modifier = method.getModifiers();
229                 if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) {
230                     getCallerClass = method;
231                     break;
232                 }
233             }
234         } catch (final ClassNotFoundException cnfe) {
235             LOGGER.debug("sun.reflect.Reflection is not installed");   // ----------------------------
236         

-----Original Message-----
From: Remko Popma [mailto:remkop@yahoo.com] 
Sent: Saturday, July 27, 2013 5:40 AM
To: Log4J Users List; Remko Popma
Subject: Re: async logger on slow single core env performs 50% worse than log4j v1

I quickly reviewed the code and as far as I can tell:
* only the following places in Log4j-2 will create a permanent thread in addition to your application threads: AsyncLoggers, AsyncAppenders, o.a.l.l.c.net.SocketServer, o.a.l.l.c.net.UDPSocketServer and o.a.l.l.c.helpers.*CachedClock
* synchronous logging will not create any threads
* RollingFile creates a short-lived thread for the roll-over, *only* if the old file needs to be compressed to a .zip or .gz file (the file rename action is synchronous)

So I'm thinking that the difference in CPU usage is caused by something other than threads or async logging.
I'd be interested in your answers to my questions below.

Best regards,
Remko


________________________________
 From: Remko Popma <re...@yahoo.com>
To: Log4J Users List <lo...@logging.apache.org> 
Sent: Saturday, July 27, 2013 12:53 PM
Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
 

I don't think we've ever done any performance testing on the kind of environment you describe, so this is great feedback, thanks!

First, configuration via XML instead of sys props is on the todo list.

Second, you mentioned you use system property "AsyncLoggerContextSelector" to switch on AsyncLoggers.
This is incorrect. The correct key is "Log4jContextSelector" (and that would explain why removing this setting made no difference).

Third, if I understand correctly you are essentially logging to a memory-mapped file. In that case any buffering is just wasting CPU resources, so you should not use the Fast*File appenders as their buffering cannot be switched off. (Non-Fast) FileAppenders also use bufferedIO=true by default, but you can switch this off in config. I would expect this to save some CPU.

On that note, you mentioned CPU usage as your performance measure. Is that the most important number? Do you have any throughput/latency goals?
Do you have any tools on your platform to see what the CPU is doing? Which threads are busy for example?

In terms of GC, making all loggers Async has a small benefit in that it re-uses log event objects.


I am still intrigued by the difference in CPU usage you mention between log4j-1.2 and 2.0. Is your application code exactly the same? Or do you use the pattern formats that are now available in log4j-2.0?

Regards,
Remko


________________________________
From: "SMITH, CURTIS" <cs...@att.com>
To: Log4J Users List <lo...@logging.apache.org> 
Sent: Saturday, July 27, 2013 6:55 AM
Subject: RE: async logger on slow single core env performs 50% worse than log4j v1


LOL well that's obvious now.  :)  It was more a case of wishful thinking and why not give it a "try".    But it's still odd that my attempts to slim it down It's still 2x worse than v1.  Something else is in play.

curt

-----Original Message-----
From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
Sent: Friday, July 26, 2013 5:34 PM
To: Log4J Users List
Subject: Re: async logger on slow single core env performs 50% worse than log4j v1

I'm curious why you are even trying to use Async anything with a single core environment (unless it is hyper-threaded). Only 1 thread can be active at a time so when you switch threads the active thread will just stop. This won't gain you any additional throughput but you will still incur the additional overhead of thread management and locking.

Ralph

On Jul 26, 2013, at 1:55 PM, SMITH, CURTIS wrote:

> I removed  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
> No change in CPU, but going from FastRollingFile to RollingFile I got back 10% of my lost CPU.  Still at 40% CPU where v1 runs at 20%.
> 
> I would like to get down to the equivalent behavior as we got from log4j v1, then try v2 features to get it better.  Since I'm still seeing worse performance, I'm guessing that there's still one or more threads under the hood vs V1 with:  sync Logger and RollingFile.
> 
> Any guesses for me to try?
> 
> Tnx curt
> 
> _____________________________________________
> From: SMITH, CURTIS
> Sent: Friday, July 26, 2013 1:16 PM
> To: log4j-user@logging.apache.org
> Subject: async logger on slow single core env performs 50% worse than log4j v1
> 
> 
> I suspect a slow single core env is a new scenario for v2 and async logger.   My view is that there's a mis match between v2's async logger thread design that works great on multi-core envs and this embedded slow single core env...   Sooo I need to try a few different configurations to see what does run best on a slow single core...
> 
> But I need your tips as to what I might change / tune to get v2 to perform as good or better than v1 in a single core env.
> 
> FWIW:  log4j v1 ran my standard use case test averaging 20% CPU.  Log4j v2 ran at 50% CPU, so more than 2x worse.
> 
> Our business logic is highly threaded so any subsystem that has a "hot" thread like this config that has 5 loggers and 3 appenders I might be shooting myself in the foot.  You know this new design the best so I'm open as to what to pick and choose from v2 that is likely to perform the best?
> 
> FYI:  I feel using system properties vs exclusively using declarative configuration all within the log4j2.xml separates out configuration.  I'd prefer to not have to use system properties for any configuration.
> 
> My first experiment will be to remove the async logger property.
> 
> Any thoughts re the FastRollingFile appender or any other tuning that might be better for a single core env.  It's a slow Arm v5 or so, pretty old and lacking the better context switching features of newer chips.  The VM is also slow,  IBM J9 J2ME JDK1.6.   Benchmarking the J9 vs Oracle J2ME, J9 is real slow and poor at thread context switching.  But you get what you pay for, J9 is also real cheap.
> 
> ******
> ******
> Note:  the log files are on /tmp a memory FS in our env.  So the worst case of a synchronous logger from the same thread as the logger.debug call may not perform that badly thanks to Linux FS buffering and memfs having low latency.  Just mentioning.
> 
> 
> // Manually set the log4j v2 async logger tuning parameters here.  DLA does not have a system property
>                // property file
>                System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>                System.setProperty("AsyncLogger.RingBufferSize", "128");        // min size permissable to keep memory low
>                System.setProperty("AsyncLogger.WaitStrategy", "Block");        // less CPU, better for embedded env
>                System.setProperty("log4j2.disable.jmx", "true");                       // saves on a jmx jar and we don't use JMX anyway
> 
> <?xml version="1.0" encoding="UTF-8"?>
> <configuration status="trace" level="trace" >  <!-- log4j v2 debug add these: status="trace" level="trace" -->
>        <appenders>
>                <FastRollingFile name="DLA"
>                        fileName="/tmp/att/sync/log/dla.log"
>                        filePattern="/tmp/att/sync/log/dla.log.%i" append="true">
>                        <PatternLayout>
>                                <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>                        </PatternLayout>
>                        <Policies>
>                                <SizeBasedTriggeringPolicy size="3 MB" />
>                        </Policies>
>                        <DefaultRolloverStrategy max="2" />
>                </FastRollingFile>
>                <FastRollingFile name="DEVICES"
>                        fileName="/tmp/att/sync/log/dla_devices.log"
>                        filePattern="/tmp/att/sync/log/dla_devices.log.%i" append="true">
>                        <PatternLayout>
>                                <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>                        </PatternLayout>
>                        <Policies>
>                                <SizeBasedTriggeringPolicy size="3 MB" />
>                        </Policies>
>                        <DefaultRolloverStrategy max="1" />
>                </FastRollingFile>
>                <FastRollingFile name="VIDEO"
>                        fileName="/tmp/att/sync/log/dla_video.log"
>                        filePattern="/tmp/att/sync/log/dla_video.log.%i" append="true">
>                        <PatternLayout>
>                                <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>                        </PatternLayout>
>                        <Policies>
>                                <SizeBasedTriggeringPolicy size="3 MB" />
>                        </Policies>
>                        <DefaultRolloverStrategy max="1" />
>                </FastRollingFile>
>                <Console name="CO" target="SYSTEM_OUT">
>                        <PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
>                </Console>
>        </appenders>
>        <loggers>
>                <logger name="com.att.dlc.afm" additivity="false" >
>                        <appender-ref ref="DLA" />
>                </logger>
>                <logger name="com.att.dlc.devices" additivity="false" level="debug">
>                        <appender-ref ref="DEVICES" />
>                </logger>
>                <logger name="com.att.dlc.util.serialport" additivity="false" level="debug">
>                        <appender-ref ref="DEVICES" />
>                </logger>
>                <logger name="com.att.dlc.webcamserver" additivity="false" level="debug">
>                        <appender-ref ref="VIDEO" />
>                </logger>
>                <logger name="com.att.dlc.devices.cameras" additivity="false" level="debug">
>                        <appender-ref ref="VIDEO" />
>                </logger>
>                <root level="debug">
>                        <appender-ref ref="DLA" />
>                </root>
>        </loggers>
> </configuration>
> 
> Curt Smith
> AT&T Digital Life
> DLC Software Development
> 404-499-7013
> (cell) 678-365-6508
> 
> 
> 


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


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

RE: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Posted by "SMITH, CURTIS" <cs...@att.com>.

>> Are the test programs identical? I

Yes identical excepting for log4j versions and the required totally different way of configuring.

>> MDC

Not coded this yet, wanting to in one version or the other.  So no code to post since I haven't gotten to MDC vs NDC (??) yet.  Just making sure going to v2 is doable perf-wise.  We're short of CPU as it is in this env.   :)

Thanks for the help and opinions!

BTW since you guys know the details well,  we just need simple fish tagging, no location stuff, just a few context variables put into the context at event creation time on a thread, then all logs along that flow log 3-5 variables pulled from the context.  Is this doable in v1 NDC??   I would just guess a name-value look up by name in the PatternLayout shouldn’t' be much of a perf hit???

curt

-----Original Message-----
From: Remko Popma [mailto:remkop@yahoo.com] 
Sent: Tuesday, July 30, 2013 10:14 AM
To: Log4J-Users List
Subject: Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

It may be possible (but a bit of a hack) to use async loggers without reflection. It involves compiling your own version of the
com.lmax.disruptor.util.Util class where you replace the implementation of the #getUnsafe() method with a simple call to sun.misc.Unsafe.getUnsafe().
Obviously this is not pretty and there are no guarantees that you won&#x27;t get a SecurityException or so next... :-(

You may be better off using AsyncAppender if you want your blocking I/O to happen in another thread. This may still be beneficial even on a one-core machine.

Back to the difference between log4j-1.2 (20% CPU) and log4j-2.0 (40% CPU).
Are the test programs identical? I remember you mentioned below that you
use MDC with 2.0 but not with 1.2. Can you give a sample of your log4j
usage with 1.2 and with 2.0? (Maybe create a JIRA and attach files to it?)

Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Posted by Remko Popma <re...@yahoo.com>.

It may be possible (but a bit of a hack) to use async loggers without reflection. It involves compiling your own version of the
com.lmax.disruptor.util.Util class where you replace the implementation of the #getUnsafe() method with a simple call to sun.misc.Unsafe.getUnsafe().
Obviously this is not pretty and there are no guarantees that you won&#x27;t get a SecurityException or so next... :-(

You may be better off using AsyncAppender if you want your blocking I/O to happen in another thread. This may still be beneficial even on a one-core machine.

Back to the difference between log4j-1.2 (20% CPU) and log4j-2.0 (40% CPU).
Are the test programs identical? I remember you mentioned below that you
use MDC with 2.0 but not with 1.2. Can you give a sample of your log4j
usage with 1.2 and with 2.0? (Maybe create a JIRA and attach files to it?)

Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Posted by Ralph Goers <ra...@dslextreme.com>.

The exception with the Disruptor wouldn't be. It basically means you cannot use the Async Loggers. The benefit to using the BasicContextSelector is that it is lighter weight and you won't get the warning about the Sun Reflection class being missing.]

I have not tested with J2ME so I can't really say what will work and what won't.

Ralph

On Jul 29, 2013, at 2:40 PM, SMITH, CURTIS wrote:

> Hi Ralph, my exception is from the disruptor jar apparently using reflection (below).  How is that related to the ClassLoaderContextSelector?
> 
> I would have guessed that the BasicContextSelector is default???   I'm not setting Log4jContextSelector so it has to be using some context, wouldn't the default be the simplest?
> 
> 
> Is there benefit from me setting:  "Log4jContextSelector" to "org.apache.logging.log4j.core.selector.BasicContextSelector".
> 
> FWIW I'm having to give up on async logger because my VM doesn't support reflection, and unless I'm not understanding this new architecture, this exception says I'm locked out from testing async logger without reflection.
> 
> Tnx curt
> 
> -----Original Message-----
> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
> Sent: Monday, July 29, 2013 2:15 PM
> To: Log4J Users List
> Subject: Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1
> 
> Yes.  ClassLoaderContextSelector is complicated and probably not at all what you want. it uses the Sun reflection class, which you've noticed is not installed, and runs slower without it. I don't think ClassLoaderContextSelector will be of any benefit to you over BasicContextSelector.
> 
> 
> On Jul 29, 2013, at 9:05 AM, SMITH, CURTIS wrote:
> 
>> Ralph,  Was your comment about BasicContextSelector me and my quest to get V2 to run as well as V1 on my slow single core J2ME env?
>> 
>> My test run with AsyncLogger blew up.  This J2ME VM does not have reflection.  Guessing that disruptor uses reflection to cast methods/objects (bottom).
>> 
>> This leaves me with just one more experiment to get V2 to perform as well as V1:  RollingFile with bufferedIO=false
>> 
>> RE: MDC, no we'll not use any location info, just passing values like username (example) and similar  constant values from each transaction initiation into the log.  
>> 
>> 
>> #0   ERROR   > Error occurred while trying to activate bundle!
>> java.lang.ExceptionInInitializerError
>>       at java.lang.J9VMInternals.initialize(J9VMInternals.java:233)
>>       at java.lang.Class.newInstanceImpl(Native Method)
>>       at java.lang.Class.newInstance(Class.java:1279)
>>       at com.prosyst.mbs.impl.framework.BundleImpl.startIt(BundleImpl.java:4287)
>>       at com.prosyst.mbs.impl.framework.BundleImpl.simpleStart(BundleImpl.java:1744)
>>       at com.prosyst.mbs.impl.framework.BundleImpl.start0(BundleImpl.java:1642)
>>       at com.prosyst.mbs.impl.framework.BundleImpl.start0(BundleImpl.java:1515)
>>       at com.prosyst.mbs.impl.framework.BundleImpl.start(BundleImpl.java:1350)
>>       at com.prosyst.mbs.impl.framework.BundleImpl.start(BundleImpl.java:1060)
>>       at com.prosyst.mbs.impl.framework.module.boot.BootImpl.start(BootImpl.java:869)
>>       at com.prosyst.mbs.impl.framework.module.boot.BootImpl.executeBoot(BootImpl.java:386)
>>       at com.prosyst.mbs.impl.framework.module.boot.BootImpl.processDefaultBoot(BootImpl.java:163)
>>       at com.prosyst.mbs.impl.framework.module.boot.BootImpl.start(BootImpl.java:93)
>>       at com.prosyst.mbs.impl.framework.FrameworkLauncher.start(FrameworkLauncher.java:1194)
>>       at com.prosyst.mbs.impl.framework.FrameworkLauncher.finishLaunch(FrameworkLauncher.java:501)
>>       at com.prosyst.mbs.impl.framework.FrameworkLauncher.launch(FrameworkLauncher.java:476)
>>       at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:195)
>>       at java.lang.reflect.Method.invoke(Method.java:242)
>>       at com.prosyst.mbs.impl.framework.Start.processFrameworkLaunch(Start.java:196)
>>       at com.prosyst.mbs.impl.framework.Start.main(Start.java:82)
>> Caused by: java.lang.IllegalStateException: Unexpected error building Logger: null
>>       at com.att.dlc.logging.LoggerFactory.buildLogger(LoggerFactory.java:92)
>>       at com.att.dlc.logging.LoggerFactory.getLogger(LoggerFactory.java:34)
>>       at com.att.dlc.osgi.Activator.<clinit>(Activator.java:120)
>>       at java.lang.J9VMInternals.initializeImpl(Native Method)
>>       at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>>       ... 19 more
>> Caused by: java.lang.reflect.InvocationTargetException
>>       at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:197)
>>       at java.lang.reflect.Constructor.newInstance(Constructor.java:204)
>>       at com.att.dlc.logging.LoggerFactory.buildLogger(LoggerFactory.java:89)
>>       ... 23 more
>> Caused by: java.lang.ExceptionInInitializerError
>>       at java.lang.J9VMInternals.initialize(J9VMInternals.java:233)
>>       at org.apache.logging.log4j.core.async.AsyncLogger.calculateRingBufferSize(AsyncLogger.java:123)
>>       at org.apache.logging.log4j.core.async.AsyncLogger.<clinit>(AsyncLogger.java:89)
>>       at java.lang.J9VMInternals.initializeImpl(Native Method)
>>       at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>>       at org.apache.logging.log4j.core.async.AsyncLoggerContext.newInstance(AsyncLoggerContext.java:51)
>>       at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:274)
>>       at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:255)
>>       at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:51)
>>       at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:364)
>>       at com.att.dlc.logging.Log4jLogger.<init>(Log4jLogger.java:38)
>>       at com.att.dlc.logging.Log4jLogger.<init>(Log4jLogger.java:46)
>>       at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:195)
>>       ... 25 more
>> Caused by: java.lang.RuntimeException: Unable to load unsafe
>>       at com.lmax.disruptor.util.Util.<clinit>(Util.java:112)
>>       at java.lang.J9VMInternals.initializeImpl(Native Method)
>>       at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>>       ... 37 more
>> Caused by: java.security.PrivilegedActionException: java.lang.NoSuchFieldException: theUnsafe
>>       at java.security.AccessController.doPrivileged(AccessController.java:259)
>>       at com.lmax.disruptor.util.Util.<clinit>(Util.java:108)
>>       ... 39 more
>> Caused by: java.lang.NoSuchFieldException: theUnsafe
>>       at java.lang.Class.getDeclaredFieldImpl(Native Method)
>>       at java.lang.Class.getDeclaredField(Class.java:487)
>>       at com.lmax.disruptor.util.Util$1.run(Util.java:102)
>>       at com.lmax.disruptor.util.Util$1.run(Util.java:99)
>>       at java.security.AccessController.doPrivileged(AccessController.java:255)
>>       ... 40 more
>> 
>> 
>> 
>> 
>> 
>> 
>> 
>> 
>> 
>> 
>> -----Original Message-----
>> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
>> Sent: Monday, July 29, 2013 11:05 AM
>> To: Log4J Users List
>> Subject: Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> This probably warrants an enhancement to Log4jContextFactory. I can imagine other use cases where defaulting to BasicContextSelector also makes sense.
>> 
>> Ralph
>> 
>> On Jul 29, 2013, at 8:02 AM, Ralph Goers wrote:
>> 
>>> In your environment I would definitely recommend using BasicContextSelector as you are unlikely to have need for multiple LoggerContexts.
>>> 
>>> Ralph
>>> 
>>> On Jul 29, 2013, at 7:08 AM, SMITH, CURTIS wrote:
>>> 
>>>> Hi guys,  I mentioned this observation last week, that my embedded single core env, the VM also does not support reflection.  Is reflection used in the hot path of logging that might be affecting my testing of V2 using more CPU than v1?
>>>> 
>>>>>>> LOGGER.debug("sun.reflect.Reflection is not installed");   // Ã∞Â¯Ã¢â√˚Ä±Ã∫â•˚----------------------------
>>>> 
>>>> I get this log at VM startup time.
>>>> 
>>>> Curt
>>>> ------------------------
>>>> 
>>>> 
>>>> package org.apache.logging.log4j.core.selector;
>>>> 
>>>> public class ClassLoaderContextSelector implements ContextSelector {
>>>> 
>>>> private static void setupCallerCheck() {
>>>> 223         try {
>>>> 224             final ClassLoader loader = Loader.getClassLoader();
>>>> 225             final Class clazz = loader.loadClass("sun.reflect.Reflection");
>>>> 226             final Method[] methods = clazz.getMethods();
>>>> 227             for (final Method method : methods) {
>>>> 228                 final int modifier = method.getModifiers();
>>>> 229                 if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) {
>>>> 230                     getCallerClass = method;
>>>> 231                     break;
>>>> 232                 }
>>>> 233             }
>>>> 234         } catch (final ClassNotFoundException cnfe) {
>>>> 235             LOGGER.debug("sun.reflect.Reflection is not installed");   // Ã∞Â¯Ã¢â√˚Ä±Ã∫â•˚----------------------------
>>>> 236         
>>>> 
>>>> -----Original Message-----
>>>> From: Remko Popma [mailto:remkop@yahoo.com] 
>>>> Sent: Saturday, July 27, 2013 5:40 AM
>>>> To: Log4J Users List; Remko Popma
>>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>>> 
>>>> I quickly reviewed the code and as far as I can tell:
>>>> * only the following places in Log4j-2 will create a permanent thread in addition to your application threads:Ã∞â≈  AsyncLoggers, AsyncAppenders, o.a.l.l.c.net.SocketServer,Ã∞â≈  o.a.l.l.c.net.UDPSocketServer andÃ∞â≈  o.a.l.l.c.helpers.*CachedClock
>>>> * synchronous logging will not create any threads
>>>> * RollingFile creates a short-lived thread for the roll-over, *only*Ã∞â≈  if the old file needs to be compressed to a .zip or .gz file (the file rename action is synchronous)
>>>> 
>>>> So I'm thinking that the difference in CPU usage is caused by something other than threads or async logging.
>>>> I'd be interested in your answers to my questions below.
>>>> 
>>>> Best regards,
>>>> Remko
>>>> 
>>>> 
>>>> ________________________________
>>>> From: Remko Popma <re...@yahoo.com>
>>>> To: Log4J Users List <lo...@logging.apache.org> 
>>>> Sent: Saturday, July 27, 2013 12:53 PM
>>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>>> 
>>>> 
>>>> I don't think we've ever done any performance testing on the kind of environment you describe, so this is great feedback, thanks!
>>>> 
>>>> First, configuration via XML instead of sys props is on the todo list.
>>>> 
>>>> Second, you mentioned you use system property "AsyncLoggerContextSelector" to switch on AsyncLoggers.
>>>> This is incorrect. The correct key is "Log4jContextSelector" (and that would explain why removing this setting made no difference).
>>>> 
>>>> Third, if I understand correctly you are essentially logging to a memory-mapped file. In that case any buffering is just wasting CPU resources, so you should not use the Fast*File appenders as their buffering cannot be switched off. (Non-Fast) FileAppenders also use bufferedIO=true by default, but you can switch this off in config. I would expect this to save some CPU.
>>>> 
>>>> On that note, you mentioned CPU usage as your performance measure. Is that the most important number? Do you have any throughput/latency goals?
>>>> Do you have any tools on your platform to see what the CPU is doing? Which threads are busy for example?
>>>> 
>>>> In terms of GC, making all loggers Async has a small benefit in that it re-uses log event objects.
>>>> 
>>>> 
>>>> I am still intrigued by the difference in CPU usage you mention between log4j-1.2 and 2.0. Is your application code exactly the same? Or do you use the pattern formats that are now available in log4j-2.0?
>>>> 
>>>> Regards,
>>>> Remko
>>>> 
>>>> 
>>>> ________________________________
>>>> From: "SMITH, CURTIS" <cs...@att.com>
>>>> To: Log4J Users List <lo...@logging.apache.org> 
>>>> Sent: Saturday, July 27, 2013 6:55 AM
>>>> Subject: RE: async logger on slow single core env performs 50% worse than log4j v1
>>>> 
>>>> 
>>>> LOL well that's obvious now.Ã∞â≈   :)Ã∞â≈   It was more a case of wishful thinking and why not give it a "try".Ã∞â≈   Ã∞â≈   But it's still odd that my attempts to slim it down It's still 2x worse than v1.Ã∞â≈   Something else is in play.
>>>> 
>>>> curt
>>>> 
>>>> -----Original Message-----
>>>> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
>>>> Sent: Friday, July 26, 2013 5:34 PM
>>>> To: Log4J Users List
>>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>>> 
>>>> I'm curious why you are even trying to use Async anything with a single core environment (unless it is hyper-threaded). Only 1 thread can be active at a time so when you switch threads the active thread will just stop. This won't gain you any additional throughput but you will still incur the additional overhead of thread management and locking.
>>>> 
>>>> Ralph
>>>> 
>>>> On Jul 26, 2013, at 1:55 PM, SMITH, CURTIS wrote:
>>>> 
>>>>> I removedÃ∞â≈   System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>>>> No change in CPU, but going from FastRollingFile to RollingFile I got back 10% of my lost CPU.Ã∞â≈   Still at 40% CPU where v1 runs at 20%.
>>>>> 
>>>>> I would like to get down to the equivalent behavior as we got from log4j v1, then try v2 features to get it better.Ã∞â≈   Since I'm still seeing worse performance, I'm guessing that there's still one or more threads under the hood vs V1 with:Ã∞â≈   sync Logger and RollingFile.
>>>>> 
>>>>> Any guesses for me to try?
>>>>> 
>>>>> Tnx curt
>>>>> 
>>>>> _____________________________________________
>>>>> From: SMITH, CURTIS
>>>>> Sent: Friday, July 26, 2013 1:16 PM
>>>>> To: log4j-user@logging.apache.org
>>>>> Subject: async logger on slow single core env performs 50% worse than log4j v1
>>>>> 
>>>>> 
>>>>> I suspect a slow single core env is a new scenario for v2 and async logger.Ã∞â≈  Ã∞â≈   My view is that there's a mis match between v2's async logger thread design that works great on multi-core envs and this embedded slow single core env...Ã∞â≈  Ã∞â≈   Sooo I need to try a few different configurations to see what does run best on a slow single core...
>>>>> 
>>>>> But I need your tips as to what I might change / tune to get v2 to perform as good or better than v1 in a single core env.
>>>>> 
>>>>> FWIW:Ã∞â≈   log4j v1 ran my standard use case test averaging 20% CPU.Ã∞â≈   Log4j v2 ran at 50% CPU, so more than 2x worse.
>>>>> 
>>>>> Our business logic is highly threaded so any subsystem that has a "hot" thread like this config that has 5 loggers and 3 appenders I might be shooting myself in the foot.Ã∞â≈   You know this new design the best so I'm open as to what to pick and choose from v2 that is likely to perform the best?
>>>>> 
>>>>> FYI:Ã∞â≈   I feel using system properties vs exclusively using declarative configuration all within the log4j2.xml separates out configuration.Ã∞â≈   I'd prefer to not have to use system properties for any configuration.
>>>>> 
>>>>> My first experiment will be to remove the async logger property.
>>>>> 
>>>>> Any thoughts re the FastRollingFile appender or any other tuning that might be better for a single core env.Ã∞â≈   It's a slow Arm v5 or so, pretty old and lacking the better context switching features of newer chips.Ã∞â≈   The VM is also slow,Ã∞â≈   IBM J9 J2ME JDK1.6.Ã∞â≈  Ã∞â≈   Benchmarking the J9 vs Oracle J2ME, J9 is real slow and poor at thread context switching.Ã∞â≈   But you get what you pay for, J9 is also real cheap.
>>>>> 
>>>>> ******
>>>>> ******
>>>>> Note:Ã∞â≈   the log files are on /tmp a memory FS in our env.Ã∞â≈   So the worst case of a synchronous logger from the same thread as the logger.debug call may not perform that badly thanks to Linux FS buffering and memfs having low latency.Ã∞â≈   Just mentioning.
>>>>> 
>>>>> 
>>>>> // Manually set the log4j v2 async logger tuning parameters here.Ã∞â≈   DLA does not have a system property
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   // property file
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   System.setProperty("AsyncLogger.RingBufferSize", "128");Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   // min size permissable to keep memory low
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   System.setProperty("AsyncLogger.WaitStrategy", "Block");Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   // less CPU, better for embedded env
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   System.setProperty("log4j2.disable.jmx", "true");Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈  Ã∞â≈   // saves on a jmx jar and we don't use JMX anyway
>>>>> 
>>>>> <?xml version="1.0" encoding="UTF-8"?>
>>>>> <configuration status="trace" level="trace" >Ã∞â≈   <!-- log4j v2 debug add these: status="trace" level="trace" -->
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <appenders>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <FastRollingFile name="DLA"
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   fileName="/tmp/att/sync/log/dla.log"
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   filePattern="/tmp/att/sync/log/dla.log.%i" append="true">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <PatternLayout>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </PatternLayout>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <Policies>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <SizeBasedTriggeringPolicy size="3 MB" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </Policies>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <DefaultRolloverStrategy max="2" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </FastRollingFile>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <FastRollingFile name="DEVICES"
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   fileName="/tmp/att/sync/log/dla_devices.log"
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   filePattern="/tmp/att/sync/log/dla_devices.log.%i" append="true">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <PatternLayout>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </PatternLayout>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <Policies>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <SizeBasedTriggeringPolicy size="3 MB" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </Policies>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <DefaultRolloverStrategy max="1" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </FastRollingFile>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <FastRollingFile name="VIDEO"
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   fileName="/tmp/att/sync/log/dla_video.log"
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   filePattern="/tmp/att/sync/log/dla_video.log.%i" append="true">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <PatternLayout>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </PatternLayout>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <Policies>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <SizeBasedTriggeringPolicy size="3 MB" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </Policies>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <DefaultRolloverStrategy max="1" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </FastRollingFile>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <Console name="CO" target="SYSTEM_OUT">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </Console>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </appenders>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <loggers>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <logger name="com.att.dlc.afm" additivity="false" >
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <appender-ref ref="DLA" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </logger>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <logger name="com.att.dlc.devices" additivity="false" level="debug">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <appender-ref ref="DEVICES" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </logger>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <logger name="com.att.dlc.util.serialport" additivity="false" level="debug">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <appender-ref ref="DEVICES" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </logger>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <logger name="com.att.dlc.webcamserver" additivity="false" level="debug">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <appender-ref ref="VIDEO" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </logger>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <logger name="com.att.dlc.devices.cameras" additivity="false" level="debug">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <appender-ref ref="VIDEO" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </logger>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <root level="debug">
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   <appender-ref ref="DLA" />
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </root>
>>>>> Ã∞â≈   Ã∞â≈   Ã∞â≈   Ã∞â≈   </loggers>
>>>>> </configuration>
>>>>> 
>>>>> Curt Smith
>>>>> AT&T Digital Life
>>>>> DLC Software Development
>>>>> 404-499-7013
>>>>> (cell) 678-365-6508
>>>>> 
>>>>> 
>>>>> 
>>>> 
>>>> 
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>> 
>>>> 
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>> Ã¢â•¢â•˙Ã≠Â¢Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã∞â•˚Ã¢â•¢â•˙Ã¢â•¢â•˙Ã≠Â¥FÃ∞â•ˇ
>> VÃ∞Â§7V'67&Ã—â√«&RÃ∞â≈ RÃ∞Ë∫Ã∞Ë∫Ã—â√«Ã∞â√ıÃ≠Â¢Ã∞â√«Ã∞Â¶sFÃ≠Â¢Ã¢Ë˛â•œW6W"Ã¢Ë˛â•œVÃ∞Â§7V'67&Ã—â√«&TÃ∞â√«Ã∞Â¶vvÃ—â√«Ã∞Å„rÃ∞Å„6Ã¢â√˚Â«RÃ∞Å„Ã∞Â·&pÃ¢â•¢â•˙Ã≠Â¤fÃ∞Â·"FFÃ—Ë˝FÃ—â√«Ã∞Â¶Ã∞Å„Ã∞â≈ 6Ã∞Â¶Ã∞Ë∫Ã∞Ë∫Ã∞Å„G2Ã∞â≈ RÃ∞Ë∫Ã∞Ë∫Ã—â√«Ã∞â√ıÃ≠Â¢Ã∞â√«Ã∞Â¶sFÃ≠Â¢Ã¢Ë˛â•œW6W"Ã∞Ë∫Ã¢â√˚Â«VÃ∞Î©Ã∞â√«Ã∞Â¶vvÃ—â√«Ã∞Å„rÃ∞Å„6Ã¢â√˚Â«RÃ∞Å„Ã∞Â·&pÃ¢â•¢â•˙ 
>>> 
>> 
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>> 
>> â•’Â¢Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚â•’â•’Â¥FÃ”
> VÃ§7V'67&Ë∫&RÃ≠RÃˆÃˆË∫Ã∞Â¢Ã∫Ã¶sFÂ¢â˜…W6W"â˜…VÃ§7V'67&Ë∫&TÃ∫Ã¶vvË∫ÃœrÃœ6â√«RÃœÃ·&pâ•’Â¤fÃ·"FFË˛FË∫Ã¶ÃœÃ≠6Ã¶ÃˆÃˆÃœG2Ã≠RÃˆÃˆË∫Ã∞Â¢Ã∫Ã¶sFÂ¢â˜…W6W"Ãˆâ√«VÃΩÃ∫Ã¶vvË∫ÃœrÃœ6â√«RÃœÃ·&pâ•’ 
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
> 
> B—KKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKCBÈ[˛†X˛ØÜ˚X˙KK[XZ[√ÙÍ—]\Ù\—][˛†X˛ØÜ˚X˙PÙÙÚ[˙Ë˘\XÚK˝Ü˙ÃBŒ˝Ü√Y][€˘[€€[X[˙ËK[XZ[√ÙÍ—]\Ù\—Z[ÙÙÚ[˙Ë˘\XÚK˝Ü˙ÃB∞


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

RE: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Posted by "SMITH, CURTIS" <cs...@att.com>.

Hi Ralph, my exception is from the disruptor jar apparently using reflection (below).  How is that related to the ClassLoaderContextSelector?

I would have guessed that the BasicContextSelector is default???   I'm not setting Log4jContextSelector so it has to be using some context, wouldn't the default be the simplest?


Is there benefit from me setting:  "Log4jContextSelector" to "org.apache.logging.log4j.core.selector.BasicContextSelector".

FWIW I'm having to give up on async logger because my VM doesn't support reflection, and unless I'm not understanding this new architecture, this exception says I'm locked out from testing async logger without reflection.

Tnx curt

-----Original Message-----
From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
Sent: Monday, July 29, 2013 2:15 PM
To: Log4J Users List
Subject: Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Yes.  ClassLoaderContextSelector is complicated and probably not at all what you want. it uses the Sun reflection class, which you've noticed is not installed, and runs slower without it. I don't think ClassLoaderContextSelector will be of any benefit to you over BasicContextSelector.


On Jul 29, 2013, at 9:05 AM, SMITH, CURTIS wrote:

> Ralph,  Was your comment about BasicContextSelector me and my quest to get V2 to run as well as V1 on my slow single core J2ME env?
> 
> My test run with AsyncLogger blew up.  This J2ME VM does not have reflection.  Guessing that disruptor uses reflection to cast methods/objects (bottom).
> 
> This leaves me with just one more experiment to get V2 to perform as well as V1:  RollingFile with bufferedIO=false
> 
> RE: MDC, no we'll not use any location info, just passing values like username (example) and similar  constant values from each transaction initiation into the log.  
> 
> 
> #0   ERROR   > Error occurred while trying to activate bundle!
> java.lang.ExceptionInInitializerError
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:233)
>        at java.lang.Class.newInstanceImpl(Native Method)
>        at java.lang.Class.newInstance(Class.java:1279)
>        at com.prosyst.mbs.impl.framework.BundleImpl.startIt(BundleImpl.java:4287)
>        at com.prosyst.mbs.impl.framework.BundleImpl.simpleStart(BundleImpl.java:1744)
>        at com.prosyst.mbs.impl.framework.BundleImpl.start0(BundleImpl.java:1642)
>        at com.prosyst.mbs.impl.framework.BundleImpl.start0(BundleImpl.java:1515)
>        at com.prosyst.mbs.impl.framework.BundleImpl.start(BundleImpl.java:1350)
>        at com.prosyst.mbs.impl.framework.BundleImpl.start(BundleImpl.java:1060)
>        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.start(BootImpl.java:869)
>        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.executeBoot(BootImpl.java:386)
>        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.processDefaultBoot(BootImpl.java:163)
>        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.start(BootImpl.java:93)
>        at com.prosyst.mbs.impl.framework.FrameworkLauncher.start(FrameworkLauncher.java:1194)
>        at com.prosyst.mbs.impl.framework.FrameworkLauncher.finishLaunch(FrameworkLauncher.java:501)
>        at com.prosyst.mbs.impl.framework.FrameworkLauncher.launch(FrameworkLauncher.java:476)
>        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:195)
>        at java.lang.reflect.Method.invoke(Method.java:242)
>        at com.prosyst.mbs.impl.framework.Start.processFrameworkLaunch(Start.java:196)
>        at com.prosyst.mbs.impl.framework.Start.main(Start.java:82)
> Caused by: java.lang.IllegalStateException: Unexpected error building Logger: null
>        at com.att.dlc.logging.LoggerFactory.buildLogger(LoggerFactory.java:92)
>        at com.att.dlc.logging.LoggerFactory.getLogger(LoggerFactory.java:34)
>        at com.att.dlc.osgi.Activator.<clinit>(Activator.java:120)
>        at java.lang.J9VMInternals.initializeImpl(Native Method)
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>        ... 19 more
> Caused by: java.lang.reflect.InvocationTargetException
>        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:197)
>        at java.lang.reflect.Constructor.newInstance(Constructor.java:204)
>        at com.att.dlc.logging.LoggerFactory.buildLogger(LoggerFactory.java:89)
>        ... 23 more
> Caused by: java.lang.ExceptionInInitializerError
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:233)
>        at org.apache.logging.log4j.core.async.AsyncLogger.calculateRingBufferSize(AsyncLogger.java:123)
>        at org.apache.logging.log4j.core.async.AsyncLogger.<clinit>(AsyncLogger.java:89)
>        at java.lang.J9VMInternals.initializeImpl(Native Method)
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>        at org.apache.logging.log4j.core.async.AsyncLoggerContext.newInstance(AsyncLoggerContext.java:51)
>        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:274)
>        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:255)
>        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:51)
>        at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:364)
>        at com.att.dlc.logging.Log4jLogger.<init>(Log4jLogger.java:38)
>        at com.att.dlc.logging.Log4jLogger.<init>(Log4jLogger.java:46)
>        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:195)
>        ... 25 more
> Caused by: java.lang.RuntimeException: Unable to load unsafe
>        at com.lmax.disruptor.util.Util.<clinit>(Util.java:112)
>        at java.lang.J9VMInternals.initializeImpl(Native Method)
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>        ... 37 more
> Caused by: java.security.PrivilegedActionException: java.lang.NoSuchFieldException: theUnsafe
>        at java.security.AccessController.doPrivileged(AccessController.java:259)
>        at com.lmax.disruptor.util.Util.<clinit>(Util.java:108)
>        ... 39 more
> Caused by: java.lang.NoSuchFieldException: theUnsafe
>        at java.lang.Class.getDeclaredFieldImpl(Native Method)
>        at java.lang.Class.getDeclaredField(Class.java:487)
>        at com.lmax.disruptor.util.Util$1.run(Util.java:102)
>        at com.lmax.disruptor.util.Util$1.run(Util.java:99)
>        at java.security.AccessController.doPrivileged(AccessController.java:255)
>        ... 40 more
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> -----Original Message-----
> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
> Sent: Monday, July 29, 2013 11:05 AM
> To: Log4J Users List
> Subject: Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1
> 
> This probably warrants an enhancement to Log4jContextFactory. I can imagine other use cases where defaulting to BasicContextSelector also makes sense.
> 
> Ralph
> 
> On Jul 29, 2013, at 8:02 AM, Ralph Goers wrote:
> 
>> In your environment I would definitely recommend using BasicContextSelector as you are unlikely to have need for multiple LoggerContexts.
>> 
>> Ralph
>> 
>> On Jul 29, 2013, at 7:08 AM, SMITH, CURTIS wrote:
>> 
>>> Hi guys,  I mentioned this observation last week, that my embedded single core env, the VM also does not support reflection.  Is reflection used in the hot path of logging that might be affecting my testing of V2 using more CPU than v1?
>>> 
>>>>>> LOGGER.debug("sun.reflect.Reflection is not installed");   // Ã¯â√ıÆ‚----------------------------
>>> 
>>> I get this log at VM startup time.
>>> 
>>> Curt
>>> ------------------------
>>> 
>>> 
>>> package org.apache.logging.log4j.core.selector;
>>> 
>>> public class ClassLoaderContextSelector implements ContextSelector {
>>> 
>>> private static void setupCallerCheck() {
>>> 223         try {
>>> 224             final ClassLoader loader = Loader.getClassLoader();
>>> 225             final Class clazz = loader.loadClass("sun.reflect.Reflection");
>>> 226             final Method[] methods = clazz.getMethods();
>>> 227             for (final Method method : methods) {
>>> 228                 final int modifier = method.getModifiers();
>>> 229                 if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) {
>>> 230                     getCallerClass = method;
>>> 231                     break;
>>> 232                 }
>>> 233             }
>>> 234         } catch (final ClassNotFoundException cnfe) {
>>> 235             LOGGER.debug("sun.reflect.Reflection is not installed");   // Ã¯â√ıÆ‚----------------------------
>>> 236         
>>> 
>>> -----Original Message-----
>>> From: Remko Popma [mailto:remkop@yahoo.com] 
>>> Sent: Saturday, July 27, 2013 5:40 AM
>>> To: Log4J Users List; Remko Popma
>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> I quickly reviewed the code and as far as I can tell:
>>> * only the following places in Log4j-2 will create a permanent thread in addition to your application threads:Ã≠ AsyncLoggers, AsyncAppenders, o.a.l.l.c.net.SocketServer,Ã≠ o.a.l.l.c.net.UDPSocketServer andÃ≠ o.a.l.l.c.helpers.*CachedClock
>>> * synchronous logging will not create any threads
>>> * RollingFile creates a short-lived thread for the roll-over, *only*Ã≠ if the old file needs to be compressed to a .zip or .gz file (the file rename action is synchronous)
>>> 
>>> So I'm thinking that the difference in CPU usage is caused by something other than threads or async logging.
>>> I'd be interested in your answers to my questions below.
>>> 
>>> Best regards,
>>> Remko
>>> 
>>> 
>>> ________________________________
>>> From: Remko Popma <re...@yahoo.com>
>>> To: Log4J Users List <lo...@logging.apache.org> 
>>> Sent: Saturday, July 27, 2013 12:53 PM
>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> 
>>> I don't think we've ever done any performance testing on the kind of environment you describe, so this is great feedback, thanks!
>>> 
>>> First, configuration via XML instead of sys props is on the todo list.
>>> 
>>> Second, you mentioned you use system property "AsyncLoggerContextSelector" to switch on AsyncLoggers.
>>> This is incorrect. The correct key is "Log4jContextSelector" (and that would explain why removing this setting made no difference).
>>> 
>>> Third, if I understand correctly you are essentially logging to a memory-mapped file. In that case any buffering is just wasting CPU resources, so you should not use the Fast*File appenders as their buffering cannot be switched off. (Non-Fast) FileAppenders also use bufferedIO=true by default, but you can switch this off in config. I would expect this to save some CPU.
>>> 
>>> On that note, you mentioned CPU usage as your performance measure. Is that the most important number? Do you have any throughput/latency goals?
>>> Do you have any tools on your platform to see what the CPU is doing? Which threads are busy for example?
>>> 
>>> In terms of GC, making all loggers Async has a small benefit in that it re-uses log event objects.
>>> 
>>> 
>>> I am still intrigued by the difference in CPU usage you mention between log4j-1.2 and 2.0. Is your application code exactly the same? Or do you use the pattern formats that are now available in log4j-2.0?
>>> 
>>> Regards,
>>> Remko
>>> 
>>> 
>>> ________________________________
>>> From: "SMITH, CURTIS" <cs...@att.com>
>>> To: Log4J Users List <lo...@logging.apache.org> 
>>> Sent: Saturday, July 27, 2013 6:55 AM
>>> Subject: RE: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> 
>>> LOL well that's obvious now.Ã≠  :)Ã≠  It was more a case of wishful thinking and why not give it a "try".Ã≠  Ã≠  But it's still odd that my attempts to slim it down It's still 2x worse than v1.Ã≠  Something else is in play.
>>> 
>>> curt
>>> 
>>> -----Original Message-----
>>> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
>>> Sent: Friday, July 26, 2013 5:34 PM
>>> To: Log4J Users List
>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> I'm curious why you are even trying to use Async anything with a single core environment (unless it is hyper-threaded). Only 1 thread can be active at a time so when you switch threads the active thread will just stop. This won't gain you any additional throughput but you will still incur the additional overhead of thread management and locking.
>>> 
>>> Ralph
>>> 
>>> On Jul 26, 2013, at 1:55 PM, SMITH, CURTIS wrote:
>>> 
>>>> I removedÃ≠  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>>> No change in CPU, but going from FastRollingFile to RollingFile I got back 10% of my lost CPU.Ã≠  Still at 40% CPU where v1 runs at 20%.
>>>> 
>>>> I would like to get down to the equivalent behavior as we got from log4j v1, then try v2 features to get it better.Ã≠  Since I'm still seeing worse performance, I'm guessing that there's still one or more threads under the hood vs V1 with:Ã≠  sync Logger and RollingFile.
>>>> 
>>>> Any guesses for me to try?
>>>> 
>>>> Tnx curt
>>>> 
>>>> _____________________________________________
>>>> From: SMITH, CURTIS
>>>> Sent: Friday, July 26, 2013 1:16 PM
>>>> To: log4j-user@logging.apache.org
>>>> Subject: async logger on slow single core env performs 50% worse than log4j v1
>>>> 
>>>> 
>>>> I suspect a slow single core env is a new scenario for v2 and async logger.Ã≠ Ã≠  My view is that there's a mis match between v2's async logger thread design that works great on multi-core envs and this embedded slow single core env...Ã≠ Ã≠  Sooo I need to try a few different configurations to see what does run best on a slow single core...
>>>> 
>>>> But I need your tips as to what I might change / tune to get v2 to perform as good or better than v1 in a single core env.
>>>> 
>>>> FWIW:Ã≠  log4j v1 ran my standard use case test averaging 20% CPU.Ã≠  Log4j v2 ran at 50% CPU, so more than 2x worse.
>>>> 
>>>> Our business logic is highly threaded so any subsystem that has a "hot" thread like this config that has 5 loggers and 3 appenders I might be shooting myself in the foot.Ã≠  You know this new design the best so I'm open as to what to pick and choose from v2 that is likely to perform the best?
>>>> 
>>>> FYI:Ã≠  I feel using system properties vs exclusively using declarative configuration all within the log4j2.xml separates out configuration.Ã≠  I'd prefer to not have to use system properties for any configuration.
>>>> 
>>>> My first experiment will be to remove the async logger property.
>>>> 
>>>> Any thoughts re the FastRollingFile appender or any other tuning that might be better for a single core env.Ã≠  It's a slow Arm v5 or so, pretty old and lacking the better context switching features of newer chips.Ã≠  The VM is also slow,Ã≠  IBM J9 J2ME JDK1.6.Ã≠ Ã≠  Benchmarking the J9 vs Oracle J2ME, J9 is real slow and poor at thread context switching.Ã≠  But you get what you pay for, J9 is also real cheap.
>>>> 
>>>> ******
>>>> ******
>>>> Note:Ã≠  the log files are on /tmp a memory FS in our env.Ã≠  So the worst case of a synchronous logger from the same thread as the logger.debug call may not perform that badly thanks to Linux FS buffering and memfs having low latency.Ã≠  Just mentioning.
>>>> 
>>>> 
>>>> // Manually set the log4j v2 async logger tuning parameters here.Ã≠  DLA does not have a system property
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  // property file
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  System.setProperty("AsyncLogger.RingBufferSize", "128");Ã≠  Ã≠  Ã≠  Ã≠  // min size permissable to keep memory low
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  System.setProperty("AsyncLogger.WaitStrategy", "Block");Ã≠  Ã≠  Ã≠  Ã≠  // less CPU, better for embedded env
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  System.setProperty("log4j2.disable.jmx", "true");Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠ Ã≠  // saves on a jmx jar and we don't use JMX anyway
>>>> 
>>>> <?xml version="1.0" encoding="UTF-8"?>
>>>> <configuration status="trace" level="trace" >Ã≠  <!-- log4j v2 debug add these: status="trace" level="trace" -->
>>>> Ã≠  Ã≠  Ã≠  Ã≠  <appenders>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <FastRollingFile name="DLA"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  fileName="/tmp/att/sync/log/dla.log"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  filePattern="/tmp/att/sync/log/dla.log.%i" append="true">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <SizeBasedTriggeringPolicy size="3 MB" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <DefaultRolloverStrategy max="2" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </FastRollingFile>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <FastRollingFile name="DEVICES"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  fileName="/tmp/att/sync/log/dla_devices.log"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  filePattern="/tmp/att/sync/log/dla_devices.log.%i" append="true">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <SizeBasedTriggeringPolicy size="3 MB" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <DefaultRolloverStrategy max="1" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </FastRollingFile>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <FastRollingFile name="VIDEO"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  fileName="/tmp/att/sync/log/dla_video.log"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  filePattern="/tmp/att/sync/log/dla_video.log.%i" append="true">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <SizeBasedTriggeringPolicy size="3 MB" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <DefaultRolloverStrategy max="1" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </FastRollingFile>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <Console name="CO" target="SYSTEM_OUT">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </Console>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  </appenders>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  <loggers>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.afm" additivity="false" >
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="DLA" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.devices" additivity="false" level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="DEVICES" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.util.serialport" additivity="false" level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="DEVICES" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.webcamserver" additivity="false" level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="VIDEO" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.devices.cameras" additivity="false" level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="VIDEO" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <root level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="DLA" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </root>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  </loggers>
>>>> </configuration>
>>>> 
>>>> Curt Smith
>>>> AT&T Digital Life
>>>> DLC Software Development
>>>> 404-499-7013
>>>> (cell) 678-365-6508
>>>> 
>>>> 
>>>> 
>>> 
>>> 
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>> 
>>> 
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>> â•’Â¢Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚â•’â•’Â¥FÃ”
> VÃ§7V'67&Ë∫&RÃ≠RÃˆÃˆË∫Ã∞Â¢Ã∫Ã¶sFÂ¢â˜…W6W"â˜…VÃ§7V'67&Ë∫&TÃ∫Ã¶vvË∫ÃœrÃœ6â√«RÃœÃ·&pâ•’Â¤fÃ·"FFË˛FË∫Ã¶ÃœÃ≠6Ã¶ÃˆÃˆÃœG2Ã≠RÃˆÃˆË∫Ã∞Â¢Ã∫Ã¶sFÂ¢â˜…W6W"Ãˆâ√«VÃΩÃ∫Ã¶vvË∫ÃœrÃœ6â√«RÃœÃ·&pâ•’ 
>> 
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
> 
> ‹¢ÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒ‹‹¥Fò
Vç7V'67&ˆ&RÂRÖÖˆÃ¢ÆösF¢◊W6W"◊Vç7V'67&ˆ&TÆövvˆæræ6∫Ræ÷&p‹¤f÷"FF˜FˆöæÂ6öÖÖæG2ÂRÖÖˆÃ¢ÆösF¢◊W6W"Ö∫VÇÆövvˆæræ6∫Ræ÷&p‹ 


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

Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Posted by Ralph Goers <ra...@dslextreme.com>.

Yes.  ClassLoaderContextSelector is complicated and probably not at all what you want. it uses the Sun reflection class, which you've noticed is not installed, and runs slower without it. I don't think ClassLoaderContextSelector will be of any benefit to you over BasicContextSelector.


On Jul 29, 2013, at 9:05 AM, SMITH, CURTIS wrote:

> Ralph,  Was your comment about BasicContextSelector me and my quest to get V2 to run as well as V1 on my slow single core J2ME env?
> 
> My test run with AsyncLogger blew up.  This J2ME VM does not have reflection.  Guessing that disruptor uses reflection to cast methods/objects (bottom).
> 
> This leaves me with just one more experiment to get V2 to perform as well as V1:  RollingFile with bufferedIO=false
> 
> RE: MDC, no we'll not use any location info, just passing values like username (example) and similar  constant values from each transaction initiation into the log.  
> 
> 
> #0   ERROR   > Error occurred while trying to activate bundle!
> java.lang.ExceptionInInitializerError
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:233)
>        at java.lang.Class.newInstanceImpl(Native Method)
>        at java.lang.Class.newInstance(Class.java:1279)
>        at com.prosyst.mbs.impl.framework.BundleImpl.startIt(BundleImpl.java:4287)
>        at com.prosyst.mbs.impl.framework.BundleImpl.simpleStart(BundleImpl.java:1744)
>        at com.prosyst.mbs.impl.framework.BundleImpl.start0(BundleImpl.java:1642)
>        at com.prosyst.mbs.impl.framework.BundleImpl.start0(BundleImpl.java:1515)
>        at com.prosyst.mbs.impl.framework.BundleImpl.start(BundleImpl.java:1350)
>        at com.prosyst.mbs.impl.framework.BundleImpl.start(BundleImpl.java:1060)
>        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.start(BootImpl.java:869)
>        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.executeBoot(BootImpl.java:386)
>        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.processDefaultBoot(BootImpl.java:163)
>        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.start(BootImpl.java:93)
>        at com.prosyst.mbs.impl.framework.FrameworkLauncher.start(FrameworkLauncher.java:1194)
>        at com.prosyst.mbs.impl.framework.FrameworkLauncher.finishLaunch(FrameworkLauncher.java:501)
>        at com.prosyst.mbs.impl.framework.FrameworkLauncher.launch(FrameworkLauncher.java:476)
>        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:195)
>        at java.lang.reflect.Method.invoke(Method.java:242)
>        at com.prosyst.mbs.impl.framework.Start.processFrameworkLaunch(Start.java:196)
>        at com.prosyst.mbs.impl.framework.Start.main(Start.java:82)
> Caused by: java.lang.IllegalStateException: Unexpected error building Logger: null
>        at com.att.dlc.logging.LoggerFactory.buildLogger(LoggerFactory.java:92)
>        at com.att.dlc.logging.LoggerFactory.getLogger(LoggerFactory.java:34)
>        at com.att.dlc.osgi.Activator.<clinit>(Activator.java:120)
>        at java.lang.J9VMInternals.initializeImpl(Native Method)
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>        ... 19 more
> Caused by: java.lang.reflect.InvocationTargetException
>        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:197)
>        at java.lang.reflect.Constructor.newInstance(Constructor.java:204)
>        at com.att.dlc.logging.LoggerFactory.buildLogger(LoggerFactory.java:89)
>        ... 23 more
> Caused by: java.lang.ExceptionInInitializerError
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:233)
>        at org.apache.logging.log4j.core.async.AsyncLogger.calculateRingBufferSize(AsyncLogger.java:123)
>        at org.apache.logging.log4j.core.async.AsyncLogger.<clinit>(AsyncLogger.java:89)
>        at java.lang.J9VMInternals.initializeImpl(Native Method)
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>        at org.apache.logging.log4j.core.async.AsyncLoggerContext.newInstance(AsyncLoggerContext.java:51)
>        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:274)
>        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:255)
>        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:51)
>        at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:364)
>        at com.att.dlc.logging.Log4jLogger.<init>(Log4jLogger.java:38)
>        at com.att.dlc.logging.Log4jLogger.<init>(Log4jLogger.java:46)
>        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:195)
>        ... 25 more
> Caused by: java.lang.RuntimeException: Unable to load unsafe
>        at com.lmax.disruptor.util.Util.<clinit>(Util.java:112)
>        at java.lang.J9VMInternals.initializeImpl(Native Method)
>        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
>        ... 37 more
> Caused by: java.security.PrivilegedActionException: java.lang.NoSuchFieldException: theUnsafe
>        at java.security.AccessController.doPrivileged(AccessController.java:259)
>        at com.lmax.disruptor.util.Util.<clinit>(Util.java:108)
>        ... 39 more
> Caused by: java.lang.NoSuchFieldException: theUnsafe
>        at java.lang.Class.getDeclaredFieldImpl(Native Method)
>        at java.lang.Class.getDeclaredField(Class.java:487)
>        at com.lmax.disruptor.util.Util$1.run(Util.java:102)
>        at com.lmax.disruptor.util.Util$1.run(Util.java:99)
>        at java.security.AccessController.doPrivileged(AccessController.java:255)
>        ... 40 more
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> -----Original Message-----
> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
> Sent: Monday, July 29, 2013 11:05 AM
> To: Log4J Users List
> Subject: Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1
> 
> This probably warrants an enhancement to Log4jContextFactory. I can imagine other use cases where defaulting to BasicContextSelector also makes sense.
> 
> Ralph
> 
> On Jul 29, 2013, at 8:02 AM, Ralph Goers wrote:
> 
>> In your environment I would definitely recommend using BasicContextSelector as you are unlikely to have need for multiple LoggerContexts.
>> 
>> Ralph
>> 
>> On Jul 29, 2013, at 7:08 AM, SMITH, CURTIS wrote:
>> 
>>> Hi guys,  I mentioned this observation last week, that my embedded single core env, the VM also does not support reflection.  Is reflection used in the hot path of logging that might be affecting my testing of V2 using more CPU than v1?
>>> 
>>>>>> LOGGER.debug("sun.reflect.Reflection is not installed");   // Ã¯â√ıÆ‚----------------------------
>>> 
>>> I get this log at VM startup time.
>>> 
>>> Curt
>>> ------------------------
>>> 
>>> 
>>> package org.apache.logging.log4j.core.selector;
>>> 
>>> public class ClassLoaderContextSelector implements ContextSelector {
>>> 
>>> private static void setupCallerCheck() {
>>> 223         try {
>>> 224             final ClassLoader loader = Loader.getClassLoader();
>>> 225             final Class clazz = loader.loadClass("sun.reflect.Reflection");
>>> 226             final Method[] methods = clazz.getMethods();
>>> 227             for (final Method method : methods) {
>>> 228                 final int modifier = method.getModifiers();
>>> 229                 if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) {
>>> 230                     getCallerClass = method;
>>> 231                     break;
>>> 232                 }
>>> 233             }
>>> 234         } catch (final ClassNotFoundException cnfe) {
>>> 235             LOGGER.debug("sun.reflect.Reflection is not installed");   // Ã¯â√ıÆ‚----------------------------
>>> 236         
>>> 
>>> -----Original Message-----
>>> From: Remko Popma [mailto:remkop@yahoo.com] 
>>> Sent: Saturday, July 27, 2013 5:40 AM
>>> To: Log4J Users List; Remko Popma
>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> I quickly reviewed the code and as far as I can tell:
>>> * only the following places in Log4j-2 will create a permanent thread in addition to your application threads:Ã≠ AsyncLoggers, AsyncAppenders, o.a.l.l.c.net.SocketServer,Ã≠ o.a.l.l.c.net.UDPSocketServer andÃ≠ o.a.l.l.c.helpers.*CachedClock
>>> * synchronous logging will not create any threads
>>> * RollingFile creates a short-lived thread for the roll-over, *only*Ã≠ if the old file needs to be compressed to a .zip or .gz file (the file rename action is synchronous)
>>> 
>>> So I'm thinking that the difference in CPU usage is caused by something other than threads or async logging.
>>> I'd be interested in your answers to my questions below.
>>> 
>>> Best regards,
>>> Remko
>>> 
>>> 
>>> ________________________________
>>> From: Remko Popma <re...@yahoo.com>
>>> To: Log4J Users List <lo...@logging.apache.org> 
>>> Sent: Saturday, July 27, 2013 12:53 PM
>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> 
>>> I don't think we've ever done any performance testing on the kind of environment you describe, so this is great feedback, thanks!
>>> 
>>> First, configuration via XML instead of sys props is on the todo list.
>>> 
>>> Second, you mentioned you use system property "AsyncLoggerContextSelector" to switch on AsyncLoggers.
>>> This is incorrect. The correct key is "Log4jContextSelector" (and that would explain why removing this setting made no difference).
>>> 
>>> Third, if I understand correctly you are essentially logging to a memory-mapped file. In that case any buffering is just wasting CPU resources, so you should not use the Fast*File appenders as their buffering cannot be switched off. (Non-Fast) FileAppenders also use bufferedIO=true by default, but you can switch this off in config. I would expect this to save some CPU.
>>> 
>>> On that note, you mentioned CPU usage as your performance measure. Is that the most important number? Do you have any throughput/latency goals?
>>> Do you have any tools on your platform to see what the CPU is doing? Which threads are busy for example?
>>> 
>>> In terms of GC, making all loggers Async has a small benefit in that it re-uses log event objects.
>>> 
>>> 
>>> I am still intrigued by the difference in CPU usage you mention between log4j-1.2 and 2.0. Is your application code exactly the same? Or do you use the pattern formats that are now available in log4j-2.0?
>>> 
>>> Regards,
>>> Remko
>>> 
>>> 
>>> ________________________________
>>> From: "SMITH, CURTIS" <cs...@att.com>
>>> To: Log4J Users List <lo...@logging.apache.org> 
>>> Sent: Saturday, July 27, 2013 6:55 AM
>>> Subject: RE: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> 
>>> LOL well that's obvious now.Ã≠  :)Ã≠  It was more a case of wishful thinking and why not give it a "try".Ã≠  Ã≠  But it's still odd that my attempts to slim it down It's still 2x worse than v1.Ã≠  Something else is in play.
>>> 
>>> curt
>>> 
>>> -----Original Message-----
>>> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
>>> Sent: Friday, July 26, 2013 5:34 PM
>>> To: Log4J Users List
>>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> I'm curious why you are even trying to use Async anything with a single core environment (unless it is hyper-threaded). Only 1 thread can be active at a time so when you switch threads the active thread will just stop. This won't gain you any additional throughput but you will still incur the additional overhead of thread management and locking.
>>> 
>>> Ralph
>>> 
>>> On Jul 26, 2013, at 1:55 PM, SMITH, CURTIS wrote:
>>> 
>>>> I removedÃ≠  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>>> No change in CPU, but going from FastRollingFile to RollingFile I got back 10% of my lost CPU.Ã≠  Still at 40% CPU where v1 runs at 20%.
>>>> 
>>>> I would like to get down to the equivalent behavior as we got from log4j v1, then try v2 features to get it better.Ã≠  Since I'm still seeing worse performance, I'm guessing that there's still one or more threads under the hood vs V1 with:Ã≠  sync Logger and RollingFile.
>>>> 
>>>> Any guesses for me to try?
>>>> 
>>>> Tnx curt
>>>> 
>>>> _____________________________________________
>>>> From: SMITH, CURTIS
>>>> Sent: Friday, July 26, 2013 1:16 PM
>>>> To: log4j-user@logging.apache.org
>>>> Subject: async logger on slow single core env performs 50% worse than log4j v1
>>>> 
>>>> 
>>>> I suspect a slow single core env is a new scenario for v2 and async logger.Ã≠ Ã≠  My view is that there's a mis match between v2's async logger thread design that works great on multi-core envs and this embedded slow single core env...Ã≠ Ã≠  Sooo I need to try a few different configurations to see what does run best on a slow single core...
>>>> 
>>>> But I need your tips as to what I might change / tune to get v2 to perform as good or better than v1 in a single core env.
>>>> 
>>>> FWIW:Ã≠  log4j v1 ran my standard use case test averaging 20% CPU.Ã≠  Log4j v2 ran at 50% CPU, so more than 2x worse.
>>>> 
>>>> Our business logic is highly threaded so any subsystem that has a "hot" thread like this config that has 5 loggers and 3 appenders I might be shooting myself in the foot.Ã≠  You know this new design the best so I'm open as to what to pick and choose from v2 that is likely to perform the best?
>>>> 
>>>> FYI:Ã≠  I feel using system properties vs exclusively using declarative configuration all within the log4j2.xml separates out configuration.Ã≠  I'd prefer to not have to use system properties for any configuration.
>>>> 
>>>> My first experiment will be to remove the async logger property.
>>>> 
>>>> Any thoughts re the FastRollingFile appender or any other tuning that might be better for a single core env.Ã≠  It's a slow Arm v5 or so, pretty old and lacking the better context switching features of newer chips.Ã≠  The VM is also slow,Ã≠  IBM J9 J2ME JDK1.6.Ã≠ Ã≠  Benchmarking the J9 vs Oracle J2ME, J9 is real slow and poor at thread context switching.Ã≠  But you get what you pay for, J9 is also real cheap.
>>>> 
>>>> ******
>>>> ******
>>>> Note:Ã≠  the log files are on /tmp a memory FS in our env.Ã≠  So the worst case of a synchronous logger from the same thread as the logger.debug call may not perform that badly thanks to Linux FS buffering and memfs having low latency.Ã≠  Just mentioning.
>>>> 
>>>> 
>>>> // Manually set the log4j v2 async logger tuning parameters here.Ã≠  DLA does not have a system property
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  // property file
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  System.setProperty("AsyncLogger.RingBufferSize", "128");Ã≠  Ã≠  Ã≠  Ã≠  // min size permissable to keep memory low
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  System.setProperty("AsyncLogger.WaitStrategy", "Block");Ã≠  Ã≠  Ã≠  Ã≠  // less CPU, better for embedded env
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  System.setProperty("log4j2.disable.jmx", "true");Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠ Ã≠  // saves on a jmx jar and we don't use JMX anyway
>>>> 
>>>> <?xml version="1.0" encoding="UTF-8"?>
>>>> <configuration status="trace" level="trace" >Ã≠  <!-- log4j v2 debug add these: status="trace" level="trace" -->
>>>> Ã≠  Ã≠  Ã≠  Ã≠  <appenders>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <FastRollingFile name="DLA"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  fileName="/tmp/att/sync/log/dla.log"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  filePattern="/tmp/att/sync/log/dla.log.%i" append="true">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <SizeBasedTriggeringPolicy size="3 MB" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <DefaultRolloverStrategy max="2" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </FastRollingFile>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <FastRollingFile name="DEVICES"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  fileName="/tmp/att/sync/log/dla_devices.log"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  filePattern="/tmp/att/sync/log/dla_devices.log.%i" append="true">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <SizeBasedTriggeringPolicy size="3 MB" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <DefaultRolloverStrategy max="1" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </FastRollingFile>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <FastRollingFile name="VIDEO"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  fileName="/tmp/att/sync/log/dla_video.log"
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  filePattern="/tmp/att/sync/log/dla_video.log.%i" append="true">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </PatternLayout>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <SizeBasedTriggeringPolicy size="3 MB" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </Policies>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <DefaultRolloverStrategy max="1" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </FastRollingFile>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <Console name="CO" target="SYSTEM_OUT">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </Console>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  </appenders>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  <loggers>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.afm" additivity="false" >
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="DLA" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.devices" additivity="false" level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="DEVICES" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.util.serialport" additivity="false" level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="DEVICES" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.webcamserver" additivity="false" level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="VIDEO" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <logger name="com.att.dlc.devices.cameras" additivity="false" level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="VIDEO" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </logger>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <root level="debug">
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  <appender-ref ref="DLA" />
>>>> Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  Ã≠  </root>
>>>> Ã≠  Ã≠  Ã≠  Ã≠  </loggers>
>>>> </configuration>
>>>> 
>>>> Curt Smith
>>>> AT&T Digital Life
>>>> DLC Software Development
>>>> 404-499-7013
>>>> (cell) 678-365-6508
>>>> 
>>>> 
>>>> 
>>> 
>>> 
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>> 
>>> 
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>> â•’Â¢Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚Ã‚â•’â•’Â¥FÃ”
> VÃ§7V'67&Ë∫&RÃ≠RÃˆÃˆË∫Ã∞Â¢Ã∫Ã¶sFÂ¢â˜…W6W"â˜…VÃ§7V'67&Ë∫&TÃ∫Ã¶vvË∫ÃœrÃœ6â√«RÃœÃ·&pâ•’Â¤fÃ·"FFË˛FË∫Ã¶ÃœÃ≠6Ã¶ÃˆÃˆÃœG2Ã≠RÃˆÃˆË∫Ã∞Â¢Ã∫Ã¶sFÂ¢â˜…W6W"Ãˆâ√«VÃΩÃ∫Ã¶vvË∫ÃœrÃœ6â√«RÃœÃ·&pâ•’ 
>> 
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
> 
> ‹¢ÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒ‹‹¥FòVç7V'67&ˆ&RÂRÖÖˆÃ¢ÆösF¢◊W6W"◊Vç7V'67&ˆ&TÆövvˆæræ6∫Ræ÷&p‹¤f÷"FF˜FˆöæÂ6öÖÖæG2ÂRÖÖˆÃ¢ÆösF¢◊W6W"Ö∫VÇÆövvˆæræ6∫Ræ÷&p‹ 


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

RE: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Posted by "SMITH, CURTIS" <cs...@att.com>.

Ralph,  Was your comment about BasicContextSelector me and my quest to get V2 to run as well as V1 on my slow single core J2ME env?

My test run with AsyncLogger blew up.  This J2ME VM does not have reflection.  Guessing that disruptor uses reflection to cast methods/objects (bottom).

This leaves me with just one more experiment to get V2 to perform as well as V1:  RollingFile with bufferedIO=false

RE: MDC, no we'll not use any location info, just passing values like username (example) and similar  constant values from each transaction initiation into the log.  


#0   ERROR   > Error occurred while trying to activate bundle!
java.lang.ExceptionInInitializerError
        at java.lang.J9VMInternals.initialize(J9VMInternals.java:233)
        at java.lang.Class.newInstanceImpl(Native Method)
        at java.lang.Class.newInstance(Class.java:1279)
        at com.prosyst.mbs.impl.framework.BundleImpl.startIt(BundleImpl.java:4287)
        at com.prosyst.mbs.impl.framework.BundleImpl.simpleStart(BundleImpl.java:1744)
        at com.prosyst.mbs.impl.framework.BundleImpl.start0(BundleImpl.java:1642)
        at com.prosyst.mbs.impl.framework.BundleImpl.start0(BundleImpl.java:1515)
        at com.prosyst.mbs.impl.framework.BundleImpl.start(BundleImpl.java:1350)
        at com.prosyst.mbs.impl.framework.BundleImpl.start(BundleImpl.java:1060)
        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.start(BootImpl.java:869)
        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.executeBoot(BootImpl.java:386)
        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.processDefaultBoot(BootImpl.java:163)
        at com.prosyst.mbs.impl.framework.module.boot.BootImpl.start(BootImpl.java:93)
        at com.prosyst.mbs.impl.framework.FrameworkLauncher.start(FrameworkLauncher.java:1194)
        at com.prosyst.mbs.impl.framework.FrameworkLauncher.finishLaunch(FrameworkLauncher.java:501)
        at com.prosyst.mbs.impl.framework.FrameworkLauncher.launch(FrameworkLauncher.java:476)
        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:195)
        at java.lang.reflect.Method.invoke(Method.java:242)
        at com.prosyst.mbs.impl.framework.Start.processFrameworkLaunch(Start.java:196)
        at com.prosyst.mbs.impl.framework.Start.main(Start.java:82)
Caused by: java.lang.IllegalStateException: Unexpected error building Logger: null
        at com.att.dlc.logging.LoggerFactory.buildLogger(LoggerFactory.java:92)
        at com.att.dlc.logging.LoggerFactory.getLogger(LoggerFactory.java:34)
        at com.att.dlc.osgi.Activator.<clinit>(Activator.java:120)
        at java.lang.J9VMInternals.initializeImpl(Native Method)
        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
        ... 19 more
Caused by: java.lang.reflect.InvocationTargetException
        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:197)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:204)
        at com.att.dlc.logging.LoggerFactory.buildLogger(LoggerFactory.java:89)
        ... 23 more
Caused by: java.lang.ExceptionInInitializerError
        at java.lang.J9VMInternals.initialize(J9VMInternals.java:233)
        at org.apache.logging.log4j.core.async.AsyncLogger.calculateRingBufferSize(AsyncLogger.java:123)
        at org.apache.logging.log4j.core.async.AsyncLogger.<clinit>(AsyncLogger.java:89)
        at java.lang.J9VMInternals.initializeImpl(Native Method)
        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
        at org.apache.logging.log4j.core.async.AsyncLoggerContext.newInstance(AsyncLoggerContext.java:51)
        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:274)
        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:255)
        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:51)
        at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:364)
        at com.att.dlc.logging.Log4jLogger.<init>(Log4jLogger.java:38)
        at com.att.dlc.logging.Log4jLogger.<init>(Log4jLogger.java:46)
        at java.lang.reflect.AccessibleObject.invokeV(AccessibleObject.java:195)
        ... 25 more
Caused by: java.lang.RuntimeException: Unable to load unsafe
        at com.lmax.disruptor.util.Util.<clinit>(Util.java:112)
        at java.lang.J9VMInternals.initializeImpl(Native Method)
        at java.lang.J9VMInternals.initialize(J9VMInternals.java:211)
        ... 37 more
Caused by: java.security.PrivilegedActionException: java.lang.NoSuchFieldException: theUnsafe
        at java.security.AccessController.doPrivileged(AccessController.java:259)
        at com.lmax.disruptor.util.Util.<clinit>(Util.java:108)
        ... 39 more
Caused by: java.lang.NoSuchFieldException: theUnsafe
        at java.lang.Class.getDeclaredFieldImpl(Native Method)
        at java.lang.Class.getDeclaredField(Class.java:487)
        at com.lmax.disruptor.util.Util$1.run(Util.java:102)
        at com.lmax.disruptor.util.Util$1.run(Util.java:99)
        at java.security.AccessController.doPrivileged(AccessController.java:255)
        ... 40 more










-----Original Message-----
From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
Sent: Monday, July 29, 2013 11:05 AM
To: Log4J Users List
Subject: Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

This probably warrants an enhancement to Log4jContextFactory. I can imagine other use cases where defaulting to BasicContextSelector also makes sense.

Ralph

On Jul 29, 2013, at 8:02 AM, Ralph Goers wrote:

> In your environment I would definitely recommend using BasicContextSelector as you are unlikely to have need for multiple LoggerContexts.
> 
> Ralph
> 
> On Jul 29, 2013, at 7:08 AM, SMITH, CURTIS wrote:
> 
>> Hi guys,  I mentioned this observation last week, that my embedded single core env, the VM also does not support reflection.  Is reflection used in the hot path of logging that might be affecting my testing of V2 using more CPU than v1?
>> 
>>>>> LOGGER.debug("sun.reflect.Reflection is not installed");   // ï∞ƒ----------------------------
>> 
>> I get this log at VM startup time.
>> 
>> Curt
>> ------------------------
>> 
>> 
>> package org.apache.logging.log4j.core.selector;
>> 
>> public class ClassLoaderContextSelector implements ContextSelector {
>> 
>> private static void setupCallerCheck() {
>> 223         try {
>> 224             final ClassLoader loader = Loader.getClassLoader();
>> 225             final Class clazz = loader.loadClass("sun.reflect.Reflection");
>> 226             final Method[] methods = clazz.getMethods();
>> 227             for (final Method method : methods) {
>> 228                 final int modifier = method.getModifiers();
>> 229                 if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) {
>> 230                     getCallerClass = method;
>> 231                     break;
>> 232                 }
>> 233             }
>> 234         } catch (final ClassNotFoundException cnfe) {
>> 235             LOGGER.debug("sun.reflect.Reflection is not installed");   // ï∞ƒ----------------------------
>> 236         
>> 
>> -----Original Message-----
>> From: Remko Popma [mailto:remkop@yahoo.com] 
>> Sent: Saturday, July 27, 2013 5:40 AM
>> To: Log4J Users List; Remko Popma
>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> I quickly reviewed the code and as far as I can tell:
>> * only the following places in Log4j-2 will create a permanent thread in addition to your application threads:Â AsyncLoggers, AsyncAppenders, o.a.l.l.c.net.SocketServer,Â o.a.l.l.c.net.UDPSocketServer andÂ o.a.l.l.c.helpers.*CachedClock
>> * synchronous logging will not create any threads
>> * RollingFile creates a short-lived thread for the roll-over, *only*Â if the old file needs to be compressed to a .zip or .gz file (the file rename action is synchronous)
>> 
>> So I'm thinking that the difference in CPU usage is caused by something other than threads or async logging.
>> I'd be interested in your answers to my questions below.
>> 
>> Best regards,
>> Remko
>> 
>> 
>> ________________________________
>> From: Remko Popma <re...@yahoo.com>
>> To: Log4J Users List <lo...@logging.apache.org> 
>> Sent: Saturday, July 27, 2013 12:53 PM
>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> 
>> I don't think we've ever done any performance testing on the kind of environment you describe, so this is great feedback, thanks!
>> 
>> First, configuration via XML instead of sys props is on the todo list.
>> 
>> Second, you mentioned you use system property "AsyncLoggerContextSelector" to switch on AsyncLoggers.
>> This is incorrect. The correct key is "Log4jContextSelector" (and that would explain why removing this setting made no difference).
>> 
>> Third, if I understand correctly you are essentially logging to a memory-mapped file. In that case any buffering is just wasting CPU resources, so you should not use the Fast*File appenders as their buffering cannot be switched off. (Non-Fast) FileAppenders also use bufferedIO=true by default, but you can switch this off in config. I would expect this to save some CPU.
>> 
>> On that note, you mentioned CPU usage as your performance measure. Is that the most important number? Do you have any throughput/latency goals?
>> Do you have any tools on your platform to see what the CPU is doing? Which threads are busy for example?
>> 
>> In terms of GC, making all loggers Async has a small benefit in that it re-uses log event objects.
>> 
>> 
>> I am still intrigued by the difference in CPU usage you mention between log4j-1.2 and 2.0. Is your application code exactly the same? Or do you use the pattern formats that are now available in log4j-2.0?
>> 
>> Regards,
>> Remko
>> 
>> 
>> ________________________________
>> From: "SMITH, CURTIS" <cs...@att.com>
>> To: Log4J Users List <lo...@logging.apache.org> 
>> Sent: Saturday, July 27, 2013 6:55 AM
>> Subject: RE: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> 
>> LOL well that's obvious now.Â  :)Â  It was more a case of wishful thinking and why not give it a "try".Â  Â  But it's still odd that my attempts to slim it down It's still 2x worse than v1.Â  Something else is in play.
>> 
>> curt
>> 
>> -----Original Message-----
>> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
>> Sent: Friday, July 26, 2013 5:34 PM
>> To: Log4J Users List
>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> I'm curious why you are even trying to use Async anything with a single core environment (unless it is hyper-threaded). Only 1 thread can be active at a time so when you switch threads the active thread will just stop. This won't gain you any additional throughput but you will still incur the additional overhead of thread management and locking.
>> 
>> Ralph
>> 
>> On Jul 26, 2013, at 1:55 PM, SMITH, CURTIS wrote:
>> 
>>> I removedÂ  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>> No change in CPU, but going from FastRollingFile to RollingFile I got back 10% of my lost CPU.Â  Still at 40% CPU where v1 runs at 20%.
>>> 
>>> I would like to get down to the equivalent behavior as we got from log4j v1, then try v2 features to get it better.Â  Since I'm still seeing worse performance, I'm guessing that there's still one or more threads under the hood vs V1 with:Â  sync Logger and RollingFile.
>>> 
>>> Any guesses for me to try?
>>> 
>>> Tnx curt
>>> 
>>> _____________________________________________
>>> From: SMITH, CURTIS
>>> Sent: Friday, July 26, 2013 1:16 PM
>>> To: log4j-user@logging.apache.org
>>> Subject: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> 
>>> I suspect a slow single core env is a new scenario for v2 and async logger.Â Â  My view is that there's a mis match between v2's async logger thread design that works great on multi-core envs and this embedded slow single core env...Â Â  Sooo I need to try a few different configurations to see what does run best on a slow single core...
>>> 
>>> But I need your tips as to what I might change / tune to get v2 to perform as good or better than v1 in a single core env.
>>> 
>>> FWIW:Â  log4j v1 ran my standard use case test averaging 20% CPU.Â  Log4j v2 ran at 50% CPU, so more than 2x worse.
>>> 
>>> Our business logic is highly threaded so any subsystem that has a "hot" thread like this config that has 5 loggers and 3 appenders I might be shooting myself in the foot.Â  You know this new design the best so I'm open as to what to pick and choose from v2 that is likely to perform the best?
>>> 
>>> FYI:Â  I feel using system properties vs exclusively using declarative configuration all within the log4j2.xml separates out configuration.Â  I'd prefer to not have to use system properties for any configuration.
>>> 
>>> My first experiment will be to remove the async logger property.
>>> 
>>> Any thoughts re the FastRollingFile appender or any other tuning that might be better for a single core env.Â  It's a slow Arm v5 or so, pretty old and lacking the better context switching features of newer chips.Â  The VM is also slow,Â  IBM J9 J2ME JDK1.6.Â Â  Benchmarking the J9 vs Oracle J2ME, J9 is real slow and poor at thread context switching.Â  But you get what you pay for, J9 is also real cheap.
>>> 
>>> ******
>>> ******
>>> Note:Â  the log files are on /tmp a memory FS in our env.Â  So the worst case of a synchronous logger from the same thread as the logger.debug call may not perform that badly thanks to Linux FS buffering and memfs having low latency.Â  Just mentioning.
>>> 
>>> 
>>> // Manually set the log4j v2 async logger tuning parameters here.Â  DLA does not have a system property
>>> Â  Â  Â  Â  Â  Â  Â  Â  // property file
>>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLogger.RingBufferSize", "128");Â  Â  Â  Â  // min size permissable to keep memory low
>>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLogger.WaitStrategy", "Block");Â  Â  Â  Â  // less CPU, better for embedded env
>>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("log4j2.disable.jmx", "true");Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â Â  // saves on a jmx jar and we don't use JMX anyway
>>> 
>>> <?xml version="1.0" encoding="UTF-8"?>
>>> <configuration status="trace" level="trace" >Â  <!-- log4j v2 debug add these: status="trace" level="trace" -->
>>> Â  Â  Â  Â  <appenders>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="DLA"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla.log"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla.log.%i" append="true">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="2" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="DEVICES"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla_devices.log"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla_devices.log.%i" append="true">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="1" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="VIDEO"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla_video.log"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla_video.log.%i" append="true">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="1" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <Console name="CO" target="SYSTEM_OUT">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </Console>
>>> Â  Â  Â  Â  </appenders>
>>> Â  Â  Â  Â  <loggers>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.afm" additivity="false" >
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DLA" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.devices" additivity="false" level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DEVICES" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.util.serialport" additivity="false" level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DEVICES" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.webcamserver" additivity="false" level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="VIDEO" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.devices.cameras" additivity="false" level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="VIDEO" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <root level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DLA" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </root>
>>> Â  Â  Â  Â  </loggers>
>>> </configuration>
>>> 
>>> Curt Smith
>>> AT&T Digital Life
>>> DLC Software Development
>>> 404-499-7013
>>> (cell) 678-365-6508
>>> 
>>> 
>>> 
>> 
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>> 
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>> ‹¢ÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒ‹‹¥Fò
Vç7V'67&ˆ&RÂRÖÖˆÃ¢ÆösF¢◊W6W"◊Vç7V'67&ˆ&TÆövvˆæræ6∫Ræ÷&p‹¤f÷"FF˜FˆöæÂ6öÖÖæG2ÂRÖÖˆÃ¢ÆösF¢◊W6W"Ö∫VÇÆövvˆæræ6∫Ræ÷&p‹ 
> 


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

Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Posted by Ralph Goers <ra...@dslextreme.com>.

This probably warrants an enhancement to Log4jContextFactory. I can imagine other use cases where defaulting to BasicContextSelector also makes sense.

Ralph

On Jul 29, 2013, at 8:02 AM, Ralph Goers wrote:

> In your environment I would definitely recommend using BasicContextSelector as you are unlikely to have need for multiple LoggerContexts.
> 
> Ralph
> 
> On Jul 29, 2013, at 7:08 AM, SMITH, CURTIS wrote:
> 
>> Hi guys,  I mentioned this observation last week, that my embedded single core env, the VM also does not support reflection.  Is reflection used in the hot path of logging that might be affecting my testing of V2 using more CPU than v1?
>> 
>>>>> LOGGER.debug("sun.reflect.Reflection is not installed");   // ï∞ƒ----------------------------
>> 
>> I get this log at VM startup time.
>> 
>> Curt
>> ------------------------
>> 
>> 
>> package org.apache.logging.log4j.core.selector;
>> 
>> public class ClassLoaderContextSelector implements ContextSelector {
>> 
>> private static void setupCallerCheck() {
>> 223         try {
>> 224             final ClassLoader loader = Loader.getClassLoader();
>> 225             final Class clazz = loader.loadClass("sun.reflect.Reflection");
>> 226             final Method[] methods = clazz.getMethods();
>> 227             for (final Method method : methods) {
>> 228                 final int modifier = method.getModifiers();
>> 229                 if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) {
>> 230                     getCallerClass = method;
>> 231                     break;
>> 232                 }
>> 233             }
>> 234         } catch (final ClassNotFoundException cnfe) {
>> 235             LOGGER.debug("sun.reflect.Reflection is not installed");   // ï∞ƒ----------------------------
>> 236         
>> 
>> -----Original Message-----
>> From: Remko Popma [mailto:remkop@yahoo.com] 
>> Sent: Saturday, July 27, 2013 5:40 AM
>> To: Log4J Users List; Remko Popma
>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> I quickly reviewed the code and as far as I can tell:
>> * only the following places in Log4j-2 will create a permanent thread in addition to your application threads:Â AsyncLoggers, AsyncAppenders, o.a.l.l.c.net.SocketServer,Â o.a.l.l.c.net.UDPSocketServer andÂ o.a.l.l.c.helpers.*CachedClock
>> * synchronous logging will not create any threads
>> * RollingFile creates a short-lived thread for the roll-over, *only*Â if the old file needs to be compressed to a .zip or .gz file (the file rename action is synchronous)
>> 
>> So I'm thinking that the difference in CPU usage is caused by something other than threads or async logging.
>> I'd be interested in your answers to my questions below.
>> 
>> Best regards,
>> Remko
>> 
>> 
>> ________________________________
>> From: Remko Popma <re...@yahoo.com>
>> To: Log4J Users List <lo...@logging.apache.org> 
>> Sent: Saturday, July 27, 2013 12:53 PM
>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> 
>> I don't think we've ever done any performance testing on the kind of environment you describe, so this is great feedback, thanks!
>> 
>> First, configuration via XML instead of sys props is on the todo list.
>> 
>> Second, you mentioned you use system property "AsyncLoggerContextSelector" to switch on AsyncLoggers.
>> This is incorrect. The correct key is "Log4jContextSelector" (and that would explain why removing this setting made no difference).
>> 
>> Third, if I understand correctly you are essentially logging to a memory-mapped file. In that case any buffering is just wasting CPU resources, so you should not use the Fast*File appenders as their buffering cannot be switched off. (Non-Fast) FileAppenders also use bufferedIO=true by default, but you can switch this off in config. I would expect this to save some CPU.
>> 
>> On that note, you mentioned CPU usage as your performance measure. Is that the most important number? Do you have any throughput/latency goals?
>> Do you have any tools on your platform to see what the CPU is doing? Which threads are busy for example?
>> 
>> In terms of GC, making all loggers Async has a small benefit in that it re-uses log event objects.
>> 
>> 
>> I am still intrigued by the difference in CPU usage you mention between log4j-1.2 and 2.0. Is your application code exactly the same? Or do you use the pattern formats that are now available in log4j-2.0?
>> 
>> Regards,
>> Remko
>> 
>> 
>> ________________________________
>> From: "SMITH, CURTIS" <cs...@att.com>
>> To: Log4J Users List <lo...@logging.apache.org> 
>> Sent: Saturday, July 27, 2013 6:55 AM
>> Subject: RE: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> 
>> LOL well that's obvious now.Â  :)Â  It was more a case of wishful thinking and why not give it a "try".Â  Â  But it's still odd that my attempts to slim it down It's still 2x worse than v1.Â  Something else is in play.
>> 
>> curt
>> 
>> -----Original Message-----
>> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
>> Sent: Friday, July 26, 2013 5:34 PM
>> To: Log4J Users List
>> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> I'm curious why you are even trying to use Async anything with a single core environment (unless it is hyper-threaded). Only 1 thread can be active at a time so when you switch threads the active thread will just stop. This won't gain you any additional throughput but you will still incur the additional overhead of thread management and locking.
>> 
>> Ralph
>> 
>> On Jul 26, 2013, at 1:55 PM, SMITH, CURTIS wrote:
>> 
>>> I removedÂ  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>> No change in CPU, but going from FastRollingFile to RollingFile I got back 10% of my lost CPU.Â  Still at 40% CPU where v1 runs at 20%.
>>> 
>>> I would like to get down to the equivalent behavior as we got from log4j v1, then try v2 features to get it better.Â  Since I'm still seeing worse performance, I'm guessing that there's still one or more threads under the hood vs V1 with:Â  sync Logger and RollingFile.
>>> 
>>> Any guesses for me to try?
>>> 
>>> Tnx curt
>>> 
>>> _____________________________________________
>>> From: SMITH, CURTIS
>>> Sent: Friday, July 26, 2013 1:16 PM
>>> To: log4j-user@logging.apache.org
>>> Subject: async logger on slow single core env performs 50% worse than log4j v1
>>> 
>>> 
>>> I suspect a slow single core env is a new scenario for v2 and async logger.Â Â  My view is that there's a mis match between v2's async logger thread design that works great on multi-core envs and this embedded slow single core env...Â Â  Sooo I need to try a few different configurations to see what does run best on a slow single core...
>>> 
>>> But I need your tips as to what I might change / tune to get v2 to perform as good or better than v1 in a single core env.
>>> 
>>> FWIW:Â  log4j v1 ran my standard use case test averaging 20% CPU.Â  Log4j v2 ran at 50% CPU, so more than 2x worse.
>>> 
>>> Our business logic is highly threaded so any subsystem that has a "hot" thread like this config that has 5 loggers and 3 appenders I might be shooting myself in the foot.Â  You know this new design the best so I'm open as to what to pick and choose from v2 that is likely to perform the best?
>>> 
>>> FYI:Â  I feel using system properties vs exclusively using declarative configuration all within the log4j2.xml separates out configuration.Â  I'd prefer to not have to use system properties for any configuration.
>>> 
>>> My first experiment will be to remove the async logger property.
>>> 
>>> Any thoughts re the FastRollingFile appender or any other tuning that might be better for a single core env.Â  It's a slow Arm v5 or so, pretty old and lacking the better context switching features of newer chips.Â  The VM is also slow,Â  IBM J9 J2ME JDK1.6.Â Â  Benchmarking the J9 vs Oracle J2ME, J9 is real slow and poor at thread context switching.Â  But you get what you pay for, J9 is also real cheap.
>>> 
>>> ******
>>> ******
>>> Note:Â  the log files are on /tmp a memory FS in our env.Â  So the worst case of a synchronous logger from the same thread as the logger.debug call may not perform that badly thanks to Linux FS buffering and memfs having low latency.Â  Just mentioning.
>>> 
>>> 
>>> // Manually set the log4j v2 async logger tuning parameters here.Â  DLA does not have a system property
>>> Â  Â  Â  Â  Â  Â  Â  Â  // property file
>>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLogger.RingBufferSize", "128");Â  Â  Â  Â  // min size permissable to keep memory low
>>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLogger.WaitStrategy", "Block");Â  Â  Â  Â  // less CPU, better for embedded env
>>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("log4j2.disable.jmx", "true");Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â Â  // saves on a jmx jar and we don't use JMX anyway
>>> 
>>> <?xml version="1.0" encoding="UTF-8"?>
>>> <configuration status="trace" level="trace" >Â  <!-- log4j v2 debug add these: status="trace" level="trace" -->
>>> Â  Â  Â  Â  <appenders>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="DLA"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla.log"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla.log.%i" append="true">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="2" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="DEVICES"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla_devices.log"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla_devices.log.%i" append="true">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="1" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="VIDEO"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla_video.log"
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla_video.log.%i" append="true">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="1" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <Console name="CO" target="SYSTEM_OUT">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </Console>
>>> Â  Â  Â  Â  </appenders>
>>> Â  Â  Â  Â  <loggers>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.afm" additivity="false" >
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DLA" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.devices" additivity="false" level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DEVICES" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.util.serialport" additivity="false" level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DEVICES" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.webcamserver" additivity="false" level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="VIDEO" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.devices.cameras" additivity="false" level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="VIDEO" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>>> Â  Â  Â  Â  Â  Â  Â  Â  <root level="debug">
>>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DLA" />
>>> Â  Â  Â  Â  Â  Â  Â  Â  </root>
>>> Â  Â  Â  Â  </loggers>
>>> </configuration>
>>> 
>>> Curt Smith
>>> AT&T Digital Life
>>> DLC Software Development
>>> 404-499-7013
>>> (cell) 678-365-6508
>>> 
>>> 
>>> 
>> 
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>> 
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>> ‹¢ÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒ‹‹¥FòVç7V'67&ˆ&RÂRÖÖˆÃ¢ÆösF¢◊W6W"◊Vç7V'67&ˆ&TÆövvˆæræ6∫Ræ÷&p‹¤f÷"FF˜FˆöæÂ6öÖÖæG2ÂRÖÖˆÃ¢ÆösF¢◊W6W"Ö∫VÇÆövvˆæræ6∫Ræ÷&p‹ 
> 


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

Re: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1

Posted by Ralph Goers <ra...@dslextreme.com>.

In your environment I would definitely recommend using BasicContextSelector as you are unlikely to have need for multiple LoggerContexts.

Ralph

On Jul 29, 2013, at 7:08 AM, SMITH, CURTIS wrote:

> Hi guys,  I mentioned this observation last week, that my embedded single core env, the VM also does not support reflection.  Is reflection used in the hot path of logging that might be affecting my testing of V2 using more CPU than v1?
> 
>>>> LOGGER.debug("sun.reflect.Reflection is not installed");   // ï∞ƒ----------------------------
> 
> I get this log at VM startup time.
> 
> Curt
> ------------------------
> 
> 
> package org.apache.logging.log4j.core.selector;
> 
> public class ClassLoaderContextSelector implements ContextSelector {
> 
> private static void setupCallerCheck() {
> 223         try {
> 224             final ClassLoader loader = Loader.getClassLoader();
> 225             final Class clazz = loader.loadClass("sun.reflect.Reflection");
> 226             final Method[] methods = clazz.getMethods();
> 227             for (final Method method : methods) {
> 228                 final int modifier = method.getModifiers();
> 229                 if (method.getName().equals("getCallerClass") && Modifier.isStatic(modifier)) {
> 230                     getCallerClass = method;
> 231                     break;
> 232                 }
> 233             }
> 234         } catch (final ClassNotFoundException cnfe) {
> 235             LOGGER.debug("sun.reflect.Reflection is not installed");   // ï∞ƒ----------------------------
> 236         
> 
> -----Original Message-----
> From: Remko Popma [mailto:remkop@yahoo.com] 
> Sent: Saturday, July 27, 2013 5:40 AM
> To: Log4J Users List; Remko Popma
> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
> 
> I quickly reviewed the code and as far as I can tell:
> * only the following places in Log4j-2 will create a permanent thread in addition to your application threads:Â AsyncLoggers, AsyncAppenders, o.a.l.l.c.net.SocketServer,Â o.a.l.l.c.net.UDPSocketServer andÂ o.a.l.l.c.helpers.*CachedClock
> * synchronous logging will not create any threads
> * RollingFile creates a short-lived thread for the roll-over, *only*Â if the old file needs to be compressed to a .zip or .gz file (the file rename action is synchronous)
> 
> So I'm thinking that the difference in CPU usage is caused by something other than threads or async logging.
> I'd be interested in your answers to my questions below.
> 
> Best regards,
> Remko
> 
> 
> ________________________________
> From: Remko Popma <re...@yahoo.com>
> To: Log4J Users List <lo...@logging.apache.org> 
> Sent: Saturday, July 27, 2013 12:53 PM
> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
> 
> 
> I don't think we've ever done any performance testing on the kind of environment you describe, so this is great feedback, thanks!
> 
> First, configuration via XML instead of sys props is on the todo list.
> 
> Second, you mentioned you use system property "AsyncLoggerContextSelector" to switch on AsyncLoggers.
> This is incorrect. The correct key is "Log4jContextSelector" (and that would explain why removing this setting made no difference).
> 
> Third, if I understand correctly you are essentially logging to a memory-mapped file. In that case any buffering is just wasting CPU resources, so you should not use the Fast*File appenders as their buffering cannot be switched off. (Non-Fast) FileAppenders also use bufferedIO=true by default, but you can switch this off in config. I would expect this to save some CPU.
> 
> On that note, you mentioned CPU usage as your performance measure. Is that the most important number? Do you have any throughput/latency goals?
> Do you have any tools on your platform to see what the CPU is doing? Which threads are busy for example?
> 
> In terms of GC, making all loggers Async has a small benefit in that it re-uses log event objects.
> 
> 
> I am still intrigued by the difference in CPU usage you mention between log4j-1.2 and 2.0. Is your application code exactly the same? Or do you use the pattern formats that are now available in log4j-2.0?
> 
> Regards,
> Remko
> 
> 
> ________________________________
> From: "SMITH, CURTIS" <cs...@att.com>
> To: Log4J Users List <lo...@logging.apache.org> 
> Sent: Saturday, July 27, 2013 6:55 AM
> Subject: RE: async logger on slow single core env performs 50% worse than log4j v1
> 
> 
> LOL well that's obvious now.Â  :)Â  It was more a case of wishful thinking and why not give it a "try".Â  Â  But it's still odd that my attempts to slim it down It's still 2x worse than v1.Â  Something else is in play.
> 
> curt
> 
> -----Original Message-----
> From: Ralph Goers [mailto:ralph.goers@dslextreme.com] 
> Sent: Friday, July 26, 2013 5:34 PM
> To: Log4J Users List
> Subject: Re: async logger on slow single core env performs 50% worse than log4j v1
> 
> I'm curious why you are even trying to use Async anything with a single core environment (unless it is hyper-threaded). Only 1 thread can be active at a time so when you switch threads the active thread will just stop. This won't gain you any additional throughput but you will still incur the additional overhead of thread management and locking.
> 
> Ralph
> 
> On Jul 26, 2013, at 1:55 PM, SMITH, CURTIS wrote:
> 
>> I removedÂ  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>> No change in CPU, but going from FastRollingFile to RollingFile I got back 10% of my lost CPU.Â  Still at 40% CPU where v1 runs at 20%.
>> 
>> I would like to get down to the equivalent behavior as we got from log4j v1, then try v2 features to get it better.Â  Since I'm still seeing worse performance, I'm guessing that there's still one or more threads under the hood vs V1 with:Â  sync Logger and RollingFile.
>> 
>> Any guesses for me to try?
>> 
>> Tnx curt
>> 
>> _____________________________________________
>> From: SMITH, CURTIS
>> Sent: Friday, July 26, 2013 1:16 PM
>> To: log4j-user@logging.apache.org
>> Subject: async logger on slow single core env performs 50% worse than log4j v1
>> 
>> 
>> I suspect a slow single core env is a new scenario for v2 and async logger.Â Â  My view is that there's a mis match between v2's async logger thread design that works great on multi-core envs and this embedded slow single core env...Â Â  Sooo I need to try a few different configurations to see what does run best on a slow single core...
>> 
>> But I need your tips as to what I might change / tune to get v2 to perform as good or better than v1 in a single core env.
>> 
>> FWIW:Â  log4j v1 ran my standard use case test averaging 20% CPU.Â  Log4j v2 ran at 50% CPU, so more than 2x worse.
>> 
>> Our business logic is highly threaded so any subsystem that has a "hot" thread like this config that has 5 loggers and 3 appenders I might be shooting myself in the foot.Â  You know this new design the best so I'm open as to what to pick and choose from v2 that is likely to perform the best?
>> 
>> FYI:Â  I feel using system properties vs exclusively using declarative configuration all within the log4j2.xml separates out configuration.Â  I'd prefer to not have to use system properties for any configuration.
>> 
>> My first experiment will be to remove the async logger property.
>> 
>> Any thoughts re the FastRollingFile appender or any other tuning that might be better for a single core env.Â  It's a slow Arm v5 or so, pretty old and lacking the better context switching features of newer chips.Â  The VM is also slow,Â  IBM J9 J2ME JDK1.6.Â Â  Benchmarking the J9 vs Oracle J2ME, J9 is real slow and poor at thread context switching.Â  But you get what you pay for, J9 is also real cheap.
>> 
>> ******
>> ******
>> Note:Â  the log files are on /tmp a memory FS in our env.Â  So the worst case of a synchronous logger from the same thread as the logger.debug call may not perform that badly thanks to Linux FS buffering and memfs having low latency.Â  Just mentioning.
>> 
>> 
>> // Manually set the log4j v2 async logger tuning parameters here.Â  DLA does not have a system property
>> Â  Â  Â  Â  Â  Â  Â  Â  // property file
>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLoggerContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLogger.RingBufferSize", "128");Â  Â  Â  Â  // min size permissable to keep memory low
>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("AsyncLogger.WaitStrategy", "Block");Â  Â  Â  Â  // less CPU, better for embedded env
>> Â  Â  Â  Â  Â  Â  Â  Â  System.setProperty("log4j2.disable.jmx", "true");Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â Â  // saves on a jmx jar and we don't use JMX anyway
>> 
>> <?xml version="1.0" encoding="UTF-8"?>
>> <configuration status="trace" level="trace" >Â  <!-- log4j v2 debug add these: status="trace" level="trace" -->
>> Â  Â  Â  Â  <appenders>
>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="DLA"
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla.log"
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla.log.%i" append="true">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="2" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="DEVICES"
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla_devices.log"
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla_devices.log.%i" append="true">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="1" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>> Â  Â  Â  Â  Â  Â  Â  Â  <FastRollingFile name="VIDEO"
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  fileName="/tmp/att/sync/log/dla_video.log"
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  filePattern="/tmp/att/sync/log/dla_video.log.%i" append="true">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <pattern>[%d][%-5p][%-15t][%-15c{1}]:%m%n</pattern>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </PatternLayout>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <Policies>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <SizeBasedTriggeringPolicy size="3 MB" />
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  </Policies>
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <DefaultRolloverStrategy max="1" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </FastRollingFile>
>> Â  Â  Â  Â  Â  Â  Â  Â  <Console name="CO" target="SYSTEM_OUT">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </Console>
>> Â  Â  Â  Â  </appenders>
>> Â  Â  Â  Â  <loggers>
>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.afm" additivity="false" >
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DLA" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.devices" additivity="false" level="debug">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DEVICES" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.util.serialport" additivity="false" level="debug">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DEVICES" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.webcamserver" additivity="false" level="debug">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="VIDEO" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>> Â  Â  Â  Â  Â  Â  Â  Â  <logger name="com.att.dlc.devices.cameras" additivity="false" level="debug">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="VIDEO" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </logger>
>> Â  Â  Â  Â  Â  Â  Â  Â  <root level="debug">
>> Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  Â  <appender-ref ref="DLA" />
>> Â  Â  Â  Â  Â  Â  Â  Â  </root>
>> Â  Â  Â  Â  </loggers>
>> </configuration>
>> 
>> Curt Smith
>> AT&T Digital Life
>> DLC Software Development
>> 404-499-7013
>> (cell) 678-365-6508
>> 
>> 
>> 
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
> ‹¢ÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒ‹‹¥FòVç7V'67&ˆ&RÂRÖÖˆÃ¢ÆösF¢◊W6W"◊Vç7V'67&ˆ&TÆövvˆæræ6∫Ræ÷&p‹¤f÷"FF˜FˆöæÂ6öÖÖæG2ÂRÖÖˆÃ¢ÆösF¢◊W6W"Ö∫VÇÆövvˆæræ6∫Ræ÷&p‹ 


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