Investigate startup performance between main and jar

[snicoll]

See spring-projects/spring-framework#19523

[snicoll]

I've done some basic tests using these sample apps and none of the numbers checks out. For instance, config service starts under 4s for me and the reporter claims 16s.

We need the exact apps and more details about how to reproduce this.

[dsyer]

FWIW I see virtually no difference between Spring Boot 1.3.8 and 1.4.2 with a plain vanilla Spring Boot + Actuator app (starts up in about 2s). Launching from a fat jar is marginally faster, but it's only about 30% for the benchmarks I ran so far. I'll publish some more when I have a complete picture. This is with local filesystem on a SSD.

One observation that might be relevant: setting -Djava.security.egd=file:/dev/./urandom has a huge effect on 1.3.8 in terms of variability (but not really 1.4.2, so maybe something changed in Tomcat) - the fastest runs are just as fast, but the slow ones are really bad (up to 20 times worse). If you are running benchmarks entropy is going to be under pressure so that's expected, and I switched to running with that flag set after I noticed that. Maybe the OP environment was also entropy poor (but that doesn't explain the difference between 1.3.8 and 1.4.2)?

[snicoll]

maybe something changed in Tomcat

@wilkinsona requested a change in Tomcat to improve this by default, yes.

[wilkinsona]

They rejected my request. Apparently huge variance in startup time is the desired default behaviour. To overcome this, we use a custom session manager that only initializes the SecureRandom the first time someone requests a session. This brings Tomcat's behaviour into line with Jetty and Undertow and means that only those who are using HTTP sessions pay the price for using them.

[dsyer]

Roger that. It explains the difference that I saw between 1.4.2 and 1.3.8 anyway (but not the OP issue).

[berndgoetz]

Startup times of 2 to 4 seconds sound awesome. Is it my hardware? Should not make that huge of a difference, I have a Mac Book Pro 2013... I'll rerun my tests and give you more details about my setup. Will have to wait until the weekend, though.

[snicoll]

@berndgoetz this is what we need:

We need the exact apps and more details about how to reproduce this.

Thanks!

[berndgoetz]

Here's the example: https://github.com/berndgoetz/spring-boot-startup. I've included some details how I ran the application and some measurements in the README file.

[dsyer]

Your app is a bit like the Petclinic (Hibernate and Spring Data JPA), so I'd expect it to have similar characteristics.

It starts for me in 5s (jar file) or under 4s (main method) on my Dell desktop, and on my old laptop (2011 vintage) it's 10s and 9s (surprisingly not much faster for the main method there). I know that @aclement has also found that his Mac runs things much faster from the exploded jar with the main method, but nothing ever ran as slow as yours did from the jar. Do you have something else in your environment (encypted disk, AV software or something)?

Can you try these benchmarks on your box: https://github.com/dsyer/spring-boot-startup-bench?

[berndgoetz]

@snicoll the config server starts up on my Mac (2013) in about 4 seconds, yes. But when I start the same application as a jar, it bumps up to 15/16 seconds. I've created a new repository for it, just to be sure we're talking about the same thing: https://github.com/berndgoetz/config-service.

I still get the same numbers, main class: 4 seconds, jar: 15 seconds. I continue collecting numbers, separately from this comment.

@dsyer adding the security property to the startup as

java -Djava.security.egd=file:/dev/./urandom -jar target/config-service-0.0.1-SNAPSHOT.jar

added 2-3 seconds startup time (again, on my MacBook Pro from 2013) for me.

[berndgoetz]

I have collected a few more startup numbers today for the config service at https://github.com/berndgoetz/config-service.

Machine	Main run	Main debug	Jar	spring-boot:run
MacBook Pro 2013 i7 2.6GHz	4.5	5.4	15	3.5
Lenovo laptop i5 6300U 2.4GHz	7.8	8.5	12	8
Lenovo desktop i7 4770 3.4GHz	4	4.4	6.2	4
VM Xeon E5 2680 v3 2.5GHz	6.5	10	7.7	5

Now to the reservation service at https://github.com/berndgoetz/spring-boot-startup. It connects to the local config service above on port 8888:

Machine	Main run	Main debug	Jar	spring-boot:run
MacBook Pro 2013 i7 2.6GHz	7.5	10.7	40	7
Lenovo laptop i5 6300U 2.4GHz	15.4	20	20	12.7
Lenovo desktop i7 4770 3.4GHz	6.7	7.5	12	6.6
VM Xeon E5 2680 v3 2.5GHz	8	9	14	8.5

