search

aws / serverless-java-container

A Java wrapper to run Spring, Spring Boot, Jersey, and other apps inside AWS Lambda.
https://aws.amazon.com/serverless/
Apache License 2.0
1.5k stars 560 forks source link

Request timing out #177

Closed LarsKoelpin closed 6 years ago

LarsKoelpin commented 6 years ago

Scenario

I'm trying to migrate my Sprintboot App to AWS Lambda, using aws-serverless-java-container-spring version 1.1.3.

  1. I uploaded my application.jar to S3
  2. I created a lambda function with starting class de.lambda.LambdaApp
  3. I test using the following event 
    {
"body": "",
"resource": "/jsonrpc",
"requestContext": {
"resourceId": "123456",
"apiId": "1234567890",
"resourcePath": "/jsonrpc",
"httpMethod": "POST",
"requestId": "c6af9ac6-7b61-11e6-9a41-93e8deadbeef",
"accountId": "123456789012",
"identity": {
  "apiKey": null,
  "userArn": null,
  "cognitoAuthenticationType": null,
  "caller": null,
  "userAgent": "Custom User Agent String",
  "user": null,
  "cognitoIdentityPoolId": null,
  "cognitoIdentityId": null,
  "cognitoAuthenticationProvider": null,
  "sourceIp": "127.0.0.1",
  "accountId": null
},
"stage": "prod"
},
"queryStringParameters": {},
"headers": {
"Via": "1.1 08f323deadbeefa7af34d5feb414ce27.cloudfront.net (CloudFront)",
"Accept-Language": "en-US,en;q=0.8",
"Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8",
"User-Agent": "Custom User Agent String",
"Accept-Encoding": "gzip, deflate, sdch"
},
"pathParameters": {
"proxy": "hello"
},
"httpMethod": "POST",
"stageVariables": {},
"path": "/jsonrpc"
}

Expected behavior

My Lambda function exits the request.

Actual behavior

It seems like my Spring application gets started, but never handles the request. (https://github.com/LarsKoelpin/springboot-aws-timeout/blob/58c271767a740315e92ad7a16334cabbfc210634/1-configuration/src/main/java/de/lambda/LambdaApp.java#L35 never gets invoked)

Steps to reproduce

I created a repository at https://github.com/LarsKoelpin/springboot-aws-timeout

Full log output

Cloudwatch

[2018-08-01 13:10:40.776] NO-REQUEST-ID INFO d.l.LambdaApp - INITIALIZING HANDLER [2018-08-01 13:10:41.099] NO-REQUEST-ID INFO c.a.s.p.i.LambdaContainerHandler - Starting Lambda Container Handler [2018-08-01 13:10:41.387] NO-REQUEST-ID INFO c.a.s.p.i.s.AwsServletContext - 1 Spring WebApplicationInitializers detected on classpath

13:10:42
. ____ _ __ _ _

13:10:42
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \

13:10:42
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \

13:10:42
\\/ ___)| |_)| | | | | || (_| | ) ) ) )

13:10:42
' |____| .__|_| |_|_| |_\__, | / / / /

13:10:42
=========|_|==============|___/=/_/_/_/

13:10:42
:: Spring Boot ::

13:10:43
2018-08-01 13:10:43.140 INFO 1 --- [ main] de.lambda.Application : Starting Application on ip-10-11-112-32.eu-central-1.compute.internal with PID 1 (/var/task started by sbx_user1068 in /)

13:10:43
2018-08-01 13:10:43.143 INFO 1 --- [ main] de.lambda.Application : No active profile set, falling back to default profiles: default

13:10:43
2018-08-01 13:10:43.439 INFO 1 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@17ed40e0: startup date [Wed Aug 01 13:10:43 UTC 2018]; root of context hierarchy

