ExceptionInInitializerError when using spring with profile

[shuangy92]

• Framework version: 1.3
• Implementations: Spring & Spring Boot

Scenario

At first I was using spring boot with spring profile, and I found that the application has a high possibility to launch twice.
The first launch is fast, and as soon as the log prints out START RequestId：..., the second launch starts.
It may happen at any time during the first launch. The farthest place the first launch can reach from my observation is to print out o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup.
In 10 times of cold start, this issue happens like 8 times. (Yes some times the application do launch once only)
If the application only launches once, it takes ~10s. But for twice, it takes ~40s. The refreshing context for the second launch takes ~10s.

What I mean "launch twice" is that the static init block of SpringBootLambdaContainerHandler was entered twice.
I also tried to declare SpringBootLambdaContainerHandler as a member attribute of MyStreamLambdaHandler, and init it in the constructor. It shows that the constructor was also entered twice.

I thought this can only happen when there's multiple class loaders. So I print out the loader and it's ancestors in the static init block like this:

public class MyStreamLambdaHandler implements RequestStreamHandler {
    private static SpringBootLambdaContainerHandler<AwsProxyRequest, AwsProxyResponse> handler;
    private static final ClassLoader loader;

    static {
        try {
            loader = Thread.currentThread().getContextClassLoader();
            while (loader != null) {
                log.info("loader: {}", loader);
                loader = loader.getParent();
            }

            handler = SpringBootLambdaContainerHandler.getAwsProxyHandler(App.class, "develop");
        } catch (ContainerInitializationException e) {
            // if we fail here. We re-throw the exception to force another cold start
            throw new RuntimeException("Could not initialize Spring Boot application", e);
        }
    }
    ...
}

The result is here:
First launch:

07:54:33.069 INFO --- [ main] c.w.c.h.c.MyStreamLambdaHandler : loader: java.net.URLClassLoader@5d099f62
07:54:33.070 INFO --- [ main] c.w.c.h.c.MyStreamLambdaHandler : loader: sun.misc.Launcher$AppClassLoader@33909752
07:54:33.070 INFO --- [ main] c.w.c.h.c.MyStreamLambdaHandler : loader: sun.misc.Launcher$ExtClassLoader@66480dd7

Second luanch:

07:54:44.903 INFO --- [ main] c.w.c.h.c.MyStreamLambdaHandler : loader: java.net.URLClassLoader@1d56ce6a
07:54:44.903 INFO --- [ main] c.w.c.h.c.MyStreamLambdaHandler : loader: sun.misc.Launcher$AppClassLoader@33909752
07:54:44.903 INFO --- [ main] c.w.c.h.c.MyStreamLambdaHandler : loader: sun.misc.Launcher$ExtClassLoader@5383967b

As you can see, it's super weird that the same AppClassLoader has different ExtClassLoader as parent...

I also tried to "lazy init" the handler as introduced at #201.
By this way, the application only launches once in handleRequest, but it takes ~30s (~10s for refresh context).

I then tried not to use profile, nothing changed.
I tried to reduced the dependecy and make the application almost the same to demo. The issue still exists.
Finally I found that as long as I'm using spring boot, this issue always happens.

BTW, I found someone who encountered the similar problem at here:
https://forum.serverless.com/t/aws-lambda-coldstart-springboot-booting-2-times/5850

Next, I removed all spring-boot dependecies and used spring only (with profile).
By this way, I got ExceptionInInitializerError directly. The log is here:

07:19:45.637 INFO --- [ main] c.a.s.p.internal.LambdaContainerHandler : Starting Lambda Container Handler
07:19:47.484 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'aws-servless-java-container'
07:19:47.485 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'aws-servless-java-container'
07:19:47.486 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms
07:19:47.487 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring root WebApplicationContext
07:19:47.487 INFO --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization started
07:19:47.487 INFO --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext initialized in 0 ms
07:19:47.777 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'aws-servless-java-container'
07:19:47.777 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'aws-servless-java-container'
07:19:47.777 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms
START RequestId: 7b44e995-1bae-4031-bd24-c2b4c7e6cc31 Version: $LATEST
Error loading class xx.MyStreamLambdaHandler: java.lang.ExceptionInInitializerError
java.lang.ExceptionInInitializerError
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
Caused by: java.lang.IllegalStateException: Cannot initialize context because there is already a root application context present - check whether you have multiple ContextLoader* definitions in your web.xml!
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:262)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:103)
at com.amazonaws.serverless.proxy.spring.LambdaSpringApplicationInitializer.notifyStartListeners(LambdaSpringApplicationInitializer.java:176)
at com.amazonaws.serverless.proxy.spring.LambdaSpringApplicationInitializer.onStartup(LambdaSpringApplicationInitializer.java:170)
at com.amazonaws.serverless.proxy.spring.SpringLambdaContainerHandler.initialize(SpringLambdaContainerHandler.java:192)
at com.amazonaws.serverless.proxy.spring.SpringLambdaContainerHandler.getAwsProxyHandler(SpringLambdaContainerHandler.java:98)
at xx.MyStreamLambdaHandler.<clinit>(MyStreamLambdaHandler.java:22)
... 2 more

END RequestId: 7b44e995-1bae-4031-bd24-c2b4c7e6cc31
REPORT RequestId: 7b44e995-1bae-4031-bd24-c2b4c7e6cc31	Duration: 71.95 ms	Billed Duration: 100 ms Memory Size: 1024 MB	Max Memory Used: 98 MB	
Error loading class xx.MyStreamLambdaHandler
java.lang.ExceptionInInitializerError
07:19:49.209 INFO --- [ main] c.a.s.p.internal.LambdaContainerHandler : Starting Lambda Container Handler
07:19:51.081 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'aws-servless-java-container'
07:19:51.082 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'aws-servless-java-container'
07:19:51.083 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms
07:19:51.096 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring root WebApplicationContext
07:19:51.096 INFO --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization started
07:19:51.096 INFO --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext initialized in 0 ms
07:19:51.458 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'aws-servless-java-container'
07:19:51.458 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'aws-servless-java-container'
07:19:51.458 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms

But if I get rid of profile, the application launches once only.

I looked into the codes, and found that initilizer.onStartup was called twice at newHandler.activateSpringProfiles(profiles) and newHandler.initialize().

I tried to remove L98 and the issue then disappers.
I'm not sure if this fix is correct... Any help is appreciated. I still want to use spring boot with profile but I need to reduced the cold start time.

=============== update
Just confirmed that remove L98 doesn't fix the issue. It happened again.
But this time the stack trace changes:

10:24:49.129 INFO --- [ main] c.a.s.p.internal.LambdaContainerHandler : Starting Lambda Container Handler
10:24:51.107 INFO --- [ main] o.h.validator.internal.util.Version : HV000001: Hibernate Validator 6.0.13.Final
10:24:51.529 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'aws-servless-java-container'
10:24:51.530 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'aws-servless-java-container'
10:24:51.532 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
10:24:51.532 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring root WebApplicationContext
10:24:51.532 INFO --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization started
10:24:51.533 INFO --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext initialized in 1 ms
START RequestId: 4121d608-9438-4edc-9da9-47a5f90eea70 Version: $LATEST
10:24:52.368 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'aws-servless-java-container'
10:24:52.369 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'aws-servless-java-container'
10:24:52.369 INFO --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms
10:24:52.371 ERROR --- [ main] c.a.s.p.internal.LambdaContainerHandler : Error while handling request
java.lang.IllegalStateException: Cannot initialize context because there is already a root application context present - check whether you have multiple ContextLoader* definitions in your web.xml!
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:262)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:103)
at xx.LambdaSpringApplicationInitializer.notifyStartListeners(LambdaSpringApplicationInitializer.java:184)
at xx.LambdaSpringApplicationInitializer.onStartup(LambdaSpringApplicationInitializer.java:178)
at xx.SpringLambdaContainerHandler.initialize(SpringLambdaContainerHandler.java:197)
at xx.SpringLambdaContainerHandler.handleRequest(SpringLambdaContainerHandler.java:180)
at xx.SpringLambdaContainerHandler.handleRequest(SpringLambdaContainerHandler.java:47)
at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxy(LambdaContainerHandler.java:177)
at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxyStream(LambdaContainerHandler.java:209)
at xx.MyStreamLambdaHandler.handleRequest(MyStreamLambdaHandler.java:32)
at lambdainternal.EventHandlerLoader$2.call(EventHandlerLoader.java:888)
at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:293)
at lambdainternal.AWSLambda.<clinit>(AWSLambda.java:64)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at lambdainternal.LambdaRTEntry.main(LambdaRTEntry.java:104)
10:24:52.371 ERROR --- [ main] c.a.s.proxy.AwsProxyExceptionHandler : Called exception handler for:
java.lang.IllegalStateException: Cannot initialize context because there is already a root application context present - check whether you have multiple ContextLoader* definitions in your web.xml!
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:262)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:103)
at xx.LambdaSpringApplicationInitializer.notifyStartListeners(LambdaSpringApplicationInitializer.java:184)
at xx.LambdaSpringApplicationInitializer.onStartup(LambdaSpringApplicationInitializer.java:178)
at xx.SpringLambdaContainerHandler.initialize(SpringLambdaContainerHandler.java:197)
at xx.SpringLambdaContainerHandler.handleRequest(SpringLambdaContainerHandler.java:180)
at xx.SpringLambdaContainerHandler.handleRequest(SpringLambdaContainerHandler.java:47)
at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxy(LambdaContainerHandler.java:177)
at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxyStream(LambdaContainerHandler.java:209)
at xx.MyStreamLambdaHandler.handleRequest(MyStreamLambdaHandler.java:32)
at lambdainternal.EventHandlerLoader$2.call(EventHandlerLoader.java:888)
at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:293)
at lambdainternal.AWSLambda.<clinit>(AWSLambda.java:64)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at lambdainternal.LambdaRTEntry.main(LambdaRTEntry.java:104)
java.lang.IllegalStateException: Cannot initialize context because there is already a root application context present - check whether you have multiple ContextLoader* definitions in your web.xml!
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:262)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:103)
at xx.LambdaSpringApplicationInitializer.notifyStartListeners(LambdaSpringApplicationInitializer.java:184)
at xx.LambdaSpringApplicationInitializer.onStartup(LambdaSpringApplicationInitializer.java:178)
at xx.SpringLambdaContainerHandler.initialize(SpringLambdaContainerHandler.java:197)
at xx.SpringLambdaContainerHandler.handleRequest(SpringLambdaContainerHandler.java:180)
at xx.SpringLambdaContainerHandler.handleRequest(SpringLambdaContainerHandler.java:47)
at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxy(LambdaContainerHandler.java:177)
at com.amazonaws.serverless.proxy.internal.LambdaContainerHandler.proxyStream(LambdaContainerHandler.java:209)
at xx.MyStreamLambdaHandler.handleRequest(MyStreamLambdaHandler.java:32)
at lambdainternal.EventHandlerLoader$2.call(EventHandlerLoader.java:888)
at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:293)
at lambdainternal.AWSLambda.<clinit>(AWSLambda.java:64)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at lambdainternal.LambdaRTEntry.main(LambdaRTEntry.java:104)
END RequestId: 4121d608-9438-4edc-9da9-47a5f90eea70
REPORT RequestId: 4121d608-9438-4edc-9da9-47a5f90eea70	Duration: 882.54 ms	Billed Duration: 900 ms Memory Size: 1024 MB	Max Memory Used: 112 MB	

BTW, I printed the stack trace in the static init block. It's the same for both launches:

07:54:44.880 INFO --- [ main] c.w.c.h.c.MyStreamLambdaHandler : trace: [java.lang.Thread.getStackTrace(Thread.java:1559), xx.MyStreamLambdaHandler.<clinit>(MyStreamLambdaHandler.java:35), java.lang.Class.forName0(Native Method), java.lang.Class.forName(Class.java:348), lambdainternal.HandlerInfo.fromString(HandlerInfo.java:31), lambdainternal.AWSLambda.findUserMethods(AWSLambda.java:93), lambdainternal.AWSLambda.startRuntime(AWSLambda.java:286), lambdainternal.AWSLambda.<clinit>(AWSLambda.java:64), java.lang.Class.forName0(Native Method), java.lang.Class.forName(Class.java:348), lambdainternal.LambdaRTEntry.main(LambdaRTEntry.java:104)]

=============== update
Also needs to initialized = true after initializer.setSpringProfiles(getServletContext(), profiles)
Now the problem disappears again. But it's kinda hard for me to confirm the fix since it's a random issue...
=============== update
If the app is really small (like the demo), then the possibility the issue happens is greatly reduced.
For example, I tried to cold start >10 times, and only get 1 time of problem like this:

03:16:55.234 INFO --- [ main] c.a.s.p.internal.LambdaContainerHandler : Starting Lambda Container Handler
03:16:55.674 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : 1 Spring WebApplicationInitializers detected on classpath

. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.0.6.RELEASE)

03:16:57.643 INFO 1 --- [ main] xx.MyApp : Starting MyApp on ip-10-128-123-138.ap-southeast-1.compute.internal with PID 1 (/var/task started by sbx_user1060 in /)
03:16:57.645 INFO 1 --- [ main] xx.MyApp : The following profiles are active: develop
03:17:00.626 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext
03:17:00.626 INFO 1 --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 2751 ms
03:17:01.367 INFO 1 --- [ main] o.s.b.w.servlet.ServletRegistrationBean : Servlet dispatcherServlet mapped to [/]
03:17:01.369 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'dispatcherServlet'
03:17:01.369 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
03:17:03.221 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 1821 ms
03:17:03.226 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'characterEncodingFilter' to: [/*]
03:17:03.226 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'errorPageFilter' to: [/*]
03:17:03.227 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
03:17:03.227 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'httpPutFormContentFilter' to: [/*]
03:17:03.227 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'requestContextFilter' to: [/*]
START RequestId: 730e90c9-816b-4dc2-a78e-929e0fd19499 Version: $LATEST
03:17:06.004 INFO --- [ main] c.a.s.p.internal.LambdaContainerHandler : Starting Lambda Container Handler
03:17:06.737 INFO --- [ main] c.a.s.p.i.servlet.AwsServletContext : 1 Spring WebApplicationInitializers detected on classpath

. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.0.6.RELEASE)

03:17:09.799 INFO 1 --- [ main] xx.MyApp : Starting MyApp on ip-10-128-123-138.ap-southeast-1.compute.internal with PID 1 (/var/task started by sbx_user1060 in /)
03:17:09.813 INFO 1 --- [ main] xx.MyApp : The following profiles are active: develop
03:17:14.163 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext
03:17:14.164 INFO 1 --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 4200 ms
03:17:15.277 INFO 1 --- [ main] o.s.b.w.servlet.ServletRegistrationBean : Servlet dispatcherServlet mapped to [/]
03:17:15.278 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring DispatcherServlet 'dispatcherServlet'
03:17:15.278 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
03:17:18.022 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : Completed initialization in 2744 ms
03:17:18.025 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'characterEncodingFilter' to: [/*]
03:17:18.041 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'errorPageFilter' to: [/*]
03:17:18.041 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
03:17:18.041 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'httpPutFormContentFilter' to: [/*]
03:17:18.042 INFO 1 --- [ main] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'requestContextFilter' to: [/*]
03:17:19.238 INFO 1 --- [ main] xx.MyApp : Started MyApp in 11.666 seconds (JVM running for 15.354)
03:17:19.481 INFO 1 --- [ main] c.a.s.p.internal.LambdaContainerHandler : 118.201.58.126 - [02/02/2019:03:16:53Z] "GET /contacts/v1/hello HTTP/1.1" 200 11 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36" combined
END RequestId: 730e90c9-816b-4dc2-a78e-929e0fd19499
REPORT RequestId: 730e90c9-816b-4dc2-a78e-929e0fd19499	Duration: 15336.28 ms	Billed Duration: 15400 ms Memory Size: 1024 MB	Max Memory Used: 145 MB	
START RequestId: 86f22afe-131c-4ae1-8afa-3cccc0234f24 Version: $LATEST
03:26:40.498 INFO 1 --- [ main] c.a.s.p.internal.LambdaContainerHandler : 118.201.58.126 - [02/02/2019:03:26:40Z] "GET /contacts/v1/hello HTTP/1.1" 200 11 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36" combined
END RequestId: 86f22afe-131c-4ae1-8afa-3cccc0234f24
REPORT RequestId: 86f22afe-131c-4ae1-8afa-3cccc0234f24	Duration: 35.07 ms	Billed Duration: 100 ms Memory Size: 1024 MB	Max Memory Used: 150 MB	

[sapessi]

Thanks for the report. We have seen this before and we are trying to isolate the root cause. In the meanwhile, a good suggestion to get around the issue came up in #210 - take a look here.

[sapessi]

I think the class loader is a red herring. Since you got the log output twice, it means the static code was executed twice, which in turn means you were running in a new instance of the function. Each instance is completely isolated so you would have a different instance of the class loader.

I'm trying to replicate the issue in a unit test but I'm having little luck. The only way I can make the double-init happen is if I explicitly call the activateSpringProfiles method after I initialized the handler, which is expected behavior. I'll keep you posted.

[sapessi]

Any chance you can share your source code @shuangy92?

[shuangy92]

@sapessi I tested with this project and attached some logs.
I used StaticGenarator to manipulate the boot time.
From my observation, when the DIVIDEND is large, the app has a large chance to boot once, and vice versa. I guess this issue might somehow be related with boot time?

[shuangy92]

I changed the lambda memory size from 1G to 2G, now the app can boot once with DIVIDEND = 10 in 9s.

[sapessi]

thanks @shuangy92 I'll keep testing and trying to replicate. I'll have to push this out to a future release because I want to get 1.3.1 out sooner rather than later.

[Noisyfox]

(Slightliy) more detailed explaination: #210 (comment)

Make sure your static init code runs less than 10 seconds otherwise you will get a dual-init problem. Put the init in the handler callback with a null check like this (by @grsterin):

public class StreamLambdaHandler implements RequestStreamHandler {
    private SpringBootLambdaContainerHandler<AwsProxyRequest, AwsProxyResponse> handler;

    public void handleRequest(InputStream inputStream, OutputStream outputStream, Context context)
            throws IOException {
        if (handler == null) {
            try {
                handler = SpringBootLambdaContainerHandler.getAwsProxyHandler(Application.class);
            } catch (ContainerInitializationException e) {
                e.printStackTrace();
                throw new RuntimeException("Could not initialize Spring Boot application", e);
            }
        }
        handler.proxyStream(inputStream, outputStream, context);
    }
}

[shuangy92]

@Noisyfox I tried this way, but it doesn't reduce my cold start time much. See my quote below.

I also tried to "lazy init" the handler as introduced at #201.
By this way, the application only launches once in handleRequest, but it takes ~30s (~10s for refresh context).

I finally changed the lambda memory size to 3008M (which is the upper limit). Now it works fine.

[shuangy92]

Well just checked the logs. 3008M memory only helps a little. Looks like once the issue happens, then it happens continuously, and vice versa.
One of my lambda (size 72.7M) is now continuously booting twice, but 5 hours ago it was continuously booting once...

[Noisyfox]

One of my lambda (size 72.7M) is now continuously booting twice, but 5 hours ago it was continuously booting once...

Even with the lazy-init approch?

[sapessi]

Hey @Noisyfox, @shuangy92

There is indeed a 10 seconds limit to the init time. If your class takes longer than 10 seconds to instantiate during the Lambda function init it will be automatically restarted.

I see two ways around this. First a radical way:

• Drop Spring/SpringBoot: It is just too slow at starting large applications. If you are looking for performance my recommendation would be to explore Spark with Dagger2. This is not necessarily a criticism of Spring - the framework was built for runtime performance on a stateful machine rather than the fast boot required for Lambda.

Next, something that we could experiment with (I have not tried this myself so it's completely untested at the moment, just an idea off the top of my head):

• Instead of using a static block to initialize the handler and Spring application, use the constructor. From the constructor, spawn a separate thread that performs the initialization of the app. In the constructor itself, wait for a few seconds (<10 seconds) so that you still take advantage of the performance boost. Then, use a latch to have the handleRequest method wait until the initialization of the framework in the separate thread completes before making the first proxy call.