0

I recently observed the phenomenon that Spring Boot applications start up very slowly on my Fedora 30 computer, taking up to serveral minutes, while the same package starts very fast on Windows computers. On Fedora I have two versions of Java installed: Java 8

openjdk version "1.8.0_222"
OpenJDK Runtime Environment (build 1.8.0_222-b10)
OpenJDK 64-Bit Server VM (build 25.222-b10, mixed mode)

and Java 11

openjdk version "11.0.4" 2019-07-16
OpenJDK Runtime Environment 18.9 (build 11.0.4+11)
OpenJDK 64-Bit Server VM 18.9 (build 11.0.4+11, mixed mode, sharing)

I tried to start with both versions and found it's much faster on JDK11 (~18s) than on JDK1.8 (~146s). The starting process is by using command line or Intellij IDEA, and monitored with VisualVM. The command lines used are:

sudo alternatives --config java
java -jar car-hailing-order-server.jar

When starting with JDK1.8 I could see a message addressing the problem of JMX server connection, either from Intellij IDEA or the VisualVM thread dump. When starting in Intellij IDEA I could see the error message presented in the Event log window:

10:46 AM order-server: Failed to retrieve application JMX service URL

and a similar message also occurs in the thread dump while monitored by VisualVM:

2019-10-09 10:22:44
Full thread dump OpenJDK 64-Bit Server VM (25.222-b10 mixed mode):

"JMX server connection timeout 18" #18 daemon prio=9 os_prio=0 tid=0x00007f6830013000 nid=0xd47 in Object.wait() [0x00007f68860fc000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000007700aaee0> (a [I)
        at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:168)
        - locked <0x00000007700aaee0> (a [I)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI Scheduler(0)" #17 daemon prio=9 os_prio=0 tid=0x00007f6830010800 nid=0xd45 waiting on condition [0x00007f68861fd000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000006c762a450> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI TCP Connection(1)-192.168.10.2" #16 daemon prio=9 os_prio=0 tid=0x00007f6824248000 nid=0xd44 runnable [0x00007f688c3f2000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
        - locked <0x000000077006fec8> (a java.io.BufferedInputStream)
        at java.io.FilterInputStream.read(FilterInputStream.java:83)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:555)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$97/842634384.run(Unknown Source)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - <0x000000076d234ab8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"Log4j2-TF-4-Scheduled-2" #15 daemon prio=5 os_prio=0 tid=0x00007f68a05b0800 nid=0xd43 waiting on condition [0x00007f688c1f1000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000076e7c72c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI TCP Accept-0" #14 daemon prio=9 os_prio=0 tid=0x00007f682c042800 nid=0xd3f runnable [0x00007f688c2f2000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
        at java.net.ServerSocket.implAccept(ServerSocket.java:545)
        at java.net.ServerSocket.accept(ServerSocket.java:513)
        at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:52)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:405)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:377)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Attach Listener" #9 daemon prio=9 os_prio=0 tid=0x00007f685c001000 nid=0xd3a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x00007f68a01f3000 nid=0xd38 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007f68a01e8000 nid=0xd37 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f68a01e6800 nid=0xd36 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f68a01d7000 nid=0xd35 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f68a01d5000 nid=0xd34 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f68a01ab000 nid=0xd33 in Object.wait() [0x00007f688d2ad000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000006c7661f40> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
        - locked <0x00000006c7661f40> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

   Locked ownable synchronizers:
        - None

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f68a01a6800 nid=0xd32 in Object.wait() [0x00007f688d3ae000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000006c766dae0> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        - locked <0x00000006c766dae0> (a java.lang.ref.Reference$Lock)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

   Locked ownable synchronizers:
        - None

"main" #1 prio=5 os_prio=0 tid=0x00007f68a004c800 nid=0xd2c runnable [0x00007f68a451e000]
   java.lang.Thread.State: RUNNABLE
        at java.io.RandomAccessFile.readBytes(Native Method)
        at java.io.RandomAccessFile.read(RandomAccessFile.java:377)
        at org.springframework.boot.loader.data.RandomAccessDataFile$FileAccess.read(RandomAccessDataFile.java:224)
        - locked <0x00000006c769f688> (a java.lang.Object)
        at org.springframework.boot.loader.data.RandomAccessDataFile$FileAccess.access$400(RandomAccessDataFile.java:206)
        at org.springframework.boot.loader.data.RandomAccessDataFile.read(RandomAccessDataFile.java:117)
        at org.springframework.boot.loader.data.RandomAccessDataFile.read(RandomAccessDataFile.java:101)
        at org.springframework.boot.loader.jar.CentralDirectoryFileHeader.fromRandomAccessData(CentralDirectoryFileHeader.java:176)
        at org.springframework.boot.loader.jar.JarFileEntries.getEntry(JarFileEntries.java:247)
        at org.springframework.boot.loader.jar.JarFileEntries.getEntry(JarFileEntries.java:232)
        at org.springframework.boot.loader.jar.JarFileEntries.getEntry(JarFileEntries.java:220)
        at org.springframework.boot.loader.jar.JarFileEntries.containsEntry(JarFileEntries.java:173)
        at org.springframework.boot.loader.jar.JarFile.containsEntry(JarFile.java:214)
        at org.springframework.boot.loader.jar.JarURLConnection.get(JarURLConnection.java:274)
        at org.springframework.boot.loader.jar.Handler.openConnection(Handler.java:96)
        at java.net.URL.openConnection(URL.java:991)
        at sun.misc.URLClassPath$Loader.getResource(URLClassPath.java:746)
        at sun.misc.URLClassPath.getResource(URLClassPath.java:249)
        at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
        at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
        - locked <0x0000000770d23b60> (a java.lang.Object)
        at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:93)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        at org.springframework.context.support.GenericApplicationContext.<init>(GenericApplicationContext.java:112)
        at org.springframework.context.annotation.AnnotationConfigApplicationContext.<init>(AnnotationConfigApplicationContext.java:64)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:172)
        at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:122)
        at org.springframework.boot.SpringApplication.createApplicationContext(SpringApplication.java:607)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:310)
        at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:139)
        - locked <0x00000006c766df68> (a java.util.concurrent.atomic.AtomicBoolean)
        at org.springframework.cloud.bootstrap.BootstrapApplicationListener.bootstrapServiceContext(BootstrapApplicationListener.java:203)
        at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:114)
        at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:71)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
        at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:75)
        at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
        at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:347)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:306)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1260)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1248)
        at com.winsky.carhailing.order.server.Application.main(Application.java:15)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
        at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
        at org.springframework.boot.loader.Launcher.launch(Launcher.java:50)
        at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:51)

   Locked ownable synchronizers:
        - None