Comments/Findings:

• Please take the numbers with a grain of salt, the numbers are not exact and are hard to reproduce as such - I've rerun the applications a couple of times, and I then took an average. The differences between the startup types kept stable, though
• My MacBook Pro from 2013
• The faster the CPU, and the more cores, the smaller the difference, it seems. We have a compute intensive phase of the application life cycle, obviously
• Interesting to see for me is that spring-boot:run is as fast or sometimes faster than starting via the main method

Except if you want to look into the MacBook differences more closely, I think you can't do a lot about the whole thing here. Feel free to close this issue. I will most probably have some new follow-up investigations concerning even bigger differences in startup times when it comes to run a Spring Boot application in a Websphere Liberty container.

[dsyer]

Thanks for the update. Seems like your MacBook sucks. You could take the inexactness out of the tests by running the benchmarks as I suggested above already. How about doing that?

[berndgoetz]

I missed that one. Yes, I will do that, keep you posted.

[berndgoetz]

Ok, got it now - my MacBook Pro didn't suck, I just had a virus scanner running on it. After removing the virus scanner, I reran my reservation service as a jar file again, and it now starts up even slightly faster than the main method start, in below 7 seconds compared to the 40 seconds before. Crazy stuff. I can imagine that virus scanners have a lot of work to do when a process unfolds/unpacks/looks into a file with many files in it. This is a huge efficiency killer, I have to say. So for anybody coming here for slow Spring Boot startup times: It's your virus scanner, stupid! ;-)

Here are the numbers, before and after:

Host: snoopie, i7, 2.6GHz, 16 GB 1600 MHz DDR3, 500 GB SSD

Benchmark                                   Mode  Cnt   Score   Error  Units
ConfigServerBenchmark.devtoolsRestart       avgt   10   0.994 ± 0.105   s/op
ConfigServerBenchmark.explodedJarMain       avgt   10   3.768 ± 0.091   s/op
ConfigServerBenchmark.fatJar138             avgt   10   6.773 ± 0.485   s/op
ConfigServerBenchmark.fatJar142             avgt   10  18.972 ± 0.264   s/op
MinimalBenchmark.explodedJarMain            avgt   10   1.984 ± 0.098   s/op
MinimalBenchmark.fatJar                     avgt   10  11.982 ± 0.471   s/op
PetclinicBenchmark.devtoolsRestart          avgt   10   1.605 ± 0.193   s/op
PetclinicBenchmark.explodedJarMain          avgt   10   5.791 ± 0.460   s/op
PetclinicBenchmark.fatJar                   avgt   10  36.068 ± 0.585   s/op
PetclinicBenchmark.noverify                 avgt   10  31.803 ± 0.639   s/op
ShadedBenchmark.explodedShadedMain          avgt   10  29.622 ± 0.585   s/op
ShadedBenchmark.shaded                      avgt   10   8.082 ± 0.182   s/op
SpringBoot138Benchmark.explodedJarLauncher  avgt   10   5.506 ± 0.072   s/op
SpringBoot138Benchmark.explodedJarMain      avgt   10   2.464 ± 0.065   s/op
SpringBoot138Benchmark.fatJar               avgt   10   5.318 ± 0.073   s/op
SpringBoot142Benchmark.explodedJarLauncher  avgt   10  16.373 ± 0.447   s/op
SpringBoot142Benchmark.explodedJarMain      avgt   10   2.888 ± 0.271   s/op
SpringBoot142Benchmark.fatJar               avgt   10  16.247 ± 0.464   s/op
SpringBootThinBenchmark.basic138Thin        avgt   10   3.394 ± 0.146   s/op
SpringBootThinBenchmark.basic142Thin        avgt   10   3.543 ± 0.045   s/op

After deactivating virus scanner:

