Search code examples
tomcatout-of-memorylogbackpermgenredeploy

Gracefully stop Logback in container environment

Today I get PermGen OutOfMemory error.

Analysis shown that Nearest GC Root for WebappClassLoader is Logback thread:

this     - value: org.apache.catalina.loader.WebappClassLoader #4
  <- contextClassLoader (thread object)     - class: java.lang.Thread, value: org.apache.catalina.loader.WebappClassLoader #4

which is:

java.lang.Thread#11 - logback-1

Thread dump from heap dump for this thread:

"logback-1" daemon prio=5 tid=34 WAITING
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)
   Local Variable: java.util.concurrent.SynchronousQueue$TransferStack$SNode#1
   Local Variable: java.util.concurrent.SynchronousQueue$TransferStack#6
at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:925)
   Local Variable: java.util.concurrent.SynchronousQueue#6
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
   Local Variable: java.util.concurrent.ThreadPoolExecutor#34
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
   Local Variable: java.util.concurrent.ThreadPoolExecutor$Worker#11
at java.lang.Thread.run(Thread.java:745)

I use Tomcat 8 with hot redeploy feature reloadable="true" and externalized CLASSPATH via PreResources:

<Context docBase="/home/user/devel/app/src/main/webapp"
         reloadable="true">
    <Resources>
        <!-- To override application.properties and logback.xml -->
        <PreResources className="org.apache.catalina.webresources.DirResourceSet"
                       base="/home/user/devel/app/.config"
                       internalPath="/"
                       webAppMount="/WEB-INF/classes" />
    </Resources>
</Context>

and logback.xml with scan="true":

<configuration debug="false" scan="true" scanPeriod="5 seconds">
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    ...

After saving modification in /home/user/devel/app/.config/logback.xml Tomcat 8 receive notification (I am not sure what API used to monitor changes on fs) and application redeploying was started. That is what happen before PermGen OutOfMemory.

How can I Gracefully stop Logback in container environment?

How to stop "logback-1" thread?

I found a few related discussion but can't understand what to do with that info:

UPDATE I play with heap dump in visualvm. Under level of reference jump from bad logback-1 thread:

lvl1 = flatten(filter(referees(heap.findObject(0xf4c77610)), "!/WebappClassLoader/(classof(it).name)"))

lvl2 = flatten(map(lvl1, "referees(it)"))

lvl3 = flatten(map(lvl2, "referees(it)"))

it refer to

ch.qos.logback.core.util.ExecutorServiceUtil$1

By grepping in Logback sources for ExecutorServiceUtil I found changelog entry:

All threads opened by ch.qos.logback.core.util.ExecutorServiceUtil#THREAD_FACTORY are now daemons, which fixes an application hang on shutdown when LoggerContext#stop() is not called (LOGBACK-929). Note that daemon threads are abruptly terminated by the JVM, which may cause undesirable results, such as corrupted files written by the FileAppender. It is still highly recommended for the application to call LoggerContext#stop() (e.g., in a shutdown hook) to gracefully shutdown appenders.

Is that right that in container environment daemon threads are danger and lead to memory leaks?

Solution

  • I am not fully understand what should I do. Currently I remove jul-to-slf4j bridge from project pom.xml and this line:

    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator"/>

    from logback.xml. Even with this line application have no "logback-1" thread.

    As suggest official docs I register:

    public class ShutdownCleanupListener implements ServletContextListener {
    @Override
    public void contextInitialized(ServletContextEvent sce) { }

    @Override
    public void contextDestroyed(ServletContextEvent sce) {
        if (LoggerFactory.getILoggerFactory() instanceof LoggerContext) {
            ((LoggerContext) LoggerFactory.getILoggerFactory() ).stop();
        } 
    }
}

    in web.xml:

    <listener>
    <listener-class>com.app.servlet.ShutdownCleanupListener</listener-class>
</listener>

    To remove direct dependency on:

    import ch.qos.logback.classic.LoggerContext;

    reflection may be used.

    Not sure if I am doing right. I will see if get PermGen OutOfMemory error because of Logback.

    UPDATE After I have discovered reference dependency from ExecutorServiceUtil class I checked Logback sources and found that this class create threads with names like bad above:

     thread.setName("logback-" + threadNumber.getAndIncrement());

    This class only used in ch.qos.logback.core.ContextBase and thread leaned up inside:

    public void stop() {
  // We don't check "started" here, because the executor service uses
  // lazy initialization, rather than being created in the start method
  stopExecutorService();
  started = false;
}

    Note that LoggerContext is subclass of ContextBase so above solution really fix my problem.