Todd Huss opened SPR-4694 and commented
Since upgrading from Spring 2.0.8 to Spring 2.5.3 our application that runs in signed jars (as required by webstart) starts VERY slowly. It runs fine in a signed jar with Spring 2.0.8 but since the upgrade now takes 5 or more minutes to start as opposed to 10-15 seconds under Spring 2.0.8.
What's interesting is that it's equally fast with Spring 2.5.3 as long as the jar is unsigned. However, as soon as you sign the jar and then run the application (via java -cp ourfile.jar mainclass) it takes forever to start. Downgrading back to Spring 2.0.8 also solves the issue. Getting stack dumps show that it seems like as of Spring 2.5.x (we tried 2.5.1-2.5.3) during startup on a signed jar is now spending a tremendous amount of time doing jar verification triggered from org.springframework.core.io.UrlResource. Here are a couple sample stack dumps of what the application is doing during the now very long startup period:
....
at java.util.jar.JarFile.getManifestFromReference(JarFile.java:159)
at java.util.jar.JarFile.getManifest(JarFile.java:146)
at sun.net.www.protocol.jar.URLJarFile.isSuperMan(URLJarFile.java:155)
- locked <0x8c031f88> (a sun.net.www.protocol.jar.URLJarFile)
at sun.net.www.protocol.jar.URLJarFile.getManifest(URLJarFile.java:121)
at java.util.jar.JarFile.maybeInstantiateVerifier(JarFile.java:287)
at java.util.jar.JarFile.getInputStream(JarFile.java:381)
- locked <0x8c031f88> (a sun.net.www.protocol.jar.URLJarFile)
at sun.net.www.protocol.jar.JarURLConnection.getInputStream(JarURLConnection.java:144)
at org.springframework.core.io.UrlResource.getInputStream(UrlResource.java:123)
at org.springframework.core.type.classreading.SimpleMetadataReaderFactory.getMetadataReader(SimpleMetadataReaderFactory.java:74)
or here
....
at java.util.jar.JarVerifier.processEntry(JarVerifier.java:250)
- locked <0x8d9c05a0> (a [B)
at java.util.jar.JarVerifier.update(JarVerifier.java:188)
at java.util.jar.JarFile.initializeVerifier(JarFile.java:321)
at java.util.jar.JarFile.getInputStream(JarFile.java:386)
- locked <0x8dc380e8> (a sun.net.www.protocol.jar.URLJarFile)
at sun.net.www.protocol.jar.JarURLConnection.getInputStream(JarURLConnection.java:144)
at org.springframework.core.io.UrlResource.getInputStream(UrlResource.java:123)
Affects: 2.5.1, 2.5.2, 2.5.3
Issue Links: - #16509 Spring-specific index file for component candidate classes
13 votes, 10 watchers
Comment From: spring-projects-issues
Juergen Hoeller commented
The first stacktrace looks like you're using component scanning... So I assume the configuration of your application is not identical when running against Spring 2.0.8 versus 2.5.3?
It sounds like the issue also shows when simply replacing the 2.0.8 jar with a 2.5.3 jar, but I guess only the second stacktrace applies in that scenario... Where does that UrlResource.getInputStream() call come from there?
Juergen
Comment From: spring-projects-issues
Todd Huss commented
Hi Juergen,
To answer your first question I don't believe we are using component scanning because the application configuration is identical between 2.0.8 and 2.5.3. I built the same code once using 2.0.8 and signed the jar and then I built it with 2.5.3 and signed the jar and once the jar is signed the startup time goes from 10-15 seconds to 5 or more minutes. With the jar unsigned startup time is the same between 2.0.8 and 2.5.3.
Sorry, I should have included a complete stack trace the first time. Here's a complete stack trace running Spring 2.5.3 where the application is taking minutes to start. To answer your second question our code is initializing Spring with the following code which is how UrlResource.getInputStream() ultimately gets called:
String[] paths = {"classpath:gs/data/applicationContext-data.xml", "classpath:gs/data/dao/hibernate/applicationContext-hibernate.xml", "classpath:gs/data/school/performance/applicationContext-performance.xml" }; ClassPathXmlApplicationContext ctx =new ClassPathXmlApplicationContext(paths);
Here's the stack trace:
at java.util.Arrays.copyOfRange(Arrays.java:3209)
at java.lang.String.<init>(String.java:216)
at java.lang.StringBuilder.toString(StringBuilder.java:430)
at sun.security.util.ManifestDigester.<init>(ManifestDigester.java:150)
at java.util.jar.JarVerifier.processEntry(JarVerifier.java:250)
- locked <0x8df507f8> (a [B)
at java.util.jar.JarVerifier.update(JarVerifier.java:188)
at java.util.jar.JarFile.initializeVerifier(JarFile.java:321)
at java.util.jar.JarFile.getInputStream(JarFile.java:386)
- locked <0x8e1c8008> (a sun.net.www.protocol.jar.URLJarFile)
at sun.net.www.protocol.jar.JarURLConnection.getInputStream(JarURLConnection.java:144)
at org.springframework.core.io.UrlResource.getInputStream(UrlResource.java:123)
at org.springframework.core.type.classreading.SimpleMetadataReaderFactory.getMetadataReader(SimpleMetadataReaderFactory.java:74)
at org.springframework.core.type.classreading.CachingMetadataReaderFactory.getMetadataReader(CachingMetadataReaderFactory.java:68)
- locked <0x8d4ff2a8> (a java.util.HashMap)
at org.springframework.context.annotation.ClassPathScanningCandidateComponentProvider.findCandidateComponents(ClassPathScanningCandidateComponentProvider.java:181)
at org.springframework.context.annotation.ClassPathBeanDefinitionScanner.doScan(ClassPathBeanDefinitionScanner.java:200)
at org.springframework.context.annotation.ComponentScanBeanDefinitionParser.parse(ComponentScanBeanDefinitionParser.java:84)
at org.springframework.beans.factory.xml.NamespaceHandlerSupport.parse(NamespaceHandlerSupport.java:69)
at org.springframework.beans.factory.xml.BeanDefinitionParserDelegate.parseCustomElement(BeanDefinitionParserDelegate.java:1253)
at org.springframework.beans.factory.xml.BeanDefinitionParserDelegate.parseCustomElement(BeanDefinitionParserDelegate.java:1243)
at org.springframework.beans.factory.xml.DefaultBeanDefinitionDocumentReader.parseBeanDefinitions(DefaultBeanDefinitionDocumentReader.java:135)
at org.springframework.beans.factory.xml.DefaultBeanDefinitionDocumentReader.registerBeanDefinitions(DefaultBeanDefinitionDocumentReader.java:92)
at org.springframework.beans.factory.xml.XmlBeanDefinitionReader.registerBeanDefinitions(XmlBeanDefinitionReader.java:507)
at org.springframework.beans.factory.xml.XmlBeanDefinitionReader.doLoadBeanDefinitions(XmlBeanDefinitionReader.java:398)
at org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions(XmlBeanDefinitionReader.java:342)
at org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions(XmlBeanDefinitionReader.java:310)
at org.springframework.beans.factory.support.AbstractBeanDefinitionReader.loadBeanDefinitions(AbstractBeanDefinitionReader.java:143)
at org.springframework.beans.factory.support.AbstractBeanDefinitionReader.loadBeanDefinitions(AbstractBeanDefinitionReader.java:178)
at org.springframework.beans.factory.support.AbstractBeanDefinitionReader.loadBeanDefinitions(AbstractBeanDefinitionReader.java:149)
at org.springframework.beans.factory.support.AbstractBeanDefinitionReader.loadBeanDefinitions(AbstractBeanDefinitionReader.java:212)
at org.springframework.context.support.AbstractXmlApplicationContext.loadBeanDefinitions(AbstractXmlApplicationContext.java:113)
at org.springframework.context.support.AbstractXmlApplicationContext.loadBeanDefinitions(AbstractXmlApplicationContext.java:80)
at org.springframework.context.support.AbstractRefreshableApplicationContext.refreshBeanFactory(AbstractRefreshableApplicationContext.java:123)
at org.springframework.context.support.AbstractApplicationContext.obtainFreshBeanFactory(AbstractApplicationContext.java:423)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:353)
- locked <0x8d455c30> (a java.lang.Object)
at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:139)
at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:93)
at gs.data.util.SpringUtil.<clinit>(SpringUtil.java:31)
Comment From: spring-projects-issues
Juergen Hoeller commented
Hmm, this is odd... Your stacktrace clearly indicates the use of a
Juergen
Comment From: spring-projects-issues
Todd Huss commented
Juergen, you were of course spot on, another developer had enabled component scanning and I wasn't aware of it. Disabling component scanning in a signed jar seems to resolve the issue. Here's the component scanning config we had:
Disabling component scanning fixes the issue so here's where we are now:
Spring 2.5.3 Unsigned jar with component scanning = fast startup Spring 2.5.3 Signed jar without component scanning = fast startup Spring 2.5.3 Signed jar with component scanning = very slow startup
Comment From: spring-projects-issues
Tom Jahncke commented
I am experiencing the same issue.
It seems that the scanning is about 4 times slower with signed jars.
If I crank down the logging to debug I see the "ClassPathBeanDefinitionScanner" being logged 241 times for our application. Running without the signed jars took 6 seconds and running with signed jars took 23 seconds.
I will greatly appreciate any fixes you can provided to increase the performance. FYI, we are using spring in a Swing application so this overhead is greatly impacting the launch time for our application and causing frustration with the user community.
Thanks!
- Tom
Comment From: spring-projects-issues
Tom Jahncke commented
Here is an idea on how to address this issue:
If there was the ability to generate a file based on the output of the component-scan functionality. Spring would need to have a hook to look for this file when doing component-scan. This file would ideally be built at build time of the jar. The build process could generate this file and include it in the classpath. Then the jars don't have to be scanned each time the application launches. This would increase the launch time of all spring application that utilize component-scan.
It this functionality already exist, I apologize for my ignorance :)
Thanks!
Tom
Comment From: spring-projects-issues
Juergen Hoeller commented
Closing groups of outdated issues. Please reopen if still relevant.
Comment From: spring-projects-issues
Theodor P commented
The problem still exists (I'm currently using Spring 4.3.0). Although closed for being outdated, I dare to reopen it as I want to ask whether this a Spring or Java performance problem.
The hint to remove component scanning has partially worked. Some Apache CXF web services generated using introspection at runtime still require a fair amount of time. This wouldn't be an easy applicable solution either when one has already dozens (perhaps hundreds?) of annotated components that have to be replaced with XML bean definitions
Comment From: spring-projects-issues
Juergen Hoeller commented
I'm afraid there's nothing we can do about this particular case since it simply is bound by the number of class files that we have to peek into here... and with every single class InputStream being super-expensive to obtain, this adds up.
We did implement an alternative along the lines of the above in 5.0 though, allowing for a build-time generated index that is transparently picked up by component-scan instructions in an application: please see #16509.
The corresponding reference docs: https://docs.spring.io/spring/docs/current/spring-framework-reference/core.html#beans-scanning-index
Comment From: in-fke
Why not open the Jar File while turning off the verification?
public JarFile(File file, boolean verify, int mode)
see related https://github.com/AdoptOpenJDK/IcedTea-Web/issues/889
Comment From: bclozel
@in-fke what would be the point of signed jars in the first place then? Shouldn't the user start the JVM with the noverify option in this case?
Comment From: in-fke
@in-fke what would be the point of signed jars in the first place then? Shouldn't the user start the JVM with the noverify option in this case?
If the Jar is opened for classloading, it should be verified, but if it's also opened for component scanning, it may not be necessary? Just wondering if there is potential for optimization if the Jar is opened on different occasions.
Comment From: bclozel
We've added a mode where this task is performed at build time (see Juergen's comment) and I don't think any other optimization can beat that. As for not performing verifications when scanning, this could have unintended security effects. Given the current state of things, I don't see a good reason for us to invest in this now.
Comment From: in-fke
Ok, thank you for following up on this so quickly. Your response makes sense to me.