single core benchmark comparison: Log4j v1 NDC vs v2 MDC = v2 MDC runs higher CPU
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.go...@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
use of ThreadContext cleanup vs memory leaks etc
Greetings,
A terse recap of performance on my J2ME on a slow single core env:
BasicContextSelector and BufferedIO=false for RollingFile DOES seem to equal
log4j v1 performance in my most recent benchmarks. I'm not comfortable with
this result because what happened is the V1 benchmarks jumped worse to equal
the V2 benchmarks without explanation. So I'm digging into that issue. But
I'm wanting to move to using V2's MDC to see if that has much of a perf hit for
just put'ing a few variables into ThreadContext and referencing them in the
Pattern: %X{transID} etc
The log4j-users-guide.pdf does not have any MDC API discussion, just
configuration parameters. This URL is all I've found:
http://logging.apache.org/log4j/2.x/manual/thread-context.html
Let me start by saying that most threads never die. They wait on queues so I
believe I never have to worry about ThreadContext.clear / removeStack etc. Or
Do I??
But to clarify proper API use, the above URL infers that thread local object
storage is cleaned up with ThreadContext.clear()
Maybe it's left over from V1 NDC but the JavaDoc on ThreadContext has some
strongly worded recommendation for calling ThreadContext.removeStack()
Each thread that created a diagnostic context by calling
push(java.lang.String)http://logging.apache.org/log4j/2.x/log4j-api/apidocs/org/apache/logging/log4j/ThreadContext.html
should call this method before exiting. Otherwise, the memory used by the
thread cannot be reclaimed by the VM.
As this is such an important problem in heavy duty systems and because it is
difficult to always guarantee that the remove method is called before exiting a
thread, this method has been augmented to lazily remove references to dead
threads. In practice, this means that you can be a little sloppy and
occasionally forget to call
remove(java.lang.String)http://logging.apache.org/log4j/2.x/log4j-api/apidocs/org/apache/logging/log4j/ThreadContext.html
before exiting a thread. However, you must call remove sometime. If you never
call it, then your application is sure to run out of memory.
I could use what the suggested cleanup of ThreadContext is??
Also: there's no reasoning for the getStack() vs getImutableStack(), my guess
is one uses a map.clone() and one doesn't. I need to bridge the context Map
around a queue so I do need to get the Map and then put the map elements back
into the servicing thread's context. I would like to avoid a map.clone/new Map
if I can. Which should I use: getStack or getImutableStack?
Thanks, curt
Curt Smith
ATT Digital Life
DLC Software Development
404-499-7013
(cell) 678-365-6508
RE: use of ThreadContext cleanup vs memory leaks etc
Thanks Remko.
Sure re perf reporting to this group.
If I do find I have short lived threads, do I call ThreadContext.clear() if I
only use the map feature to assure no memory leaks?
Tnx curt
-Original Message-
From: Remko Popma [mailto:rem...@yahoo.com]
Sent: Thursday, August 01, 2013 11:18 AM
To: Log4J Users List
Subject: Re: use of ThreadContext cleanup vs memory leaks etc
Curt,
I think the warning about memory leaks is mostly for short-lived threads. If
you create a new Thread often, put things in the ThreadContext and then let the
thread die, things will pile up in the ThreadContext. If the threads from
which you do logging essentially live forever then don't worry about it.
ThreadContext has both a stack and a map. Personally I don't see much use for
the stack, and I only use the map methods:
* put(String, String)
* get(String)
* containsKey(String)
* remove(String)
* isEmpty()
The layout pattern for the map is %X(key) like you said. With the stack you
only have patterns to display the full stack contents (%x, %NDC).
Since beta7, both the stack and the map are copy-on-write implementations
(avoiding the need to copy the stack/map for every log event).
There is no ThreadContext#getStack() method, but there are the #getContext()
and #getImmutableContext() methods.
With the default (copy-on-write) implementations, getContext() creates a copy,
and getImmutableContext() returns a reference the underlying immutable map.
(That said, I don't see why you would need either of those methods. Just use
the put/get/remove/... methods on ThreadContext. In my app I only ever need to
use ThreadContext#put().)
If you find out more about the difference in performance on j2me between log4j
v1 and v2 I'd be very interested, please keep us posted!
Hope this helps,
Remko
From: SMITH, CURTIS cs0...@att.com
To: log4j-user@logging.apache.org log4j-user@logging.apache.org
Sent: Thursday, August 1, 2013 10:54 PM
Subject: use of ThreadContext cleanup vs memory leaks etc
Greetings,
A terse recap of performance on my J2ME on a slow single core env:
BasicContextSelector and BufferedIO=false for RollingFile DOES seem to equal
log4j v1 performance in my most recent benchmarks. I'm not comfortable with
this result because what happened is the V1 benchmarks jumped worse to equal
the V2 benchmarks without explanation. So I'm digging into that issue. But
I'm wanting to move to using V2's MDC to see if that has much of a perf hit for
just put'ing a few variables into ThreadContext and referencing them in the
Pattern: %X{transID} etc
The log4j-users-guide.pdf does not have any MDC API discussion, just
configuration parameters. This URL is all I've found:
http://logging.apache.org/log4j/2.x/manual/thread-context.html
Let me start by saying that most threads never die. They wait on queues so I
believe I never have to worry about ThreadContext.clear / removeStack etc. Or
Do I??
But to clarify proper API use, the above URL infers that thread local object
storage is cleaned up with ThreadContext.clear()
Maybe it's left over from V1 NDC but the JavaDoc on ThreadContext has some
strongly worded recommendation for calling ThreadContext.removeStack()
Each thread that created a diagnostic context by calling
push(java.lang.String)http://logging.apache.org/log4j/2.x/log4j-api/apidocs/org/apache/logging/log4j/ThreadContext.html
should call this method before exiting. Otherwise, the memory used by the
thread cannot be reclaimed by the VM.
As this is such an important problem in heavy duty systems and because it is
difficult to always guarantee that the remove method is called before exiting a
thread, this method has been augmented to lazily remove references to dead
threads. In practice, this means that you can be a little sloppy and
occasionally forget to call
remove(java.lang.String)http://logging.apache.org/log4j/2.x/log4j-api/apidocs/org/apache/logging/log4j/ThreadContext.html
before exiting a thread. However, you must call remove sometime. If you never
call it, then your application is sure to run out of memory.
I could use what the suggested cleanup of ThreadContext is??
Also: there's no reasoning for the getStack() vs getImutableStack(), my guess
is one uses a map.clone() and one doesn't. I need to bridge the context Map
around a queue so I do need to get the Map and then put the map elements back
into the servicing thread's context. I would like to avoid a map.clone/new Map
if I can. Which should I use: getStack or getImutableStack?
Thanks, curt
Curt Smith
ATT Digital Life
DLC Software Development
404-499-7013
(cell) 678-365-6508
-
To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-user-h...@logging.apache.org
RE: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1
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:rem...@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: async logger on slow single core env performs 50% worse than log4j v1
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 1ms 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:rem...@yahoo.com] 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 cs0...@att.com To: Log4J Users List log4j-user@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.go...@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
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:rem...@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 rem...@yahoo.com
To: Log4J Users List log4j-user@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 cs0...@att.com
To: Log4J Users List log4j-user@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.go...@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
RE: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1
.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.go...@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:rem...@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 rem...@yahoo.com
To: Log4J Users List log4j-user@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 cs0...@att.com
To: Log4J Users List log4j-user@logging.apache.org
Sent: Saturday, July 27, 2013 6:55 AM
RE: reflection? RE: async logger on slow single core env performs 50% worse than log4j v1
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.go...@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 ERRORError 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
RE: programmatically setting level for many loggers not working for 2nd - Nth logger
Oh! So you're right. That's what feed back is for.logger name=abc
I see the name I need to use now.
My 2nd part of this question is, why should I embed into code a configuration
dependency of abc , there needs to be a get list/iterator of loggers API to
prevent having ot keep code and log4j2.xml in sync, right?
Tnx curt
-Original Message-
From: Ralph Goers [mailto:ralph.go...@dslextreme.com]
Sent: Thursday, July 25, 2013 6:39 PM
To: Log4J Users List
Subject: Re: programmatically setting level for many loggers not working for
2nd - Nth logger
I don't understand. You don't have any loggers configured named VIDEO, DLA
or DEVICES. You do have appenders with those names. All those
getLoggerConfig calls should end up returning the root loggerConfig.
Ralph
On Jul 25, 2013, at 2:36 PM, SMITH, CURTIS wrote:
Programmatical setting of loggers only works for the first logger declared
unfortunately. Further there's a missing API that allows me to get a list
of loggers (or configurations) to walk and set level like get Category in v1.
See my code below that has coupling between code and log4j2.xml
Only the DLA logger seems to work for setting level at run time. If I
remove the level=DEBUG attributes from the loggers, then I don't get any
logs.
Code:
if (logLevelDebug != null) {
LoggerContext ctx = (LoggerContext)
LogManager.getContext(false);
Configuration config = ctx.getConfiguration();
LoggerConfig loggerConfig =
config.getLoggerConfig(LogManager.ROOT_LOGGER_NAME);
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(VIDEO); // doesn't
work. Is coupling with log4j2.xml
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(DLA);// this
works, but is first declared in log4j2.xml
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(DEVICES);// doesn't
work
loggerConfig.setLevel(Level.DEBUG);
ctx.updateLoggers(); // This causes all Loggers to refetch
information from their LoggerConfig.
logger.debug(ErrorLogsUI: setting root logger to DEBUG);
}
String logLevelWarn = req.getParameter(logLevelWarn);
if (logLevelWarn != null) {
LoggerContext ctx = (LoggerContext)
LogManager.getContext(false);
Configuration config = ctx.getConfiguration();
LoggerConfig loggerConfig =
config.getLoggerConfig(LogManager.ROOT_LOGGER_NAME);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(VIDEO);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(DLA);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(DEVICES);
loggerConfig.setLevel(Level.WARN);
ctx.updateLoggers(); // This causes all Loggers to refetch
information from their LoggerConfig.
logger.warn(ErrorLogsUI: setting root logger to WARN);
}
?xml version=1.0 encoding=UTF-8?
configuration 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
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
RE: programmatically setting level for many loggers not working for 2nd - Nth logger
Yes that works, thanks a lot for that tip!
LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
Configuration config = ctx.getConfiguration();
MapString, LoggerConfig loggers = config.getLoggers();
for(String key : loggers.keySet()) {// - big help
LoggerConfig cfg = loggers.get(key);
cfg.setLevel(Level.INFO);
}
ctx.updateLoggers(); // This causes all Loggers to refetch information from
their LoggerConfig.
-Original Message-
From: Ralph Goers [mailto:ralph.go...@dslextreme.com]
Sent: Friday, July 26, 2013 10:45 AM
To: Log4J Users List
Subject: Re: programmatically setting level for many loggers not working for
2nd - Nth logger
If I understand your question correctly, the Configuration interface has a
getLoggers() call that returns a Map of all the LoggerConfig objects.
Ralph
On Jul 26, 2013, at 6:51 AM, SMITH, CURTIS wrote:
Oh! So you're right. That's what feed back is for.logger
name=abc I see the name I need to use now.
My 2nd part of this question is, why should I embed into code a
configuration dependency of abc , there needs to be a get list/iterator of
loggers API to prevent having ot keep code and log4j2.xml in sync, right?
Tnx curt
-Original Message-
From: Ralph Goers [mailto:ralph.go...@dslextreme.com]
Sent: Thursday, July 25, 2013 6:39 PM
To: Log4J Users List
Subject: Re: programmatically setting level for many loggers not working for
2nd - Nth logger
I don't understand. You don't have any loggers configured named VIDEO,
DLA or DEVICES. You do have appenders with those names. All those
getLoggerConfig calls should end up returning the root loggerConfig.
Ralph
On Jul 25, 2013, at 2:36 PM, SMITH, CURTIS wrote:
Programmatical setting of loggers only works for the first logger declared
unfortunately. Further there's a missing API that allows me to get a list
of loggers (or configurations) to walk and set level like get Category in
v1. See my code below that has coupling between code and log4j2.xml
Only the DLA logger seems to work for setting level at run time. If I
remove the level=DEBUG attributes from the loggers, then I don't get any
logs.
Code:
if (logLevelDebug != null) {
LoggerContext ctx = (LoggerContext)
LogManager.getContext(false);
Configuration config = ctx.getConfiguration();
LoggerConfig loggerConfig =
config.getLoggerConfig(LogManager.ROOT_LOGGER_NAME);
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(VIDEO); // doesn't
work. Is coupling with log4j2.xml
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(DLA);// this
works, but is first declared in log4j2.xml
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(DEVICES);// doesn't
work
loggerConfig.setLevel(Level.DEBUG);
ctx.updateLoggers(); // This causes all Loggers to refetch
information from their LoggerConfig.
logger.debug(ErrorLogsUI: setting root logger to DEBUG);
}
String logLevelWarn = req.getParameter(logLevelWarn);
if (logLevelWarn != null) {
LoggerContext ctx = (LoggerContext)
LogManager.getContext(false);
Configuration config = ctx.getConfiguration();
LoggerConfig loggerConfig =
config.getLoggerConfig(LogManager.ROOT_LOGGER_NAME);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(VIDEO);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(DLA);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(DEVICES);
loggerConfig.setLevel(Level.WARN);
ctx.updateLoggers(); // This causes all Loggers to refetch
information from their LoggerConfig.
logger.warn(ErrorLogsUI: setting root logger to WARN);
}
?xml version=1.0 encoding=UTF-8?
configuration 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
RE: async logger on slow single core env performs 50% worse than log4j v1
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
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.go...@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
programmatically setting level for many loggers not working for 2nd - Nth logger
Programmatical setting of loggers only works for the first logger declared
unfortunately. Further there's a missing API that allows me to get a list of
loggers (or configurations) to walk and set level like get Category in v1. See
my code below that has coupling between code and log4j2.xml
Only the DLA logger seems to work for setting level at run time. If I remove
the level=DEBUG attributes from the loggers, then I don't get any logs.
Code:
if (logLevelDebug != null) {
LoggerContext ctx = (LoggerContext)
LogManager.getContext(false);
Configuration config = ctx.getConfiguration();
LoggerConfig loggerConfig =
config.getLoggerConfig(LogManager.ROOT_LOGGER_NAME);
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(VIDEO); // doesn't
work. Is coupling with log4j2.xml
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(DLA);// this
works, but is first declared in log4j2.xml
loggerConfig.setLevel(Level.DEBUG);
loggerConfig = config.getLoggerConfig(DEVICES);// doesn't
work
loggerConfig.setLevel(Level.DEBUG);
ctx.updateLoggers(); // This causes all Loggers to refetch
information from their LoggerConfig.
logger.debug(ErrorLogsUI: setting root logger to DEBUG);
}
String logLevelWarn = req.getParameter(logLevelWarn);
if (logLevelWarn != null) {
LoggerContext ctx = (LoggerContext)
LogManager.getContext(false);
Configuration config = ctx.getConfiguration();
LoggerConfig loggerConfig =
config.getLoggerConfig(LogManager.ROOT_LOGGER_NAME);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(VIDEO);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(DLA);
loggerConfig.setLevel(Level.WARN);
loggerConfig = config.getLoggerConfig(DEVICES);
loggerConfig.setLevel(Level.WARN);
ctx.updateLoggers(); // This causes all Loggers to refetch
information from their LoggerConfig.
logger.warn(ErrorLogsUI: setting root logger to WARN);
}
?xml version=1.0 encoding=UTF-8?
configuration 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 /
FYI, in embedded env: got sun.reflect.Reflection is not installed
My testing of log4j v2 just started getting my log output to my log files, but
had configuration status=trace level=trace
I googled and found this no reflection log to stdout is from log4j2. :)
This is an embedded env; IBM J9 J2ME jdk 1.6 on single core Arm chip, but I
guess no reflection... I hope nothing internal is now going to malfunction?
package org.apache.logging.log4j.core.selector;
public class
ClassLoaderContextSelectorhttp://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
implements
ContextSelectorhttp://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ContextSelector.html
{
private static void setupCallerCheck() {
223http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
try {
224http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
final ClassLoader loader = Loader.getClassLoader();
225http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
final Class clazz = loader.loadClass(sun.reflect.Reflection);
226http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
final Method[] methods = clazz.getMethods();
227http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
for (final Method method : methods) {
228http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
final int modifier = method.getModifiers();
229http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
if (method.getName().equals(getCallerClass)
Modifier.isStatic(modifier)) {
230http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
getCallerClass = method;
231http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
break;
232http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
}
233http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
}
234http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
} catch (final ClassNotFoundException cnfe) {
235http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
LOGGER.debug(sun.reflect.Reflection is not installed); //
--
236http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/selector/ClassLoaderContextSelector.html
}
Curt Smith
ATT Digital Life
DLC Software Development
404-499-7013
(cell) 678-365-6508
RE: Logging only particular users
If a sequence of execution for a user follows is handled by one thread (often the case in j2ee) then look at fish tagging, MDC. Log4j2 can put user and any other context in a thread Local object behind the scenes. http://logging.apache.org/log4j/2.x/manual/thread-context.html curt -Original Message- From: Michael Wechner [mailto:michael.wech...@wyona.com] Sent: Wednesday, July 24, 2013 10:35 AM To: Log4J Users List Subject: Logging only particular users Hi We are using log4j for many years now for our open source CMS www.yanel.org and it works really great and I really would like to thank everyone who contributed to log4j. Over the years we are experiencing that more and more people are using our software, which is very nice, but it also makes it harder to debug. Hence I had the idea that it would be nice if one could filter the log file, such that one would see only the log statements generated by requests of a particular user. I guess a simple way to accomplish this would be to add the user or session id to the log statement and then to grep for this user or session id. But it seems to me a bit crude and hence I wanted to ask if somebody might have tried something similar? Thanks Michael - To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-user-h...@logging.apache.org - To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-user-h...@logging.apache.org
Confused: want low latency: do I need BOTH async logger AND async appender??
http://logging.apache.org/log4j/2.x/manual/async.html This URL describes that v2 has both async logger and async appender. What is the suggested config for an embedded situation where I want low latency, nothing fancy? I've had do this in code since we don't own the cmd line: OSGi and system vendor owns the box and java command line. 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 Tnx curt Curt Smith ATT Digital Life DLC Software Development 404-499-7013 (cell) 678-365-6508
Not getting my log output, need debugging v2 tips?
I feel apologetic for asking how to debug a v2 configuration but there's no
links off the v2 website. My env is embedded and I'm not getting any missing
classpath problems, I solved those. I am getting console output but none of my
FastRollingFile appenders are emitting their logs.
Some of my problem may have been translating my v1 log4j.properties into the v2
equivalent.
Maybe I need to create a logger for the log4j packages to the console appender?
I attempted that. See highlighted logger:
log4j.logger.com.att.dlc.afm=DEBUG,DEVICES,ERRORLOG
log4j.additivity.com.att.dlc.afm=false
log4j.logger.com.att.dlc.devices=DEBUG,DEVICES,ERRORLOG
log4j.additivity.com.att.dlc.devices=false
log4j.logger.com.att.dlc.util.serialport=DEBUG,DEVICES,ERRORLOG
log4j.additivity.com.att.dlc.util.serialport=false
log4j.logger.com.att.dlc.webcamserver=DEBUG,VIDEO,ERRORLOG
log4j.additivity.com.att.dlc.webcamserver=false
log4j.logger.com.att.dlc.devices.cameras=DEBUG,VIDEO,ERRORLOG
log4j.additivity.com.att.dlc.devices.cameras=false
?xml version=1.0 encoding=UTF-8?
configuration
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
SizedBasedTriggeringPolicy 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
SizedBasedTriggeringPolicy 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
SizedBasedTriggeringPolicy 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=org.apache level=debug
appender-ref ref=CO /
/logger
logger name=com.att.dlc.afm additivity=false level=debug
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
ATT Digital Life
DLC Software Development
404-499-7013
(cell) 678-365-6508
Log4j2: Programmatically setting log4j2 log level
From a thread back in May: My question to the below snips of the thread are; My app has many Catagories (using 1.x terminology). To setLevel in 1.x I had to getCurrentCatagories() and iterate over the list setting level. In 2.x, does the code below set all Appenders regardless of what Level they were set to in log4j.xml? loggerConfig.setLevel(Level.DEBUG); ctx.updateLoggers(); The next question is how to set the level of just one Appender (Logger??) ? Is there a way to get the list / iterator of Appenders(Logger?) like you could get a a list of Catagories in 1.x? It appears that LogManager.getLogger(foo) you need to know the logger names at coding time. Thanks, curt === Ralph Goers said: No, the X Logger does not inherit its level from the root Logger. It inherits its level from the root LoggerConfig. See the picture at http://logging.apache.org/log4j/2.x/manual/architecture.html. The level you are modifying is brought into each Logger so that the level can be tested very quickly. That is why the note on the setLevel method says it is there primarily for unit testing. To do what you are attempting below you would need to do: LoggerContext ctx = (LoggerContext) LogManager.getContext(false); Configuration config = ctx.getConfiguration(); LoggerConfig loggerConfig = config.getRootLogger(); /* You could also specify the actual logger name as below and it will return the LoggerConfig used by the Logger. LoggerConfig loggerConfig = getLoggerConfig(X); */ loggerConfig.setLevel(Level.DEBUG); ctx.updateLoggers(); // This causes all Loggers to refetch information from their LoggerConfig. Ralph Eric Scheie said: This is the actual code I used. LoggerContext ctx = (LoggerContext) LogManager.getContext(false); Configuration config = ctx.getConfiguration(); LoggerConfig loggerConfig = config.getLoggerConfig(LogManager. ROOT_LOGGER_NAME); loggerConfig.setLevel(level); ctx.updateLoggers(); - To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-user-h...@logging.apache.org
