[jira] [Created] (LOG4J2-819) PermGen OutOfMemoryError when reloading webapp on Tomcat 6

Discussion:

Costa Theodosiou (JIRA)

2014-09-10 06:13:28 UTC

Costa Theodosiou created LOG4J2-819:
---------------------------------------

Summary: PermGen OutOfMemoryError when reloading webapp on Tomcat 6
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical

When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.

After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.

When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.

Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.

I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-10 13:26:28 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Gary Gregory updated LOG4J2-819:
--------------------------------
Attachment: gg-cc-clock.patch

How about allowing clock threads to be stopped along the lines of this patch?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-cc-clock.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-10 13:44:28 UTC

Permalink

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-10 13:58:28 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Gary Gregory updated LOG4J2-819:
--------------------------------
Attachment: gg-log4j2-clocks.patch

All clocks are now stoppable in this patch. The Log4jWebInitializerImpl stops the clock but should the stop() call be in the logger context instead?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-10 14:00:42 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Gary Gregory updated LOG4J2-819:
--------------------------------
Comment: was deleted

(was: How about allowing clock threads to be stopped along the lines of this patch?)

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-10 14:02:28 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14128485#comment-14128485 ]

Gary Gregory edited comment on LOG4J2-819 at 9/10/14 2:02 PM:
--------------------------------------------------------------

All clocks are now stoppable in this patch. The Log4jWebInitializerImpl stops the clock but should the stop() call be in the logger context instead?

[~costat]: Can you apply this patch and try it in your scenario?

was (Author: garydgregory):
All clocks are now stoppable in this patch. The Log4jWebInitializerImpl stops the clock but should the stop() call be in the logger context instead?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-10 23:55:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14129390#comment-14129390 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

I'm leaning towards not fixing this. Stopping (and re-starting!) clock threads brings too much complexity.

These clocks were designed to be used in ultralow (sub-microsecond) latency applications.
Web apps don't fall into that category.

Web apps should just use the default system clock. Using any other class gives them no benefits and only trouble.

I will update the site docs to that effect.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Costa Theodosiou (JIRA)

2014-09-11 00:13:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14129418#comment-14129418 ]

Costa Theodosiou commented on LOG4J2-819:
-----------------------------------------

The scenario I reported was a default scenario. I did not configure a different clock to whatever was created by default. The CoarseCachedClock$1 Thread was created regardless.

The CoarseCachedClock singleton is created automatically by the classloader. The singleton creates the Thread and the Thread is kicked off by the CoarseCachedClock constructor. This means regardless of what ClockFactory.getClock() you want, the Thread is already there chugging along.

Perhaps what is needed is a for CoarseCachedClock.instance() to return a singleton that is created *on demand*. Synchronization of this static method will also have to be considered so that one and only one instance is ever created.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-11 00:30:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14129437#comment-14129437 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Aha! Thanks for pointing that out, I completely missed that. We should definitely fix that.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-11 00:31:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14129437#comment-14129437 ]

Remko Popma edited comment on LOG4J2-819 at 9/11/14 12:31 AM:
--------------------------------------------------------------

Aha! Thanks for pointing that out. I assumed you had configured the CoarseCachedClock and I completely missed that a singleton is always created. We should definitely fix that.

was (Author: ***@yahoo.com):
Aha! Thanks for pointing that out, I completely missed that. We should definitely fix that.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-11 01:05:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14129465#comment-14129465 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

I disagree, from my reply on the ML:

Hi Remko & Matt,

Thank you for chiming in.

As of now, the threads still exist and are not cleanly stoppable. The only way to cleanly and _simply_ stop a thread is with a flag as the patch does. From a design stand point it does not smell right to start threads and not offer a clean way to stop them. So that's one point I see in favor of _at least_ having the new cleaner clocks in master. Whether or not we stop them automatically is another issue.

I see your point about web apps but that only means (to me) that out web integration needs to override the clock factory with one that does not use a thread. If the user configures a thread based clock anyway, then what? He or she is hosed? That does not sound right.

So from a process POV, I would like to:

(1) Agree on how to stop a thread-based clock (my patch minus the call from the web code).
(2) Discuss on who should do the stopping, if any one. At worse, the use can call the stop() method. At least we would have something in 2.1...

Thoughts?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Matt Sicker (JIRA)

2014-09-11 01:32:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14129486#comment-14129486 ]

Matt Sicker commented on LOG4J2-819:
------------------------------------

I feel like we should have a central thread factory sort of thing that keeps track of anything we spawn so we can kill it off with the LoggerContext.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Costa Theodosiou (JIRA)

2014-09-11 01:59:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14129514#comment-14129514 ]

Costa Theodosiou commented on LOG4J2-819:
-----------------------------------------

[~garydgregory] Regarding the patch, StopFlagThread.setStopFlag() needs to take a boolean stopFlag parameter.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-11 02:46:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14129542#comment-14129542 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

It turned out that this issue is caused by the singleton CoarseCachedClock that is created and started automatically even if the user does not configure a clock. That should be fixed; the instance should only be created on demand.

Also, the documentation for these clocks needs to clarify that they are intended for niche applications and should not be used in web applications. If the docs say "Don't do this!", and the user does it anyway, then I think it is fine if this doesn't work as expected.