Benchmark                                   Mode  Cnt  Score   Error  Units
ConfigServerBenchmark.devtoolsRestart       avgt   10  0.981 ± 0.092   s/op
ConfigServerBenchmark.explodedJarMain       avgt   10  3.618 ± 0.179   s/op
ConfigServerBenchmark.fatJar138             avgt   10  3.664 ± 0.049   s/op
ConfigServerBenchmark.fatJar142             avgt   10  3.786 ± 0.066   s/op
MinimalBenchmark.explodedJarMain            avgt   10  1.871 ± 0.030   s/op
MinimalBenchmark.fatJar                     avgt   10  2.341 ± 0.189   s/op
PetclinicBenchmark.devtoolsRestart          avgt   10  1.374 ± 0.192   s/op
PetclinicBenchmark.explodedJarMain          avgt   10  5.291 ± 0.157   s/op
PetclinicBenchmark.fatJar                   avgt   10  6.993 ± 0.211   s/op
PetclinicBenchmark.noverify                 avgt   10  6.293 ± 0.142   s/op
ShadedBenchmark.explodedShadedMain          avgt   10  6.780 ± 0.245   s/op
ShadedBenchmark.shaded                      avgt   10  8.834 ± 2.291   s/op
SpringBoot138Benchmark.explodedJarLauncher  avgt   10  3.306 ± 0.073   s/op
SpringBoot138Benchmark.explodedJarMain      avgt   10  2.472 ± 0.067   s/op
SpringBoot138Benchmark.fatJar               avgt   10  2.900 ± 0.065   s/op
SpringBoot142Benchmark.explodedJarLauncher  avgt   10  3.293 ± 0.053   s/op
SpringBoot142Benchmark.explodedJarMain      avgt   10  2.645 ± 0.040   s/op
SpringBoot142Benchmark.fatJar               avgt   10  3.159 ± 0.044   s/op
SpringBootThinBenchmark.basic138Thin        avgt   10  2.986 ± 0.092   s/op
SpringBootThinBenchmark.basic142Thin        avgt   10  3.232 ± 0.049   s/op

@dsyer Thank you for your wonderful and great startup benchmark. You rock!

[dsyer]

Here's a top tip from @aclement -XX:TieredStopAtLevel=1

Benchmark                                   Mode  Cnt  Score   Error  Units
ConfigServerBenchmark.devtoolsRestart       avgt   10  0.842 ± 0.047   s/op
ConfigServerBenchmark.explodedJarMain       avgt   10  2.451 ± 0.100   s/op
ConfigServerBenchmark.fatJar138             avgt   10  3.002 ± 0.091   s/op
ConfigServerBenchmark.fatJar142             avgt   10  2.936 ± 0.101   s/op
MinimalBenchmark.explodedJarMain            avgt   10  1.268 ± 0.077   s/op
MinimalBenchmark.fatJar                     avgt   10  1.537 ± 0.078   s/op
PetclinicBenchmark.devtoolsRestart          avgt   10  1.107 ± 0.054   s/op
PetclinicBenchmark.explodedJarMain          avgt   10  3.618 ± 0.149   s/op
PetclinicBenchmark.fatJar                   avgt   10  5.040 ± 0.229   s/op
PetclinicBenchmark.noverify                 avgt   10  4.402 ± 0.149   s/op
ShadedBenchmark.explodedShadedMain          avgt   10  3.764 ± 0.085   s/op
ShadedBenchmark.shaded                      avgt   10  5.871 ± 0.123   s/op
SpringBoot138Benchmark.explodedJarLauncher  avgt   10  2.224 ± 0.083   s/op
SpringBoot138Benchmark.explodedJarMain      avgt   10  1.542 ± 0.044   s/op
SpringBoot138Benchmark.fatJar               avgt   10  2.102 ± 0.126   s/op
SpringBoot142Benchmark.explodedJarLauncher  avgt   10  2.232 ± 0.067   s/op
SpringBoot142Benchmark.explodedJarMain      avgt   10  1.684 ± 0.087   s/op
SpringBoot142Benchmark.fatJar               avgt   10  2.146 ± 0.080   s/op
SpringBootThinBenchmark.basic138Thin        avgt   10  1.908 ± 0.120   s/op
SpringBootThinBenchmark.basic142Thin        avgt   10  2.081 ± 0.088   s/op