13:10:47
2018-08-01 13:10:47.210 INFO 1 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$d6b2b1e1] is not eligible for getting processed by all BeanPostProcessors (for example: not eligi

13:10:47
2018-08-01 13:10:47.348 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext

13:10:47
2018-08-01 13:10:47.348 INFO 1 --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 3911 ms

13:10:48
2018-08-01 13:10:48.241 INFO 1 --- [ main] o.s.b.w.servlet.ServletRegistrationBean : Servlet dispatcherServlet mapped to [/]

13:10:48
2018-08-01 13:10:48.259 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring FrameworkServlet 'dispatcherServlet'

13:10:48
2018-08-01 13:10:48.259 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started

13:10:48
2018-08-01 13:10:48.758 INFO 1 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]

13:10:49
2018-08-01 13:10:49.559 WARN 1 --- [ main] aWebConfiguration$JpaWebMvcConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning

13:10:50
2018-08-01 13:10:50.060 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...

13:10:50
2018-08-01 13:10:50.463 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.

13:10:50
START RequestId: 49af85f0-958c-11e8-88e8-7da03f260b4a Version: $LATEST

13:10:52
[2018-08-01 13:10:51.760] NO-REQUEST-ID INFO d.l.LambdaApp - INITIALIZING HANDLER

13:10:54
[2018-08-01 13:10:53.377] NO-REQUEST-ID INFO c.a.s.p.i.LambdaContainerHandler - Starting Lambda Container Handler

13:10:55
[2018-08-01 13:10:54.878] NO-REQUEST-ID INFO c.a.s.p.i.s.AwsServletContext - 1 Spring WebApplicationInitializers detected on classpath

13:11:00
. ____ _ __ _ _

13:11:00
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \

13:11:00
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \

13:11:00
\\/ ___)| |_)| | | | | || (_| | ) ) ) )

13:11:00
' |____| .__|_| |_|_| |_\__, | / / / /

13:11:00
=========|_|==============|___/=/_/_/_/

13:11:00
:: Spring Boot ::

13:11:00
END RequestId: 49af85f0-958c-11e8-88e8-7da03f260b4a

13:11:00
REPORT RequestId: 49af85f0-958c-11e8-88e8-7da03f260b4a  Duration: 10002.90 ms   Billed Duration: 10000 ms Memory Size: 320 MB   Max Memory Used: 77 MB

13:11:00
2018-08-01T13:11:00.804Z 49af85f0-958c-11e8-88e8-7da03f260b4a Task timed out after 10.00 seconds

13:11:00

13:11:02
[2018-08-01 13:11:01.245] NO-REQUEST-ID INFO d.l.LambdaApp - INITIALIZING HANDLER [2018-08-01 13:11:01.586] NO-REQUEST-ID INFO c.a.s.p.i.LambdaContainerHandler - Starting Lambda Container Handler [2018-08-01 13:11:01.881] NO-REQUEST-ID INFO c.a.s.p.i.s.AwsServletContext - 1 Spring WebApplicationInitializers detected on classpath

13:11:03
. ____ _ __ _ _

13:11:03
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \

13:11:03
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \

13:11:03
\\/ ___)| |_)| | | | | || (_| | ) ) ) )

13:11:03
' |____| .__|_| |_|_| |_\__, | / / / /

13:11:03
=========|_|==============|___/=/_/_/_/

13:11:03
:: Spring Boot ::

13:11:03
2018-08-01 13:11:03.644 INFO 1 --- [ main] de.lambda.Application : Starting Application on ip-10-11-112-32.eu-central-1.compute.internal with PID 1 (/var/task started by sbx_user1068 in /)

13:11:03
2018-08-01 13:11:03.646 INFO 1 --- [ main] de.lambda.Application : No active profile set, falling back to default profiles: default

13:11:03
2018-08-01 13:11:03.937 INFO 1 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@33e5ccce: startup date [Wed Aug 01 13:11:03 UTC 2018]; root of context hierarchy

