Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reinitialization of Spring context when using SnapStart #805

Closed
maschnetwork opened this issue Mar 19, 2024 · 3 comments
Closed

Reinitialization of Spring context when using SnapStart #805

maschnetwork opened this issue Mar 19, 2024 · 3 comments
Assignees

Comments

@maschnetwork
Copy link
Collaborator

To help us debug your issue fill in the basic information below using the options provided

Serverless Java Container version: 2.0.0

Implementations: Spring Boot 3

Framework version: SpringBoot 3.1.4 (or higher)

Frontend service: REST API

Deployment method: CDK

Scenario

During the first call to a SnapStart enabled Lambda function the Spring Context re-initializes which results in a high request duration of around 4-5 seconds for a standard Spring Boot Application (accessing a PostgreSQL DB). In prior versions (tested with 2.0.0-M2) this does not happen and the request duration is much faster (1-2 seconds). There seems to be an issue with the latest version and how the initialization of the context is handled.

Expected behavior

The Spring context should not re-initialize as it should be stored within the SnapShot.

Actual behavior

The spring context re-initializes

Steps to reproduce

  • Enable SnapStart on a function with the Serverless Java Container v 2.0.0
  • See how the Spring Context is re-intitialized in the logs and the restore takes 4+ seconds
  • Create a new function version with previous Serverless Java Container v 2.0.0-M2
  • No context re-intitialization and fast startup within 1-2 seconds

Full log output

Paste the full log output from the Lambda function's CloudWatch logs

With 2.0.0 (Issue - Spring context re-initializes):


