I am running into an apparent ClassLoader leak with the following configuration:
I have a simple application:
ApplicationConfig:
@ApplicationPath("/service")
public class ApplicationConfig extends Application {
public ApplicationConfig() {
}
@Override
public Set<Class<?>> getClasses(){
Set<Class<?>> resources = new java.util.HashSet<>();
resources.add(org.mdeggers.cplanapi.resource.CostInfoResource.class);
resources.add(org.mdeggers.cplanapi.resource.InstituteInfoResource.class);
resources.add(org.mdeggers.cplanapi.resource.InstituteTypeInfoResource.class);
resources.add(org.mdeggers.cplanapi.mapper.NotFoundExceptionMapper.class);
return resources;
}
}
One of three resources:
@Path("/v1/inst")
public class InstituteInfoResource {
public InstituteInfoResource() {
}
@GET
@Path("info")
@Produces({MediaType.APPLICATION_JSON})
public InstituteContainer getNationalList() {
InstituteInfo instituteinfo = new InstituteInfo();
return instituteinfo.getNational();
}
@GET
@Path("info/{ state : [A-Z]{2} }")
@Produces({MediaType.APPLICATION_JSON})
public InstituteContainer getStateList(@PathParam("state") String state) {
InstituteInfo instituteinfo = new InstituteInfo();
return instituteinfo.getState(state);
}
}
The InstituteInfo class is a DAO that makes requests into a MySQL database and returns a container with the information.
This all works, but on undeploying the Tomcat Manager complains that there is a leak after unloading the web application.
Doing a heap dump and looking at it with the following OQL in Eclipse MAT shows that the application still resides in memory, with started=false.
SELECT wcl.contextName.toString() AS contextName,
wcl.started AS started,
wcl.@retainedHeapSize AS retainedSize
FROM org.apache.catalina.loader.WebappClassLoader wcl
| contextName | started | retainedSize |
|---|---|---|
| /cplanapi | false | 586,720 |
| /docs | true | 46,664 |
| /host-manager | true | 47,288 |
| /manager | true | 47,392 |
| /examples | true | 85,432 |
| ROOT | true | 46,912 |
GC roots for cplanapi are:
class com.sun.naming.internal.ResourceManager
'- propertiesCache java.util.WeakHashMap
'- table java.util.WeakHashMap$Entry[16]
'- [13] java.util.WeakHashMap$Entry
'- referent org.apache.catalina.loader.WebappClassLoader
This occurs on both Windows and Linux, and with the above JRE as well as Java 1.8.0_202.
Any thoughts on how to resolve this would be greatly appreciated.
Startup log (JRE 11)
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server version name: Apache Tomcat/7.0.107
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server built: Nov 18 2020 12:18:55 UTC
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server version number: 7.0.107.0
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: OS Name: Windows 10
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: OS Version: 10.0
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Architecture: amd64
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Java Home: D:\Programs-x64\Java\jdk-11.0.10+9-jre
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: JVM Version: 11.0.10+9
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: JVM Vendor: AdoptOpenJDK
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: CATALINA_BASE: D:\Programs\Apache\apache-tomcat-7.0.107
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: CATALINA_HOME: D:\Programs\Apache\apache-tomcat-7.0.107
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.util.logging.config.file=D:\Programs\Apache\apache-tomcat-7.0.107\conf\logging.properties
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcom.sun.management.jmxremote
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcom.sun.management.jmxremote.port=9005
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcom.sun.management.jmxremote.ssl=false
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcom.sun.management.jmxremote.authenticate=false
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -DRDS_HOSTNAME=localhost
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dignore.endorsed.dirs=
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcatalina.base=D:\Programs\Apache\apache-tomcat-7.0.107
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcatalina.home=D:\Programs\Apache\apache-tomcat-7.0.107
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.io.tmpdir=D:\Programs\Apache\apache-tomcat-7.0.107\temp
Jan 31, 2021 10:09:19 AM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFO: Loaded Apache Tomcat Native library [1.2.25] using APR version [1.7.0].
Jan 31, 2021 10:09:19 AM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFO: APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
Jan 31, 2021 10:09:19 AM org.apache.catalina.core.AprLifecycleListener initializeSSL
INFO: OpenSSL successfully initialized [OpenSSL 1.1.1g 21 Apr 2020]
Jan 31, 2021 10:09:19 AM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-apr-8080"]
Jan 31, 2021 10:09:19 AM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-apr-127.0.0.1-8009"]
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 644 ms
Jan 31, 2021 10:09:19 AM org.apache.catalina.core.StandardService startInternal
INFO: Starting service [Catalina]
Jan 31, 2021 10:09:19 AM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.107
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\docs]
Jan 31, 2021 10:09:19 AM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Jan 31, 2021 10:09:20 AM org.apache.catalina.util.SessionIdGeneratorBase createSecureRandom
WARNING: Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [457] milliseconds.
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deployment of web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\docs] has finished in [905] ms
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\examples]
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deployment of web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\examples] has finished in [344] ms
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\host-manager]
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deployment of web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\host-manager] has finished in [146] ms
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\manager]
Jan 31, 2021 10:09:20 AM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Jan 31, 2021 10:09:21 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deployment of web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\manager] has finished in [148] ms
Jan 31, 2021 10:09:21 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\ROOT]
Jan 31, 2021 10:09:21 AM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Jan 31, 2021 10:09:21 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deployment of web application directory [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\ROOT] has finished in [136] ms
Jan 31, 2021 10:09:21 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-apr-8080"]
Jan 31, 2021 10:09:21 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-apr-127.0.0.1-8009"]
Jan 31, 2021 10:09:21 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 1766 ms
Deploy
Jan 31, 2021 10:09:49 AM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\cplanapi.war]
Jan 31, 2021 10:09:50 AM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Jan 31, 2021 10:09:53 AM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deployment of web application archive [D:\Programs\Apache\apache-tomcat-7.0.107\webapps\cplanapi.war] has finished in [3,558] ms
Undeploy
Jan 31, 2021 10:10:27 AM org.apache.catalina.startup.HostConfig undeploy
INFO: Undeploying context [/cplanapi]
Shutdown
Jan 31, 2021 10:10:37 AM org.apache.catalina.core.StandardServer await
INFO: A valid shutdown command was received via the shutdown port. Stopping the Server instance.
Jan 31, 2021 10:10:37 AM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-apr-8080"]
Jan 31, 2021 10:10:37 AM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["ajp-apr-127.0.0.1-8009"]
Jan 31, 2021 10:10:37 AM org.apache.catalina.core.StandardService stopInternal
INFO: Stopping service [Catalina]
Jan 31, 2021 10:10:37 AM org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["http-apr-8080"]
Jan 31, 2021 10:10:37 AM org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["ajp-apr-127.0.0.1-8009"]
Jan 31, 2021 10:10:37 AM org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["http-apr-8080"]
Jan 31, 2021 10:10:37 AM org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["ajp-apr-127.0.0.1-8009"]
Nothing seems to be dangling in the web application.
After some comments from Mark Thomas on the Tomcat mailing list, I managed to track down the problems (there are two). The trick was to exclude soft references in the GC ROOT analysis to reveal the actual culprits.
The fix for that is given in the bug report. Basically, you have to set a system property, and add a servlet context listener to clear the buffer before shutting down the web application.
This is marked as closed / fixed, but it appears not to be. Turning off JMX for log4j (for now) by using another system property fixes this issue.