logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mahesh Dilhan <mail.mahesh...@gmail.com>
Subject Re: Catalina.out trace : memory leak
Date Fri, 11 Apr 2014 02:19:59 GMT
Observed followings after

 - removing
 Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
from catalina.properties
- change <Root> .. </Root> tag to
    <AsyncRoot level="INFO" includeLocation="false">
        <AppenderRef ref="RollingFile-${web:contextPath}"/>
    </AsyncRoot>


On start-up

014-04-11 07:43:03,640 ERROR An exception occurred processing Appender
RollingFile-/app java.lang.NullPointerException
       at java.lang.StringBuilder.<init>(StringBuilder.java:92)
       at
org.apache.logging.log4j.core.pattern.NameAbbreviator$PatternAbbreviator.abbreviate(NameAbbreviator.java:286)
       at
org.apache.logging.log4j.core.pattern.NamePatternConverter.abbreviate(NamePatternConverter.java:53)
       at
org.apache.logging.log4j.core.pattern.LoggerPatternConverter.format(LoggerPatternConverter.java:64)
       at
org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
       at
org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:172)
       at
org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:52)
       at
org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:45)
       at
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:118)
       at
org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
       at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
       at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
       at
org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:117)
       at
org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:222)
       at
org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:207)
       at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
       at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
       at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
       at java.lang.Thread.run(Thread.java:619)


Also Console
Apr 11, 2014 7:42:49 AM org.apache.catalina.loader.WebappClassLoader
checkThreadLocalMapForLeaks
SEVERE: The web application [/clearing-newcdev10] created a ThreadLocal
with key of type [java.lang.ThreadLocal] (value
[java.lang.ThreadLocal@131d70a]) and a value of type [
org.apache.logging.log4j.core.async.AsyncLogger.Info] (value
[org.apache.logging.log4j.core.async.AsyncLogger$Info@11cd743]) 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.



*Now JConsole has two thread *

*Name: AsyncLoggerConfig-1*
State: TIMED_WAITING
Total blocked: 0  Total waited: 307,234

Stack trace:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:317)
com.lmax.disruptor.SleepingWaitStrategy.applyWaitMethod(SleepingWaitStrategy.java:78)
com.lmax.disruptor.SleepingWaitStrategy.waitFor(SleepingWaitStrategy.java:51)
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:123)
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
java.lang.Thread.run(Thread.java:619)


*Name: AsyncLogger-1*
State: TIMED_WAITING
Total blocked: 0  Total waited: 325,479

Stack trace:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:317)
com.lmax.disruptor.SleepingWaitStrategy.applyWaitMethod(SleepingWaitStrategy.java:78)
com.lmax.disruptor.SleepingWaitStrategy.waitFor(SleepingWaitStrategy.java:51)
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:123)
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
java.lang.Thread.run(Thread.java:619)




On Thu, Apr 10, 2014 at 8:45 PM, Remko Popma <remko.popma@gmail.com> wrote:

