かんがるーさんの日記

最近自分が興味をもったものを調べた時の手順等を書いています。今は Spring Boot をいじっています。

Spring Boot 2.1.x の Web アプリを 2.2.x へバージョンアップする ( その１２ )( spring.main.lazy-initialization を試してみる )

概要

記事一覧はこちらです。

Spring Boot 2.1.x の Web アプリを 2.2.x へバージョンアップする ( その１１ )( Docker コンテナの image をバージョンアップする ) の続きです。

  • 今回の手順で確認できるのは以下の内容です。
    • Bean の生成タイミングを起動時ではなく必要になったタイミングにすることで起動時間を短縮するための spring.main.lazy-initialization という設定項目が追加されたので、どのくらい短縮できるのか試してみます。

参照したサイト・書籍

目次

  1. jar ファイルを作成して起動時間を短縮するためのオプションなしで実行してみる
  2. -Dspring.main.lazy-initialization=true を追加してみる
  3. -XX:TieredStopAtLevel=1 も追加してみる
  4. Multiple Spring Data modules found, entering strict repository configuration mode! とは？
  5. s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing のログがなぜ出力されるのか？
  6. -Dspring.main.lazy-initialization=true を設定すると /actuator/health が何も返さなくなる！？
  7. 最後に

手順

jar ファイルを作成して起動時間を短縮するためのオプションなしで実行してみる

まずは ksbysample-webapp-lending-2.2.2-RELEASE.jar を作成して、起動時間を短縮するためのオプションは何もつけない以下のコマンドで起動してみます。

set JAVA_HOME=D:\Java\jdk-11.0.5+10
set PATH=%JAVA_HOME%\bin;%PATH%
set WEBAPP_HOME=D:\webapps\ksbysample-webapp-lending
set WEBAPP_JAR=ksbysample-webapp-lending-2.2.2-RELEASE.jar
set LOGS_DIR=%WEBAPP_HOME%\logs
set PATH_HEAPDUMPFILE=%LOGS_DIR%\heapdump.hprof
set PATH_ERRORFILE=%LOGS_DIR%\hs_err.log

java -Xms1024m -Xmx1024m ^
     -XX:MaxMetaspaceSize=384m ^
     -XX:+UseG1GC ^
     -Xlog:gc*=debug:logs/gc.log:time,level,tags:filesize=10m,filecount=5 ^
     -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%PATH_HEAPDUMPFILE% ^
     -XX:+CrashOnOutOfMemoryError ^
     -XX:ErrorFile=%PATH_ERRORFILE% ^
     -Dsun.net.inetaddr.ttl=100 ^
     -Dspring.profiles.active=product ^
     -jar lib\%WEBAPP_JAR%

５回実行して Started Application in ... seconds に表示された時間は 14.955、15.53、16.493、15.992、15.773（平均 15.7486）でした。

14.955 の時の Starting Application on ... ～ Started Application in ... seconds までのログは以下のものでした。

