You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Joan Balagueró - ventusproxy <jo...@ventusproxy.com> on 2018/08/16 10:59:54 UTC
Verifying we are using async loggers
Hello,
We are using async loggers in our log4j2.xml, enabling
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContex
tSelector when we start tomcat.
When tomcat starts, we can see:
2018-08-07 21:03:56,535 localhost-startStop-1 TRACE Using default
SystemClock for timestamps.
2018-08-07 21:03:56,536 localhost-startStop-1 TRACE Using DummyNanoClock for
nanosecond timestamps.
2018-08-07 21:03:56,536 localhost-startStop-1 DEBUG Reconfiguration complete
for context[name=AsyncContext@4d8d549e] at URI
/home/ventusproxy/app/ROOT/WEB-INF/log4j.xml
(org.apache.logging.log4j.core.async.AsyncLoggerContext@2c9ae56e) with
optional ClassLoader: null
2018-08-07 21:03:56,536 localhost-startStop-1 DEBUG Shutdown hook enabled.
Registering a new one.
2018-08-07 21:03:56,537 localhost-startStop-1 DEBUG
LoggerContext[name=AsyncContext@4d8d549e,
org.apache.logging.log4j.core.async.AsyncLoggerContext@2c9ae56e] started OK.
2018-08-07 21:03:56,538 localhost-startStop-1 TRACE Using default
SystemClock for timestamps.
2018-08-07 21:03:56,539 localhost-startStop-1 DEBUG
AsyncLogger.ThreadNameStrategy=CACHED
2018-08-07 21:03:56,556 Log4j2-TF-1-AsyncLogger[AsyncContext@4d8d549e]-1
DEBUG Now writing to /home/ventusproxy/logs/vproxy_system.2018-08-07 at
2018-08-07T21:03:56.556-0400
2018-08-07 21:03:57,081 localhost-startStop-1 DEBUG PluginManager
'Converter' found 42 plugins
2018-08-07 21:03:57,082 localhost-startStop-1 DEBUG Starting
OutputStreamManager SYSTEM_OUT.false.false-2
2018-08-07 21:03:57,083 localhost-startStop-1 TRACE
[DefaultAsyncContext@localhost-startStop-1] AsyncLoggerDisruptor creating
new disruptor for this context.
2018-08-07 21:03:57,083 localhost-startStop-1 TRACE property
AsyncLogger.WaitStrategy=TIMEOUT
2018-08-07 21:03:57,092 localhost-startStop-1 DEBUG
[DefaultAsyncContext@localhost-startStop-1] Starting AsyncLogger disruptor
for this context with ringbufferSize=262144,
waitStrategy=TimeoutBlockingWaitStrategy,
exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerDefaultExcep
tionHandler@71fd86cb...
2018-08-07 21:03:57,093 localhost-startStop-1 TRACE
[DefaultAsyncContext@localhost-startStop-1] AsyncLoggers use a threadlocal
translator
2018-08-07 21:03:57,093 localhost-startStop-1 DEBUG Starting
LoggerContext[name=DefaultAsyncContext@localhost-startStop-1,
org.apache.logging.log4j.core.async.AsyncLoggerContext@77ae266d]...
2018-08-07 21:03:57,094 localhost-startStop-1 DEBUG Reconfiguration started
for context[name=DefaultAsyncContext@localhost-startStop-1] at URI null
(org.apache.logging.log4j.core.async.AsyncLoggerContext@77ae266d) with
optional ClassLoader: null
2018-08-07 21:03:57,094 localhost-startStop-1 DEBUG Using
configurationFactory
org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@4b6e6fdf
2018-08-07 21:03:57,133 localhost-startStop-1 DEBUG Initializing
configuration
XmlConfiguration[location=/home/ventusproxy/app/ROOT/WEB-INF/log4j.xml]
And finally (last debug line):
2018-08-07 21:03:57,200 localhost-startStop-1 DEBUG
LoggerContext[name=DefaultAsyncContext@localhost-startStop-1,
org.apache.logging.log4j.core.async.AsyncLoggerContext@77ae266d] started OK.
When we perform a thread dump with JStack we see 2 threads:
"Log4j2-TF-7-AsyncLogger[DefaultAsyncContext@localhost-startStop-1]-2" #23
daemon prio=5 os_prio=0 tid=0x00007f1ee8ad9800 nid=0x625d runnable
[0x00007f1f05817000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000925d3ad8> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitN
anos(AbstractQueuedSynchronizer.java:2078)
at
com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitSt
rategy.java:38)
at
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarri
er.java:56)
at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:124)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- None
"Log4j2-TF-1-AsyncLogger[AsyncContext@4d8d549e]-1" #21 daemon prio=5
os_prio=0 tid=0x00007f1ee88d8800 nid=0x625c runnable [0x00007f1f06073000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000093099540> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitN
anos(AbstractQueuedSynchronizer.java:2078)
at
com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitSt
rategy.java:38)
at
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarri
er.java:56)
at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:124)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- None
And when we stop tomcat, all these errors are logged:
07-Aug-2018 21:07:29.991 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The
web application [ROOT] appears to have started a thread named
[Log4j2-TF-7-AsyncLogger[DefaultAsyncContext@localhost-startStop-1]-2] but
has failed to stop it. This is very likely to create a memory leak. Stack
trace of thread:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitN
anos(AbstractQueuedSynchronizer.java:2078)
com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitSt
rategy.java:38)
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarri
er.java:56)
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:124)
java.lang.Thread.run(Thread.java:748)
07-Aug-2018 21:07:29.993 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@494a6bc6]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@46d89786])
but failed to remove it when the web application was stopped. Threads are
going to be renewed over time to try and avoid a probable memory leak.
07-Aug-2018 21:07:29.993 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@494a6bc6]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@7fca5b63])
but failed to remove it when the web application was stopped. Threads are
going to be renewed over time to try and avoid a probable memory leak.
07-Aug-2018 21:07:29.994 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@7d2c87bb]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@316c8d06])
but failed to remove it when the web application was stopped. Threads are
going to be renewed over time to try and avoid a probable memory leak.
07-Aug-2018 21:07:29.994 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@74afa5d5]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@5913f960])
but failed to remove it when the web application was stopped. Threads are
going to be renewed over time to try and avoid a probable memory leak.
07-Aug-2018 21:07:29.994 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@401baca6]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@154a0d1e])
but failed to remove it when the web application was stopped. Threads are
going to be renewed over time to try and avoid a probable memory leak.
07-Aug-2018 21:07:29.995 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@1cc2936f]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@5a5ca16e])
but failed to remove it when the web application was stopped. Threads are
going to be renewed over time to try and avoid a probable memory leak.
07-Aug-2018 21:07:29.995 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks
The web application [ROOT] created a ThreadLocal with key of type
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@473f581f]) and a value
of type [org.apache.logging.log4j.core.async.RingBufferLogEventTranslator]
(value
[org.apache.logging.log4j.core.async.RingBufferLogEventTranslator@2d89f1b])
but failed to remove it when the web application was stopped. Threads are
going to be renewed over time to try and avoid a probable memory leak.
So:
1. With these traces can I confirm I'm using full asynchronous
logging?
2. I've read that async logging starts just one thread, but here I see
2 (like when we mix sync and async logging). Is this true?
3. How can I remove these errors from the catalina.out? The
application stops correctly so these messages are not really a problem, but
I'd prefer to remove them if it's possible.
Thanks,
Joan.
Re: Verifying we are using async loggers
Posted by Remko Popma <re...@gmail.com>.
1. With these traces can I confirm I'm using full asynchronous
logging?
Yes. We see AsyncLogger and not AsyncConfigLogger so all logging is happening asynchronously.
2. I've read that async logging starts just one thread, but here I see
2 (like when we mix sync and async logging). Is this true?
I would also expect just 1 async logging background thread. Unsure why there are two.
3. How can I remove these errors from the catalina.out? The
application stops correctly so these messages are not really a problem, but
I'd prefer to remove them if it's possible.
Unsure why these warnings are showing. I spend quite a bit of time making them go away with a previous version of log4j but they’re back again. :-(
I’m not going to try again.
(Shameless plug) Every java main() method deserves http://picocli.info
> On Aug 16, 2018, at 18:59, Joan Balagueró - ventusproxy <jo...@ventusproxy.com> wrote:
>
> 1. With these traces can I confirm I'm using full asynchronous
> logging?
>
> 2. I've read that async logging starts just one thread, but here I see
> 2 (like when we mix sync and async logging). Is this true?
>
> 3. How can I remove these errors from the catalina.out? The
> application stops correctly so these messages are not really a problem, but
> I'd prefer to remove them if it's possible.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org