Executable JAR application startup is much slower after 3.2.0 about spring-boot

[philwebb]

Thanks for reporting this @deathy. Do you by any chance have a sample application that replicates the performance issues you're seeing?

[deathy]

Yes I'll try to create a proper sample in the next days. Might take some time, have to see with different numbers/sizes of files and need to see if it's the same with an in-memory database.

Meanwhile I have some numbers from debugging my app startup:

• 1823 files and 236 directories inside executable jar
• in org.springframework.boot.loader.zip.VirtualZipDataBlock#VirtualZipDataBlock constructor I have:
  • centralRecords.length = 1754
  • parts.size = 14033
    • ByteArrayDataBlock: 5263 items
    • VirtualZipDataBlock$DataPart: 8770 items
  • centralParts.size = 5262
  • sizeOfCentralDirectory = 176218

Grouping the 14033 parts by DataBlock::size, top 5:

• size 0: 3508 blocks
• size 46: 1804 blocks
• size 30: 1776 blocks
• size 16: 1756 blocks
• size 2: 215 blocks

Also ran async-profiler with event=alloc:

[deathy]

Observed during debugging:

JDK JarInputStream/ZipInputStream called from hibernate loader read sequentially.

Reading sequentially next 512 or how ever many bytes (saw some 3 byte reads for iterating entries) re-incur the whole traversal that was already done since for (DataBlock part : this.parts) inside org.springframework.boot.loader.zip.VirtualDataBlock#read is a linear lookup?

It can't skip ahead even though pos is passed in as param.
That matches with java/util/ImmutableCollections$ListItr.next appearing in profile.

[philwebb]

@deathy just to double check, are you using the latest 3.2.x release?

[deathy]

@philwebb yes I'm on 3.2.4 with original application.

I finally managed to make a sample: https://github.com/deathy/spring-startup-test
Has a bunch of randomly generated files and basic config to trigger visible difference (although much lower than original app since it's simpler). Measured startup times are in README there.
And through it discovered another condition of this happening: actually having the hibernate scanner active.

In automatic configuration since #15565 and #15321 the Hibernate Scanner is disabled by default.
But it is not disabled if you're actually using EntityManagerFactoryBuilder manually unless you pass in specific property.

In my original app I added .properties(Map.of("hibernate.archive.scanner","org.hibernate.boot.archive.scan.internal.DisabledScanner")) and that completely eliminated time from Hibernate Scanner.

There I also had two persistence contexts (separate DBs) so the scan was being performed twice.
I still see a significant difference compared to running unpacked but 2-3X not 4-5X and profiling so far hasn't shown any big obvious block like before, everything is more spread out.

The sequential iteration through parts in VirtualDataBlock#read still feels wrong but I have a workaround for scanner and not sure anything else uses it that heavily.

Hibernate Scanner questions:

• should JpaBaseConfiguration#entityManagerFactory and EntityManagerFactoryBuilder have the same default meaning disabling Hibernate Scanner?
  • if not, maybe potential footgun should be documented somewhere?