logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Joan Balagueró - ventusproxy <joan.balagu...@ventusproxy.com>
Subject Verifying we are using async loggers
Date Thu, 16 Aug 2018 10:59:54 GMT
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.

 


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message