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:[email protected]]
> 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 <[email protected]>
> To: Log4J Users List <[email protected]>
> 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" <[email protected]>
> To: Log4J Users List <[email protected]>
> 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:[email protected]]
> 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: [email protected]
>> 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: [email protected]
> For additional commands, e-mail: [email protected]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [email protected]
> For additional commands, e-mail: [email protected]
> ‹¢ÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒ‹‹¥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: [email protected]
For additional commands, e-mail: [email protected]