In general, Log4j should never stop its clock as long as the app is running and logging, or the log timestamp will not update anymore. So I don't think the Clock interface needs a stop() method. Let's avoid the complexities of managing a life cycle.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 13:01:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131494#comment-14131494 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

@Costa Theodosiou: The point of the method call is to "raise the flag" not to make it configurable. Would a different method name communicate this intent for you? Can you suggest an example?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 13:01:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131494#comment-14131494 ]

Gary Gregory edited comment on LOG4J2-819 at 9/12/14 1:01 PM:
--------------------------------------------------------------

@Costa Theodosiou: The point of the method call is to "raise the flag" not to make it configurable. Would a different method name communicate this intent for you? Can you suggest an alternative?

was (Author: garydgregory):
@Costa Theodosiou: The point of the method call is to "raise the flag" not to make it configurable. Would a different method name communicate this intent for you? Can you suggest an example?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 13:03:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131496#comment-14131496 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

Users can always shoot themselves in the foot ;) If we give them a gun in the form of a threaded clock, we should at the very least give programmatic access to unload the gun (stop the thread). My inclination is to commit the clock changes, but not hook up calls to stop the clock, then discuss it some more.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 13:13:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131504#comment-14131504 ]

Remko Popma edited comment on LOG4J2-819 at 9/12/14 1:12 PM:
-------------------------------------------------------------

[~garydgregory] I don't like having a stop() method in the first place, because the Log4j clock should never be stopped: if you stop it log timestamps will not increase any more from that point onwards. The thing is, if you have a stop() method you need a start() method. And that opens the box of Pandora...

There is no reason for the Clock interface to have a stop() method except for the implementation detail of the thread, and I'd like to look at other ways to address this issue first before committing to a stop() method in the Clock interface.

was (Author: ***@yahoo.com):
[~garydgregory] I don't like having a stop() method in the first place, because the Log4j clock should never be stopped: if you stop it log timestamps will not increase any more from that point onwards. The thing is, if you have a stop() method you need a start() method. And that opens the box of Pandora...

There is not reason for the Clock interface to have a stop() method except for the implementation detail of the thread, and I'd like to look at other ways to address this issue first before committing to a stop() method in the Clock interface.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 13:13:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131504#comment-14131504 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

[~garydgregory] I don't like having a stop() method in the first place, because the Log4j clock should never be stopped: if you stop it log timestamps will not increase any more from that point onwards. The thing is, if you have a stop() method you need a start() method. And that opens the box of Pandora...

There is not reason for the Clock interface to have a stop() method except for the implementation detail of the thread, and I'd like to look at other ways to address this issue first before committing to a stop() method in the Clock interface.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Costa Theodosiou (JIRA)

2014-09-12 13:17:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131508#comment-14131508 ]

Costa Theodosiou commented on LOG4J2-819:
-----------------------------------------

[~garydgregory] If the intent is to set the flag, then setStopFlag() should set the flag to true. It is currently set to false which is also the default value of boolean stopFlag.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 13:27:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131517#comment-14131517 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

[~costat] I'm having trouble reproducing the issue. You mentioned that you did not configure any clock and that the CoarseCachedClock singleton is created automatically by the classloader. That does not match what I am seeing. If I call {{ClockFactory.getClock().currentTimeMillis()}} without any system properties, there is no CoarseCachedClock singleton (and also no associated thread).

I can even do {{CoarseCachedClock.class.getName()}} and I get the same result: no CoarseCachedClock singleton and also no associated thread. I only see the clock updater thread being started after explicitly calling {{CoarseCachedClock.instance()}} or {{CachedClock.instance()}}.

So I wonder how the thread was created...

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 13:29:33 UTC

Permalink

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 13:37:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131517#comment-14131517 ]

Remko Popma edited comment on LOG4J2-819 at 9/12/14 1:36 PM:
-------------------------------------------------------------

[~costat] I'm having trouble reproducing the issue. You mentioned that you did not configure any clock and that the CoarseCachedClock singleton is created automatically by the classloader. That does not match what I am seeing. If I call {{ClockFactory.getClock().currentTimeMillis()}} without any system properties, no CachedClock or CoarseCachedClock singleton is created (and neither are their associated updater threads).

I can even do {{CoarseCachedClock.class.getName()}} and I get the same result: no CoarseCachedClock singleton and also no associated thread. I only see the clock updater thread being started after explicitly calling {{CoarseCachedClock.instance()}} or {{CachedClock.instance()}}.

So I wonder how the thread was created...

As far as I can see, the clock updater thread can only be started if:
# the application explicitly calls {{CoarseCachedClock.instance()}} or {{CachedClock.instance()}}.
# system property {{log4j.Clock}} has one of these four values:
#* "CachedClock"
#* "CoarseCachedClock"
#* "org.apache.logging.log4j.core.util.CachedClock"
#* "org.apache.logging.log4j.core.util.CoarseCachedClock"

was (Author: ***@yahoo.com):
[~costat] I'm having trouble reproducing the issue. You mentioned that you did not configure any clock and that the CoarseCachedClock singleton is created automatically by the classloader. That does not match what I am seeing. If I call {{ClockFactory.getClock().currentTimeMillis()}} without any system properties, no CachedClock or CoarseCachedClock singleton is created (and neither are their associated updater threads).

I can even do {{CoarseCachedClock.class.getName()}} and I get the same result: no CoarseCachedClock singleton and also no associated thread. I only see the clock updater thread being started after explicitly calling {{CoarseCachedClock.instance()}} or {{CachedClock.instance()}}.