> OK, One more thing you can try is, instead of making all loggers async by
> setting system property
> Log4jContextSelector=org.apache.logging.log4j.core.async.
> AsyncLoggerContextSelector,
>
> instead remove that property
> and replace the <Root></Root> elements in your log4j2.xml config with
> <AsyncRoot></AsyncRoot> elements. This will also use the disruptor but uses
> a slightly different mechanism.
>
> Do you still see the problem after these changes?
>
>
>
> On Thu, Apr 10, 2014 at 6:58 PM, Mahesh Dilhan <mail.mahesh.lk@gmail.com
> >wrote:
>
> > HI
> >
> > Answers are in blue
> >
> > This may be caused by the LoggerContext.stop() method not being called.
> >
> > Which version of Tomcat are you using?  Special care is needed for Tomcat
> > 7.0.40 and older.
> > *apache-tomcat-7.0.47*
> >
> > A similar issue, LOG4J2-578 seemed to be caused by a config issue where
> the
> > version number in web.xml was incorrect.
> > Can you check this?
> >
> > *<web-app xmlns="http://java.sun.com/xml/ns/javaee
> > <http://java.sun.com/xml/ns/javaee>"
> >  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance
> > <http://www.w3.org/2001/XMLSchema-instance>"
> >  xsi:schemaLocation="http://java.sun.com/xml/ns/javaee
> > <http://java.sun.com/xml/ns/javaee>*
> > *    http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd
> > <http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd>"   version="3.0"
> >  metadata-complete="true">*
> >
> > *WEB-INF/lib does not contains any servlet-api, [tomcat container
> provides
> > the servlet-api.jar] *
> > Also, are the log4j jars under the shared Catalina lib? No
> > I suspect the problem goes away if you put the log4j jars under your
> > webapp's WEB-INF/lib folder.
> >
> > *Dependencies are located in WEB-INF/lib ,*
> > *<dependency>*
> > *            <groupId>com.lmax</groupId>*
> > *            <artifactId>disruptor</artifactId>*
> > *            <version>3.2.1</version>*
> > *        </dependency> *
> > *        <dependency>*
> > *            <groupId>org.apache.logging.log4j</groupId>*
> > *            <artifactId>log4j-api</artifactId>*
> > *            <version>2.0-rc1</version>*
> > *        </dependency>*
> > *        <dependency>*
> > *            <groupId>org.apache.logging.log4j</groupId>*
> > *            <artifactId>log4j-core</artifactId>*
> > *            <version>2.0-rc1</version>*
> > *        </dependency>*
> > *        <dependency>*
> > *            <groupId>org.apache.logging.log4j</groupId>*
> > *            <artifactId>log4j-slf4j-impl</artifactId>*
> > *            <version>2.0-rc1</version>*
> > *        </dependency>*
> > *        <dependency>*
> > *            <groupId>org.apache.logging.log4j</groupId>*
> > *            <artifactId>log4j-1.2-api</artifactId>*
> > *            <version>2.0-rc1</version>*
> > *        </dependency>*
> >
> >
> > *For test 1 Configurations are  in -catalina.properties  & for test 2
> that
> > is in -catalina.sh [CATALINA_OPTS] , in both occation, it worked*
> >
> >
> *Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector*
> > *log4j2.disable.jmx=true*
> >
> > But I still get following console out
> >
> >
> > 2014-04-10 12:56:09,120 DEBUG Shutting down OutputStreamManager
> SYSTEM_OUT
> > 2014-04-10 12:56:09,123 DEBUG JMX disabled for log4j2. Not registering
> > MBeans.
> > 2014-04-10 12:56:09,168 DEBUG Using default SystemClock for timestamps
> > 2014-04-10 12:56:09,169 DEBUG AsyncLogger.ThreadNameStrategy=CACHED
> > 2014-04-10 12:56:09,171 DEBUG property AsyncLogger.WaitStrategy=null
> > 2014-04-10 12:56:09,173 DEBUG disruptor event handler uses
> > SleepingWaitStrategy
> > 2014-04-10 12:56:09,197 DEBUG No AsyncLogger.ExceptionHandler specified
> > 2014-04-10 12:56:09,203 DEBUG Starting AsyncLogger disruptor with
> > ringbuffer size 262144...
> >
> > SEVERE: The web application [/app] created a ThreadLocal with key of type
> > [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@17b3a1e]) and a
> > value
> > of type [org.apache.logging.log4j.core.async.AsyncLogger.Info] (value
> > [org.apache.logging.log4j.core.async.AsyncLogger$Info@1aca2de]) 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.
> > Apr 10, 2014 2:53:28 PM org.apache.catalina.loader.WebappClassLoader
> > checkThreadLocalMapForLeaks
> >
> >
> >
> > *Also JConsole*
> >
> > *Name: AsyncLogger-1*
> > *State: TIMED_WAITING*
> > *Total blocked: 1  Total waited: 228,630 [ this number getting increased
> ]*
> >
> > *Stack trace: *
> > *sun.misc.Unsafe.park(Native Method)*
> > *java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:317)*
> >
> >
> *com.lmax.disruptor.SleepingWaitStrategy.applyWaitMethod(SleepingWaitStrategy.java:78)*
> >
> >
> *com.lmax.disruptor.SleepingWaitStrategy.waitFor(SleepingWaitStrategy.java:51)*
> >
> >
> *com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)*
> >
> *com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:123)*
> >
> >
> *java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)*
> >
> >
> *java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)*
> > *java.lang.Thread.run(Thread.java:619)*
> >
> >
> > On Thu, Apr 10, 2014 at 9:51 AM, Remko Popma <remko.popma@gmail.com>
> > wrote:
> >
> > > This may be caused by the LoggerContext.stop() method not being called.
> > >
> > > Which version of Tomcat are you using? Special care is needed for
> Tomcat
> > > 7.0.40 and older.
> > >
> > > A similar issue, LOG4J2-578 seemed to be caused by a config issue where
> > > the version number in web.xml was incorrect. Can you check this?
> > >
> > > Also, are the log4j jars under the shared Catalina lib? I suspect the
> > > problem goes away if you put the log4j jars under your webapp's
> > WEB-INF/lib
> > > folder.
> > >
> > > Remko
> > >
> > > Sent from my iPhone
> > >
> > > > On 2014/04/10, at 11:24, Mahesh Dilhan <mail.mahesh.lk@gmail.com>
> > wrote:
> > > >
> > > > HI
> > > >
> > > > I got following catalina console out continuously  when I try to stop
> > the
> > > > web application.
> > > >
> > > > Brief  on configuration
> > > > *version : rc1*
> > > >
> > > > *Log4j2.xml*
> > > >
> > > > <Configuration status="OFF" >
> > > >  <Appenders>
> > > >    <RollingRandomAccessFile name="RollingFile-${web:contextPath}"
> > > > fileName="${sys:catalina.home}/logs/current/${web:contextPath}.log"
> > > > immediateFlush="false" append="false"
> > > >
> > > >
> > >
> >
> filePattern="${sys:catalina.home}/logs/archived/%d{yyyy-MM-dd}${contextName}-%d{yyyy-MM-dd}.log.gz">
> > > >      <PatternLayout>
> > > >        <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
> > > >      </PatternLayout>
> > > >      <Policies>
> > > >        <TimeBasedTriggeringPolicy />
> > > >      </Policies>
> > > >    </RollingRandomAccessFile>
> > > >  </Appenders>
> > > >  <Loggers>
> > > >    <Root level="INFO" includeLocation="false">
> > > >      <AppenderRef ref="RollingFile-${web:contextPath}"/>
> > > >
> > > >    </Root>
> > > >  </Loggers>
> > > > </Configuration>
> > > >
> > > > *Tomcat properties :*
> > > > Asysnc logger [tomcat is configured with the property
> > > >
> > >
> >
> {Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
> > > > }
> > > >
> > > >
> > > >
> > > >
> > > >
> > > > Apr 08, 2014 12:32:17 PM org.apache.catalina.loader.WebappClassLoader
> > > > clearReferencesThreads
> > > > SEVERE: The web application [/app] appears to have started a thread
> > named
> > > > [AsyncLogger-1] but has failed to stop it. *This is very likely to
> > > create a
> > > > memory leak.*
> > > > Apr 08, 2014 12:32:17 PM org.apache.catalina.loader.WebappClassLoader
> > > > checkThreadLocalMapForLeaks
> > > > SEVERE: The web application [/app] created a ThreadLocal with key of
> > type
> > > > [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@e8d7057]) and
> a
> > > value
> > > > of type [org.apache.logging.log4j.core.async.AsyncLogger.Info]
> (value
> > > > [org.apache.logging.log4j.core.async.AsyncLogger$Info@67ca6737]) 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.
> > > >
> > > >
> > > >
> > > > What could be missing in my configuration to run into a such console
> > > trace ?
> > > > What are the fixes I should look-into ?
> > > >
> > > >
> > > > Thanks
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> > > For additional commands, e-mail: log4j-user-help@logging.apache.org
> > >
> > >
> >
>



-- 
Mahesh Dilhan
Software Engineer

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