OpenJdk initial startup time very slow

Question

I'm running openjdk 11.0.3 on a server. Whenever the server has been rebooted (every night): For the first initial launch of my Application, the users have to wait for 35 Seconds before the Application is even started. (Before the first System.out.println is written from main Method.) (subsequent launches are very fast though) I have tried the following option to debug this:

-Xlog:class+load:file=classload.txt

Here are the most important finds:

... 
[2.284s][info][class,load] jdk.internal.loader.URLClassPath$FileLoader source: jrt:/java.base
[5.032s][info][class,load] sun.security.rsa.RSASignature$SHA1withRSA source: jrt:/java.base
…
[5.051s][info][class,load] java.util.LinkedList$Node source: jrt:/java.base 
[8.121s][info][class,load] pos.LFChangeable source: file:/C:/Users/rho/AppData/Roaming/edapp/pos.jar
…
[8.135s][info][class,load] java.io.FileNotFoundException source: jrt:/java.base
[10.584s][info][class,load] sun.reflect.misc.ReflectUtil source: jrt:/java.base
…
[11.744s][info][class,load] java.security.NoSuchAlgorithmException source: jrt:/java.base
[34.853s][info][class,load] jdk.internal.logger.DefaultLoggerFinder source: jrt:/java.base

Why is it hanging for 23 Seconds between loading java.security.NoSuchAlgorithmException and jdk.internal.logger.DefaultLoggerFinder? And what about the other seconds of slowdowns?

edit: Based on the comments, I will clarify some. This is a windows rdp server. Actually, it is more than one server, but the problem persists on all servers. The Application is a standalone Application. So every morning there are problems as users who log in to start the Application, will try to start it multiple times when "nothing happens". I have now tried restarting one of the servers quite a few times, and this is what I found:

Starting my Application with java11 after reboot takes on average 40 seconds before the first System.out.println. Then it is only 1-2 Seconds before my first JFrame shows. Starting my Application with java8 (sun) after reboots takes on average 16 Seconds before the first System.out.println. But I then get a 25 second delay before my first JFrame shows. Starting my Application with java11 after already started with java8 takes on average 4-6 seconds.

Abort

If subsequent launches are fast I wouldn't worry so much about what the Java application is doing. Most likely you are waiting for disk I/O. Perhaps the disks have gone to sleep and need to spin up, that can easily take 10-15 seconds? Then for subsequent runs the files are cached. Perhaps you can solve the problem by starting the application proactively after restart (cyberciti.biz/faq/linux-execute-cron-job-after-system-reboot)? – Ansel

What server are you using? Just a shot in the dark: are you using SecureRandom somewhere? On a server you might be short of entropy which would explain that the first startup is so slowly. (For Tomcat see also wiki.apache.org/tomcat/HowTo/FasterStartUp#Entropy_Source) – Lingonberry

Taking a few stack traces (jstack, jcmd, ...) during the application startup might give some insights. The VM is likely started in <100ms so a startup of 35s suggests something else is going on. Joachim's suggestion that it may be the entropy source is a good guess and the stack trace may reveal more. – Gamesome

Answer 1

Your application might be suffering from the absence of a “class data-sharing (CDS) archive”. Such an archive allows much faster loading of standard classes and has been generated by default by some installers of previous versions, but OpenJDK 11 does not have an installer.

This is addressed by JEP 341:

Currently, a JDK image includes a default class list, generated at build time, in the lib directory. Users who want to take advantage of CDS, even with just the default class list provided in the JDK, must run java -Xshare:dump as an extra step. This option is documented, but many users are unaware of it.

So while this JEP is about JDK 12 doing the necessary steps automatically, it also mentions the fix for JDK 11: just run java -Xshare:dump on the command line once, to generate the archive.

Note that you can improve the startup time even further by including application classes in the CDS. See also the Class Data Sharing section of the JDK 11 documentation.

Kristopherkristos

I've tried java -Xshare:dump now, unfortunately, it didn't seem seem to speed up things much. still 33.285s until jdk.internal.logger.DefaultLoggerFinder – Abort

After you ran with -Xshare:dump, you may use -Xshare:on to force the usage, to be sure that it didn’t fall back to not using it for some reason. You may also check the linked article and use -XX:SharedClassListFile to include far more classes. Besides that, there’s still the possibility that there is some other activity than class loading involved. Perhaps, the NoSuchAlgorithmException is truly thrown, someone catches it and does a lengthy operation before trying to log it (which causes the loading of DefaultLoggerFinder. – Kristopherkristos

Answer 2

I have now tested extensively, and I am prepared to publish my results, along with the 2 different "solutions" that I made. First, let me explain my application a bit. It is a swing enterprise-application that started it's life 13 years ago, and has been extended every since. This application therefore is big, does a lot of different things (although most users uses only a portion of it), and has about 120 jar-files on it's classpath including all the third-party-jars. As previously mentioned, after restart of the server it takes 35 seconds before my first login-JFrame is shown.

Solution 1: This was my first solution, and is not a solution to the slow start, but more a solution to the user not starting multiple instances of the application. I noticed that although my application was very slow on the first initial start, other applications were not. A workaround was therefore to make a small standalone-application to display the splash screen, that I start like this in my program:

splashProcess = Runtime.getRuntime().exec("javaw -jar splash.jar");

Later I just kill it off with

splashProcess.destroy();

Note that if I should create a splashscreen with new JFrame() instead, it would take the usual 35 seconds before it is displayed.

Solution 2: While testing, I found out I could simulate a restart by just deleting all the jar-files and copying them back. In addition to reduced testing time, I found out that starting the application with just the 4-5 jar-files needed for the initial startup was very fast (although that would have lead to ClassNotFoundExceptions later), this also ment that I could try to figure out which jar-file which led to the hang, by starting by copying all jar-files back, and then omitting one and one more. However, I found out that it was not one jar-file that was to blame. The seconds it takes before the application start was steadily reduced a little bit each time I removed some jar-files. So, it seems that the problem is that the first time I call new JFrame() in my application, java seems to build some sort of index or something of all classes in the classpath, although they are not used at this time. I don't know why it does this, but this process takes quite some time with 120 jar-files on the classpath. This led me to solution nr 2. When my application now starts, I check for an argument "startSilent". If this is present, the only thing my application does is show a new JDialog with size 0,0 and then call System.exit(0); I then made a script that runs my application with the "startSilent"-parameter that starts when the user logs in. Now, if the user logs into the server and waits at least 35 seconds before starting our application, the start is now lightning fast, as the application has already started and exited once, so that the "classpath-index" or whatever it is has been built. If the user starts the application after a shorter time, the start-time is reduced by how long the silent-script has already run. (And the start will always be at least a fair degree faster than before, as the script starts before the desktop is ready).

So these are the results of my findings. I hope other will find them useful, and if someone can explain why what I call the "classpath-index" is created as it is, I would be welcome.

Abort

Thanks for following up. Had a similar symptom after JDK-8 > 11 but wasn't severe so lived with it for a few years. After startup JFrame remains blank for 2-3s before painting. We had a background thread load up 32 .DLLs (mathematical solvers) using JNI, query & unload them. Three ~800ms delays were seen in the native method call. Perfectly repeatable, but if a DLL was deleted, the delay just moved to a different one. It felt like Java was "stopping the world" to do book-keeping or something. Changing GCs (Parallel vs G1GC) or heap settings didn't affect it. With JDK8 it all loaded in 100ms. – Sombrous

Simple workaround was to defer this thread to a point the user is less likely to notice, but would still be good to get an understanding of the underlying cause. – Sombrous