So I wonder how the thread was created...

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 13:43:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131517#comment-14131517 ]

Remko Popma edited comment on LOG4J2-819 at 9/12/14 1:42 PM:
-------------------------------------------------------------

[~costat] I'm having trouble reproducing the issue. You mentioned that you did not configure any clock and that the CoarseCachedClock singleton is created automatically by the classloader. That does not match what I am seeing. If I call {{ClockFactory.getClock().currentTimeMillis()}} without any system properties, no CachedClock or CoarseCachedClock singleton is created (and neither are their associated updater threads).

I can even do {{CoarseCachedClock.class.getName()}} and I get the same result: no CoarseCachedClock singleton and also no associated thread. I only see the clock updater thread being started after explicitly calling {{CoarseCachedClock.instance()}} or {{CachedClock.instance()}}.

So I wonder how the thread was created...

As far as I can see, the clock updater thread can only be started if:
# the application explicitly calls {{CoarseCachedClock.instance()}} or {{CachedClock.instance()}}.
# system property {{log4j.Clock}} has one of these four values:
#* "CachedClock"
#* "CoarseCachedClock"
#* "org.apache.logging.log4j.core.util.CachedClock"
#* "org.apache.logging.log4j.core.util.CoarseCachedClock"

Can you double check that neither of the above is happening in your application?

was (Author: ***@yahoo.com):
[~costat] I'm having trouble reproducing the issue. You mentioned that you did not configure any clock and that the CoarseCachedClock singleton is created automatically by the classloader. That does not match what I am seeing. If I call {{ClockFactory.getClock().currentTimeMillis()}} without any system properties, no CachedClock or CoarseCachedClock singleton is created (and neither are their associated updater threads).

I can even do {{CoarseCachedClock.class.getName()}} and I get the same result: no CoarseCachedClock singleton and also no associated thread. I only see the clock updater thread being started after explicitly calling {{CoarseCachedClock.instance()}} or {{CachedClock.instance()}}.

So I wonder how the thread was created...

As far as I can see, the clock updater thread can only be started if:
# the application explicitly calls {{CoarseCachedClock.instance()}} or {{CachedClock.instance()}}.
# system property {{log4j.Clock}} has one of these four values:
#* "CachedClock"
#* "CoarseCachedClock"
#* "org.apache.logging.log4j.core.util.CachedClock"
#* "org.apache.logging.log4j.core.util.CoarseCachedClock"

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 13:55:34 UTC

Permalink

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 13:56:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131551#comment-14131551 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

[~costat]: Oops, good catch! Fix in the new patch attached.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 13:56:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Gary Gregory updated LOG4J2-819:
--------------------------------
Attachment: gg-log4j2-clocks-v2.patch

v2 of the patch (fixed stop flag set method).

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 13:59:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131553#comment-14131553 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 14:09:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131582#comment-14131582 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Thanks for the link! I'll take another look to see if I overlooked something...

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 14:32:35 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131604#comment-14131604 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

By the way, why do you need a boolean flag? Isn't it simpler to just call {{updaterThread.interrupt();}} from the clock's stop() method, and change the run() method to {{while (!interrupted()) \{...\}}}. The sleep time in this case is only one millisecond, but in general interrupt is better than a stop flag because it allows the thread to detect that it was stopped and return early from its call to sleep(). The biggest advantage in this case is that you don't need to build infrastructure to maintain the boolean anymore, so no need for the StopFlagThread any more. (The Thread.interrupt() method is not deprecated like the Thread.stop(), suspend() and resume() methods.)

That said, I still don't like having a public {{Clock.stop() method}}. This unloads the gun for web apps (so they can no longer shoot themselves in the foot even if they try), but also hands out the gun to everyone else so they can shoot themselves (by stopping the clock prematurely)... :-(

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 14:51:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131604#comment-14131604 ]

Remko Popma edited comment on LOG4J2-819 at 9/12/14 2:51 PM:
-------------------------------------------------------------

By the way, why use a boolean flag? Isn't it simpler to just call {{updaterThread.interrupt();}} from the clock's stop() method, and change the run() method to {{while (!interrupted()) \{...\}}}. In general the built-in interrupt() is better than a custom stop flag because it allows the thread to return early from its call to sleep() when interrupted. The biggest advantage in this case is that we don't need to build infrastructure to maintain the boolean anymore, so no need for the StopFlagThread any more. (The Thread.interrupt() method is not deprecated like the Thread.stop(), suspend() and resume() methods.)

That said, I still don't like having a public {{Clock.stop() method}}. This unloads the gun for web apps (so they can no longer shoot themselves in the foot even if they try), but also hands out the gun to everyone else so they can shoot themselves (by stopping the clock prematurely)... :-(

was (Author: ***@yahoo.com):
By the way, why do you need a boolean flag? Isn't it simpler to just call {{updaterThread.interrupt();}} from the clock's stop() method, and change the run() method to {{while (!interrupted()) \{...\}}}. The sleep time in this case is only one millisecond, but in general interrupt is better than a stop flag because it allows the thread to detect that it was stopped and return early from its call to sleep(). The biggest advantage in this case is that you don't need to build infrastructure to maintain the boolean anymore, so no need for the StopFlagThread any more. (The Thread.interrupt() method is not deprecated like the Thread.stop(), suspend() and resume() methods.)