Without the flag:

 Benchmark                                   Mode  Cnt  Score   Error  Units
 ConfigServerBenchmark.devtoolsRestart       avgt   10  1.034 ± 0.201   s/op
 ConfigServerBenchmark.explodedJarMain       avgt   10  3.271 ± 0.234   s/op
 ConfigServerBenchmark.fatJar138             avgt   10  3.267 ± 0.173   s/op
 ConfigServerBenchmark.fatJar142             avgt   10  3.423 ± 0.160   s/op
 PetclinicBenchmark.devtoolsRestart          avgt   10  1.387 ± 0.399   s/op
 PetclinicBenchmark.explodedJarMain          avgt   10  5.491 ± 0.357   s/op
 PetclinicBenchmark.explodedShadedMain       avgt   10  5.266 ± 0.332   s/op
 PetclinicBenchmark.fatJar                   avgt   10  6.130 ± 0.271   s/op
 PetclinicBenchmark.noverify                 avgt   10  5.430 ± 0.217   s/op
 PetclinicBenchmark.shaded                   avgt   10  7.975 ± 0.307   s/op
 SpringBoot138Benchmark.explodedJarLauncher  avgt   10  2.764 ± 0.149   s/op
 SpringBoot138Benchmark.explodedJarMain      avgt   10  2.004 ± 0.074   s/op
 SpringBoot138Benchmark.fatJar               avgt   10  2.589 ± 0.107   s/op
 SpringBoot142Benchmark.explodedJarLauncher  avgt   10  2.873 ± 0.105   s/op
 SpringBoot142Benchmark.explodedJarMain      avgt   10  2.229 ± 0.083   s/op
 SpringBoot142Benchmark.fatJar               avgt   10  2.677 ± 0.209   s/op
 SpringBootThinBenchmark.basic138Thin        avgt   10  2.474 ± 0.134   s/op
 SpringBootThinBenchmark.basic142Thin        avgt   10  2.764 ± 0.160   s/op
 MinimalBenchmark.explodedJarMain            avgt   10  1.602 ± 0.120   s/op
 MinimalBenchmark.fatJar                     avgt   10  1.901 ± 0.089   s/op

[dsyer]

Here's another MBP benchmark result (from Andy C):

ac-rmbp, late-2013, i7, 2.6Ghz, 16gb RAM, SSD (717MB/s READ), JDK180_92

Benchmark                                   Mode  Cnt   Score    Error  Units
ConfigServerBenchmark.devtoolsRestart       avgt   10   1.057 ±  0.108   s/op
ConfigServerBenchmark.explodedJarMain       avgt   10   4.115 ±  0.253   s/op
ConfigServerBenchmark.fatJar138             avgt   10   4.479 ±  0.167   s/op
ConfigServerBenchmark.fatJar142             avgt   10   5.555 ±  0.626   s/op
MinimalBenchmark.explodedJarMain            avgt   10   2.142 ±  0.136   s/op
MinimalBenchmark.fatJar                     avgt   10   3.183 ±  0.058   s/op
PetclinicBenchmark.devtoolsRestart          avgt   10   1.451 ±  0.174   s/op
PetclinicBenchmark.explodedJarMain          avgt   10   5.519 ±  0.153   s/op
PetclinicBenchmark.fatJar                   avgt   10   9.107 ±  0.247   s/op
PetclinicBenchmark.noverify                 avgt   10   8.351 ±  0.243   s/op
ShadedBenchmark.explodedShadedMain          avgt   10  11.479 ± 17.311   s/op
ShadedBenchmark.shaded                      avgt   10   8.043 ±  0.287   s/op
SpringBoot138Benchmark.explodedJarLauncher  avgt   10   3.543 ±  0.077   s/op
SpringBoot138Benchmark.explodedJarMain      avgt   10   2.578 ±  0.059   s/op
SpringBoot138Benchmark.fatJar               avgt   10   3.327 ±  0.109   s/op
SpringBoot142Benchmark.explodedJarLauncher  avgt   10   4.664 ±  0.121   s/op
SpringBoot142Benchmark.explodedJarMain      avgt   10   2.834 ±  0.108   s/op
SpringBoot142Benchmark.fatJar               avgt   10   4.484 ±  0.050   s/op

[berndgoetz]

MacBook Pro (15-inch, 2016), 2.9 GHz Intel Core i7, 16 GB 2133 MHz LPDDR3:

# Run complete. Total time: 00:14:26