13:11:07
2018-08-01 13:11:07.706 INFO 1 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$9ffdba35] is not eligible for getting processed by all BeanPostProcessors (for example: not eligi

13:11:07
2018-08-01 13:11:07.883 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring embedded WebApplicationContext

13:11:07
2018-08-01 13:11:07.883 INFO 1 --- [ main] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 3980 ms

13:11:08
2018-08-01 13:11:08.701 INFO 1 --- [ main] o.s.b.w.servlet.ServletRegistrationBean : Servlet dispatcherServlet mapped to [/]

13:11:08
2018-08-01 13:11:08.703 INFO 1 --- [ main] c.a.s.p.i.servlet.AwsServletContext : Initializing Spring FrameworkServlet 'dispatcherServlet'

13:11:08
2018-08-01 13:11:08.704 INFO 1 --- [ main] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started

13:11:08
2018-08-01 13:11:08.927 INFO 1 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]

13:11:09
2018-08-01 13:11:09.364 WARN 1 --- [ main] aWebConfiguration$JpaWebMvcConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning

13:11:10
2018-08-01 13:11:10.403 INFO 1 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...

Lambda

START RequestId: 49af85f0-958c-11e8-88e8-7da03f260b4a Version: $LATEST
[2018-08-01 13:10:51.760] NO-REQUEST-ID INFO d.l.LambdaApp - INITIALIZING HANDLER 
[2018-08-01 13:10:53.377] NO-REQUEST-ID INFO c.a.s.p.i.LambdaContainerHandler - Starting Lambda Container Handler 
[2018-08-01 13:10:54.878] NO-REQUEST-ID INFO c.a.s.p.i.s.AwsServletContext - 1 Spring WebApplicationInitializers detected on classpath 
  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                        

END RequestId: 49af85f0-958c-11e8-88e8-7da03f260b4a
REPORT RequestId: 49af85f0-958c-11e8-88e8-7da03f260b4a  Duration: 10002.90 ms   Billed Duration: 10000 ms   Memory Size: 320 MB Max Memory Used: 77 MB  
2018-08-01T13:11:00.804Z 49af85f0-958c-11e8-88e8-7da03f260b4a Task timed out after 10.00 seconds

What I tried

Any help would be appreciated :)

sapessi commented 6 years ago

Hi @LarsKoelpin, looks like the cold start is genuinely timing out after 10 seconds. the quick fix is obviously to increase the timeout for the Lambda function to 30 seconds. I understand that this cold start time is definitely not desirable. We need to try and figure out where Spring is spending all the time. We have a bunch of cold start tips in the getting started guide. The first thing I would try in your case is replace the @ComponentScan annotation with direct @Import statements for the specific classes you need.

Unfortunately the amount of introspection Spring does is counter-productive in a Lambda environment where resources are limited and start time matters. The good news is that with real production traffic cold starts should only impact 1% of less of all requests.

LarsKoelpin commented 6 years ago

Hey @SAPessi thanks for your response.

As the example is just a part of the app (I tested with my "real" App, in which 30 seconds timeout isn't even suffiecient, so increasing the timeout is obviously not an option). I thought Spring indexing would be enough. I'll try the Import Method for now. Do you think JPA could be the bottleneck here (I'm also shipping H2, which could be as problem aswell)?

However I think it's not related to aws-serverless-java-container and its my own fault, so I'm going to close this issue. If I'm mistaken feel free to reopen this issue.

sapessi commented 6 years ago

Hey @LarsKoelpin, I'll keep this open for now as changes to the library may come from this investigation as well as updates to the documentation.

The primary challenge here is that while a Lambda function can have a timeout of 5 minutes, API Gateway has a hard timeout of 30 seconds. In practice, this means that the first request coming in will trigger a cold start in Lambda. However, if your application takes longer than 30 seconds to start, API Gateway will return a 504 error. Meanwhile, in the background, Lambda will finish starting up the app so that following requests will be successful.

This is obviously not ideal so our goal should be to reduce the "cold start" time for your API to less than 30 seconds - ideally much, much less than that.

What have you tried so far?

LarsKoelpin commented 6 years ago

Hey @SAPessi I updated my Test Application to use a real RDS Postgres instance and removed any h2 related dependencies while using the Import Annotation. Unfortunately had no success, in fact even increasing the timeout to more than 90 seconds (1400mb RAM, 1min 30s timeout).

I don't think the API Gateway should not be a problem, since it is a test event, I guess?

edit: Removing Spring-data-jpa completely reduced startup time to ~500ms