Running the petclinic sample spring app (https://github.com/spring-projects/spring-petclinic) with -Xscmx50M -Xshareclasses causes Exception in thread "main" java.lang.reflect.InvocationTargetException on second run.
Output:
2018-02-22 12:46:31.942 INFO 1 --- [ main] o.s.s.petclinic.PetClinicApplication : Starting PetClinicApplication v2.0.0 on 85de4731ae7f with PID 1 (/tmp/spring-petclinic-2.0.0.jar started by root in /)
2018-02-22 12:46:31.957 INFO 1 --- [ main] o.s.s.petclinic.PetClinicApplication : No active profile set, falling back to default profiles: default
2018-02-22 12:46:32.082 INFO 1 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@44fd0272: startup date [Thu Feb 22 12:46:32 UTC 2018]; root of context hierarchy
2018-02-22 12:46:35.192 INFO 1 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$1cb4efe6] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
Exception in thread "main" java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:50)
at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:51)
Caused by: java.lang.NoClassDefFoundError: ch.qos.logback.classic.spi.ThrowableProxy
at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:119)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:419)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.log(Logger.java:765)
at org.apache.logging.slf4j.SLF4JLogger.logMessage(SLF4JLogger.java:232)
at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2163)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2118)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2101)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1995)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1967)
at org.apache.commons.logging.LogFactory$Log4jLog.log(LogFactory.java:302)
at org.apache.commons.logging.LogFactory$Log4jLog.error(LogFactory.java:254)
at org.springframework.boot.SpringApplication.reportFailure(SpringApplication.java:833)
at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:807)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:338)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1246)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1234)
at org.springframework.samples.petclinic.PetClinicApplication.main(PetClinicApplication.java:32)
... 8 more
Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy
at java.net.URLClassLoader.findClass(URLClassLoader.java:588)
at java.lang.ClassLoader.loadClassHelper(ClassLoader.java:933)
at java.lang.ClassLoader.loadClass(ClassLoader.java:878)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:338)
at java.lang.ClassLoader.loadClass(ClassLoader.java:861)
... 26 more
@stevewallin Can you supply the java -version output from the build you used?
Java 8 docker file from adopt: https://hub.docker.com/r/adoptopenjdk/openjdk8-openj9/
openjdk version "1.8.0-internal"
OpenJDK Runtime Environment (build 1.8.0-internal-jenkins_2018_01_30_13_02-b00)
Eclipse OpenJ9 VM (build 2.9, JRE 1.8.0 Linux amd64-64 Compressed References 20180130_57 (JIT enabled, AOT enabled)
OpenJ9 - 8f03f71
OMR - f410d65
JCL - 687ce89 based on jdk8u152-b16)
@hangshao0 Can you take a look at this?
Looks like it is caused by the following JCL code in java.net.URLClassLoader.findClass() :
Class clazz = (Class)AccessController.doPrivileged(loader, acc);
if (clazz == null) {
throw new ClassNotFoundException(name);
clazz is null here.
I assume this is a preliminary comment, but to be clear, we need to figure out why using -Xshareclasses causes this behavior.
I've tried 10+ times, I can start up petclinic sample spring app successfully:
2018-02-23 20:06:33.554 INFO 591 --- [ restartedMain] o.s.s.petclinic.PetClinicApplication : Starting PetClinicApplication on 304746d8cd8a with PID 591 (/root/spring-petclinic/target/classes started by root in /root/spring-petclinic)
2018-02-23 20:06:33.560 INFO 591 --- [ restartedMain] o.s.s.petclinic.PetClinicApplication : The following profiles are active: production
2018-02-23 20:06:33.703 INFO 591 --- [ restartedMain] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@219e695c: startup date [Fri Feb 23 20:06:33 UTC 2018]; root of context hierarchy
2018-02-23 20:06:36.745 INFO 591 --- [ restartedMain] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$bfa711d4] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
...
...
2018-02-23 20:06:42.997 INFO 591 --- [ restartedMain] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
2018-02-23 20:06:42.999 INFO 591 --- [ restartedMain] o.s.j.e.a.AnnotationMBeanExporter : Bean with name 'dataSource' has been autodetected for JMX exposure
2018-02-23 20:06:43.008 INFO 591 --- [ restartedMain] o.s.j.e.a.AnnotationMBeanExporter : Located MBean 'dataSource': registering with JMX server as MBean [com.zaxxer.hikari:name=dataSource,type=HikariDataSource]
2018-02-23 20:06:43.065 INFO 591 --- [ restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2018-02-23 20:06:43.070 INFO 591 --- [ restartedMain] o.s.s.petclinic.PetClinicApplication : Started PetClinicApplication in 10.454 seconds (JVM running for 11.209)
I am using the following commands on https://github.com/spring-projects/spring-petclinic:
git clone https://github.com/spring-projects/spring-petclinic.git
cd spring-petclinic
./mvnw spring-boot:run
@stevewallin, Is the failure rate 100% on your side ? Does it fail if option "-Xscmx50M -Xshareclasses" is removed ?
It works fine without the cache and 100% failure rate (after first run)
I actually did a mvn install to get a jar file and run with jar
The issue here is related to nested jars.
spring-petclinic-2.0.0.jar is a runnable jar that has its dependent jars/classes under spring-petclinic-2.0.0.jar!/BOOT-INF/. URLClassLoader itself does not support nested jar, so it is not able to find the classes inside nested jars. Spring-boot has its own classloader called LaunchedURLClassLoader that extends URLClassLoader and overrides methods like findResource() and loadClass() so that it is able to load classes inside nested jars.
LaunchedURLClassLoader sets AppClassLoader as its parent so it will delegate to AppClassLoader first when loading classes. ApplClassLoader will search in its class path (/path/spring-petclinic-2.0.0.jar) and it is not able to find any classes from nested jars inside spring-petclinic-2.0.0.jar, then LauchedURLClassLoader will load the class.
When running with -Xshareclasses on a cold cache, I see
class load: org.springframework.boot.SpringApplication from: jar:file:/path/spring-petclinic-2.0.0.jar!/BOOT-INF/lib/spring-boot-2.0.0.BUILD-SNAPSHOT.jar!/
Stored class org/springframework/boot/SpringApplication in shared cache for class-loader id 3 with URL /path/spring-petclinic-2.0.0.jar (index 78).
LauchedURLClassLoader (loader id 3) loads the class org/springframework/boot/SpringApplication and stores it to the shared cache, with the trimmed URL /path/spring-petclinic-2.0.0.jar (See SharedClassAbstractHelper.recursiveJarTrim()),
Things changed when running again with the same cache, where appClassLoader loads classes it should not load:
Failed to find class org/springframework/boot/SpringApplication in shared cache for class-loader id 0.
Failed to find class org/springframework/boot/SpringApplication in shared cache for class-loader id 1.
Found class org/springframework/boot/SpringApplication in shared cache for class-loader id 2.
class load: org.springframework.boot.SpringApplication from: file:/path/spring-petclinic-2.0.0.jar
LauchedURLClassLoader delegates to appClassLoader (loader id 2) whose URL is /path/spring-petclinic-2.0.0.jar. The shared cache checks the URL, finding it is the same one as it is stored, the class is returned. The classes that were loaded by LauchedURLClassLoader is now loaded by appClassLoader...
So -Xshareclasses is not compatible with nested jars now.
@hangshao0 Ok, so it's not supported. At a minimum, we should probably do a better job reporting that to the user :) .
Is supporting nested jar files something we should also consider :) ?
I think Spring fat jars are going to be a prime target for shared cache so support would be good there... but I guess I'm just not expecting a runtime exception after enabling the cache ;)
We could investigate some way to detect a subclass of URLClassLoader which is incompatible with class sharing, and disable sharing for that subclass. It will be tricky to tell the difference between subclasses which are compatible and those which are not. The heiristic might end up disabling sharing for some subclass which is compatible.
I had suggested in person to Hang to update the Spring classloader to support sharing, and see if we can contribute that update to the project.
We patched java.net.URLClassLoader with some shared classes APIs so that it woks with -Xshareclasses. URLClassLoader itself does not support nested jars, I guess it is one of the reasons why we do not support nested jars.
We can consider supporting nested jars. There is no shared classes APIs that works with nested jars for the time being, but we can add them. Then the custom class loader (that deals with nested jars) needs to be patched with these shared classes APIs to work with -Xshareclasses.
About the error reporting, probably we could detect the nested jar and disable appClassLoader from finding class from shared cache and report the error.
This is a new feature request. @DanHeidinga , are you fine with moving forward to support nested jar ?
Steve is right - enabling the SCC shouldn't result in an exception being thrown.
There appears to be several ways to make / use nested jars:
It's the last case that SCC has issues with. At a minimum, we should write something up to help users that run into this issue know to unpack Spring's fat jar and run the unpacked version. The Spring doc [1] suggests running using the appropriate launcher such as:
$ unzip -q myapp.jar
$ java org.springframework.boot.loader.JarLauncher
[1] provides some great documentation on the structure of Spring's fat jars that can be used to detect them and may allow us to either enable/disable SCC support as needed.
It also lists a number of other projects that provide fat jar / one jar / uber jar support. A quick survey of them to find the common usage patterns, jar layout designs, ways to detect their use, etc would give us a good basis to design SCC fat jar support.
I'd suggest the following:
@hangshao0 Is this the kind of approach you were thinking?
[1] https://docs.spring.io/spring-boot/docs/current/reference/html/executable-jar.html
Is this the kind of approach you were thinking?
It was something that I was thinking last week.
But we might do even better, on my second thought. Instead of dealing with the nested jars in the java level, we might be able to move the code change inside to the VM. It might be possible to detect and handle nested jars in the shared classes C code so that we do not need to add shared classes Java level APIs and patch them to the custom class loader. I guess this is a more preferable solution. I will try hacking the code and see how it goes.
Most helpful comment
It was something that I was thinking last week.
But we might do even better, on my second thought. Instead of dealing with the nested jars in the java level, we might be able to move the code change inside to the VM. It might be possible to detect and handle nested jars in the shared classes C code so that we do not need to add shared classes Java level APIs and patch them to the custom class loader. I guess this is a more preferable solution. I will try hacking the code and see how it goes.