We are updating from Java 7 to new JRE, initially to Java 8.
The same webapp (whether compiled for Java 7 or Java 8) is taking a long time to start under Java 8.
A very simple webapp, just containing a single servlet, is around 3x slower (from 0.5s to 1.5s).
A typical production webapp, with Spring etc, is taking over 15 minutes to start (from 15s previously!).
Taking thread dumps during startup always yields the same trace:
2021-03-15 14:52:40
Full thread dump OpenJDK 64-Bit Server VM (25.282-b08 mixed mode):
"Service Thread" #9 daemon prio=9 os_prio=0 tid=0x00007f180c26c000 nid=0x95 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread3" #8 daemon prio=9 os_prio=0 tid=0x00007f180c259000 nid=0x94 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007f180c256800 nid=0x93 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f180c255000 nid=0x92 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f180c252000 nid=0x91 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f180c24f000 nid=0x90 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f180c21b800 nid=0x8f in Object.wait() [0x00007f17f56ff000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000006c221e250> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
- locked <0x00000006c221e250> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f180c217000 nid=0x8e in Object.wait() [0x00007f17f580f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000006c2224188> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000006c2224188> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"main" #1 prio=5 os_prio=0 tid=0x00007f180c00b000 nid=0x82 runnable [0x00007f181541c000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.FileDispatcherImpl.close0(Native Method)
at sun.nio.ch.FileDispatcherImpl.close(FileDispatcherImpl.java:102)
at sun.nio.ch.FileChannelImpl.implCloseChannel(FileChannelImpl.java:141)
at java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:115)
- locked <0x000000076fa5ce30> (a java.lang.Object)
at java.nio.channels.Channels$1.close(Channels.java:178)
at java.nio.file.Files.copy(Files.java:3028)
at sun.net.www.protocol.jar.URLJarFile$1.run(URLJarFile.java:220)
at sun.net.www.protocol.jar.URLJarFile$1.run(URLJarFile.java:216)
at java.security.AccessController.doPrivileged(Native Method)
at sun.net.www.protocol.jar.URLJarFile.retrieve(URLJarFile.java:215)
at sun.net.www.protocol.jar.URLJarFile.getJarFile(URLJarFile.java:71)
at sun.net.www.protocol.jar.JarFileFactory.get(JarFileFactory.java:99)
at sun.net.www.protocol.jar.JarURLConnection.connect(JarURLConnection.java:122)
at sun.net.www.protocol.jar.JarURLConnection.getInputStream(JarURLConnection.java:152)
at sun.misc.URLClassPath$Loader.findResource(URLClassPath.java:725)
at sun.misc.URLClassPath.findResource(URLClassPath.java:225)
at java.net.URLClassLoader$2.run(URLClassLoader.java:572)
at java.net.URLClassLoader$2.run(URLClassLoader.java:570)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findResource(URLClassLoader.java:569)
at java.lang.ClassLoader.getResource(ClassLoader.java:1089)
at java.net.URLClassLoader.getResourceAsStream(URLClassLoader.java:233)
at org.springframework.core.io.ClassPathResource.getInputStream(ClassPathResource.java:166)
at org.springframework.core.type.classreading.SimpleMetadataReader.<init>(SimpleMetadataReader.java:50)
at org.springframework.core.type.classreading.SimpleMetadataReaderFactory.getMetadataReader(SimpleMetadataReaderFactory.java:98)
at org.springframework.core.type.classreading.CachingMetadataReaderFactory.getMetadataReader(CachingMetadataReaderFactory.java:102)
- locked <0x00000006ccd0fb20> (a org.springframework.core.type.classreading.CachingMetadataReaderFactory$1)
at org.springframework.core.type.classreading.SimpleMetadataReaderFactory.getMetadataReader(SimpleMetadataReaderFactory.java:93)
at org.springframework.context.annotation.ConfigurationClassParser.asSourceClass(ConfigurationClassParser.java:591)
at org.springframework.context.annotation.ConfigurationClassParser$SourceClass.getMemberClasses(ConfigurationClassParser.java:753)
at org.springframework.context.annotation.ConfigurationClassParser.processMemberClasses(ConfigurationClassParser.java:311)
at org.springframework.context.annotation.ConfigurationClassParser.doProcessConfigurationClass(ConfigurationClassParser.java:243)
at org.springframework.context.annotation.ConfigurationClassParser.processConfigurationClass(ConfigurationClassParser.java:226)
at org.springframework.context.annotation.ConfigurationClassParser.parse(ConfigurationClassParser.java:193)
at org.springframework.context.annotation.ConfigurationClassParser.parse(ConfigurationClassParser.java:163)
at org.springframework.context.annotation.ConfigurationClassPostProcessor.processConfigBeanDefinitions(ConfigurationClassPostProcessor.java:306)
at org.springframework.context.annotation.ConfigurationClassPostProcessor.postProcessBeanDefinitionRegistry(ConfigurationClassPostProcessor.java:239)
at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanDefinitionRegistryPostProcessors(PostProcessorRegistrationDelegate.java:254)
at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanFactoryPostProcessors(PostProcessorRegistrationDelegate.java:94)
at org.springframework.context.support.AbstractApplicationContext.invokeBeanFactoryPostProcessors(AbstractApplicationContext.java:606)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:462)
- locked <0x00000006c2384bd0> (a java.lang.Object)
at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:403)
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:106)
at io.undertow.servlet.core.ApplicationListeners.contextInitialized(ApplicationListeners.java:187)
at io.undertow.servlet.core.DeploymentManagerImpl.deploy(DeploymentManagerImpl.java:196)
at com.evolok.undertow.core.UndertowServerRunner.start(UndertowServerRunner.java:82)
at com.evolok.undertow.core.Server.start(Server.java:43)
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 ___evolok.UndertowBootstrap.main(UndertowBootstrap.java:40)
"VM Thread" os_prio=0 tid=0x00007f180c20d800 nid=0x8d runnable
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f180c021000 nid=0x83 runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f180c022800 nid=0x84 runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f180c024800 nid=0x85 runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f180c026000 nid=0x86 runnable
"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00007f180c028000 nid=0x87 runnable
"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00007f180c029800 nid=0x88 runnable
"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00007f180c02b800 nid=0x89 runnable
"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00007f180c02d000 nid=0x8a runnable
"GC task thread#8 (ParallelGC)" os_prio=0 tid=0x00007f180c02f000 nid=0x8b runnable
"GC task thread#9 (ParallelGC)" os_prio=0 tid=0x00007f180c030800 nid=0x8c runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007f180c26e800 nid=0x96 waiting on condition
JNI global references: 16
Heap
PSYoungGen total 512000K, used 75381K [0x000000076b600000, 0x0000000796680000, 0x00000007c0000000)
eden space 471552K, 15% used [0x000000076b600000,0x000000076ff9d590,0x0000000788280000)
from space 40448K, 0% used [0x0000000789780000,0x0000000789780000,0x000000078bf00000)
to space 116736K, 0% used [0x000000078f480000,0x000000078f480000,0x0000000796680000)
ParOldGen total 363008K, used 208784K [0x00000006c2200000, 0x00000006d8480000, 0x000000076b600000)
object space 363008K, 57% used [0x00000006c2200000,0x00000006cede4328,0x00000006d8480000)
Metaspace used 12974K, capacity 13240K, committed 13440K, reserved 1060864K
class space used 1560K, capacity 1608K, committed 1664K, reserved 1048576K
It appears that something is going on in java.nio.file.Files.copy, but am at a loss how to investigate it further.
Any help appreciated.
After a bit of digging I found the issue was in a subclass of URLConnection we are using for executable war support: JarJarURLConnection (from https://github.com/robo-code/robocode/blob/master/robocode.host/src/main/java/net/sf/robocode/host/jarjar/JarJarURLConnection.java)
It seems that under Java 8 some of the time URLConnection.setUseCaches is called with false and this causes the jar to be copied/extracted again and again (and again). I simply overrode this method with an empty body so that the default true is always used. Since the files are all local I see no reason to not use the cache always.