Benchmark                                   Mode  Cnt  Score   Error  Units
ConfigServerBenchmark.devtoolsRestart       avgt   10  0.920 ± 0.030   s/op
ConfigServerBenchmark.explodedJarMain       avgt   10  3.019 ± 0.418   s/op
ConfigServerBenchmark.fatJar138             avgt   10  3.373 ± 0.045   s/op
ConfigServerBenchmark.fatJar142             avgt   10  3.273 ± 0.041   s/op
JsaBenchmark.sharedClasses                  avgt   10  0.102 ± 0.005   s/op
JsaBenchmark.thinMain                       avgt   10  0.095 ± 0.005   s/op
MinimalBenchmark.explodedJarMain            avgt   10  1.515 ± 0.013   s/op
MinimalBenchmark.fatJar                     avgt   10  1.849 ± 0.030   s/op
PetclinicBenchmark.devtoolsRestart          avgt   10  1.303 ± 0.060   s/op
PetclinicBenchmark.explodedJarMain          avgt   10  4.058 ± 0.041   s/op
PetclinicBenchmark.fatJar                   avgt   10  5.748 ± 0.053   s/op
PetclinicBenchmark.noverify                 avgt   10  5.000 ± 0.058   s/op
ShadedBenchmark.explodedShadedMain          avgt   10  5.150 ± 0.382   s/op
ShadedBenchmark.shaded                      avgt   10  6.653 ± 0.302   s/op
SpringBoot138Benchmark.explodedJarLauncher  avgt   10  2.549 ± 0.016   s/op
SpringBoot138Benchmark.explodedJarMain      avgt   10  1.825 ± 0.027   s/op
SpringBoot138Benchmark.fatJar               avgt   10  2.399 ± 0.040   s/op
SpringBoot142Benchmark.explodedJarLauncher  avgt   10  2.722 ± 0.152   s/op
SpringBoot142Benchmark.explodedJarMain      avgt   10  2.051 ± 0.070   s/op
SpringBoot142Benchmark.fatJar               avgt   10  2.541 ± 0.041   s/op
SpringBootThinBenchmark.basic138Thin        avgt   10  2.168 ± 0.027   s/op
SpringBootThinBenchmark.basic142Thin        avgt   10  2.340 ± 0.023   s/op
SpringBootThinBenchmark.petclinicThin       avgt   10  4.590 ± 0.056   s/op

[sahilnagpal]

Any updates on this issue? I am facing the same problem. Running the application as java -jar is taking almost 7 times more time as compared to mvn spring-boot:run.

[dsyer]

No updates. Check your system for antivirus and similar constraints. Read the discussion above.

[sahilnagpal]

@dsyer We are using spring boot for local, staging and prod environment. Staging and prod are AWS EC2 instances having Ubuntu as their OS. I don't think so it is an antivirus issue as the issue is reproable on almost everyone's Mac and Linux machine in the team.

I would really appreciate if you can mention what other similar constraints might be leading to much a performance dip.

mvn spring-boot:run takes around 160 seconds, which is still ok as we really have a huge application. However, java -jar on the repackaged jar takes approximately 1300 seconds which slows down the deployment of staging and prod environments.

The trace logs in both the cases are full of "Looking for matching resources in jar file" somehow indicating that component scan is taking a lot of time. The findPathMatchingResources method in the PathMatchingResourcePatternResolver class uses doFindPathMatchingJarResources method (which takes more time according to logs and is probably used when the application is run as a jar) as compared to doFindPathMatchingFileResources method (which is used when we use mvn spring-boot:run).

[dsyer]

I guess you don't have to use the "java -jar" form if it costs you so much. Really you are just paying the cost of unzipping all your jar files. You could measure that to get an idea I suppose. I don't have any idea why it is so expensive in your case, but disk I/O is very expensive, and your EC2 instances are probably paying heavily for it. You could try changing the storage. Or unpack the app when you build the EC2 image.

[wilkinsona]

Really you are just paying the cost of unzipping all your jar files

A fat jar shouldn't add any unzipping cost for jar files in BOOT-INF/lib as they are stored in the jar without being compressed. There's still an unzipping cost of extracting the contents of the nested jar, but that should be the same as the cost with an unpacked app.

[asarkar]

@sahilnagpal I'm curious what steps did you take in benchmarking the start up? I looked into @dsyer repo here, which is pretty cool, but the method for applying that to external projects is neither documented, nor very clear to me yet (dsyer/spring-boot-startup-bench#7).

[vvondra]

btw. We have seen huge improvements of startup time by using -XX:+TieredCompilation -XX:TieredStopAtLevel=1 (80s -> 20s), at an expense of 20-60% slower performance when running fully warmed up (which is fine since for us it's from 5ms -> 8ms response time)

[philwebb]

We've done quite a bit of work on the jar launcher since this issue was raised (such as #11207). Since most of the figures in this issue are now outdated I'm going to close this one and we can take any new performance issues as they come.