Closed shuangy92 closed 4 years ago
sapessi
commented
5 years ago 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
commented
5 years ago 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
commented
5 years ago Any chance you can share your source code @shuangy92?
shuangy92
commented
5 years ago @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
commented
5 years ago I changed the lambda memory size from 1G to 2G, now the app can boot once with DIVIDEND = 10 in 9s.
sapessi
commented
5 years ago 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
commented
5 years ago (Slightliy) more detailed explaination: https://github.com/awslabs/aws-serverless-java-container/issues/210#issuecomment-467319453
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);
}
}@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
commented
5 years ago 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
commented
5 years ago 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
commented
5 years ago 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:
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):
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. sapessi
commented
5 years ago I will implement solution #2, using a separate thread to make the most of the 10 seconds of initialization time, releasing the initialization latch when the ten seconds are over to allow Lambda to continue and use a second latch to hold the handler until the Spring application is initialized. I will make this an optional feature.
Noisyfox
commented
5 years ago That sounds very promising!
sapessi
commented
5 years ago This is on its way in release 1.4. See my last comment on #210
sapessi
commented
4 years ago Release 1.4 is out on maven central. The release notes include a list of all the changes. Closing this issue.
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 outo.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
SpringBootLambdaContainerHandlerwas entered twice. I also tried to declareSpringBootLambdaContainerHandleras a member attribute ofMyStreamLambdaHandler, 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:
The result is here: First launch:
Second luanch:
As you can see, it's super weird that the same
AppClassLoaderhas differentExtClassLoaderas 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
ExceptionInInitializerErrordirectly. The log is here:But if I get rid of profile, the application launches once only.
I looked into the codes, and found that
initilizer.onStartupwas 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:
BTW, I printed the stack trace in the static init block. It's the same for both launches:
=============== update Also needs to
initialized = trueafter 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: