logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "SMITH, CURTIS" <cs0...@att.com>
Subject single core benchmark comparison: Log4j v1 NDC vs v2 MDC = v2 MDC runs higher CPU
Date Wed, 04 Sep 2013 13:09:42 GMT
Just wanting to report my final findings of perf comparison of log4j v1 NDC vs v2 MDC:

In my single core, ARM on IBM J9 VM:   NDC ran 57% ave CPU where v2 MDC ran 76% CPU for the
same use case test scenario.  We are having to stick with v1 and NDC.  This app can't afford
loosing CPU.   

My 2 cents:   I think a benchmark that measures bytes/sec or log lines/sec and code that tunes
for higher throughput might give a false sense of accomplishment.  Just a thought.   My preferred
benchmark for a logging library after my experience testing v1 vs v2  would be: run the logging
at a typical rate of logging lines per second then tune the code for the lowest CPU lost to
the logging function.   The java implementation may be different for lowest CPU vs highest
byte rate.  Just a possibility.   My testing results finds something like this is in play.
 Too bad I can't test this app on a fast multi core env to see if my results hold for the
Oracle VM on fast multi core...   

Some guesses:   a design change (v2) that is  benchmarked on an (effective) infinite number
of free cores env may give a false metric for improved performance vs if run on a typical
application env that has a shortage of cores and the application already has the CPU running
high.   My single core env is the extreme of CPU starved app env, where if logging has to
wait for a thread to schedule onto the core more cpu maybe burned up to accomplish the same
logging volume.   I now feel that bytes per sec run on an idle multi core test env gives false
perf metrics.  I suspect a better benchmark would fix the byte rate to be a constant well
below the maximum and tune the design for minimum CPU.   Production environments I've worked
on do not have much spare CPU.  :)

curt

-----Original Message-----
From: SMITH, CURTIS 
Sent: Friday, July 26, 2013 5:55 PM
To: Log4J Users List
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


Mime
View raw message