logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Remko Popma <remko.po...@gmail.com>
Subject Re: Catalina.out trace : memory leak
Date Sun, 27 Apr 2014 12:57:27 GMT
Mahesh,

Sorry, I've been unable to spend much time on log4j recently. Can I ask you to raise one or
more Jiras for the issues you found? (Esp. the NPE in NameAbbreviator sounds like a separate
bug.)
The volume of mails on this list is quite high and without a Jira I'm worried it'll just drop
off the radar and won't get addressed...

Thanks!
Remko

Sent from my iPhone

> On 2014/04/11, at 11:43, Mahesh Dilhan <mail.mahesh.lk@gmail.com> wrote:
> 
> side note ; java version : JDK 1.6.0_10
> 
> Remko
> 
> Can you share a dummy maven webapp [.tar] some where in
> http://logging.apache.org/log4j/2.x/manual/async.html
> , with necessary dependencies  and [*Async]* configuration for log4j2.xml
> So ppl can just build and deploy it in a tomcat container [ > 7.0.40 ], and
> provide feedback, as this might be a problem in my configuration
> 
> steps of test case : deploy/ start/stop, trace catalina.out
> 
> Thanks in advance
> 
> 
> On Fri, Apr 11, 2014 at 7:49 AM, Mahesh Dilhan <mail.mahesh.lk@gmail.com>wrote:
> 
>> 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
>> 
>> 
>> 
>> 
>> 

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org


Mime
View raw message