Perf4j not shutting down the perf4j-async-stats-appender-sink-CoalescingStatistics thread properly when servlet context is restarted

Um... Ping? Is Perf4j dead?

Yeah, I guess...I'm pretty disappointed, too.

Indeed AsyncCoalescingStatisticsAppender is leaking in a Servlet environment. After a bit of research, I found if I comment the code that registers the shutdown hook it will work accordingly, because the Log4j manager will close all appenders from ServletContextListener.contextDestroyed(). (Given you use org.springframework.web.util.Log4jConfigListener).

To cover all cases I think it is better to introduce registerShutdownHook parameter to this class. By default it will be true, and work as it is now. In case you want to use this appender in a Servlet context, you just disable shutdown hook registration and close Log4j accordingly on context destroy.

All tests passed.

With registerShutdownHook option I was able to get rid of memory leaks.

I will attach a patch (will it work? don't know how to use git gui)

added registerShutdownHook option

Then you could use for web application the following configuration (in log4j.xml):

<appender name="CoalescingStatistics" class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
<param name="TimeSlice" value="60000"/>
<param name="RegisterShutdownHook" value="false"/>
<appender-ref ref="fileAppender"/>
<appender-ref ref="graphExecutionTimes"/>
<appender-ref ref="graphExecutionTPS"/>
</appender>

Octavian is correct that the shutdown hook is a source of heap leak whenever Log4j might be initialized multiple times in the one JVM lifetime, such as would occur with a servlet context reloading. We are registering a shutdown hook thread, which references the custom appender and attached appenders, preventing them from being gc()ed until JVM shutdown is underway (too late). Each Log4j reconfigure will result in a further shutdown hook being registered, increasing the heap.

Rather than making shutdown hook registration conditional (agree this fixes the webapp case, with additional configuration to remember), could we just ensure we remove (Runtime.removeShutdownHook(Thread)) the hook during close() of the Appender (lifecycle defined in AppenderSkeleton actually). The shutdown hook is superfluous after this time since it exists only to call close() if not already called. I realize that in a properly-managed servlet application the shutdown hook is going to be irrelevant, but provided it is removed it is harmless. The unregister hook approach means that webapp users don't need to remember additional configuration, and also that non-webapp users that initialize log4j repeatedly won't suffer the same heap growth.

Pull request: https://github.com/perf4j/perf4j/pull/11 .

The description and some of the observations in the original logging of this issue may be a separate/unrelated consideration. My recollection of Tomcat (and this is going way back to 4.x, 5.x days so may have changed) is that it has a hard-coded, non-configurable/non-ignorable timer it sets when tearing down a context, and context listener destroy methods and any self-managed thread cleanup must occur within that time, otherwise undefined behaviours occur. After the timeout, Tomcat invalidates the context's classloader, allowing it and things under it to be gc()ed (unless we hold a reference e.g. in a shutdown hook per above). My recollection is that this timeout was 10 seconds, which perhaps by coincidence this is the same (also hard-coded) wait time for shutdown of the queue draining thread GenericAsyncCoalescingStatisticsAppender stopDrainingThread(). So for a full/large queue perhaps the queue drain timeout will occur but only after Tomcat has started removing the context. The stack trace above is indicative of this sort of problem.

So for that part, we should raise a new issue to make the timeout configurable, see if that improves things.

I added once commit to the pull request, to make perf4j shutdown timeout configurable (in terms of time waited for draining queue thread to exit), and to interrupt that thread after the join completes/times-out.

fixed in https://github.com/perf4j/perf4j/pull/11