2020-01-08 00:29:58.925  INFO 9200 --- [main] ksbysample.webapp.lending.Application    : Starting Application on PC-02 with PID 9200 (D:\webapps\ksbysample-webapp-lending\lib\ksbysample-webapp-lending-2.2.2-RELEASE.jar started by root in D:\webapps\ksbysample-webapp-lending)
2020-01-08 00:29:58.929  INFO 9200 --- [main] ksbysample.webapp.lending.Application    : The following profiles are active: product
2020-01-08 00:30:01.018  INFO 9200 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2020-01-08 00:30:01.021  INFO 9200 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data Redis repositories in DEFAULT mode.
2020-01-08 00:30:01.084  INFO 9200 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 41ms. Found 0 Redis repository interfaces.
2020-01-08 00:30:01.938  INFO 9200 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor#0' of type [org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 00:30:02.010  INFO 9200 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 00:30:02.593  INFO 9200 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration' of type [org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 00:30:02.602  INFO 9200 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'objectPostProcessor' of type [org.springframework.security.config.annotation.configuration.AutowireBeanFactoryObjectPostProcessor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 00:30:02.611  INFO 9200 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler@6d1310f6' of type [org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 00:30:02.615  INFO 9200 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration' of type [org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 00:30:02.641  INFO 9200 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'methodSecurityMetadataSource' of type [org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 00:30:03.758  INFO 9200 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-01-08 00:30:03.783  INFO 9200 --- [main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-01-08 00:30:03.783  INFO 9200 --- [main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.29]
2020-01-08 00:30:03.884  INFO 9200 --- [main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-01-08 00:30:03.884  INFO 9200 --- [main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 4848 ms
2020-01-08 00:30:04.743  INFO 9200 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService
2020-01-08 00:30:07.902  INFO 9200 --- [main] io.lettuce.core.EpollProvider            : Starting without optional epoll library
2020-01-08 00:30:07.905  INFO 9200 --- [main] io.lettuce.core.KqueueProvider           : Starting without optional kqueue library
2020-01-08 00:30:09.538  INFO 9200 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-01-08 00:30:10.537  INFO 9200 --- [main] o.f.c.internal.license.VersionPrinter    : Flyway Community Edition 6.1.3 by Redgate
2020-01-08 00:30:10.549  INFO 9200 --- [main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2020-01-08 00:30:10.759  INFO 9200 --- [main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2020-01-08 00:30:10.804  INFO 9200 --- [main] o.f.c.internal.database.DatabaseFactory  : Database: jdbc:postgresql://localhost/ksbylending (PostgreSQL 12.1)
2020-01-08 00:30:10.864  INFO 9200 --- [main] o.f.core.internal.command.DbValidate     : Successfully validated 2 migrations (execution time 00:00.033s)
2020-01-08 00:30:10.885  INFO 9200 --- [main] o.f.core.internal.command.DbMigrate      : Current version of schema "public": 1.1
2020-01-08 00:30:10.887  INFO 9200 --- [main] o.f.core.internal.command.DbMigrate      : Schema "public" is up to date. No migration necessary.
2020-01-08 00:30:11.364  INFO 9200 --- [main] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: org.springframework.boot.actuate.autoconfigure.security.servlet.EndpointRequest$EndpointRequestMatcher@2484dbb7, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@111cba40, org.springframework.security.web.context.SecurityContextPersistenceFilter@696fad31, org.springframework.security.web.header.HeaderWriterFilter@4652c74d, org.springframework.security.web.csrf.CsrfFilter@238291d4, org.springframework.security.web.authentication.logout.LogoutFilter@6ad6443, org.springframework.security.web.authentication.www.BasicAuthenticationFilter@55296b50, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@3c18942, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@2c48cede, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@48e41b5d, org.springframework.security.web.session.SessionManagementFilter@5ea7bc4, org.springframework.security.web.access.ExceptionTranslationFilter@c48b543, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@77083e41]
2020-01-08 00:30:11.419  INFO 9200 --- [main] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: any request, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@5c448ef, org.springframework.security.web.context.SecurityContextPersistenceFilter@4a31ed12, org.springframework.security.web.header.HeaderWriterFilter@11810917, org.springframework.security.web.csrf.CsrfFilter@75bd28d, org.springframework.security.web.authentication.logout.LogoutFilter@49232c6f, org.springframework.security.web.authentication.UsernamePasswordAuthenticationFilter@5fb54740, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@3ab595c8, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@2365ea38, org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter@1ee40b5c, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@703e8050, org.springframework.security.web.session.SessionManagementFilter@13278a41, org.springframework.security.web.access.ExceptionTranslationFilter@129c4d19, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@5e3db14]
2020-01-08 00:30:11.676  INFO 9200 --- [main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 4 endpoint(s) beneath base path '/actuator'
2020-01-08 00:30:12.364  INFO 9200 --- [main] o.s.a.r.c.CachingConnectionFactory       : Attempting to connect to: [localhost:5672]
2020-01-08 00:30:12.464  INFO 9200 --- [main] o.s.a.r.c.CachingConnectionFactory       : Created new connection: rabbitConnectionFactory#70f31322:0/SimpleConnection@33d230ce [delegate=amqp://rabbitmq@127.0.0.1:5672/, localPort= 56784]
2020-01-08 00:30:12.469  INFO 9200 --- [main] o.s.amqp.rabbit.core.RabbitAdmin         : Auto-declaring a non-durable, auto-delete, or exclusive Queue (InquiringStatusOfBookQueue) durable:false, auto-delete:false, exclusive:false. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
2020-01-08 00:30:12.557  INFO 9200 --- [main] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing
2020-01-08 00:30:12.605  INFO 9200 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2020-01-08 00:30:12.610  INFO 9200 --- [main] ksbysample.webapp.lending.Application    : Started Application in 14.955 seconds (JVM running for 15.936)

時間がかかっていると思われる箇所を取り出してみました。

  • 2020-01-08 00:30:01.018 INFO 9200 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!（約2秒）
  • 2020-01-08 00:30:03.758 INFO 9200 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)（約1秒）
  • 2020-01-08 00:30:04.743 INFO 9200 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService（約1秒）
  • 2020-01-08 00:30:07.902 INFO 9200 --- [main] io.lettuce.core.EpollProvider : Starting without optional epoll library（約3秒）
  • 2020-01-08 00:30:09.538 INFO 9200 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService 'applicationTaskExecutor'（約1.5秒）
  • 2020-01-08 00:30:10.537 INFO 9200 --- [main] o.f.c.internal.license.VersionPrinter : Flyway Community Edition 6.1.3 by Redgate（約1秒）
  • 2020-01-08 00:30:12.364 INFO 9200 --- [main] o.s.a.r.c.CachingConnectionFactory : Attempting to connect to: [localhost:5672]（約0.7秒）

-Dspring.main.lazy-initialization=true を追加してみる

今度は -Dspring.main.lazy-initialization=true を追加した以下のコマンドで起動してみます。

java -Xms1024m -Xmx1024m ^
     -XX:MaxMetaspaceSize=384m ^
     -XX:+UseG1GC ^
     -Xlog:gc*=debug:logs/gc.log:time,level,tags:filesize=10m,filecount=5 ^
     -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%PATH_HEAPDUMPFILE% ^
     -XX:+CrashOnOutOfMemoryError ^
     -XX:ErrorFile=%PATH_ERRORFILE% ^
     -Dsun.net.inetaddr.ttl=100 ^
     -Dspring.profiles.active=product ^
     -Dspring.main.lazy-initialization=true ^
     -jar lib\%WEBAPP_JAR%

５回実行して Started Application in ... seconds に表示された時間は 11.479、12.201、12.216、11.865、11.346（平均 11.8214、▼3.9272）でした。

2020-01-08 23:24:29.483  INFO 20304 --- [main] ksbysample.webapp.lending.Application    : Starting Application on PC-02 with PID 20304 (D:\webapps\ksbysample-webapp-lending\lib\ksbysample-webapp-lending-2.2.2-RELEASE.jar started by root in D:\webapps\ksbysample-webapp-lending)
2020-01-08 23:24:29.486  INFO 20304 --- [main] ksbysample.webapp.lending.Application    : The following profiles are active: product
2020-01-08 23:24:31.506  INFO 20304 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2020-01-08 23:24:31.510  INFO 20304 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data Redis repositories in DEFAULT mode.
2020-01-08 23:24:31.578  INFO 20304 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 43ms. Found 0 Redis repository interfaces.
2020-01-08 23:24:32.455  INFO 20304 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor#0' of type [org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:24:32.529  INFO 20304 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:24:33.135  INFO 20304 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration' of type [org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:24:33.150  INFO 20304 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'objectPostProcessor' of type [org.springframework.security.config.annotation.configuration.AutowireBeanFactoryObjectPostProcessor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:24:33.163  INFO 20304 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler@3228d990' of type [org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:24:33.168  INFO 20304 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration' of type [org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:24:33.191  INFO 20304 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'methodSecurityMetadataSource' of type [org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:24:34.314  INFO 20304 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-01-08 23:24:34.361  INFO 20304 --- [main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-01-08 23:24:34.362  INFO 20304 --- [main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.29]
2020-01-08 23:24:34.549  INFO 20304 --- [main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-01-08 23:24:34.550  INFO 20304 --- [main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 4954 ms
2020-01-08 23:24:35.506  INFO 20304 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService
2020-01-08 23:24:37.141  INFO 20304 --- [springSessionRedisMessageListenerContainer-1] io.lettuce.core.EpollProvider            : Starting without optional epoll library
2020-01-08 23:24:37.143  INFO 20304 --- [springSessionRedisMessageListenerContainer-1] io.lettuce.core.KqueueProvider           : Starting without optional kqueue library
2020-01-08 23:24:39.653  INFO 20304 --- [main] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing
2020-01-08 23:24:39.715  INFO 20304 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2020-01-08 23:24:39.724  INFO 20304 --- [main] ksbysample.webapp.lending.Application    : Started Application in 11.479 seconds (JVM running for 12.281)

時間がかかっていると思われる箇所を取り出してみました。★は１回目と比較して再度出てきたログに付けています。

  • 2020-01-08 23:24:31.506 INFO 20304 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!（約2秒★★）
  • 2020-01-08 23:24:32.455 INFO 20304 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor#0' of type [org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)（約1秒）
  • 2020-01-08 23:24:34.314 INFO 20304 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)（約1秒★★）
  • 2020-01-08 23:24:35.506 INFO 20304 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService（約1秒★★）
  • 2020-01-08 23:24:37.141 INFO 20304 --- [springSessionRedisMessageListenerContainer-1] io.lettuce.core.EpollProvider : Starting without optional epoll library（約1.5秒★★）
  • 2020-01-08 23:24:39.653 INFO 20304 --- [main] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing（約2.5秒）

-XX:TieredStopAtLevel=1 も追加してみる

更に -XX:TieredStopAtLevel=1 を追加した以下のコマンドで起動してみます。

java -Xms1024m -Xmx1024m ^
     -XX:MaxMetaspaceSize=384m ^
     -XX:+UseG1GC ^
     -Xlog:gc*=debug:logs/gc.log:time,level,tags:filesize=10m,filecount=5 ^
     -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%PATH_HEAPDUMPFILE% ^
     -XX:+CrashOnOutOfMemoryError ^
     -XX:ErrorFile=%PATH_ERRORFILE% ^
     -Dsun.net.inetaddr.ttl=100 ^
     -Dspring.profiles.active=product ^
     -Dspring.main.lazy-initialization=true ^
     -XX:TieredStopAtLevel=1 ^
     -jar lib\%WEBAPP_JAR%

５回実行して Started Application in ... seconds に表示された時間は 8.757、9.071、9.106、9.106、8.628（平均 8.9336、１回目から▼6.815、２回目から▼2.8878）でした。

2020-01-08 23:44:56.490  INFO 2728 --- [main] ksbysample.webapp.lending.Application    : Starting Application on PC-02 with PID 2728 (D:\webapps\ksbysample-webapp-lending\lib\ksbysample-webapp-lending-2.2.2-RELEASE.jar started by root in D:\webapps\ksbysample-webapp-lending)
2020-01-08 23:44:56.494  INFO 2728 --- [main] ksbysample.webapp.lending.Application    : The following profiles are active: product
2020-01-08 23:44:58.182  INFO 2728 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2020-01-08 23:44:58.186  INFO 2728 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data Redis repositories in DEFAULT mode.
2020-01-08 23:44:58.241  INFO 2728 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 34ms. Found 0 Redis repository interfaces.
2020-01-08 23:44:58.960  INFO 2728 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor#0' of type [org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:44:59.008  INFO 2728 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:44:59.574  INFO 2728 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration' of type [org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:44:59.581  INFO 2728 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'objectPostProcessor' of type [org.springframework.security.config.annotation.configuration.AutowireBeanFactoryObjectPostProcessor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:44:59.588  INFO 2728 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler@74d7184a' of type [org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:44:59.591  INFO 2728 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration' of type [org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:44:59.605  INFO 2728 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'methodSecurityMetadataSource' of type [org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-08 23:45:00.374  INFO 2728 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-01-08 23:45:00.392  INFO 2728 --- [main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-01-08 23:45:00.392  INFO 2728 --- [main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.29]
2020-01-08 23:45:00.483  INFO 2728 --- [main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-01-08 23:45:00.483  INFO 2728 --- [main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 3901 ms
2020-01-08 23:45:01.188  INFO 2728 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService
2020-01-08 23:45:02.203  INFO 2728 --- [springSessionRedisMessageListenerContainer-1] io.lettuce.core.EpollProvider            : Starting without optional epoll library
2020-01-08 23:45:02.207  INFO 2728 --- [springSessionRedisMessageListenerContainer-1] io.lettuce.core.KqueueProvider           : Starting without optional kqueue library
2020-01-08 23:45:04.128  INFO 2728 --- [main] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing
2020-01-08 23:45:04.163  INFO 2728 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2020-01-08 23:45:04.167  INFO 2728 --- [main] ksbysample.webapp.lending.Application    : Started Application in 8.757 seconds (JVM running for 9.346)

時間がかかっていると思われる箇所を取り出してみました。

  • 2020-01-08 23:44:58.182 INFO 2728 --- [main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!（約1.5秒★★★）
  • 2020-01-08 23:45:00.374 INFO 2728 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)（約1.7秒★★★）
  • 2020-01-08 23:45:01.188 INFO 2728 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService（約0.7秒★★★）
  • 2020-01-08 23:45:02.203 INFO 2728 --- [springSessionRedisMessageListenerContainer-1] io.lettuce.core.EpollProvider : Starting without optional epoll library（約1秒★★★）
  • 2020-01-08 23:45:04.128 INFO 2728 --- [main] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing（約2秒★★）

Multiple Spring Data modules found, entering strict repository configuration mode! とは？

以下の Web ページによると Spring Data 系のモジュールが複数使用されている場合、strict repository configuration mode になるとのこと。例えば、複数の Spring Data 系モジュールを使用している場合 CrudRepository を継承するだけではどの Spring Data なのか判別できならしい。初耳です。。。

もう少し調べてみると Spring Data Redis の Repository 機能を見つけました。以下の Web ページに説明があります。なるほど、Spring Data 系ならば Repository 機能があるんですね。Spring Data JPA だけの機能だと思っていました。。。

Spring Data Redis は Spring Session のために使用しているだけなので -Dspring.data.redis.repositories.enabled=false を追加して Spring Data Redis の Repository 機能を無効にしてみます。

java -Xms1024m -Xmx1024m ^
     -XX:MaxMetaspaceSize=384m ^
     -XX:+UseG1GC ^
     -Xlog:gc*=debug:logs/gc.log:time,level,tags:filesize=10m,filecount=5 ^
     -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%PATH_HEAPDUMPFILE% ^
     -XX:+CrashOnOutOfMemoryError ^
     -XX:ErrorFile=%PATH_ERRORFILE% ^
     -Dsun.net.inetaddr.ttl=100 ^
     -Dspring.profiles.active=product ^
     -Dspring.main.lazy-initialization=true ^
     -XX:TieredStopAtLevel=1 ^
     -Dspring.data.redis.repositories.enabled=false ^
     -jar lib\%WEBAPP_JAR%

５回実行して Started Application in ... seconds に表示された時間は 8.776、8.37、8.65、8.627、8.627（平均 8.61）でした。少しだけ短くなりますが、無効にする程ではないようです。

2020-01-10 01:33:15.751  INFO 4628 --- [main] ksbysample.webapp.lending.Application    : Starting Application on PC-02 with PID 4628 (D:\webapps\ksbysample-webapp-lending\lib\ksbysample-webapp-lending-2.2.2-RELEASE.jar started by root in D:\webapps\ksbysample-webapp-lending)
2020-01-10 01:33:15.755  INFO 4628 --- [main] ksbysample.webapp.lending.Application    : The following profiles are active: product
2020-01-10 01:33:18.110  INFO 4628 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor#0' of type [org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-10 01:33:18.161  INFO 4628 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-10 01:33:18.688  INFO 4628 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration' of type [org.springframework.security.config.annotation.configuration.ObjectPostProcessorConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-10 01:33:18.696  INFO 4628 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'objectPostProcessor' of type [org.springframework.security.config.annotation.configuration.AutowireBeanFactoryObjectPostProcessor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-10 01:33:18.703  INFO 4628 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler@6e33c391' of type [org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-10 01:33:18.706  INFO 4628 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration' of type [org.springframework.security.config.annotation.method.configuration.GlobalMethodSecurityConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-10 01:33:18.722  INFO 4628 --- [main] trationDelegate$BeanPostProcessorChecker : Bean 'methodSecurityMetadataSource' of type [org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-01-10 01:33:19.584  INFO 4628 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-01-10 01:33:19.608  INFO 4628 --- [main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-01-10 01:33:19.609  INFO 4628 --- [main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.29]
2020-01-10 01:33:19.707  INFO 4628 --- [main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-01-10 01:33:19.707  INFO 4628 --- [main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 3868 ms
2020-01-10 01:33:20.371  INFO 4628 --- [main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService
2020-01-10 01:33:21.572  INFO 4628 --- [springSessionRedisMessageListenerContainer-1] io.lettuce.core.EpollProvider            : Starting without optional epoll library
2020-01-10 01:33:21.575  INFO 4628 --- [springSessionRedisMessageListenerContainer-1] io.lettuce.core.KqueueProvider           : Starting without optional kqueue library
2020-01-10 01:33:23.394  INFO 4628 --- [main] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing
2020-01-10 01:33:23.432  INFO 4628 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2020-01-10 01:33:23.436  INFO 4628 --- [main] ksbysample.webapp.lending.Application    : Started Application in 8.776 seconds (JVM running for 9.375)

s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing のログがなぜ出力されるのか？

ksbysample-webapp-lending では @EnableScheduling アノテーションを付与して Spring のスケジューリング機能を有効にしていないにもかかわらず、スケジューリング機能が有効になっていると思われるログが出ています。

ScheduledAnnotationBeanPostProcessor は org.springframework.scheduling.annotation パッケージのクラスでした。クラスのコメントを見ると Bean post-processor that registers methods annotated with @{@link Scheduled} ... という記述があります。

「Find in Path」機能で EnableScheduling で検索してみると、org.springframework.session.data.redis.config.annotation.web.http.RedisHttpSessionConfiguration クラスの中の SessionCleanupConfiguration クラスに @EnableScheduling アノテーションが付与されていました。

f:id:ksby:20200110020509p:plain

f:id:ksby:20200110020803p:plain

Spring Session で Redis 上に保存されたセッションが有効期限が切れた後に削除されるのは Redis の機能だと思っていましたが、Spring のスケジューリング機能で削除するタスクが定期的（DEFAULT_CLEANUP_CRON = "0 * * * * *"）に実行されていました。

-Dspring.main.lazy-initialization=true を設定すると /actuator/health が何も返さなくなる！？

Lazy Initialization in Spring Boot 2.2 によると spring.main.lazy-initialization=true は開発環境で設定すると良いとのこと。確かに起動時間が短縮されるのは魅力です。

そこで IntelliJ IDEA の Run/Debug Configuration ダイアログから VM Options に -Dspring.main.lazy-initialization=true を付けてみたのですが、

f:id:ksby:20200111210956p:plain

Spring Boot Actuator の Health Endpoint で何も表示されなくなりました。。。　Failed to retrieve 'health' endpoint data: javax.management.InstanceNotFoundException: org.springframework.boot:type=Endpoint,name=Health というメッセージが表示されます。

f:id:ksby:20200111211119p:plain

-Dspring.main.lazy-initialization=true を削除すると問題なく表示されます。

f:id:ksby:20200111211305p:plain

-Dspring.main.lazy-initialization=true を設定した時に http://localhost:8080/actuator/health にアクセスすると何が返ってくるのか Postman（curl を GUI にしたようなアプリです）で確認してみたところ、ログイン画面が返ってきていました。

f:id:ksby:20200111223903p:plain

新規に demo アプリ（Spring Boot Actuator を導入＋Spring Security は導入しない）を作成して動作を調査してみました。

  • ksbysample-webapp-lending と同様に -Dspring.main.lazy-initialization=true を設定すると IntelliJ IDEA の Health Endpoint には何も表示されない。
  • Postman でアクセスすると問題なくデータが取得できる！ f:id:ksby:20200111225328p:plain

表示されない時のメッセージが javax.management.InstanceNotFoundException だったので、以下の Bean を追加したところ demo アプリでは IntelliJ IDEA の Health Endpoint にデータが表示されるようになりました。

    @Bean
    static LazyInitializationExcludeFilter jmxEndpointExporterLazyInitExcludeFilter() {
        return LazyInitializationExcludeFilter.forBeanTypes(JmxEndpointExporter.class);
    }

ksbysample-webapp-lending でもこの Bean を追加すれば IntelliJ IDEA の Health Endpoint にデータが表示されるようになりましたが、Postman で http://localhost:8080/actuator/health にアクセスした時にログイン画面が表示されるのは変わりませんでした。う～ん、さっぱり分かりません。。。

最後に

  • 短縮できるといっても 5～10秒程度です。Web アプリが起動後に利用可能になるためにロードバランサーで health check をしているような場合にはあまりメリットはない気がします。

  • -Dspring.main.lazy-initialization=true とは関係ありませんが、org.springframework.boot:spring-boot-starter-data-redis＋org.springframework.session:spring-session-data-redis を導入するといろいろ処理が追加されて起動時に時間がかかることが分かりました。

履歴

2020/01/11
初版発行。