That said, I still don't like having a public {{Clock.stop() method}}. This unloads the gun for web apps (so they can no longer shoot themselves in the foot even if they try), but also hands out the gun to everyone else so they can shoot themselves (by stopping the clock prematurely)... :-(

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 15:07:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131582#comment-14131582 ]

Remko Popma edited comment on LOG4J2-819 at 9/12/14 3:07 PM:
-------------------------------------------------------------

Thanks for the link! I'll take another look to see if I overlooked something...
----
UPDATE: I read the section on initialization twice, but I could not see any way for the singletons being created (and the threads started) other than a call to (Coarse)CachedClock.instance(). Log4j only calls that method when the log4j.Clock system property has one of the four values described above. So I still don't understand what causes this issue...

was (Author: ***@yahoo.com):
Thanks for the link! I'll take another look to see if I overlooked something...

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 15:58:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131685#comment-14131685 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

You can stop a thread cleanly using:
- a boolean flag
- thread interrupt() and isInterrupted()

I reread _Effective Java_, _Java Threads_, and _Java Concurrency in Practice_ in this area.

Note that the parkNanos API we use in the threaded clocks does not thrown {{InterruptedException}} which must mean that it handles interruption requests cleanly.

The argument against using a boolean flag is that the thread will only check the flag at the top or bottom of its run loop once it comes out of blocking calls.

I am going to try another patch a la interrupt(), it should be less code.

For the clocks, flag vs. interrupt is a detail the user should not care about (hopefully).

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 16:14:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Gary Gregory updated LOG4J2-819:
--------------------------------
Attachment: gg-log4j2-clocks-interrupts.patch

This patch uses Thread.interrupt() to request the clock threads to stop.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 16:14:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131703#comment-14131703 ]

Gary Gregory edited comment on LOG4J2-819 at 9/12/14 4:14 PM:
--------------------------------------------------------------

The patch {{gg-log4j2-clocks-interrupts.patch}} uses Thread.interrupt() to request the clock threads to stop.

was (Author: garydgregory):
This patch uses Thread.interrupt() to request the clock threads to stop.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 16:20:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131710#comment-14131710 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

[~***@yahoo.com]: We need something to stop the threads. The clocks own the threads, so we have to ask the clocks, hence the stop methods.

Alternatives:
- Have the threads check some global "is log4j shutting down" flag. Bleh.
- Use a thread pool (with no size limit) for use by all Log4j threads. Creating a thread should always go through the pool. Then we can shutdown the pool as a whole. This seems like a lot of work and hard to get right since thread shutdown matters I would imagine. Only enforceable by coding convention or with some extra Maven tooling. Yikes.

What else?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 16:27:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131716#comment-14131716 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

[~costat] Can you provide a small web application that reproduces the issue?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 17:21:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131771#comment-14131771 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

[~garydgregory] My thinking is/was that the thread should not be started in the first place. Then we don't need to stop them and there is no use case for a stop() method.

However I am assuming that this thread is only started in a web app by mistake. If I'm wrong about that, then we don't have much choice...

How about having a subinterface StoppableClock extending Clock with the stop() method, and the call site would do an instanceof. Would that be overkill? That would make it less easy to call ClockFactory.getClock().stop() by mistake. And we can document that this interface and its stop() method are for Log4j internal housekeeping purposes.

About the patch, I like that we have less API surface in the interrupt version. Would you oppose removing AbstractClock as well? (SystemClock can just implement the empty stop() method directly.) About the thread name, do you want the fully qualified class name, e.g. org.apache.logging.log4j.core.util.CoarseCachedClock, in the thread name, or class.getSimpleName?

About the call site, I initially thought about calling stop() from LoggerContext.stop(), but that would cause the clock to stop updating when Log4j is reconfigured. It is probably a good idea to only call Clock (StoppableClock?).stop() when the webapp is unloaded.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 17:24:35 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131774#comment-14131774 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

By the way, can we agree to only do this if we can reproduce the issue and prove that this patch solves the problem?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 17:33:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131790#comment-14131790 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

I consider the current implementation broken and bad design.

To quote Brian Goetz et all from _Java Concurrency in Practice_:
{quote}
End-of life cycle issues can complicate the design and implementation of tasks, services, and applications, and this important element of program design is too often ignored. Dealing with failure, shutdown, and cancellation is one of the characteristics that distinguishes a well-behaved application from one that merely works.
{quote}

Let's:
# Fix the clocks
# Continue researching when/if/how log4j should automatically stop its clock.

Adding StoppableClock make the design less OO IMO, I am against it.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 18:06:35 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131847#comment-14131847 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

I don't think it is a good idea or good design to put a public client method like {{currentTimeMillis()}} in the same interface as an internal housekeeping method like {{stop()}}. It suggests that client code would be perfectly free to call either method which is obviously not the case.

There must be a better way to do this.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 18:29:35 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131882#comment-14131882 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Perhaps we'll get better ideas on what the design for this should look like when we know how it will actually be used. We can't really consider these things separately.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Ralph Goers (JIRA)

2014-09-12 18:51:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131924#comment-14131924 ]

Ralph Goers commented on LOG4J2-819:
------------------------------------

I am having problems with all of this.

First, I would expect CoarseCachedClock to be an instance of CachedClock. It isn't. I would expect a CachedClock to have extra methods like stop() that SystemClock doesn't need.

If log4j-core is in the Tomcat lib directory then Log4jLogEvent will create and own the Clock instance. The Clock cannot be shutdown until Tomcat is shutdown. The latest patch seems to be stopping the clock when a web app is undeployed. That just won't work properly.

If log4j-core is in each web apps WEB-INF/lib directory then each app will have its own Clock instance (and corresponding Thread if it is a CacnedClock), which seems odd but I guess could work fine. In this case you need to stop the Clock threads when each web app is undeployed.

These two use cases are expected to be "normal" deployment models and must both work correctly. I just don't see how to reconcile between them.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-12 18:55:35 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131935#comment-14131935 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

An alternative would be to remove CachedClock and CoarseCachedClock altogether. That would solve this Jira, it would remove the background threads completely, and it would fix LOG4J2-753, all in one swoop.

We can put the code for CachedClock as an example implementation in the javadoc for the Clock interface, or keep it in the log4j-perf module, for the small fraction of users who really want to squeeze every microsecond of performance out of their system.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Costa Theodosiou (JIRA)

2014-09-12 18:57:34 UTC

Permalink

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Ralph Goers (JIRA)

2014-09-12 19:01:35 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131947#comment-14131947 ]

Ralph Goers commented on LOG4J2-819:
------------------------------------

Remko, I think what you are proposing makes the most sense. However, it still would be good to look at Costa's project.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Costa Theodosiou (JIRA)

2014-09-12 19:04:35 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14131939#comment-14131939 ]

Costa Theodosiou edited comment on LOG4J2-819 at 9/12/14 7:04 PM:
------------------------------------------------------------------

Attached is a demo project that can cause the PermGen OutOfMemoryError.

It is a regular Servlet 2.5 + Spring + Hibernate webapp.

To replicate the issue, reload the webapp several times. Monitor the permgen memory with Java VisualVM. Once the memory leak manifests itself, the Tomcat and the application become unresponsive and permgen error is logged in the server logs.

was (Author: costat):
Attached is a demo project that can cause the PermGen OutOfMemoryError.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Ralph Goers (JIRA)

2014-09-12 19:48:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14132006#comment-14132006 ]

Ralph Goers commented on LOG4J2-819:
------------------------------------

I deployed the app to Tomcat 7. When I do a jstack I don't see any threads related to the Clock. In fact, after changing the log4j2.xml to specify status="debug" I am seeing

{code}----------> Parent Classloader:^M
***@25fa1bb6^M
, ***@6b248979] started OK.
2014-09-12 12:44:38,593 DEBUG Using default SystemClock for timestamps
{code}

in catalina.out during startup which obviously indicates that the CachedClock thread is not being started.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-12 20:35:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14132060#comment-14132060 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

I am thinking that the threaded clocks are in advertently started because they are referenced from a static variable which gets initialized when the class is referenced. This is obviously not intentional. Can you try adding a console print statement in the clock constructors? That would let us know if the clocks are started.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Ralph Goers (JIRA)

2014-09-12 20:54:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Ralph Goers updated LOG4J2-819:
-------------------------------
Attachment: demorun.zip

Gary, I don't really need to modify anything to verify they aren't being started. I have attached catalina.out and the output from jstack. As you will see, there is no clock updater thread.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Costa Theodosiou (JIRA)

2014-09-13 05:31:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Costa Theodosiou updated LOG4J2-819:
------------------------------------
Attachment: demorun-tomcat6-with-reload.zip

I have attached demorun-tomcat6-with-reload.zip which includes catalina.out which demonstrates the bug. It seems that the thread starts when the user requests that the application is reloaded - *not* when it is first deployed.