"VM Thread" os_prio=0 tid=0x00007f68a019d000 nid=0xd31 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f68a005f000 nid=0xd2d runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f68a0061000 nid=0xd2e runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f68a0062800 nid=0xd2f runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f68a0064800 nid=0xd30 runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007f68a01f5800 nid=0xd39 waiting on condition

JNI global references: 431

So I Googled and found this issue, and tried to apply these options as suggested:

java -jar -Dcom.sun.management.jmxremote.port=60021 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false car-hailing-order-server.jar

but it still doesn't work.

When I changed to JDK11 it starts fast in command line or Intellij IDEA. So the problem should have to do with the version of JDK used but I can't find a complete solution to this problem (because I want to use JDK1.8 in coordination with other team members).

Joseph Tesfaye
  • 814
  • 14
  • 26
  • Have you tried [this](https://github.com/thoeni/inetTester). It has been reported that at times resolution to `localhost` is slow, mainly on MacOS but other OSes could be involved as well. JMX shouldn't be the issue (you could even disable it and test `--spring.jmx.enabled=false` or by adding that to `application.properties` as you aren't likely to need it). – M. Deinum Oct 09 '19 at 06:09
  • @M.Deinum It returns `Method called, hostname winsky, elapsed time: 10022 (ms) `. Is this slow? I don't understand this line `it could be solved by adding the hostname that the application will return on your hosts file`. Where should I adding those lines? – Joseph Tesfaye Oct 09 '19 at 06:16
  • in `/etc/hosts` that is a file with static IP address. A 10 second lookup for a localhost (loopback) is slow. On my machine it runs less then 100ms. So try adding that information to the `/etc/hosts` file and see if it gets faster. Something like `127.0.0.1 localhost winsky` and `::1 localhost winsky` should be added (first is IPv4 the other IPv6). – M. Deinum Oct 09 '19 at 06:22
  • Yep it worked! Now it only takes about 5s to start my application. But why is the hostname "winsky"? I didn't set the name anywhere on my computer. Where is this name from? – Joseph Tesfaye Oct 09 '19 at 06:53
  • @M.Deinum Please make the comment to an answer so I can adopt it. Thank you! – Joseph Tesfaye Oct 09 '19 at 06:54

0 Answers0