In my last post, I talked about a shortcoming of Log4j with a thread leak. I took a look at the Log4j 2 source code to see if it suffers from a similar issue.
The Log4j 2 implementation that checks for changes to the configuration file is handled by FileConfigurationMonitor.java. No threads are created to monitor changes, and from my testing, I saw no thread leaks re-deploying my application to Tomcat.
The new behavior calls FileConfigurationMonitor.java checkConfiguration method during each logging call. If the time since the last check has exceeded your monitorInterval passed into the logging configuration and the file has been modified on the disk, the configuration is reloaded.
The behavior works as expected, but I encountered and initial issue by setting my refresh interval to 1 second...the minimum amount of time one can check for changes to the configuration file is hard-coded at 5 seconds. "But Log4J, what if I have a requirement where I need to apply the change within 1 second????" Five seconds seems like enough time between checks, and I could probably write my own implementation to get rid of the hard-coded limitation and plug it in somehow. But, why choose 5 seconds as the minimum and give no way to change it?
From my brief experience with Log4j 2, I like the APIs, ease of configuration settings, and will look forward to the promise of performance increases (those are always welcome no matter how small in any software). And best of all, no thread leak!
Friday, September 27, 2013
Log4j And Web Application Thread Leaks
Let's breathe some life back into this blog!
I'll start off by talking about an issue and solution I recently came across.
The Apache Log4J framework provides a way to re-configure logging on-the-fly by editing the configuration file. The implementation spawns a thread (FileWatchdog.java) that monitors the configuration file for changes. FileWatchdog never checks Thread.isInterrupted() . Instead, it catches the interruption making the FileWatchdog thread live until the jvm is stopped.
The problem with this implementation (in version 1.2.16 I tested) is there is no easy way to stop the thread--some people have written that stopping it is impossible. In a web application environment where you may re-deploy offten, the end result is several threads that never stop along with memory leaks on any held resources in the running threads.
Tomcat 7 provides us a warning:
With a simple test case, I discovered an easy way to forcibly kill these threads:
The downside with this approach is you have call the deprecated Thread.stop() method. The upside is this method is still available in Java 7. Placing the call in a ServletContextListener allows the container to stop these threads during the undeploy process.
Tomcat now shows no warning the tread was left running:
Using jvisualvm or any other tool confirms the thread was stopped.
It seems like such a quick fix (e.g. || isInterrupted()) FileWatchdog could throw in there--I'm not sure why this hasn't been addressed. Given the design decisions of Log4J to really have one instance per jvm, the current implementation makes sense. However, it's common for individual web apps to configure their logging independent of any other web apps or global logging. In addition it's just good coding standards for frameworks to provide clean startup/shutdown apis. Maybe this is been addressed in the upcoming Log4j 2 .
I'll start off by talking about an issue and solution I recently came across.
The Apache Log4J framework provides a way to re-configure logging on-the-fly by editing the configuration file. The implementation spawns a thread (FileWatchdog.java) that monitors the configuration file for changes. FileWatchdog never checks Thread.isInterrupted() . Instead, it catches the interruption making the FileWatchdog thread live until the jvm is stopped.
The problem with this implementation (in version 1.2.16 I tested) is there is no easy way to stop the thread--some people have written that stopping it is impossible. In a web application environment where you may re-deploy offten, the end result is several threads that never stop along with memory leaks on any held resources in the running threads.
Tomcat 7 provides us a warning:
Sep 27, 2013 10:29:36 AM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/log4jtest] appears to have started a thread named [FileWatchdog] but has failed to stop it. This is very likely to create a memory leak.
With a simple test case, I discovered an easy way to forcibly kill these threads:
/**
* @see ServletContextListener#contextDestroyed(ServletContextEvent)
*/
@SuppressWarnings("deprecation")
public void contextDestroyed(ServletContextEvent sce) {
for (Thread t : Thread.getAllStackTraces().keySet()) {
if (t.getName().equals("FileWatchdog")) {
System.out.println("Found FileWatchdog thread. Killing it");
t.stop();
}
}
System.out.println("contextDestroyed");
}
The downside with this approach is you have call the deprecated Thread.stop() method. The upside is this method is still available in Java 7. Placing the call in a ServletContextListener allows the container to stop these threads during the undeploy process.
Tomcat now shows no warning the tread was left running:
INFO: Reloading Context with name [/log4jtest] has started Found FileWatchdog thread. Killing it contextDestroyed Sep 27, 2013 10:40:18 AM org.apache.catalina.core.StandardContext reload
Using jvisualvm or any other tool confirms the thread was stopped.
It seems like such a quick fix (e.g. || isInterrupted()) FileWatchdog could throw in there--I'm not sure why this hasn't been addressed. Given the design decisions of Log4J to really have one instance per jvm, the current implementation makes sense. However, it's common for individual web apps to configure their logging independent of any other web apps or global logging. In addition it's just good coding standards for frameworks to provide clean startup/shutdown apis. Maybe this is been addressed in the upcoming Log4j 2 .
Subscribe to:
Posts (Atom)