Hi Remko / log4j2,
- Tnx for the correction, I'll retest async logger:
System.setProperty("Log4jContextSelector",
"org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
- Before I recompile with a test run for async logger I'll edit log4j2.xml and
add bufferedIO=false to the RolingFile appenders.
- The env is embedded java on linux env has no profiling tools or enough horse
power to run any even if they existed, so I'm stuck with using top -n 1 > a
file being called from a looping script and using excel to calc the average and
plot CPU over time through a few use cases. So file I/O etc is not measurable.
But the external use case generator does track application latency and that
jumps much more than 2x under log4j2. Let me see.... V1 latency for the main
test runs 800ms and it jumps out to 10000ms under V2 and CPU from 20% up to
40%. That latency is a function of our highly threaded design and thread
context switching latency is our best theory and we're going to address the
design to reduce threading...
The main reason for going to v2 is for fish tagging / MDC. We just need to
have context values show up in logs as the execution flows through method
calls. I haven't looked at V1 to see if it's fish tagging functionality is
good enough. I hope so as a fall back.
Thanks for your help!
curt
-----Original Message-----
From: Remko Popma [mailto:[email protected]]
Sent: Friday, July 26, 2013 11:54 PM
To: Log4J Users List
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]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
