Spring Boot startup slow on Raspberry PI

Question

Using Spring Boot 2 for an IoT application, I notice that the startup time for Spring is disproportionally slow. The platform is a Raspberry PI 2B - of course, this is going to be significantly slower than a PC. For normal code execution I measure a 20x to 50x difference.

Spring boot startup time on my PC (Win10 x64): 5 seconds
Spring boot startup time on the PI (Ubuntu Server, ARM java in docker running a jar): 11 minutes

If I use the highest factor I've ever measured (50x), I would expect to see a startup time of less than half of the current state. So far, I tried:

Excluding dependencies from auto configuration (now minimal with only only spring-boot-starter-web, kotlin, undertow, webflux, reactor and kafka)
Logging on DEBUG to see what was happening during quiet periods (mostly beans being set up, nothing suspicious, though some beans take several seconds to load)
Different docker image for Java on ARM (no effect)
CPU is consistently at 100%, memory is around 20% and there is plenty of disk space

My preliminary conclusion is that loading beans eats all the CPU cycles. I imagine that initializing a bean should not take several seconds, but it does. What could be the bottleneck here? Can I get Spring to load faster in any way?

Here is the first part of the output from a PC:

2018-01-06 13:43:03.462  INFO 9144 --- [           main] c.e.b.BasestationApplicationKt           : Starting BasestationApplicationKt on GPC with PID 9144 (C:\Data\Code\app\git\basestation\out\production\classes started by User in C:\Data\Code\app\git)
2018-01-06 13:43:03.471  INFO 9144 --- [           main] c.e.b.BasestationApplicationKt           : The following profiles are active: dev
2018-01-06 13:43:03.637  INFO 9144 --- [           main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@294e5088: startup date [Sat Jan 06 13:43:03 CET 2018]; root of context hierarchy
2018-01-06 13:43:05.578  INFO 9144 --- [           main] org.xnio                                 : XNIO version 3.3.8.Final
2018-01-06 13:43:05.600  INFO 9144 --- [           main] org.xnio.nio                             : XNIO NIO Implementation Version 3.3.8.Final
2018-01-06 13:43:05.695  WARN 9144 --- [           main] io.undertow.websockets.jsr               : UT026009: XNIO worker was not set on WebSocketDeploymentInfo, the default worker will be used
2018-01-06 13:43:05.695  WARN 9144 --- [           main] io.undertow.websockets.jsr               : UT026010: Buffer pool was not set on WebSocketDeploymentInfo, the default pool will be used
2018-01-06 13:43:05.721  INFO 9144 --- [           main] io.undertow.servlet                      : Initializing Spring embedded WebApplicationContext
2018-01-06 13:43:05.722  INFO 9144 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 2088 ms
2018-01-06 13:43:05.851  INFO 9144 --- [           main] o.s.b.w.servlet.ServletRegistrationBean  : Mapping servlet: 'dispatcherServlet' to [/]
2018-01-06 13:43:05.857  INFO 9144 --- [           main] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'characterEncodingFilter' to: [/*]
2018-01-06 13:43:07.323  INFO 9144 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/],methods=[GET]}" onto public com.app.basestation.model.Message com.app.basestation.BasestationController.home()
2018-01-06 13:43:07.330  INFO 9144 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-01-06 13:43:07.349  INFO 9144 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-01-06 13:43:07.509  INFO 9144 --- [           main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@294e5088: startup date [Sat Jan 06 13:43:03 CET 2018]; root of context hierarchy
2018-01-06 13:43:08.519  INFO 9144 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-01-06 13:43:08.553  INFO 9144 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase 2147483647
2018-01-06 13:43:08.678  INFO 9144 --- [           main] o.s.b.w.e.u.UndertowServletWebServer     : Undertow started on port(s) 11112 (http)

And the output from the PI:

2018-01-06 12:48:41.689  INFO 1 --- [           main] c.e.b.BasestationApplicationKt           : Starting BasestationApplicationKt on ubuntu with PID 1 (/app.jar started by root in /)
2018-01-06 12:48:42.019  INFO 1 --- [           main] c.e.b.BasestationApplicationKt           : The following profiles are active: prd
2018-01-06 12:48:49.827  INFO 1 --- [           main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@128c152: startup date [Sat Jan 06 12:48:49 UTC 2018]; root of context hierarchy
2018-01-06 12:54:05.276  INFO 1 --- [           main] org.xnio                                 : XNIO version 3.3.8.Final
2018-01-06 12:54:08.404  INFO 1 --- [           main] org.xnio.nio                             : XNIO NIO Implementation Version 3.3.8.Final
2018-01-06 12:54:15.847  WARN 1 --- [           main] io.undertow.websockets.jsr               : UT026009: XNIO worker was not set on WebSocketDeploymentInfo, the default worker will be used
2018-01-06 12:54:15.852  WARN 1 --- [           main] io.undertow.websockets.jsr               : UT026010: Buffer pool was not set on WebSocketDeploymentInfo, the default pool will be used
2018-01-06 12:54:19.930  INFO 1 --- [           main] io.undertow.servlet                      : Initializing Spring embedded WebApplicationContext
2018-01-06 12:54:19.934  INFO 1 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 330155 ms
2018-01-06 12:54:42.544  INFO 1 --- [           main] o.s.b.w.servlet.ServletRegistrationBean  : Mapping servlet: 'dispatcherServlet' to [/]
2018-01-06 12:54:43.206  INFO 1 --- [           main] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'characterEncodingFilter' to: [/*]
2018-01-06 12:57:18.683  INFO 1 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/],methods=[GET]}" onto public com.app.basestation.model.Message com.app.basestation.BasestationController.home()
2018-01-06 12:57:19.734  INFO 1 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-01-06 12:57:19.758  INFO 1 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-01-06 12:57:44.597  INFO 1 --- [           main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@128c152: startup date [Sat Jan 06 12:48:49 UTC 2018]; root of context hierarchy
2018-01-06 12:59:36.677  INFO 1 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-01-06 12:59:37.807  INFO 1 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase 2147483647
2018-01-06 12:59:42.664  INFO 1 --- [           main] o.s.b.w.e.u.UndertowServletWebServer     : Undertow started on port(s) 11112 (http)

I noticed a huge difference between using the OpenJDK and the Oracle SDK (specifically, Linux ARM 32 Hard Float ABI). For the Spring boot app that I executed, it look 5 minutes to load with the OpenJDK and about 10 seconds with the Oracle SDK. — snodnipper
@snodnipper hmm, I guess I have to look into an Oracle alternative then. I was indeed using resin/raspberry-pi-openjdk:8-jdk. — Jodiug

Jodiug Jodiug · Accepted Answer · 2018-06-10T08:54:08

Update:

For those reading this, I moved back to OpenJDK in 2019 due to the new Oracle policies. What I noticed is that OpenJDK has made significant performance improvements recently. If you use OpenJDK 11 and above, it has similar performance to Oracle JDK and you can easily configure its language level to work with Java 8 code. That said, if this does not work for you, try the below.

I moved to a new image: Oracle JDK instead of OpenJDK as @snodnipper suggested.

There were several things I had to do including installing a more recent version of Java 8 than the one available in the standard repository. This is the Dockerfile that ended up working for me, and now the application starts in 2 minutes.

FROM resin/raspberrypi3-buildpack-deps:jessie-scm

ENV LANG C.UTF-8
ENV JAVA_HOME /usr/lib/jvm/java-8-oracle

RUN ["cross-build-start"]
RUN echo "deb http://archive.raspberrypi.org/debian/ jessie main ui staging" > /etc/apt/sources.list.d/raspi.list
RUN rm -f /usr/bin/entry.sh
RUN wget -qO - http://archive.raspberrypi.org/debian/raspberrypi.gpg.key | apt-key add -

RUN { \
        echo '#!/bin/bash'; \
        echo 'set -e'; \
        echo; \
        echo 'dirname "$(dirname "$(readlink -f "$(which javac || which java)")")"'; \
    } > /usr/local/bin/docker-java-home && \
    chmod +x /usr/local/bin/docker-java-home

RUN apt-key adv --recv-key --keyserver keyserver.ubuntu.com C2518248EEA14886 && \
    echo "deb http://ppa.launchpad.net/webupd8team/java/ubuntu xenial main" >> /etc/apt/sources.list.d/raspi.list

RUN set -x && \
    apt-get update && \
    apt-cache madison oracle-java8-installer && \
    echo debconf shared/accepted-oracle-license-v1-1 select true | debconf-set-selections && \
    apt-get install -y oracle-java8-installer oracle-java8-set-default && \
    rm -rf /var/lib/apt/lists/* && \
    [ "$JAVA_HOME" = "$(docker-java-home)" ]

RUN [ "cross-build-end" ]

ADD build/libs/app-0.0.1-SNAPSHOT.jar /app.jar

ENV JAVA_OPTS=""
ENTRYPOINT exec java $JAVA_OPTS -Djava.security.egd=file:/dev/./urandom -jar /app.jar

Spring Boot startup slow on Raspberry PI

1 Answers