{code}
public final class CoarseCachedClock implements Clock {
...
private final Thread updater = new Thread("Clock Updater Thread") {
@Override
public void run() {
System.out.println("*************** Clock Updater Thread STARTED ***************");
while (true) {
System.out.println("*************** Clock Updater Thread RUNNING ***************");
millis = System.currentTimeMillis();

// avoid explicit dependency on sun.misc.Util
LockSupport.parkNanos(1000 * 1000);
}
}
};

private CoarseCachedClock() {
System.out.println("*************** CoarseCachedClock CREATED ***************");
updater.setDaemon(true);
updater.start();
}
{code}

The app is first loaded on line 30 of catalina.out. It is reloaded on line 519. The thread starts soon after this.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-13 06:26:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14132571#comment-14132571 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Costa, thanks for helping with the investigation.
I think this is caused by Tomcat trying to prevent memory leaks. (Ironic isn't it?)
http://wiki.apache.org/tomcat/MemoryLeakProtection#staticClassVariables

{quote}
When an app is stopped, Tomcat (even before 6.0.24) nullifies the value of all static class variables of classes loaded by the WebAppClassLoader.
{quote}

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-13 08:10:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14132571#comment-14132571 ]

Remko Popma edited comment on LOG4J2-819 at 9/13/14 8:09 AM:
-------------------------------------------------------------

Costa, thanks for helping with the investigation.

I think this is caused by Tomcat trying to prevent memory leaks. (Ironic isn't it?)
http://wiki.apache.org/tomcat/MemoryLeakProtection#staticClassVariables

{quote}
When an app is stopped, Tomcat (even before 6.0.24) nullifies the value of all static class variables of classes loaded by the WebAppClassLoader.
{quote}

So Tomcat, bless its little white cotton socks, causes the very problem it is trying to prevent: referencing the static fields in CachedClock and CoarseCachedClock will initialize these classes, which starts the background threads. Once these threads are started, the web app cannot be unloaded anymore, and voila, we have a memory leak.

I'm sure we are not the first to have this problem because Tomcat provides a workaround. They suggest to configure a [JRE Memory Leak Prevention Listener|http://tomcat.apache.org/tomcat-6.0-doc/config/listeners.html#JRE_Memory_Leak_Prevention_Listener_-_org.apache.catalina.core.JreMemoryLeakPreventionListener]. This supports a {{classesToInitialize}} attribute where we can specify the classes that should be loaded by Tomcat's common class loader instead of the webapp's context class loader.

I tried this, but unfortunately this initialization takes place at Tomcat startup, and with the log4j-core jar inside the demo.war file and not in Tomcat's lib folder I got a JreMemoryLeakPreventionListener ClassNotFoundException "Failed to load class org.apache.logging.log4j.core.util.CachedClock during Tomcat start to prevent possible memory leaks". So the workaround does not work for us here.

Potential solutions:
* Modify ClockFactory so that the CachedClock and CoarseCachedClock classes are not loaded unless the user explicitly requests these clocks, using reflection in ClockFactory.
* Remove CachedClock and CoarseCachedClock from log4j-core altogether.
* A stop() mechanism will not help because there is nobody around to call it (the web app has already been stopped before these threads are started by Tomcat's cleanup)

Although I suggested it, I'm still a bit on the fence about removing these classes. Remember that [benchmarks|https://issues.apache.org/jira/browse/LOG4J2-744?focusedCommentId=14077425&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-14077425] showed that System.currentTimeMillis() can take 3+ microseconds on Linux, vs 14 nanoseconds on Windows: a 220x(!) difference...

Thoughts?

was (Author: ***@yahoo.com):
Costa, thanks for helping with the investigation.
I think this is caused by Tomcat trying to prevent memory leaks. (Ironic isn't it?)
http://wiki.apache.org/tomcat/MemoryLeakProtection#staticClassVariables

{quote}
When an app is stopped, Tomcat (even before 6.0.24) nullifies the value of all static class variables of classes loaded by the WebAppClassLoader.
{quote}

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-13 13:56:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14132736#comment-14132736 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

It seems to be we can solve this in several ways:
- by changing the singleton final static instance and turning it into non-final lazy-initialized static. It can be initialized in the instance() method, which then should be synchronized. That means that when Tomcat scans all the classes and statics, the static singleton slot will be null and nothing happens.
or:
- not having singletons for clocks and let the clock factory cache the clock it creates. Then you shutdown the factory when log4j shutsdown.
- other?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Ralph Goers (JIRA)

2014-09-13 15:38:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14132795#comment-14132795 ]

Ralph Goers commented on LOG4J2-819:
------------------------------------

I think the Clock instance needs to be stored in the LoggerContext and shutdown with it. I only see two places that it is used.
1. AsyncLogger - the constructor takes the LoggerContext as an argument so could easily initialize its Clock from that.
2. Log4jLogEvent - There is a default constructor that uses the static clock but nothing uses that constructor. The other constructors that don't take a timestamp could require the clock or LoggerContext be passed.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-13 20:43:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14132934#comment-14132934 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

It also now feels that {{ClockFactory}} class is misnamed, {{ClockManager}} seems more accurate, especially since the API is {{getClock()}} as opposed to {{createClock()}}. Thoughts on that?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Ralph Goers (JIRA)

2014-09-13 23:32:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133025#comment-14133025 ]

Ralph Goers commented on LOG4J2-819:
------------------------------------

I think you worry too much about names ;-) I don't think it matters much one way or the other, and is nowhere near as important as making it work correctly.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 00:21:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133036#comment-14133036 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Gary, I named the class ~Factory to convey the intention that it does not manage clock instances, and client code is responsible for storing the returned Clock object itself. I don't mind changing the factory method to {{createClock()}}.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 00:41:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133039#comment-14133039 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Ralph, since LOG4J2-628 the Log4JLogEvent Clock is actually used for all (non-async logger) event timestamps. Please see the [constructor|http://logging.apache.org/log4j/2.x/log4j-core/xref/org/apache/logging/log4j/core/impl/Log4jLogEvent.html#145] on line 145-155.

I don't oppose your solution, but there is something missing:
The Coarse/CachedClock classes are loaded because of the way ClockFactory is coded. This has an undesired side effect that Tomcat ends up creating the background threads for *both* CoarseCachedClock and CacheClock after the web app is stopped. This happens *even* if Log4J uses SystemClock to create timestamps.

So just managing a central Log4j clock instance in LoggerContext is not enough. I propose we modify ClockFactory such that the class loader no longer loads Coarse/CachedClock by accident. That would solve this Jira.

That leaves the possibility that the user _intentionally_ configures CachedClock in a web application (which would also cause a memory leak). Ralph's proposal to make Clock part of the LoggerContext life cycle would address that concern.

I don't oppose that, but that will be significant work. We don't have a user requesting this feature, so before we spend a lot of time on it I just want to point out an alternative:
What about simply documenting on the site that CachedClock should not be used by web applications? There is only one brief [mention here|http://logging.apache.org/log4j/2.x/manual/async.html#SysPropsAllAsync] that CachedClock exists. CoarseCachedClock is never mentioned on the site. So I doubt that this would inconvenience any users.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Ralph Goers (JIRA)

2014-09-14 00:50:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133041#comment-14133041 ]

Ralph Goers commented on LOG4J2-819:
------------------------------------

I admit I don't completely understand why Tomcat is finding those two classes, but my understanding is the problem is the static variables in those two classes that are automatically initialized when the class is referenced. I am suggesting that those statics be removed as they are not necessary. The clock instance should be stored in the LoggerContext only.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 00:57:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133042#comment-14133042 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Tomcat loads those two classes because ClockFactory compares the user specified string with Coarse/CachedClock.class.getName(). If we change that, these classes are never loaded and their static variables do not become a problem.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Ralph Goers (JIRA)

2014-09-14 01:11:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133045#comment-14133045 ]

Ralph Goers commented on LOG4J2-819:
------------------------------------

OK. But if we remove the static variables in those two classes does the problem also not go away?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-14 02:00:37 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133051#comment-14133051 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

It seems clear that no final statics = no problems. If the statics are non-final and lazy-initialized, no problem either.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 03:48:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133068#comment-14133068 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Yes, you are both correct.

Gary's suggestion to lazily initialize the static variables is also sufficient to resolve this Jira (unintentionally started threads causing mem leaks).

Removing the static variables and managing a single Clock instance centrally in LoggerContext may be the right thing to do because it would make it possible for web apps to use CachedClock. The trade-off is that it would be significantly more work. So is that worth it?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 03:50:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133068#comment-14133068 ]

Remko Popma edited comment on LOG4J2-819 at 9/14/14 3:49 AM:
-------------------------------------------------------------

Yes, you are both correct.

Gary's suggestion to lazily initialize the static variables is also sufficient to resolve this Jira (unintentionally started threads causing mem leaks).

Removing the static variables and managing a single Clock instance centrally in LoggerContext may be the right thing to do because (in addition to fixing this Jira) it would make it possible for web apps to use CachedClock. The trade-off is that it would be significantly more work. So is that worth it?

was (Author: ***@yahoo.com):
Yes, you are both correct.

Gary's suggestion to lazily initialize the static variables is also sufficient to resolve this Jira (unintentionally started threads causing mem leaks).

Removing the static variables and managing a single Clock instance centrally in LoggerContext may be the right thing to do because it would make it possible for web apps to use CachedClock. The trade-off is that it would be significantly more work. So is that worth it?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-14 04:20:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133074#comment-14133074 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

This might be a silly comment but why is there not a clock that saves when it is started with {{System.currentTimeMillis()}} and {{System.nanoTime()}}. When {{Clock.currentTimeMillis()}} is called, it calls {{System.nanoTime()}} again and adds the difference to the original {{System.nanoTime()}} to {{System.currentTimeMillis()}}?

Is calling {{System.nanoTime()}} as expensive as {{System.currentTimeMillis()}}?

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-14 04:46:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133078#comment-14133078 ]

Gary Gregory commented on LOG4J2-819:
-------------------------------------

To answer my own question it looks like {{nanoTime}} is _more_ expensive than {{currentTimeMillis}}:
{noformat}
# Run complete. Total time: 00:01:38

Benchmark Mode Samples Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 60088 13.435 0.952 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 83142 29.188 1.191 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 46747 13.653 1.166 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedClock sample 92588 16.373 1.043 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedFinalClock sample 93548 14.057 0.803 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 70663 29.297 2.336 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 78074 25.457 1.127 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemNanoTime sample 88921 35.775 1.519 ns/op
{noformat}

I added {{systemNanoTime}} locally and did not commit.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-14 04:48:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133078#comment-14133078 ]

Gary Gregory edited comment on LOG4J2-819 at 9/14/14 4:47 AM:
--------------------------------------------------------------

To answer my own question it looks like {{nanoTime}} is _more_ expensive than {{currentTimeMillis}}. Am I reading this right?
{noformat}
# Run complete. Total time: 00:01:38

Benchmark Mode Samples Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 60088 13.435 0.952 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 83142 29.188 1.191 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 46747 13.653 1.166 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedClock sample 92588 16.373 1.043 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedFinalClock sample 93548 14.057 0.803 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 70663 29.297 2.336 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 78074 25.457 1.127 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemNanoTime sample 88921 35.775 1.519 ns/op
{noformat}

I added {{systemNanoTime}} locally and did not commit.

was (Author: garydgregory):
To answer my own question it looks like {{nanoTime}} is _more_ expensive than {{currentTimeMillis}}:
{noformat}
# Run complete. Total time: 00:01:38

Benchmark Mode Samples Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 60088 13.435 0.952 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 83142 29.188 1.191 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 46747 13.653 1.166 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedClock sample 92588 16.373 1.043 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedFinalClock sample 93548 14.057 0.803 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 70663 29.297 2.336 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 78074 25.457 1.127 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemNanoTime sample 88921 35.775 1.519 ns/op
{noformat}

I added {{systemNanoTime}} locally and did not commit.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-09-14 04:50:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133078#comment-14133078 ]

Gary Gregory edited comment on LOG4J2-819 at 9/14/14 4:50 AM:
--------------------------------------------------------------

To answer my own question it looks like {{nanoTime}} is _more_ expensive than {{currentTimeMillis}}. Am I reading this right?
{noformat}
# Run complete. Total time: 00:01:38

Benchmark Mode Samples Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 60088 13.435 0.952 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 83142 29.188 1.191 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 46747 13.653 1.166 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedClock sample 92588 16.373 1.043 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedFinalClock sample 93548 14.057 0.803 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 70663 29.297 2.336 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 78074 25.457 1.127 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemNanoTime sample 88921 35.775 1.519 ns/op
{noformat}

I added {{systemNanoTime}} locally and did not commit.

FWIW: Updating the perf framework to the current version (1.1) does not compile.

was (Author: garydgregory):
To answer my own question it looks like {{nanoTime}} is _more_ expensive than {{currentTimeMillis}}. Am I reading this right?
{noformat}
# Run complete. Total time: 00:01:38

Benchmark Mode Samples Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 60088 13.435 0.952 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 83142 29.188 1.191 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 46747 13.653 1.166 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedClock sample 92588 16.373 1.043 ns/op
o.a.l.l.p.j.ClocksBenchmark.fixedFinalClock sample 93548 14.057 0.803 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 70663 29.297 2.336 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 78074 25.457 1.127 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemNanoTime sample 88921 35.775 1.519 ns/op
{noformat}

I added {{systemNanoTime}} locally and did not commit.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 06:07:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133101#comment-14133101 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Clock latency and granularity varies wildly across hardware and OS-es. I've seen System.nanotime() take 350ns on Solaris (haven't checked Linux). And System.currentTimeMillis() we saw take 3100ns on RedHat Linux. It's a jungle out there! :-)

[This article|https://blogs.oracle.com/dholmes/entry/inside_the_hotspot_vm_clocks] is a bit dated but gives an overview of the issues.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 06:15:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133101#comment-14133101 ]

Remko Popma edited comment on LOG4J2-819 at 9/14/14 6:14 AM:
-------------------------------------------------------------

It looks like clock latency and granularity varies wildly across hardware and OS-es. I've seen System.nanotime() take 350ns on Solaris (haven't checked Linux). And System.currentTimeMillis() we saw take 3100ns on RedHat Linux. It's a jungle out there! :-)

[This article|https://blogs.oracle.com/dholmes/entry/inside_the_hotspot_vm_clocks] is a bit dated but gives an overview of the issues.

was (Author: ***@yahoo.com):
Clock latency and granularity varies wildly across hardware and OS-es. I've seen System.nanotime() take 350ns on Solaris (haven't checked Linux). And System.currentTimeMillis() we saw take 3100ns on RedHat Linux. It's a jungle out there! :-)

[This article|https://blogs.oracle.com/dholmes/entry/inside_the_hotspot_vm_clocks] is a bit dated but gives an overview of the issues.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Matt Sicker (JIRA)

2014-09-14 07:01:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133114#comment-14133114 ]

Matt Sicker commented on LOG4J2-819:
------------------------------------

I made a change to lazily initialize the two threaded Clock implementations.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 12:56:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133196#comment-14133196 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

Thanks Matt!
I confirmed that I can no longer reproduce the issue anymore after your changes.

I propose that we mark this issue as resolved so we document that this change it is part of the 2.1 release, and create a new Jira with a follow-up task to manage a single Clock instance centrally in LoggerContext as a better way to manage clocks that would also make it possible for web apps to use CachedClock.

Before resolving this issue I will make some documentation changes on the site for now to warn users not to use CachedClock in web applications.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 14:08:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma resolved LOG4J2-819.
--------------------------------
Resolution: Fixed
Fix Version/s: 2.1

This is now fixed in master.
Please verify and close.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Fix For: 2.1
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-14 14:44:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14133241#comment-14133241 ]

Remko Popma commented on LOG4J2-819:
------------------------------------

I've created LOG4J2-826 as a follow-up task based on the discussion above. Please feel free to modify the title/description if I made a mistake or missed anything.

Post by Costa Theodosiou (JIRA)
PermGen OutOfMemoryError when reloading webapp on Tomcat 6
----------------------------------------------------------
Key: LOG4J2-819
URL: https://issues.apache.org/jira/browse/LOG4J2-819
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Tomcat 6
Reporter: Costa Theodosiou
Priority: Critical
Fix For: 2.1
Attachments: demo.zip, demorun-tomcat6-with-reload.zip, demorun.zip, gg-log4j2-clocks-interrupts.patch, gg-log4j2-clocks-v2.patch
When reloading an application 3 or 4 times in Tomcat 6, the application crashes with a "java.lang.OutOfMemoryError: PermGen space" exception.
After some investigation using the "When all else fails" section of https://wiki.apache.org/tomcat/OutOfMemory in conjunction with Java VisualVM, I have narrowed down the problem to the Thread created within org.apache.logging.log4j.core.util.CoarseCachedClock.
When a Thread is created, it contains a reference to the classloader that it was created with. In this case, the Thread's contextClassLoader field contains a reference to the WebappClassLoader. When Tomcat attempts to unload the webapp, the Thread still holds onto this reference which prevents WebappClassLoader from being freed.
Perhaps the Log4jServletContextListener (Log4jWebInitializerImpl) can be made to stop the CoarseCachedClock thread.
I believe this is not an obvious issue on Tomcat 7 due to https://wiki.apache.org/tomcat/MemoryLeakProtection.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)