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