2024-03-19T15:19:30.178Z | RESTORE_START Runtime Version: java:17.v23 Runtime Version ARN: arn:aws:lambda:eu-central-1::runtime:4fa911b5b8e2bf34f399aa1563b223204a0d0ab2cbfdeba6cd2132baa63f075f
-- | --
  | 2024-03-19T15:19:31.313Z | RESTORE_REPORT Restore Duration: 1134.71 ms
  | 2024-03-19T15:19:31.319Z | START RequestId: 6c3bxX18-8fb4-47c4-9cba-7739840aeaa3 Version: 1
  | 2024-03-19T15:19:31.966Z | . ____ _ __ _ _
  | 2024-03-19T15:19:31.966Z | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
  | 2024-03-19T15:19:31.966Z | ( ( )\___ \| '_ \| '_\| \| '_ \/ _` \| \ \ \ \
  | 2024-03-19T15:19:31.966Z | \\/ ___)\| \|_)\| \| \| \| \| \|\| (_\| \| ) ) ) )
  | 2024-03-19T15:19:31.966Z | ' \|____\| .__\|_\| \|_\|_\| \|_\__, \| / / / /
  | 2024-03-19T15:19:31.966Z | =========\|_\|==============\|___/=/_/_/_/
  | 2024-03-19T15:19:31.970Z | :: Spring Boot :: (v3.2.3)
  | 2024-03-19T15:19:32.094Z | 2024-03-19T15:19:32.093Z INFO 8 --- [ Thread-0] c.a.s.p.s.AwsSpringWebRuntimeInitializer : AWS Handler: com.amazonaws.serverless.proxy.spring.SpringDelegatingLambdaContainerHandler
  | 2024-03-19T15:19:32.104Z | 2024-03-19T15:19:32.103Z INFO 8 --- [ Thread-0] o.s.boot.SpringApplication : Starting application using Java 17.0.10 with PID 8 (started by sbx_user1051 in /var/task)
  | 2024-03-19T15:19:32.105Z | 2024-03-19T15:19:32.105Z INFO 8 --- [ Thread-0] o.s.boot.SpringApplication : No active profile set, falling back to 1 default profile: "default"
  | 2024-03-19T15:19:32.773Z | 2024-03-19T15:19:32.773Z INFO 8 --- [ Thread-0] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
  | 2024-03-19T15:19:32.824Z | 2024-03-19T15:19:32.823Z INFO 8 --- [ Thread-0] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 39 ms. Found 1 JPA repository interface.
  | 2024-03-19T15:19:33.163Z | 2024-03-19T15:19:33.163Z INFO 8 --- [ Thread-0] o.s.c.f.s.w.ServerlessAutoConfiguration : Configuring Serverless Web Container
  | 2024-03-19T15:19:33.268Z | 2024-03-19T15:19:33.267Z INFO 8 --- [ Thread-0] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
  | 2024-03-19T15:19:33.630Z | 2024-03-19T15:19:33.630Z INFO 8 --- [ Thread-0] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@21d01d84
  | 2024-03-19T15:19:33.632Z | 2024-03-19T15:19:33.631Z INFO 8 --- [ Thread-0] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
  | 2024-03-19T15:19:33.667Z | 2024-03-19T15:19:33.667Z INFO 8 --- [ Thread-0] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
  | 2024-03-19T15:19:33.711Z | 2024-03-19T15:19:33.711Z INFO 8 --- [ Thread-0] org.hibernate.Version : HHH000412: Hibernate ORM core version [WORKING]
  | 2024-03-19T15:19:33.739Z | 2024-03-19T15:19:33.739Z INFO 8 --- [ Thread-0] o.h.c.internal.RegionFactoryInitiator : HHH000026: Second-level cache disabled
  | 2024-03-19T15:19:33.932Z | 2024-03-19T15:19:33.932Z INFO 8 --- [ Thread-0] o.s.o.j.p.SpringPersistenceUnitInfo : No LoadTimeWeaver setup: ignoring JPA class transformer
  | 2024-03-19T15:19:33.978Z | 2024-03-19T15:19:33.977Z WARN 8 --- [ Thread-0] org.hibernate.orm.deprecation : HHH90000025: PostgreSQLDialect does not need to be specified explicitly using 'hibernate.dialect' (remove the property setting and it will be selected by default)
  | 2024-03-19T15:19:34.699Z | 2024-03-19T15:19:34.699Z INFO 8 --- [ Thread-0] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000489: No JTA platform available (set 'hibernate.transaction.jta.platform' to enable JTA platform integration)
  | 2024-03-19T15:19:34.702Z | 2024-03-19T15:19:34.702Z INFO 8 --- [ Thread-0] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
  | 2024-03-19T15:19:35.246Z | 2024-03-19T15:19:35.246Z INFO 8 --- [ Thread-0] o.s.c.f.s.web.ServerlessServletContext : Initializing Spring DispatcherServlet 'dispatcherServlet'
  | 2024-03-19T15:19:35.246Z | 2024-03-19T15:19:35.246Z INFO 8 --- [ Thread-0] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
  | 2024-03-19T15:19:35.248Z | 2024-03-19T15:19:35.248Z INFO 8 --- [ Thread-0] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
  | 2024-03-19T15:19:35.248Z | 2024-03-19T15:19:35.248Z INFO 8 --- [ Thread-0] o.s.c.f.s.w.ServerlessAutoConfiguration : Initalized DispatcherServlet
  | 2024-03-19T15:19:35.264Z | 2024-03-19T15:19:35.264Z INFO 8 --- [ Thread-0] o.s.boot.SpringApplication : Started application in 222.596 seconds (process running for 5.694)
  | 2024-03-19T15:19:35.267Z | 2024-03-19T15:19:35.267Z INFO 8 --- [ Thread-0] o.s.c.f.serverless.web.ServerlessMVC : Application is started successfully.
  | 2024-03-19T15:19:35.496Z | END RequestId: 6c3bxX18-8fb4-47c4-9cba-7739840aeaa3
  | 2024-03-19T15:19:35.496ZREPORT RequestId: 6c3bxX18-8fb4-47c4-9cba-7739840aeaa3	Duration: 4177.34 ms	Billed Duration: 4410 ms	Memory Size: 2048 MB	Max Memory Used: 211 MB	Restore Duration: 1134.71 ms	Billed Restore Duration: 232 ms


With 2.0.0-M2 (No Issue ):

2024-03-19T16:26:58.348Z | RESTORE_START Runtime Version: java:17.v23 Runtime Version ARN: arn:aws:lambda:eu-central-1::runtime:4fa911b5b8e2bf34f399aa1563b223204a0d0ab2cbfdeba6cd2132baa63f075f
-- | --
  | 2024-03-19T16:26:59.522Z | RESTORE_REPORT Restore Duration: 1174.67 ms
  | 2024-03-19T16:26:59.530Z | START RequestId: cd612f79-c02e-4b13-9a0b-dd4445855d3c Version: 3
  | 2024-03-19T16:27:00.001Z | END RequestId: cd612f79-c02e-4b13-9a0b-dd4445855d3c
  | 2024-03-19T16:27:00.001ZREPORT RequestId: cd612f79-c02e-4b13-9a0b-dd4445855d3c	Duration: 470.48 ms	Billed Duration: 744 ms	Memory Size: 2048 MB	Max Memory Used: 208 MB	Restore Duration: 1174.67 ms	Billed Restore Duration: 273 ms
@mbfreder
Copy link
Contributor

Thanks for raising this. Let me reproduce and get back to you.

@mbfreder mbfreder assigned mbfreder and olegz and unassigned mbfreder Mar 19, 2024
olegz added a commit to olegz/aws-serverless-java-container that referenced this issue Mar 26, 2024
Also updated to s-c-function-serverless-webb 4.1.1-SNAPSHOT
This commit forces wait for full context initialization if context is created during snapstart creation
@deki
Copy link
Collaborator

deki commented Apr 4, 2024

@maschnetwork changes have been merged to the main branch in case you want to verify. A release will probably done tomorrow.

@deki
Copy link
Collaborator

deki commented Apr 8, 2024

Release 2.0.1 is now available.

@deki deki closed this as completed Apr 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants