Startup time slower in 1.5.x due to excessive calls to RandomAccessFile

[alexanderuv]

Bug Report
I have a project that is using Spring Boot 1.2.2. Now, I'm planning to migrate to 1.5.8.
I started by upgrading the packaging (maven plugin - repackage goal) first. Although there's no functional issue, I was surprised to see the startup time in the DEV server DOUBLED (at the very least). However, I can't reproduce this behavior locally - where the startup time actually went down by at least 20%.

In order to understand where the problem was, I tried using every possible version between those two to understand what was the version that introduced the problem. Unfortunately, for some reason versions 1.4.x to 1.5.1 didn't work. Looks like there was some bug that was fixed as I had some classpath issue.

However version 1.3.8 still worked and the startup time was fine. After some more profiling, I finally found something interesting. The number of calls to RandomAccessFile had grown a lot from 1.3.8 to 1.5.2.

• v1.3.8 -> ~291,000 calls
• v1.5.2 -> ~647,000 calls

This didn't seem like a problem when running locally, but when on the DEV server, it was. Now, the apps running on the DEV server are executed from a Network share, and every file operation has way more latency, so I figured the slowness might be due to the increase in file operations.

Would it be possible to cache some of these calls? or pre-read bigger chunks of the file? Even an extension point would be useful in this case.

[wilkinsona]

Thanks for sharing your findings.

The number of calls to RandomAccessFile should be a function of the number of classes that are loaded and resources that are accessed. Making that access faster via caching (if that’s even possible) would be addressing a symptom rather than the cause. I’d prefer to understand, and hopefully reduce, the apparent increase in class and resource loading. Can you please provide a small sample that illustrates the increase in calls to RandomAccessFile?

[alexanderuv]

@wilkinsona I tried to see if this happens with any other project (one that I can share) but it seems like the newer version in that case issues less than half the calls to RandomAccessFile.

It's important to mention my project has 200+ dependencies packaged within the same jar. I guess most projects don't have that many embedded jars... so it might have to do with that

I am adding some debug log statements to the loader to see if I can make sense out of it. Will share results...

Thanks for the promptness

[alexanderuv]

@wilkinsona I think I found the actual reason:

v1.3.8 loads all classes at startup and apparently those classes stay loaded. Seems to be due to usage of the system class loader, instead of a custom one. Please correct me if I'm wrong.

v1.5.2 however, has a custom mechanism to load jar files on-demand and although it does some caching, it's only at the metadata level - like files headers and positions, but not content. This means scan operations actually read the file every time.

Now check these two pics:

This is v1.3.8

It seems most of the jars, if not all are loaded during the main method.

Now, this is v.1.5.2

As you can see, all operations are triggered during initialization, when the Spring context is resolving beans. I checked again and my jar has actually 700+ nested jars, so having to go through each one of them and iterating each single class file might take some time. To be fair, I've only seen it going thru every single one of them when looking for message*.properties resources. For the rest of beans, it somehow only looks in jars where they are/could be found.

[wilkinsona]

v1.3.8 loads all classes at startup and apparently those classes stay loaded. Seems to be due to usage of the system class loader, instead of a custom one. Please correct me if I'm wrong.

AFAIK, the classes stay loaded in both 1.3.x and 1.5.x. Furthermore, while some changes were made to the ClassLoader in 1.4, Boot's custom class loader (LaunchedURLClassLoader) should be used in both versions being examined in this issue.

To be fair, I've only seen it going thru every single one of them when looking for message*.properties resources

There was a change made to message.properties detection, but it happened in 1.3.2. I don't, yet, understand the difference in behaviour between 1.3.8 and 1.5.2. Specifically, I'd expect ResourceBundleCondition to behave in the same way in both versions.

ResourceBundleCondition.getResources being called 114532 times doesn't make any sense to me yet. I'd would expect it to be called once per comma-separated entry in the spring.messages.basename property. The property defaults to messages so I'd expect a single call in a Boot app using the default configuration. That's certainly how various samples that I've just tried behave.

I still feel like I'm a long way away from understanding what's going on here and that a sample that reproduces the behaviour will be the best way to fix that. It doesn't have to be your exact application, just something that's sufficient to reproduce the kind of numbers that you've been sharing.

[spring-projects-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.