From 958b401f0f6eb68333cceeca6ecb6703533f0eee Mon Sep 17 00:00:00 2001 From: Ankur Mhatre Date: Fri, 4 Sep 2026 23:58:38 +0530 Subject: [PATCH] Spring Boot startup time: bean-by-bean diagnosis, and one directory per post Adds spring-boot-startup-time/, the companion project for BLOG-618: a runnable Spring Boot 4.1.1 application on JDK 25 that installs BufferingApplicationStartup and FlightRecorderApplicationStartup behind a system property, and a /diag/startup endpoint that computes step self time -- the number /actuator/startup does not give you and the one that names the actual culprits. Captured under docs/output/: the step tree sorted both ways, the same startup as JFR events, a +5000-class experiment putting 0.11 ms per scanned class on the classpath scan tax, the silent truncation a 2048-step buffer performs, and JDK 25 AOT cache timings (6.93 s to 4.82 s). Post body and metadata live in post/. Moves the existing Actuator project into actuator-in-production/ so the repository holds one directory per article; the root README is now an index. --- .gitignore | 5 + README.md | 171 +------ actuator-in-production/README.md | 169 +++++++ .../docs}/01-what-actuator-exposes.md | 0 .../docs}/02-boot-4-changes.md | 0 .../docs}/03-endpoint-catalogue.md | 0 .../docs}/04-securing-actuator.md | 0 .../docs}/05-custom-health-indicators.md | 0 .../06-health-indicator-failure-modes.md | 0 .../docs}/07-groups-and-probes.md | 0 .../docs}/08-diagnostics.md | 0 .../docs}/09-testing-actuator.md | 0 .../docs}/output/00-versions.txt | 0 .../docs}/output/01-default-exposure.txt | 0 .../docs}/output/02-endpoint-catalogue.txt | 0 .../docs}/output/03-open-actuator-leak.txt | 0 .../docs}/output/04-heapdump-leak.txt | 0 .../docs}/output/05-secured-matrix.txt | 0 .../docs}/output/06-management-port.txt | 0 .../output/07-custom-health-indicators.txt | 0 .../docs}/output/08-groups-and-probes.txt | 0 .../docs}/output/09-kafka-timeout.txt.naive | 0 .../docs}/output/09-kafka-timeout.txt.tuned | 0 .../docs}/output/10-slow-upstream.txt | 0 pom.xml => actuator-in-production/pom.xml | 0 .../scripts}/demo-custom-health.sh | 0 .../scripts}/demo-default-exposure.sh | 0 .../scripts}/demo-endpoint-catalogue.sh | 0 .../scripts}/demo-groups-probes.sh | 0 .../scripts}/demo-heapdump-leak.sh | 0 .../scripts}/demo-kafka-timeout.sh | 0 .../scripts}/demo-management-port.sh | 0 .../scripts}/demo-open-actuator.sh | 0 .../scripts}/demo-secured.sh | 0 .../scripts}/demo-slow-indicator.sh | 0 .../scripts}/demo-versions.sh | 0 .../scripts}/env.sh | 0 .../scripts}/run-all.sh | 0 .../scripts}/run.sh | 0 .../scripts}/stop.sh | 0 .../ActuatorProductionApplication.java | 0 .../actuator/config/DemoSecurityConfig.java | 0 .../actuator/config/OpenActuatorConfig.java | 0 .../config/SecuredActuatorConfig.java | 0 .../health/ExternalApiHealthIndicator.java | 0 .../actuator/health/KafkaHealthIndicator.java | 0 .../health/OrdersDatabaseHealthIndicator.java | 0 .../ankurm/actuator/health/UpstreamState.java | 0 .../actuator/web/DiagnosticsEndpoint.java | 0 .../ankurm/actuator/web/OrderController.java | 0 .../actuator/web/StubUpstreamController.java | 0 .../main/resources/application-details.yaml | 0 .../main/resources/application-exposeall.yaml | 0 .../main/resources/application-groups.yaml | 0 .../resources/application-kafkanaive.yaml | 0 .../main/resources/application-mgmtport.yaml | 0 .../main/resources/application-nokafka.yaml | 0 .../src}/main/resources/application-open.yaml | 0 .../main/resources/application-secured.yaml | 0 .../src}/main/resources/application.yaml | 0 .../src}/main/resources/data.sql | 0 .../src}/main/resources/schema.sql | 0 .../actuator/ActuatorExposureTests.java | 0 .../com/ankurm/actuator/HealthGroupTests.java | 0 spring-boot-startup-time/README.md | 133 ++++++ .../docs/01-the-number-boot-logs.md | 62 +++ .../docs/02-turning-instrumentation-on.md | 82 ++++ .../docs/03-the-four-phases.md | 87 ++++ .../docs/04-reading-the-step-tree.md | 86 ++++ .../docs/05-jfr-instead-of-a-buffer.md | 103 +++++ .../docs/06-the-classpath-scan-tax.md | 67 +++ .../docs/07-failure-modes.md | 89 ++++ .../docs/08-what-actually-helps.md | 98 ++++ .../docs/output/00-versions.txt | 18 + .../docs/output/01-api-corrections.txt | 56 +++ .../docs/output/02-startup-tree.txt | 67 +++ .../docs/output/03-jfr.txt | 60 +++ .../docs/output/04-scan-tax.txt | 10 + .../docs/output/05-what-helps.txt | 32 ++ .../docs/output/06-buffer-overflow.txt | 28 ++ spring-boot-startup-time/pom.xml | 58 +++ .../images/01-self-time-vs-total-time.svg | 38 ++ .../post/images/02-buffer-truncation.svg | 29 ++ spring-boot-startup-time/post/meta.md | 57 +++ spring-boot-startup-time/post/post.md | 420 ++++++++++++++++++ .../scripts/demo-buffer-overflow.sh | 25 ++ spring-boot-startup-time/scripts/demo-jfr.sh | 69 +++ .../scripts/demo-scan-tax.sh | 71 +++ .../scripts/demo-startup-tree.sh | 47 ++ .../scripts/demo-versions.sh | 16 + .../scripts/demo-what-helps.sh | 66 +++ spring-boot-startup-time/scripts/env.sh | 7 + spring-boot-startup-time/scripts/gen-bulk.sh | 22 + .../scripts/measure-startup.sh | 24 + spring-boot-startup-time/scripts/run-all.sh | 24 + spring-boot-startup-time/scripts/run.sh | 17 + spring-boot-startup-time/scripts/stop.sh | 10 + .../startup/StartupDiagnosisApplication.java | 24 + .../java/com/ankurm/startup/domain/Order.java | 30 ++ .../startup/domain/OrderRepository.java | 17 + .../ankurm/startup/slow/KeystoreLoader.java | 29 ++ .../startup/slow/LegacyRulesEngine.java | 29 ++ .../startup/slow/ReportTemplateRegistry.java | 22 + .../startup/slow/TariffCacheWarmer.java | 30 ++ .../ankurm/startup/web/OrderController.java | 22 + .../web/StartupDiagnosticsEndpoint.java | 127 ++++++ .../src/main/resources/application-lazy.yaml | 6 + .../resources/application-notracking.yaml | 3 + .../src/main/resources/application.yaml | 28 ++ .../src/main/resources/data.sql | 6 + .../src/main/resources/schema.sql | 5 + .../startup/StartupTimelineContractTests.java | 97 ++++ 112 files changed, 2744 insertions(+), 154 deletions(-) mode change 100755 => 100644 README.md create mode 100755 actuator-in-production/README.md rename {docs => actuator-in-production/docs}/01-what-actuator-exposes.md (100%) rename {docs => actuator-in-production/docs}/02-boot-4-changes.md (100%) rename {docs => actuator-in-production/docs}/03-endpoint-catalogue.md (100%) rename {docs => actuator-in-production/docs}/04-securing-actuator.md (100%) rename {docs => actuator-in-production/docs}/05-custom-health-indicators.md (100%) rename {docs => actuator-in-production/docs}/06-health-indicator-failure-modes.md (100%) rename {docs => actuator-in-production/docs}/07-groups-and-probes.md (100%) rename {docs => actuator-in-production/docs}/08-diagnostics.md (100%) rename {docs => actuator-in-production/docs}/09-testing-actuator.md (100%) rename {docs => actuator-in-production/docs}/output/00-versions.txt (100%) rename {docs => actuator-in-production/docs}/output/01-default-exposure.txt (100%) rename {docs => actuator-in-production/docs}/output/02-endpoint-catalogue.txt (100%) rename {docs => actuator-in-production/docs}/output/03-open-actuator-leak.txt (100%) rename {docs => actuator-in-production/docs}/output/04-heapdump-leak.txt (100%) rename {docs => actuator-in-production/docs}/output/05-secured-matrix.txt (100%) rename {docs => actuator-in-production/docs}/output/06-management-port.txt (100%) rename {docs => actuator-in-production/docs}/output/07-custom-health-indicators.txt (100%) rename {docs => actuator-in-production/docs}/output/08-groups-and-probes.txt (100%) rename {docs => actuator-in-production/docs}/output/09-kafka-timeout.txt.naive (100%) rename {docs => actuator-in-production/docs}/output/09-kafka-timeout.txt.tuned (100%) rename {docs => actuator-in-production/docs}/output/10-slow-upstream.txt (100%) rename pom.xml => actuator-in-production/pom.xml (100%) rename {scripts => actuator-in-production/scripts}/demo-custom-health.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-default-exposure.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-endpoint-catalogue.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-groups-probes.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-heapdump-leak.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-kafka-timeout.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-management-port.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-open-actuator.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-secured.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-slow-indicator.sh (100%) rename {scripts => actuator-in-production/scripts}/demo-versions.sh (100%) rename {scripts => actuator-in-production/scripts}/env.sh (100%) rename {scripts => actuator-in-production/scripts}/run-all.sh (100%) rename {scripts => actuator-in-production/scripts}/run.sh (100%) rename {scripts => actuator-in-production/scripts}/stop.sh (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/ActuatorProductionApplication.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/config/DemoSecurityConfig.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/config/OpenActuatorConfig.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/config/SecuredActuatorConfig.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/health/ExternalApiHealthIndicator.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/health/KafkaHealthIndicator.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/health/OrdersDatabaseHealthIndicator.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/health/UpstreamState.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/web/DiagnosticsEndpoint.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/web/OrderController.java (100%) rename {src => actuator-in-production/src}/main/java/com/ankurm/actuator/web/StubUpstreamController.java (100%) rename {src => actuator-in-production/src}/main/resources/application-details.yaml (100%) rename {src => actuator-in-production/src}/main/resources/application-exposeall.yaml (100%) rename {src => actuator-in-production/src}/main/resources/application-groups.yaml (100%) rename {src => actuator-in-production/src}/main/resources/application-kafkanaive.yaml (100%) rename {src => actuator-in-production/src}/main/resources/application-mgmtport.yaml (100%) rename {src => actuator-in-production/src}/main/resources/application-nokafka.yaml (100%) rename {src => actuator-in-production/src}/main/resources/application-open.yaml (100%) rename {src => actuator-in-production/src}/main/resources/application-secured.yaml (100%) rename {src => actuator-in-production/src}/main/resources/application.yaml (100%) rename {src => actuator-in-production/src}/main/resources/data.sql (100%) rename {src => actuator-in-production/src}/main/resources/schema.sql (100%) rename {src => actuator-in-production/src}/test/java/com/ankurm/actuator/ActuatorExposureTests.java (100%) rename {src => actuator-in-production/src}/test/java/com/ankurm/actuator/HealthGroupTests.java (100%) create mode 100644 spring-boot-startup-time/README.md create mode 100644 spring-boot-startup-time/docs/01-the-number-boot-logs.md create mode 100644 spring-boot-startup-time/docs/02-turning-instrumentation-on.md create mode 100644 spring-boot-startup-time/docs/03-the-four-phases.md create mode 100644 spring-boot-startup-time/docs/04-reading-the-step-tree.md create mode 100644 spring-boot-startup-time/docs/05-jfr-instead-of-a-buffer.md create mode 100644 spring-boot-startup-time/docs/06-the-classpath-scan-tax.md create mode 100644 spring-boot-startup-time/docs/07-failure-modes.md create mode 100644 spring-boot-startup-time/docs/08-what-actually-helps.md create mode 100644 spring-boot-startup-time/docs/output/00-versions.txt create mode 100644 spring-boot-startup-time/docs/output/01-api-corrections.txt create mode 100644 spring-boot-startup-time/docs/output/02-startup-tree.txt create mode 100644 spring-boot-startup-time/docs/output/03-jfr.txt create mode 100644 spring-boot-startup-time/docs/output/04-scan-tax.txt create mode 100644 spring-boot-startup-time/docs/output/05-what-helps.txt create mode 100644 spring-boot-startup-time/docs/output/06-buffer-overflow.txt create mode 100644 spring-boot-startup-time/pom.xml create mode 100644 spring-boot-startup-time/post/images/01-self-time-vs-total-time.svg create mode 100644 spring-boot-startup-time/post/images/02-buffer-truncation.svg create mode 100644 spring-boot-startup-time/post/meta.md create mode 100644 spring-boot-startup-time/post/post.md create mode 100755 spring-boot-startup-time/scripts/demo-buffer-overflow.sh create mode 100755 spring-boot-startup-time/scripts/demo-jfr.sh create mode 100755 spring-boot-startup-time/scripts/demo-scan-tax.sh create mode 100755 spring-boot-startup-time/scripts/demo-startup-tree.sh create mode 100755 spring-boot-startup-time/scripts/demo-versions.sh create mode 100755 spring-boot-startup-time/scripts/demo-what-helps.sh create mode 100755 spring-boot-startup-time/scripts/env.sh create mode 100755 spring-boot-startup-time/scripts/gen-bulk.sh create mode 100755 spring-boot-startup-time/scripts/measure-startup.sh create mode 100755 spring-boot-startup-time/scripts/run-all.sh create mode 100755 spring-boot-startup-time/scripts/run.sh create mode 100755 spring-boot-startup-time/scripts/stop.sh create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/StartupDiagnosisApplication.java create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/domain/Order.java create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/domain/OrderRepository.java create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/slow/KeystoreLoader.java create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/slow/LegacyRulesEngine.java create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/slow/ReportTemplateRegistry.java create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/slow/TariffCacheWarmer.java create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/web/OrderController.java create mode 100644 spring-boot-startup-time/src/main/java/com/ankurm/startup/web/StartupDiagnosticsEndpoint.java create mode 100644 spring-boot-startup-time/src/main/resources/application-lazy.yaml create mode 100644 spring-boot-startup-time/src/main/resources/application-notracking.yaml create mode 100644 spring-boot-startup-time/src/main/resources/application.yaml create mode 100644 spring-boot-startup-time/src/main/resources/data.sql create mode 100644 spring-boot-startup-time/src/main/resources/schema.sql create mode 100644 spring-boot-startup-time/src/test/java/com/ankurm/startup/StartupTimelineContractTests.java diff --git a/.gitignore b/.gitignore index 62ad1ab..75bc9f9 100644 --- a/.gitignore +++ b/.gitignore @@ -4,3 +4,8 @@ target/ .idea/ *.iml .vscode/ +*.jfr +*.aot +*.aotconf +# generated by spring-boot-startup-time/scripts/gen-bulk.sh +spring-boot-startup-time/src/main/java/com/ankurm/startup/bulk/ diff --git a/README.md b/README.md old mode 100755 new mode 100644 index 94f0813..f82b297 --- a/README.md +++ b/README.md @@ -1,167 +1,30 @@ -# spring-boot-demo — Actuator in production +# spring-boot-demo -Companion repository for **[Spring Boot Actuator in Production](https://ankurm.com/spring-boot-actuator-production-endpoints-security-health-indicators/)** on ankurm.com. +Companion code for the Spring Boot articles on **[ankurm.com](https://ankurm.com)**. -Every status code, JSON body, byte count and timing figure in the article was produced by -running this project. The transcripts live in [`docs/output/`](docs/output) and are regenerated -by a single command. +One directory per article. Each is a self-contained Maven project with its own `README.md`, +numbered documentation chapters under `docs/`, and captured real output under `docs/output/` +that a single script regenerates. Every figure quoted in an article came out of one of those +files. ---- - -## Versions - -Verified with `mvn dependency:list` on the machine that produced `docs/output/` — see -[`docs/output/00-versions.txt`](docs/output/00-versions.txt). - -| Component | Version | Notes | +| Directory | Article | What it demonstrates | |---|---|---| -| Spring Boot | 4.1.1 | GA 20 August 2026 | -| Spring Framework | 7.0.9 | via `spring-boot-starter-parent` | -| Spring Security | 7.1.1 | via `spring-boot-starter-parent` | -| `spring-boot-actuator` | 4.1.1 | | -| `spring-boot-health` | 4.1.1 | **new module in Boot 4** — `HealthIndicator` lives here now | -| `spring-boot-restclient` | 4.1.1 | **not pulled in by the web starter** | -| Micrometer | 1.17.1 | there is no Micrometer 2.x GA; see [`docs/02`](docs/02-boot-4-changes.md) | -| `kafka-clients` | 4.2.1 | what Boot 4.1.1 manages (4.3.1 is the latest on Central) | -| H2 | 2.4.240 | | -| JDK | Temurin 25.0.4.1+1 LTS | | -| Maven | 3.9.11 | | +| [`actuator-in-production/`](actuator-in-production) | [Spring Boot Actuator in Production](https://ankurm.com/spring-boot-actuator-production-endpoints-security-health-indicators/) | endpoint exposure defaults, securing Actuator, custom health indicators and how they hang | +| [`spring-boot-startup-time/`](spring-boot-startup-time) | [Why Your Spring Boot App Takes 8 Seconds to Start](spring-boot-startup-time/post/post.md) | `BufferingApplicationStartup`, JFR startup events, self time vs total time, the classpath-scan tax, the JDK 25 AOT cache | ---- +Articles whose text is kept here rather than only on the blog have it under +`/post/` — `post.md` for the body and `meta.md` for the title, excerpt and +categories. -## Quickstart +## Running any of them + +Each project needs a JDK 25 and Maven 3.9: ```bash +cd export JAVA_HOME=/path/to/jdk-25 mvn -DskipTests package - -# defaults: only /actuator/health is exposed -java -jar target/actuator-production-1.0.0.jar - -# every endpoint, no authentication - the configuration you should never ship -java -jar target/actuator-production-1.0.0.jar --spring.profiles.active=exposeall,open - -# the configuration you should ship -java -jar target/actuator-production-1.0.0.jar --spring.profiles.active=secured -``` - -Credentials for every profile that requires them: **`ops` / `ops-password`**. - -Regenerate every transcript in `docs/output/`: - -```bash -JAVA_HOME=/path/to/jdk-25 ./scripts/run-all.sh -``` - -That takes roughly three minutes, most of which is the naive Kafka scenario blocking for its -full 60 seconds. That is the point of it. - ---- - -## Profiles - -| Profile | What it demonstrates | -|---|---| -| *(none)* | Boot defaults. Only `health` on the web, `show-details: never` | -| `exposeall` | `management.endpoints.web.exposure.include: "*"` | -| `open` | A `permitAll` security chain — the misconfiguration, kept on purpose | -| `secured` | `EndpointRequest.toAnyEndpoint()` + `ROLE_ACTUATOR` + `when-authorized` details | -| `mgmtport` | Actuator on port 9001, base path `/manage`, bound to loopback | -| `details` | `show-details: always` — the full component breakdown | -| `groups` | `liveness` / `readiness` / `startup` groups wired correctly | -| `kafkanaive` | The textbook `AdminClient` health check, so its 60-second block can be timed | - -Profiles compose: `--spring.profiles.active=exposeall,open`. - ---- - -## Endpoints - -Read from the running application, not from the documentation — see -[`docs/output/02-endpoint-catalogue.txt`](docs/output/02-endpoint-catalogue.txt). - -| Endpoint | Web-exposed by default | `access` default | Notes | -|---|---|---|---| -| `health` | **yes** | `unrestricted` | the only one exposed out of the box | -| `info` | no | `unrestricted` | Boot 4.1 added `process.*` fields | -| `beans` | no | `unrestricted` | 426 beans in this app, with types and wiring | -| `conditions` | no | `unrestricted` | the auto-configuration report | -| `configprops` | no | `unrestricted` | values masked like `env` | -| `env` | no | `unrestricted` | **masks every value** unless `show-values` says otherwise | -| `loggers` | no | `unrestricted` | has a `POST` — a write endpoint | -| `mappings` | no | `unrestricted` | every URL your app serves | -| `metrics` | no | `unrestricted` | from `spring-boot-micrometer-metrics` | -| `prometheus` | no | `unrestricted` | needs `micrometer-registry-prometheus` | -| `sbom` | no | `unrestricted` | | -| `scheduledtasks` | no | `unrestricted` | | -| `threaddump` | no | `unrestricted` | two operations: JSON and `text/plain` | -| `heapdump` | no | **`none`** | `include: "*"` is **not** enough | -| `shutdown` | no | **`none`** | `include: "*"` is **not** enough | -| `startup` | no | `unrestricted` | needs a `BufferingApplicationStartup` | -| `httpexchanges` | no | `unrestricted` | needs an `HttpExchangeRepository` bean | -| `auditevents` | no | `unrestricted` | needs an `AuditEventRepository` bean | -| `logfile` | no | `unrestricted` | needs `logging.file.name` | -| `caches`, `flyway`, `liquibase`, `quartz`, `sessions`, `integrationgraph` | no | `unrestricted` | conditional on the relevant module | -| `diag` | no | `unrestricted` | **this repository's own** — delete before shipping | - -`heapdump` and `shutdown` are the only two endpoints whose `access` defaults to `none`. That -list came from Spring Boot's own `spring-configuration-metadata.json`, not from a blog. - ---- - -## Documentation - -| # | Chapter | -|---|---| -| 01 | [What Actuator actually exposes](docs/01-what-actuator-exposes.md) | -| 02 | [What changed in Spring Boot 4](docs/02-boot-4-changes.md) | -| 03 | [The endpoint catalogue](docs/03-endpoint-catalogue.md) | -| 04 | [Securing Actuator](docs/04-securing-actuator.md) | -| 05 | [Custom health indicators](docs/05-custom-health-indicators.md) | -| 06 | [Health indicator failure modes](docs/06-health-indicator-failure-modes.md) | -| 07 | [Groups, probes and Kubernetes](docs/07-groups-and-probes.md) | -| 08 | [The diagnostics endpoint](docs/08-diagnostics.md) | -| 09 | [Testing Actuator](docs/09-testing-actuator.md) | - ---- - -## Captured output - -| File | Scenario | -|---|---| -| [`00-versions.txt`](docs/output/00-versions.txt) | resolved dependency versions | -| [`01-default-exposure.txt`](docs/output/01-default-exposure.txt) | Actuator with zero configuration | -| [`02-endpoint-catalogue.txt`](docs/output/02-endpoint-catalogue.txt) | every exposed endpoint, from the running app | -| [`03-open-actuator-leak.txt`](docs/output/03-open-actuator-leak.txt) | what an anonymous caller really gets | -| [`04-heapdump-leak.txt`](docs/output/04-heapdump-leak.txt) | 59 MB, plaintext credentials inside | -| [`05-secured-matrix.txt`](docs/output/05-secured-matrix.txt) | the full authorisation matrix | -| [`06-management-port.txt`](docs/output/06-management-port.txt) | port 9001, and what it isolates | -| [`07-custom-health-indicators.txt`](docs/output/07-custom-health-indicators.txt) | DB, Kafka and external API | -| [`08-groups-and-probes.txt`](docs/output/08-groups-and-probes.txt) | liveness 200 while readiness 503 | -| [`09-kafka-timeout.txt.tuned`](docs/output/09-kafka-timeout.txt.tuned) | 1.6 s | -| [`09-kafka-timeout.txt.naive`](docs/output/09-kafka-timeout.txt.naive) | **60.2 s** | -| [`10-slow-upstream.txt`](docs/output/10-slow-upstream.txt) | a read timeout doing its job | - -Status codes and bodies are reproducible. Timing figures are indicative and drift between -machines — except the 60-second one, which is a Kafka default and lands on 60.0 s every time. - ---- - -## Layout - -``` -pom.xml -scripts/ - run-all.sh regenerate everything below docs/output/ - run.sh / stop.sh start and stop with given profiles - demo-*.sh one script per captured scenario -src/main/java/com/ankurm/actuator/ - health/ OrdersDatabase, Kafka, ExternalApi indicators + UpstreamState - config/ Secured, Open and baseline security chains - web/ DiagnosticsEndpoint, stub upstream, business controller -src/test/java/ contract tests for the surprising behaviour -docs/ numbered chapters -docs/output/ captured real output +./scripts/run-all.sh # regenerate every transcript under docs/output/ ``` ## Licence diff --git a/actuator-in-production/README.md b/actuator-in-production/README.md new file mode 100755 index 0000000..20934e8 --- /dev/null +++ b/actuator-in-production/README.md @@ -0,0 +1,169 @@ +# spring-boot-demo — Actuator in production + +Companion repository for **[Spring Boot Actuator in Production](https://ankurm.com/spring-boot-actuator-production-endpoints-security-health-indicators/)** on ankurm.com. + +Every status code, JSON body, byte count and timing figure in the article was produced by +running this project. The transcripts live in [`docs/output/`](docs/output) and are regenerated +by a single command. + +--- + +## Versions + +Verified with `mvn dependency:list` on the machine that produced `docs/output/` — see +[`docs/output/00-versions.txt`](docs/output/00-versions.txt). + +| Component | Version | Notes | +|---|---|---| +| Spring Boot | 4.1.1 | GA 20 August 2026 | +| Spring Framework | 7.0.9 | via `spring-boot-starter-parent` | +| Spring Security | 7.1.1 | via `spring-boot-starter-parent` | +| `spring-boot-actuator` | 4.1.1 | | +| `spring-boot-health` | 4.1.1 | **new module in Boot 4** — `HealthIndicator` lives here now | +| `spring-boot-restclient` | 4.1.1 | **not pulled in by the web starter** | +| Micrometer | 1.17.1 | there is no Micrometer 2.x GA; see [`docs/02`](docs/02-boot-4-changes.md) | +| `kafka-clients` | 4.2.1 | what Boot 4.1.1 manages (4.3.1 is the latest on Central) | +| H2 | 2.4.240 | | +| JDK | Temurin 25.0.4.1+1 LTS | | +| Maven | 3.9.11 | | + +--- + +## Quickstart + +```bash +export JAVA_HOME=/path/to/jdk-25 +mvn -DskipTests package + +# defaults: only /actuator/health is exposed +java -jar target/actuator-production-1.0.0.jar + +# every endpoint, no authentication - the configuration you should never ship +java -jar target/actuator-production-1.0.0.jar --spring.profiles.active=exposeall,open + +# the configuration you should ship +java -jar target/actuator-production-1.0.0.jar --spring.profiles.active=secured +``` + +Credentials for every profile that requires them: **`ops` / `ops-password`**. + +Regenerate every transcript in `docs/output/`: + +```bash +JAVA_HOME=/path/to/jdk-25 ./scripts/run-all.sh +``` + +That takes roughly three minutes, most of which is the naive Kafka scenario blocking for its +full 60 seconds. That is the point of it. + +--- + +## Profiles + +| Profile | What it demonstrates | +|---|---| +| *(none)* | Boot defaults. Only `health` on the web, `show-details: never` | +| `exposeall` | `management.endpoints.web.exposure.include: "*"` | +| `open` | A `permitAll` security chain — the misconfiguration, kept on purpose | +| `secured` | `EndpointRequest.toAnyEndpoint()` + `ROLE_ACTUATOR` + `when-authorized` details | +| `mgmtport` | Actuator on port 9001, base path `/manage`, bound to loopback | +| `details` | `show-details: always` — the full component breakdown | +| `groups` | `liveness` / `readiness` / `startup` groups wired correctly | +| `kafkanaive` | The textbook `AdminClient` health check, so its 60-second block can be timed | + +Profiles compose: `--spring.profiles.active=exposeall,open`. + +--- + +## Endpoints + +Read from the running application, not from the documentation — see +[`docs/output/02-endpoint-catalogue.txt`](docs/output/02-endpoint-catalogue.txt). + +| Endpoint | Web-exposed by default | `access` default | Notes | +|---|---|---|---| +| `health` | **yes** | `unrestricted` | the only one exposed out of the box | +| `info` | no | `unrestricted` | Boot 4.1 added `process.*` fields | +| `beans` | no | `unrestricted` | 426 beans in this app, with types and wiring | +| `conditions` | no | `unrestricted` | the auto-configuration report | +| `configprops` | no | `unrestricted` | values masked like `env` | +| `env` | no | `unrestricted` | **masks every value** unless `show-values` says otherwise | +| `loggers` | no | `unrestricted` | has a `POST` — a write endpoint | +| `mappings` | no | `unrestricted` | every URL your app serves | +| `metrics` | no | `unrestricted` | from `spring-boot-micrometer-metrics` | +| `prometheus` | no | `unrestricted` | needs `micrometer-registry-prometheus` | +| `sbom` | no | `unrestricted` | | +| `scheduledtasks` | no | `unrestricted` | | +| `threaddump` | no | `unrestricted` | two operations: JSON and `text/plain` | +| `heapdump` | no | **`none`** | `include: "*"` is **not** enough | +| `shutdown` | no | **`none`** | `include: "*"` is **not** enough | +| `startup` | no | `unrestricted` | needs a `BufferingApplicationStartup` | +| `httpexchanges` | no | `unrestricted` | needs an `HttpExchangeRepository` bean | +| `auditevents` | no | `unrestricted` | needs an `AuditEventRepository` bean | +| `logfile` | no | `unrestricted` | needs `logging.file.name` | +| `caches`, `flyway`, `liquibase`, `quartz`, `sessions`, `integrationgraph` | no | `unrestricted` | conditional on the relevant module | +| `diag` | no | `unrestricted` | **this repository's own** — delete before shipping | + +`heapdump` and `shutdown` are the only two endpoints whose `access` defaults to `none`. That +list came from Spring Boot's own `spring-configuration-metadata.json`, not from a blog. + +--- + +## Documentation + +| # | Chapter | +|---|---| +| 01 | [What Actuator actually exposes](docs/01-what-actuator-exposes.md) | +| 02 | [What changed in Spring Boot 4](docs/02-boot-4-changes.md) | +| 03 | [The endpoint catalogue](docs/03-endpoint-catalogue.md) | +| 04 | [Securing Actuator](docs/04-securing-actuator.md) | +| 05 | [Custom health indicators](docs/05-custom-health-indicators.md) | +| 06 | [Health indicator failure modes](docs/06-health-indicator-failure-modes.md) | +| 07 | [Groups, probes and Kubernetes](docs/07-groups-and-probes.md) | +| 08 | [The diagnostics endpoint](docs/08-diagnostics.md) | +| 09 | [Testing Actuator](docs/09-testing-actuator.md) | + +--- + +## Captured output + +| File | Scenario | +|---|---| +| [`00-versions.txt`](docs/output/00-versions.txt) | resolved dependency versions | +| [`01-default-exposure.txt`](docs/output/01-default-exposure.txt) | Actuator with zero configuration | +| [`02-endpoint-catalogue.txt`](docs/output/02-endpoint-catalogue.txt) | every exposed endpoint, from the running app | +| [`03-open-actuator-leak.txt`](docs/output/03-open-actuator-leak.txt) | what an anonymous caller really gets | +| [`04-heapdump-leak.txt`](docs/output/04-heapdump-leak.txt) | 59 MB, plaintext credentials inside | +| [`05-secured-matrix.txt`](docs/output/05-secured-matrix.txt) | the full authorisation matrix | +| [`06-management-port.txt`](docs/output/06-management-port.txt) | port 9001, and what it isolates | +| [`07-custom-health-indicators.txt`](docs/output/07-custom-health-indicators.txt) | DB, Kafka and external API | +| [`08-groups-and-probes.txt`](docs/output/08-groups-and-probes.txt) | liveness 200 while readiness 503 | +| [`09-kafka-timeout.txt.tuned`](docs/output/09-kafka-timeout.txt.tuned) | 1.6 s | +| [`09-kafka-timeout.txt.naive`](docs/output/09-kafka-timeout.txt.naive) | **60.2 s** | +| [`10-slow-upstream.txt`](docs/output/10-slow-upstream.txt) | a read timeout doing its job | + +Status codes and bodies are reproducible. Timing figures are indicative and drift between +machines — except the 60-second one, which is a Kafka default and lands on 60.0 s every time. + +--- + +## Layout + +``` +pom.xml +scripts/ + run-all.sh regenerate everything below docs/output/ + run.sh / stop.sh start and stop with given profiles + demo-*.sh one script per captured scenario +src/main/java/com/ankurm/actuator/ + health/ OrdersDatabase, Kafka, ExternalApi indicators + UpstreamState + config/ Secured, Open and baseline security chains + web/ DiagnosticsEndpoint, stub upstream, business controller +src/test/java/ contract tests for the surprising behaviour +docs/ numbered chapters +docs/output/ captured real output +``` + +## Licence + +MIT — see [LICENSE](../LICENSE). diff --git a/docs/01-what-actuator-exposes.md b/actuator-in-production/docs/01-what-actuator-exposes.md similarity index 100% rename from docs/01-what-actuator-exposes.md rename to actuator-in-production/docs/01-what-actuator-exposes.md diff --git a/docs/02-boot-4-changes.md b/actuator-in-production/docs/02-boot-4-changes.md similarity index 100% rename from docs/02-boot-4-changes.md rename to actuator-in-production/docs/02-boot-4-changes.md diff --git a/docs/03-endpoint-catalogue.md b/actuator-in-production/docs/03-endpoint-catalogue.md similarity index 100% rename from docs/03-endpoint-catalogue.md rename to actuator-in-production/docs/03-endpoint-catalogue.md diff --git a/docs/04-securing-actuator.md b/actuator-in-production/docs/04-securing-actuator.md similarity index 100% rename from docs/04-securing-actuator.md rename to actuator-in-production/docs/04-securing-actuator.md diff --git a/docs/05-custom-health-indicators.md b/actuator-in-production/docs/05-custom-health-indicators.md similarity index 100% rename from docs/05-custom-health-indicators.md rename to actuator-in-production/docs/05-custom-health-indicators.md diff --git a/docs/06-health-indicator-failure-modes.md b/actuator-in-production/docs/06-health-indicator-failure-modes.md similarity index 100% rename from docs/06-health-indicator-failure-modes.md rename to actuator-in-production/docs/06-health-indicator-failure-modes.md diff --git a/docs/07-groups-and-probes.md b/actuator-in-production/docs/07-groups-and-probes.md similarity index 100% rename from docs/07-groups-and-probes.md rename to actuator-in-production/docs/07-groups-and-probes.md diff --git a/docs/08-diagnostics.md b/actuator-in-production/docs/08-diagnostics.md similarity index 100% rename from docs/08-diagnostics.md rename to actuator-in-production/docs/08-diagnostics.md diff --git a/docs/09-testing-actuator.md b/actuator-in-production/docs/09-testing-actuator.md similarity index 100% rename from docs/09-testing-actuator.md rename to actuator-in-production/docs/09-testing-actuator.md diff --git a/docs/output/00-versions.txt b/actuator-in-production/docs/output/00-versions.txt similarity index 100% rename from docs/output/00-versions.txt rename to actuator-in-production/docs/output/00-versions.txt diff --git a/docs/output/01-default-exposure.txt b/actuator-in-production/docs/output/01-default-exposure.txt similarity index 100% rename from docs/output/01-default-exposure.txt rename to actuator-in-production/docs/output/01-default-exposure.txt diff --git a/docs/output/02-endpoint-catalogue.txt b/actuator-in-production/docs/output/02-endpoint-catalogue.txt similarity index 100% rename from docs/output/02-endpoint-catalogue.txt rename to actuator-in-production/docs/output/02-endpoint-catalogue.txt diff --git a/docs/output/03-open-actuator-leak.txt b/actuator-in-production/docs/output/03-open-actuator-leak.txt similarity index 100% rename from docs/output/03-open-actuator-leak.txt rename to actuator-in-production/docs/output/03-open-actuator-leak.txt diff --git a/docs/output/04-heapdump-leak.txt b/actuator-in-production/docs/output/04-heapdump-leak.txt similarity index 100% rename from docs/output/04-heapdump-leak.txt rename to actuator-in-production/docs/output/04-heapdump-leak.txt diff --git a/docs/output/05-secured-matrix.txt b/actuator-in-production/docs/output/05-secured-matrix.txt similarity index 100% rename from docs/output/05-secured-matrix.txt rename to actuator-in-production/docs/output/05-secured-matrix.txt diff --git a/docs/output/06-management-port.txt b/actuator-in-production/docs/output/06-management-port.txt similarity index 100% rename from docs/output/06-management-port.txt rename to actuator-in-production/docs/output/06-management-port.txt diff --git a/docs/output/07-custom-health-indicators.txt b/actuator-in-production/docs/output/07-custom-health-indicators.txt similarity index 100% rename from docs/output/07-custom-health-indicators.txt rename to actuator-in-production/docs/output/07-custom-health-indicators.txt diff --git a/docs/output/08-groups-and-probes.txt b/actuator-in-production/docs/output/08-groups-and-probes.txt similarity index 100% rename from docs/output/08-groups-and-probes.txt rename to actuator-in-production/docs/output/08-groups-and-probes.txt diff --git a/docs/output/09-kafka-timeout.txt.naive b/actuator-in-production/docs/output/09-kafka-timeout.txt.naive similarity index 100% rename from docs/output/09-kafka-timeout.txt.naive rename to actuator-in-production/docs/output/09-kafka-timeout.txt.naive diff --git a/docs/output/09-kafka-timeout.txt.tuned b/actuator-in-production/docs/output/09-kafka-timeout.txt.tuned similarity index 100% rename from docs/output/09-kafka-timeout.txt.tuned rename to actuator-in-production/docs/output/09-kafka-timeout.txt.tuned diff --git a/docs/output/10-slow-upstream.txt b/actuator-in-production/docs/output/10-slow-upstream.txt similarity index 100% rename from docs/output/10-slow-upstream.txt rename to actuator-in-production/docs/output/10-slow-upstream.txt diff --git a/pom.xml b/actuator-in-production/pom.xml similarity index 100% rename from pom.xml rename to actuator-in-production/pom.xml diff --git a/scripts/demo-custom-health.sh b/actuator-in-production/scripts/demo-custom-health.sh similarity index 100% rename from scripts/demo-custom-health.sh rename to actuator-in-production/scripts/demo-custom-health.sh diff --git a/scripts/demo-default-exposure.sh b/actuator-in-production/scripts/demo-default-exposure.sh similarity index 100% rename from scripts/demo-default-exposure.sh rename to actuator-in-production/scripts/demo-default-exposure.sh diff --git a/scripts/demo-endpoint-catalogue.sh b/actuator-in-production/scripts/demo-endpoint-catalogue.sh similarity index 100% rename from scripts/demo-endpoint-catalogue.sh rename to actuator-in-production/scripts/demo-endpoint-catalogue.sh diff --git a/scripts/demo-groups-probes.sh b/actuator-in-production/scripts/demo-groups-probes.sh similarity index 100% rename from scripts/demo-groups-probes.sh rename to actuator-in-production/scripts/demo-groups-probes.sh diff --git a/scripts/demo-heapdump-leak.sh b/actuator-in-production/scripts/demo-heapdump-leak.sh similarity index 100% rename from scripts/demo-heapdump-leak.sh rename to actuator-in-production/scripts/demo-heapdump-leak.sh diff --git a/scripts/demo-kafka-timeout.sh b/actuator-in-production/scripts/demo-kafka-timeout.sh similarity index 100% rename from scripts/demo-kafka-timeout.sh rename to actuator-in-production/scripts/demo-kafka-timeout.sh diff --git a/scripts/demo-management-port.sh b/actuator-in-production/scripts/demo-management-port.sh similarity index 100% rename from scripts/demo-management-port.sh rename to actuator-in-production/scripts/demo-management-port.sh diff --git a/scripts/demo-open-actuator.sh b/actuator-in-production/scripts/demo-open-actuator.sh similarity index 100% rename from scripts/demo-open-actuator.sh rename to actuator-in-production/scripts/demo-open-actuator.sh diff --git a/scripts/demo-secured.sh b/actuator-in-production/scripts/demo-secured.sh similarity index 100% rename from scripts/demo-secured.sh rename to actuator-in-production/scripts/demo-secured.sh diff --git a/scripts/demo-slow-indicator.sh b/actuator-in-production/scripts/demo-slow-indicator.sh similarity index 100% rename from scripts/demo-slow-indicator.sh rename to actuator-in-production/scripts/demo-slow-indicator.sh diff --git a/scripts/demo-versions.sh b/actuator-in-production/scripts/demo-versions.sh similarity index 100% rename from scripts/demo-versions.sh rename to actuator-in-production/scripts/demo-versions.sh diff --git a/scripts/env.sh b/actuator-in-production/scripts/env.sh similarity index 100% rename from scripts/env.sh rename to actuator-in-production/scripts/env.sh diff --git a/scripts/run-all.sh b/actuator-in-production/scripts/run-all.sh similarity index 100% rename from scripts/run-all.sh rename to actuator-in-production/scripts/run-all.sh diff --git a/scripts/run.sh b/actuator-in-production/scripts/run.sh similarity index 100% rename from scripts/run.sh rename to actuator-in-production/scripts/run.sh diff --git a/scripts/stop.sh b/actuator-in-production/scripts/stop.sh similarity index 100% rename from scripts/stop.sh rename to actuator-in-production/scripts/stop.sh diff --git a/src/main/java/com/ankurm/actuator/ActuatorProductionApplication.java b/actuator-in-production/src/main/java/com/ankurm/actuator/ActuatorProductionApplication.java similarity index 100% rename from src/main/java/com/ankurm/actuator/ActuatorProductionApplication.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/ActuatorProductionApplication.java diff --git a/src/main/java/com/ankurm/actuator/config/DemoSecurityConfig.java b/actuator-in-production/src/main/java/com/ankurm/actuator/config/DemoSecurityConfig.java similarity index 100% rename from src/main/java/com/ankurm/actuator/config/DemoSecurityConfig.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/config/DemoSecurityConfig.java diff --git a/src/main/java/com/ankurm/actuator/config/OpenActuatorConfig.java b/actuator-in-production/src/main/java/com/ankurm/actuator/config/OpenActuatorConfig.java similarity index 100% rename from src/main/java/com/ankurm/actuator/config/OpenActuatorConfig.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/config/OpenActuatorConfig.java diff --git a/src/main/java/com/ankurm/actuator/config/SecuredActuatorConfig.java b/actuator-in-production/src/main/java/com/ankurm/actuator/config/SecuredActuatorConfig.java similarity index 100% rename from src/main/java/com/ankurm/actuator/config/SecuredActuatorConfig.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/config/SecuredActuatorConfig.java diff --git a/src/main/java/com/ankurm/actuator/health/ExternalApiHealthIndicator.java b/actuator-in-production/src/main/java/com/ankurm/actuator/health/ExternalApiHealthIndicator.java similarity index 100% rename from src/main/java/com/ankurm/actuator/health/ExternalApiHealthIndicator.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/health/ExternalApiHealthIndicator.java diff --git a/src/main/java/com/ankurm/actuator/health/KafkaHealthIndicator.java b/actuator-in-production/src/main/java/com/ankurm/actuator/health/KafkaHealthIndicator.java similarity index 100% rename from src/main/java/com/ankurm/actuator/health/KafkaHealthIndicator.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/health/KafkaHealthIndicator.java diff --git a/src/main/java/com/ankurm/actuator/health/OrdersDatabaseHealthIndicator.java b/actuator-in-production/src/main/java/com/ankurm/actuator/health/OrdersDatabaseHealthIndicator.java similarity index 100% rename from src/main/java/com/ankurm/actuator/health/OrdersDatabaseHealthIndicator.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/health/OrdersDatabaseHealthIndicator.java diff --git a/src/main/java/com/ankurm/actuator/health/UpstreamState.java b/actuator-in-production/src/main/java/com/ankurm/actuator/health/UpstreamState.java similarity index 100% rename from src/main/java/com/ankurm/actuator/health/UpstreamState.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/health/UpstreamState.java diff --git a/src/main/java/com/ankurm/actuator/web/DiagnosticsEndpoint.java b/actuator-in-production/src/main/java/com/ankurm/actuator/web/DiagnosticsEndpoint.java similarity index 100% rename from src/main/java/com/ankurm/actuator/web/DiagnosticsEndpoint.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/web/DiagnosticsEndpoint.java diff --git a/src/main/java/com/ankurm/actuator/web/OrderController.java b/actuator-in-production/src/main/java/com/ankurm/actuator/web/OrderController.java similarity index 100% rename from src/main/java/com/ankurm/actuator/web/OrderController.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/web/OrderController.java diff --git a/src/main/java/com/ankurm/actuator/web/StubUpstreamController.java b/actuator-in-production/src/main/java/com/ankurm/actuator/web/StubUpstreamController.java similarity index 100% rename from src/main/java/com/ankurm/actuator/web/StubUpstreamController.java rename to actuator-in-production/src/main/java/com/ankurm/actuator/web/StubUpstreamController.java diff --git a/src/main/resources/application-details.yaml b/actuator-in-production/src/main/resources/application-details.yaml similarity index 100% rename from src/main/resources/application-details.yaml rename to actuator-in-production/src/main/resources/application-details.yaml diff --git a/src/main/resources/application-exposeall.yaml b/actuator-in-production/src/main/resources/application-exposeall.yaml similarity index 100% rename from src/main/resources/application-exposeall.yaml rename to actuator-in-production/src/main/resources/application-exposeall.yaml diff --git a/src/main/resources/application-groups.yaml b/actuator-in-production/src/main/resources/application-groups.yaml similarity index 100% rename from src/main/resources/application-groups.yaml rename to actuator-in-production/src/main/resources/application-groups.yaml diff --git a/src/main/resources/application-kafkanaive.yaml b/actuator-in-production/src/main/resources/application-kafkanaive.yaml similarity index 100% rename from src/main/resources/application-kafkanaive.yaml rename to actuator-in-production/src/main/resources/application-kafkanaive.yaml diff --git a/src/main/resources/application-mgmtport.yaml b/actuator-in-production/src/main/resources/application-mgmtport.yaml similarity index 100% rename from src/main/resources/application-mgmtport.yaml rename to actuator-in-production/src/main/resources/application-mgmtport.yaml diff --git a/src/main/resources/application-nokafka.yaml b/actuator-in-production/src/main/resources/application-nokafka.yaml similarity index 100% rename from src/main/resources/application-nokafka.yaml rename to actuator-in-production/src/main/resources/application-nokafka.yaml diff --git a/src/main/resources/application-open.yaml b/actuator-in-production/src/main/resources/application-open.yaml similarity index 100% rename from src/main/resources/application-open.yaml rename to actuator-in-production/src/main/resources/application-open.yaml diff --git a/src/main/resources/application-secured.yaml b/actuator-in-production/src/main/resources/application-secured.yaml similarity index 100% rename from src/main/resources/application-secured.yaml rename to actuator-in-production/src/main/resources/application-secured.yaml diff --git a/src/main/resources/application.yaml b/actuator-in-production/src/main/resources/application.yaml similarity index 100% rename from src/main/resources/application.yaml rename to actuator-in-production/src/main/resources/application.yaml diff --git a/src/main/resources/data.sql b/actuator-in-production/src/main/resources/data.sql similarity index 100% rename from src/main/resources/data.sql rename to actuator-in-production/src/main/resources/data.sql diff --git a/src/main/resources/schema.sql b/actuator-in-production/src/main/resources/schema.sql similarity index 100% rename from src/main/resources/schema.sql rename to actuator-in-production/src/main/resources/schema.sql diff --git a/src/test/java/com/ankurm/actuator/ActuatorExposureTests.java b/actuator-in-production/src/test/java/com/ankurm/actuator/ActuatorExposureTests.java similarity index 100% rename from src/test/java/com/ankurm/actuator/ActuatorExposureTests.java rename to actuator-in-production/src/test/java/com/ankurm/actuator/ActuatorExposureTests.java diff --git a/src/test/java/com/ankurm/actuator/HealthGroupTests.java b/actuator-in-production/src/test/java/com/ankurm/actuator/HealthGroupTests.java similarity index 100% rename from src/test/java/com/ankurm/actuator/HealthGroupTests.java rename to actuator-in-production/src/test/java/com/ankurm/actuator/HealthGroupTests.java diff --git a/spring-boot-startup-time/README.md b/spring-boot-startup-time/README.md new file mode 100644 index 0000000..6029d8f --- /dev/null +++ b/spring-boot-startup-time/README.md @@ -0,0 +1,133 @@ +# Why your Spring Boot app takes 8 seconds to start + +Companion project for **[Why Your Spring Boot App Takes 8 Seconds to Start: A Bean-by-Bean +Diagnosis](post/post.md)**. + +Every millisecond figure in the article came out of this project. The transcripts are in +[`docs/output/`](docs/output) and are regenerated by one command. + +--- + +## Versions + +Resolved by the build, not read from documentation — see +[`docs/output/00-versions.txt`](docs/output/00-versions.txt). + +| Component | Version | Notes | +|---|---|---| +| Spring Boot | 4.1.1 | GA 20 August 2026 | +| Spring Framework | 7.0.9 | via `spring-boot-starter-parent` | +| Spring Data JPA | 4.1.1 | | +| Hibernate ORM | 7.4.5.Final | | +| Tomcat (embedded) | 11.0.24 | | +| Micrometer | 1.17.1 | | +| H2 | 2.4.240 | | +| JDK | Temurin 25.0.4.1+1 LTS | AOT cache needs 24+ | +| Maven | 3.9.11 | | + +--- + +## Quickstart + +```bash +export JAVA_HOME=/path/to/jdk-25 +mvn -DskipTests package + +# recording, and serving the self-time view at /diag/startup +java -Dstartup.tracking=buffering -jar target/startup-diagnosis-1.0.0.jar + +curl -s 'localhost:8080/diag/startup?top=12' # self time -- the useful list +curl -s localhost:8080/actuator/startup # GET peeks +curl -sX POST localhost:8080/actuator/startup # POST drains. Only once. +``` + +Regenerate every transcript (~20 minutes): + +```bash +JAVA_HOME=/path/to/jdk-25 ./scripts/run-all.sh +``` + +--- + +## Switches + +Tracking is a **system property**, not a Spring property, because `ApplicationStartup` must +be set before `run()`. See [`docs/02`](docs/02-turning-instrumentation-on.md). + +| Switch | Effect | +|---|---| +| `-Dstartup.tracking=buffering` | `BufferingApplicationStartup` (default in this project) | +| `-Dstartup.tracking=jfr` | `FlightRecorderApplicationStartup`; pair with `-XX:StartFlightRecording` | +| `-Dstartup.tracking=none` | no tracking — the uninstrumented baseline | +| `-Dstartup.buffer=2048` | buffer capacity in **steps**; too small truncates silently | +| `--spring.profiles.active=lazy` | `spring.main.lazy-initialization=true` | + +--- + +## Endpoints + +| Endpoint | What it gives you | +|---|---| +| `/diag/startup?top=N` | **this project's own** — self time, phase totals, both orderings | +| `/actuator/startup` | Boot's flat timeline. `GET` peeks, `POST` drains | +| `/actuator/health`, `/actuator/beans`, `/actuator/conditions` | exposed for context | +| `/orders/summary` | the application's actual job | + +`/diag/startup` exposes bean names and wiring. **Delete it before shipping.** + +--- + +## Documentation + +| # | Chapter | +|---|---| +| 01 | [The number Boot logs, and what it hides](docs/01-the-number-boot-logs.md) | +| 02 | [Turning instrumentation on](docs/02-turning-instrumentation-on.md) | +| 03 | [The four phases hiding inside one number](docs/03-the-four-phases.md) | +| 04 | [Reading the step tree: self time versus total time](docs/04-reading-the-step-tree.md) | +| 05 | [JFR instead of a buffer](docs/05-jfr-instead-of-a-buffer.md) | +| 06 | [The classpath-scan tax, measured](docs/06-the-classpath-scan-tax.md) | +| 07 | [Failure modes](docs/07-failure-modes.md) | +| 08 | [What actually helps](docs/08-what-actually-helps.md) | + +--- + +## Captured output + +| File | Scenario | +|---|---| +| [`00-versions.txt`](docs/output/00-versions.txt) | resolved versions from the build | +| [`01-api-corrections.txt`](docs/output/01-api-corrections.txt) | `javap` and the compiler errors that corrected the code | +| [`02-startup-tree.txt`](docs/output/02-startup-tree.txt) | the step tree by self time and by total time | +| [`03-jfr.txt`](docs/output/03-jfr.txt) | the same startup as JFR events, read with `jfr` | +| [`04-scan-tax.txt`](docs/output/04-scan-tax.txt) | +5000 classes, with and without `@Component` | +| [`05-what-helps.txt`](docs/output/05-what-helps.txt) | tracking overhead, lazy init, JDK 25 AOT cache | +| [`06-buffer-overflow.txt`](docs/output/06-buffer-overflow.txt) | what a 2048-step buffer silently loses | + +Step counts and orderings are reproducible. **Timings are indicative** and drift by a few +hundred milliseconds between runs on the same machine — the ratios are the result, not the +absolute numbers. + +--- + +## Layout + +``` +pom.xml +scripts/ + run-all.sh regenerate everything under docs/output/ + run.sh / stop.sh start and stop; stop.sh matches java+jar, never the main class + gen-bulk.sh generate N classes into the scanned package + demo-*.sh one script per captured scenario +src/main/java/com/ankurm/startup/ + slow/ four beans that do real work on the way up + domain/ one entity, one repository with derived queries + web/ StartupDiagnosticsEndpoint (self time) + the business controller +src/test/java/ contract tests for drain, truncation and double-counting +docs/ numbered chapters +docs/output/ captured real output +``` + +## Licence + +MIT — see [LICENSE](../LICENSE). diff --git a/spring-boot-startup-time/docs/01-the-number-boot-logs.md b/spring-boot-startup-time/docs/01-the-number-boot-logs.md new file mode 100644 index 0000000..dbe537c --- /dev/null +++ b/spring-boot-startup-time/docs/01-the-number-boot-logs.md @@ -0,0 +1,62 @@ +# 01 — The number Boot logs, and what it hides + +next → [02 — Turning instrumentation on](02-turning-instrumentation-on.md) + +--- + +Every Spring Boot application ends its startup with one line: + +``` +Started StartupDiagnosisApplication in 6.6 seconds (process running for 7.4) +``` + +Two numbers. The first is measured from the `SpringApplication.run()` call to the +`ApplicationReadyEvent`. The second is `ManagementFactory.getRuntimeMXBean().getUptime()`, +so the gap between them is JVM bootstrap: opening the jar, verifying classes, starting the +JIT — work that happens before your code runs at all. + +Neither number tells you where the 6.6 seconds went, and the usual next move — reading the +log timestamps — is worse than it looks. The log only shows you components that chose to +log. This application spends about half a second inside `tariffCacheWarmer` and logs +nothing while doing it. On the timeline it is a silent gap between two Hibernate lines, +and you would reasonably conclude that Hibernate was slow. + +## What is actually available + +Spring Framework has carried an `ApplicationStartup` SPI since 5.3. It is a tracing +interface with one method that matters: + +```java +public interface ApplicationStartup { + StartupStep start(String name); +} +``` + +Framework and Boot call it at about two dozen named points — `spring.beans.instantiate`, +`spring.context.config-classes.parse`, `spring.data.repository.proxy`, and so on — tagging +each step with the bean name or class count involved. Steps nest, so what you get is a +tree, not a list. + +The default implementation, `DefaultApplicationStartup`, does nothing. That is the whole +reason startup profiling feels unavailable: the instrumentation is already in your +application and is switched off. + +Two implementations record it: + +| Implementation | Where it lives | Output | +|---|---|---| +| `BufferingApplicationStartup` | `spring-boot` | in-memory buffer, read over HTTP | +| `FlightRecorderApplicationStartup` | `spring-core` | JFR events in a `.jfr` file | + +There is no third option and no third-party agent needed. + +## What this repository measures + +The application here is deliberately ordinary: web, JPA over H2, three repositories, and +four beans that do real work on the way up. It starts in about 6.6 seconds on the machine +that produced [`docs/output/`](output). Every figure in the article and in these chapters +came from a file in that directory. + +--- + +next → [02 — Turning instrumentation on](02-turning-instrumentation-on.md) diff --git a/spring-boot-startup-time/docs/02-turning-instrumentation-on.md b/spring-boot-startup-time/docs/02-turning-instrumentation-on.md new file mode 100644 index 0000000..8712bd6 --- /dev/null +++ b/spring-boot-startup-time/docs/02-turning-instrumentation-on.md @@ -0,0 +1,82 @@ +# 02 — Turning instrumentation on + +← prev [01 — The number Boot logs](01-the-number-boot-logs.md) · next → [03 — The four phases](03-the-four-phases.md) + +--- + +## There is no property for this + +The single most common wasted hour: looking for `spring.application.startup=buffering` in +`application.yaml`. It does not exist. `ApplicationStartup` has to be set on the +`SpringApplication` **before** `run()`, because the steps you care about are recorded +before any configuration file has been read. + +```java +public static void main(String[] args) { + SpringApplication app = new SpringApplication(StartupDiagnosisApplication.class); + int capacity = Integer.getInteger("startup.buffer", 16384); + switch (System.getProperty("startup.tracking", "buffering")) { + case "buffering" -> app.setApplicationStartup(new BufferingApplicationStartup(capacity)); + case "jfr" -> app.setApplicationStartup(new FlightRecorderApplicationStartup()); + default -> { } + } + app.run(args); +} +``` + +That means changing which tracker you use is a **redeploy**, not a config change — worth +knowing before an incident, not during one. See +[`StartupDiagnosisApplication.java`](../src/main/java/com/ankurm/startup/StartupDiagnosisApplication.java). + +## Exposing the endpoint + +`startup` is not web-exposed by default: + +```yaml +management: + endpoints: + web: + exposure: + include: health,info,startup,beans,conditions +``` + +Exposing it without installing a tracker gives you an endpoint that returns an empty +timeline rather than an error, which is a confusing way to lose twenty minutes. + +## GET peeks, POST drains + +This is the trap that costs people their only recording. From +[`docs/output/02-startup-tree.txt`](output/02-startup-tree.txt): + +``` + GET /actuator/startup -> events in response: 400 + POST /actuator/startup -> events in response: 400 + POST /actuator/startup -> events in response: 0 + GET /actuator/startup -> events in response: 0 +``` + +`POST` calls `drainBufferedTimeline()`, which empties the buffer so the memory can be +reclaimed. Every guide shows the `POST`. If you pipe it to a file and the file is wrong, the +data is gone — the application has to be restarted to record it again. Use `GET` while you +are still working out what you want. + +## You do not need a `@Bean` for it + +Boot registers the instance as a singleton named `applicationStartup` before the context +refreshes, so it can simply be injected. Declaring your own `@Bean` produces: + +``` +Parameter 0 of constructor in ...StartupDiagnosticsEndpoint required a single bean, +but 2 were found: + - bufferingApplicationStartup: defined by method 'bufferingApplicationStartup' ... + - applicationStartup: a programmatically registered singleton +``` + +Inject the `ApplicationStartup` interface and narrow with `instanceof`, not the concrete +`BufferingApplicationStartup` — otherwise the application refuses to start whenever +somebody runs it without tracking. Full transcript in +[`docs/output/01-api-corrections.txt`](output/01-api-corrections.txt). + +--- + +← prev [01 — The number Boot logs](01-the-number-boot-logs.md) · next → [03 — The four phases](03-the-four-phases.md) diff --git a/spring-boot-startup-time/docs/03-the-four-phases.md b/spring-boot-startup-time/docs/03-the-four-phases.md new file mode 100644 index 0000000..4f831c1 --- /dev/null +++ b/spring-boot-startup-time/docs/03-the-four-phases.md @@ -0,0 +1,87 @@ +# 03 — The four phases hiding inside one number + +← prev [02 — Turning instrumentation on](02-turning-instrumentation-on.md) · next → [04 — Reading the step tree](04-reading-the-step-tree.md) + +--- + +Grouping every recorded step by name and summing **self time** (see +[chapter 04](04-reading-the-step-tree.md) for why self and not total) gives the shape of a +startup. From [`docs/output/02-startup-tree.txt`](output/02-startup-tree.txt): + +``` + self ms count step + 4253.68 361 spring.beans.instantiate + 1014.51 1 spring.context.config-classes.parse + 402.81 1 spring.boot.application.environment-prepared + 160.39 1 spring.boot.webserver.create + 153.07 1 spring.boot.application.started + 113.74 1 spring.context.refresh + 95.72 1 spring.data.repository.proxy + 51.50 6 spring.beans.smart-initialize + 43.85 1 spring.data.repository.scanning +``` + +Four phases account for essentially all of it, and they respond to entirely different +fixes. + +## 1. Bean instantiation — `spring.beans.instantiate` + +361 steps, 4.25 s. This is constructors, `@PostConstruct`, `FactoryBean.getObject()` and +proxy creation. It is where your own code lives, and it is the only phase you can fix by +changing application code. + +Note what is *not* a separate step: `@PostConstruct` has no step of its own, so a cache +warm shows up inside the owning bean's `spring.beans.instantiate`. `tariffCacheWarmer` in +this repository spends all of its 504 ms in `@PostConstruct` and none in its constructor, +and the timeline cannot tell you which. + +## 2. Configuration class parsing — `spring.context.config-classes.parse` + +One step, 1.01 s, and under JFR it carries a tag naming the cost driver: + +``` +PT1.176668418S spring.context.config-classes.parse classCount=130, +``` + +130 configuration classes. This step is component scanning plus `@Conditional` evaluation +across every auto-configuration your classpath drags in. It is proportional to *classes +inspected*, not to beans created — see [chapter 06](06-the-classpath-scan-tax.md), where +adding 5,000 classes that are not beans at all still adds half a second here. + +## 3. Environment preparation — `spring.boot.application.environment-prepared` + +403 ms before any bean exists. Property sources, profile resolution, config data imports. +Cheap to ignore and impossible to tune from application code, but it explains why "the app +does nothing for the first half second". + +## 4. Everything else + +`spring.boot.webserver.create` (160 ms), the Spring Data repository steps (~150 ms across +five step names), `spring.beans.smart-initialize`. Individually small; collectively a +second. Spring Data's contribution scales with the number of repository *interfaces* and +derived query methods, since each one is parsed and proxied. + +## The step names, in the order they nest + +``` +spring.boot.application.starting +spring.boot.application.environment-prepared +spring.boot.application.context-prepared +spring.context.refresh + ├── spring.context.beandef-registry.post-process + │ └── spring.context.config-classes.parse ← scanning + conditions + ├── spring.context.bean-factory.post-process + ├── spring.context.beans.post-process + │ └── spring.beans.instantiate (×N, nested by dependency) + └── spring.boot.webserver.create +spring.boot.application.started +spring.boot.application.ready +``` + +A step is recorded **when it ends**, which is why the outermost ones appear last in the +timeline — and why they are the first casualties of a full buffer +([chapter 07](07-failure-modes.md)). + +--- + +← prev [02 — Turning instrumentation on](02-turning-instrumentation-on.md) · next → [04 — Reading the step tree](04-reading-the-step-tree.md) diff --git a/spring-boot-startup-time/docs/04-reading-the-step-tree.md b/spring-boot-startup-time/docs/04-reading-the-step-tree.md new file mode 100644 index 0000000..d03d7b9 --- /dev/null +++ b/spring-boot-startup-time/docs/04-reading-the-step-tree.md @@ -0,0 +1,86 @@ +# 04 — Reading the step tree: self time versus total time + +← prev [03 — The four phases](03-the-four-phases.md) · next → [05 — JFR instead of a buffer](05-jfr-instead-of-a-buffer.md) + +--- + +`/actuator/startup` hands back a flat list of steps, each with a `duration`. The obvious +move is to sort by duration. The obvious move is wrong, and it is wrong in a way that +reliably sends people to optimise the wrong thing. + +Steps nest. A step's duration includes every child step underneath it. Sorting by duration +therefore ranks **containers**, not culprits. Here are the same 400 steps from the same run, +sorted both ways ([`docs/output/02-startup-tree.txt`](output/02-startup-tree.txt)): + +``` +-- slowest individual steps by TOTAL time (the containers) -- + total ms self ms step / tags + 5829.88 113.74 spring.context.refresh + 1803.62 1413.83 spring.beans.instantiate &entityManagerFactory + 1344.76 18.09 spring.context.beans.post-process + 1088.90 22.48 spring.context.beandef-registry.post-process + 1066.42 1014.51 spring.context.config-classes.parse + 514.24 10.41 spring.beans.instantiate reportTemplateRegistry + 503.84 503.84 spring.beans.instantiate tariffCacheWarmer + 479.45 8.62 spring.beans.instantiate orderController +``` + +`spring.context.refresh` is top of the list at 5.8 s and is worth nothing to you: it is the +whole refresh. `reportTemplateRegistry` looks like the fifth worst bean in the application +at 514 ms. It costs **10 ms**. The other 504 ms belong to `tariffCacheWarmer`, which +`reportTemplateRegistry` happens to depend on and therefore triggers. Same story for +`orderController` at 479 ms total and 8.6 ms self: it is the first thing that asks for the +repository. + +Whichever bean happens to be constructed first in a dependency chain inherits the whole +chain's cost in the total column. That is an artefact of construction order, not of cost. + +## Computing self time + +Subtract the direct children. The steps carry `id` and `parentId`, so it is a one-pass +aggregation: + +```java +Map childNanos = new HashMap<>(); +for (TimelineEvent event : timeline.getEvents()) { + Long parent = event.getStartupStep().getParentId(); + if (parent != null) { + childNanos.merge(parent, event.getDuration().toNanos(), Long::sum); + } +} +long self = total - childNanos.getOrDefault(step.getId(), 0L); +``` + +Sorted by self time, the same run names four real costs and nothing else: + +``` +-- slowest individual steps by SELF time (the culprits) -- + self ms total ms step / tags + 1413.83 1803.62 spring.beans.instantiate &entityManagerFactory + 1014.51 1066.42 spring.context.config-classes.parse + 503.84 503.84 spring.beans.instantiate tariffCacheWarmer + 402.81 402.81 spring.boot.application.environment-prepared + 326.96 326.96 spring.beans.instantiate keystoreLoader + 268.41 312.88 spring.beans.instantiate dataSourceScriptDatabaseInitializer + 204.92 470.83 spring.beans.instantiate orderRepository +``` + +Hibernate's `EntityManagerFactory`, configuration parsing, and the two beans this +repository put there on purpose. `reportTemplateRegistry` and `orderController` have +correctly vanished. + +[`StartupDiagnosticsEndpoint`](../src/main/java/com/ankurm/startup/web/StartupDiagnosticsEndpoint.java) +does this and serves it at `/diag/startup`. It is about 90 lines and it is the single +highest-value thing in this repository. **Delete it before shipping** — it exposes bean +names and wiring. + +## The `&` prefix + +`&entityManagerFactory` is not a typo. The ampersand is Spring's `FactoryBean` dereference +prefix, so that step is the *factory* being built, not the object it produces. When a slow +bean name starts with `&`, the cost is in a `FactoryBean` implementation — here, +`LocalContainerEntityManagerFactoryBean` bootstrapping Hibernate 7.4.5. + +--- + +← prev [03 — The four phases](03-the-four-phases.md) · next → [05 — JFR instead of a buffer](05-jfr-instead-of-a-buffer.md) diff --git a/spring-boot-startup-time/docs/05-jfr-instead-of-a-buffer.md b/spring-boot-startup-time/docs/05-jfr-instead-of-a-buffer.md new file mode 100644 index 0000000..fc98ea5 --- /dev/null +++ b/spring-boot-startup-time/docs/05-jfr-instead-of-a-buffer.md @@ -0,0 +1,103 @@ +# 05 — JFR instead of a buffer + +← prev [04 — Reading the step tree](04-reading-the-step-tree.md) · next → [06 — The classpath-scan tax](06-the-classpath-scan-tax.md) + +--- + +`FlightRecorderApplicationStartup` lives in `spring-core`, needs no dependency, and emits +each `StartupStep` as a JFR event. Swap the tracker and start a recording: + +```bash +java -XX:StartFlightRecording=filename=startup.jfr,settings=profile,dumponexit=true \ + -Dstartup.tracking=jfr -jar app.jar +``` + +Everything below is from [`docs/output/03-jfr.txt`](output/03-jfr.txt). + +## The event type + +``` +@Name("org.springframework.core.metrics.jfr.FlightRecorderStartupEvent") +@Category("Spring Application") +@Label("Startup Step") +@Description("Spring Application Startup") +class FlightRecorderStartupEvent extends jdk.jfr.Event { ... } +``` + +In JDK Mission Control it appears under the **Spring Application** category. On the command +line, the name matters more than you would expect: + +``` + --events StartupEvent -> 0 events + --events 'org.springframework.core.metrics.jfr.FlightRecorderStartupEvent' -> 398 events +``` + +`jfr print --events` matches the `@Name`, which is the fully qualified class name. The short +form silently returns nothing — no error, no warning, just an empty result that reads like +"Spring did not record anything". + +## Reading it without Mission Control + +```bash +jfr summary startup.jfr +jfr print --events 'org.springframework.core.metrics.jfr.FlightRecorderStartupEvent' \ + --json startup.jfr +``` + +The eight slowest, sorted by the recording's own `duration` field: + +``` + duration name / tags +PT6.544849841S spring.context.refresh +PT2.263845435S spring.beans.instantiate beanName=&entityManagerFactory,... +PT1.500763631S spring.context.beans.post-process +PT1.202591188S spring.context.beandef-registry.post-process postProcessor=...ConfigurationClassPostProcessor@76b224cd +PT1.176668418S spring.context.config-classes.parse classCount=130 +PT0.538651275S spring.beans.instantiate beanName=reportTemplateRegistry +PT0.535484510S spring.beans.instantiate beanName=tariffCacheWarmer +PT0.515340537S spring.boot.webserver.create factory=...TomcatServletWebServerFactory +``` + +(That run started in 7.441 s; the buffered run in [chapter 04](04-reading-the-step-tree.md) +started in 6.6 s. Same jar, different runs — see [chapter 07](07-failure-modes.md) on why +a single measurement is not a result.) + +Note that this is the *total time* list from +[chapter 04](04-reading-the-step-tree.md), with `spring.context.refresh` on top and +`reportTemplateRegistry` above `tariffCacheWarmer`. JFR gives you durations and parent ids; +it does not compute self time either. The same subtraction applies. + +## What JFR buys you that the buffer does not + +Correlation. The recording holds the JVM's own view of the same seconds: + +``` + jdk.ExecutionSample 345 + jdk.GCPhasePauseLevel1 132 + jdk.GCPhasePause 39 (289.8 ms of pause in total) + jdk.Compilation 16 + jdk.ClassLoaderStatistics 10 +``` + +If a bean's constructor is slow because a young collection landed in the middle of it, the +buffer shows you a slow bean and JFR shows you why. That is the case for using it. + +## What it costs you + +- The recording is written to a file on the machine, not served over HTTP. In a container + that means a volume or a copy out. +- The `tags` are serialised into one flat `String` attribute, because JFR events only carry + base types. Parsing `beanName=x,beanType=y,` is on you. +- `settings=profile` records a great deal more than startup steps. For a 7-second startup + that is fine; left on in production it is not. + +## Buffer or JFR? + +Use the buffer when the question is "which bean", and you can reach the application over +HTTP. Use JFR when the question is "why is that bean slow", when startup fails before the +web server is up (the buffer is unreachable then; the JFR file is not), or when you need +the same recording to answer a GC question. + +--- + +← prev [04 — Reading the step tree](04-reading-the-step-tree.md) · next → [06 — The classpath-scan tax](06-the-classpath-scan-tax.md) diff --git a/spring-boot-startup-time/docs/06-the-classpath-scan-tax.md b/spring-boot-startup-time/docs/06-the-classpath-scan-tax.md new file mode 100644 index 0000000..a9788af --- /dev/null +++ b/spring-boot-startup-time/docs/06-the-classpath-scan-tax.md @@ -0,0 +1,67 @@ +# 06 — The classpath-scan tax, measured + +← prev [05 — JFR instead of a buffer](05-jfr-instead-of-a-buffer.md) · next → [07 — Failure modes](07-failure-modes.md) + +--- + +"Narrow your component scan" is standard advice with no number attached to it. Here is the +number, from [`docs/output/04-scan-tax.txt`](output/04-scan-tax.txt). + +The experiment adds classes to the package `@SpringBootApplication` already scans and +changes nothing else. `plain` classes carry no annotation at all, which separates the cost +of *scanning* from the cost of *creating beans*. + +``` +variant | Started in (s) | parse ms | instMs | steps +---------------------------+---------------------+-----------+-----------+------- +baseline | 7.293,6.685,6.86 | 1055.69 | 4854.73 | 400 ++5000 plain classes | 7.626,7.143,7.04 | 1617.38 | 4468.31 | 400 ++5000 @Component | 11.02,11.647,11.481 | 3221.82 | 6097.98 | 5400 ++5000 @Component, lazy | 9.688,9.374,9.609 | 3434.76 | 4982.61 | 324 +``` + +Reproduce with `RUNS=3 ./scripts/demo-scan-tax.sh` (about ten minutes — each variant is a +full rebuild). + +## What the rows say + +**5,000 classes that are not beans cost ~560 ms.** `parse` goes from 1056 ms to 1617 ms +while the step count stays at exactly 400 and instantiation is unchanged. That is roughly +**0.11 ms per class inspected** on this machine. The scanner opens every `.class` file +under the base package and reads its annotation metadata before it can decide the class is +uninteresting. Classes you never wrote a `@Component` on are still on the bill. + +**Making them beans roughly triples the tax.** `parse` goes to 3.2 s, instantiation gains +1.2 s, and the timeline goes from 400 steps to 5,400. Startup goes from ~6.9 s to ~11.5 s. + +**Lazy initialisation does not touch the scan.** With the same 5,000 components, +`spring.main.lazy-initialization=true` leaves `parse` at 3.4 s — statistically unchanged — +and buys back 1.1 s of instantiation, for ~9.6 s. Lazy init defers *construction*. Bean +definitions are still created, and every class is still scanned, because Spring cannot know +whether a class is a bean without looking at it. + +That is the important asymmetry: **scanning is paid at startup no matter what you do at +runtime.** The only fix is to scan less. + +Note also that the lazy row records **324 steps against a baseline of 400**. Lazy +initialisation makes the startup tree *less* informative at exactly the moment you are +trying to read it — the beans it defers never produce a `spring.beans.instantiate` step, so +the cost moves to the first request and out of your recording entirely. + +## What to do about it + +- Set `scanBasePackages` explicitly rather than relying on the package of the main class. + An application whose main class sits in `com.example` scans `com.example.**`, which on a + large monolith is everything. +- Watch the `classCount` tag on `spring.context.config-classes.parse` (visible under JFR, + see [chapter 05](05-jfr-instead-of-a-buffer.md)). This application reports 130. If yours + reports several hundred, most of them arrived with a starter you are not using. +- `spring-context-indexer` still ships (7.0.9 is on Central) and writes a + `META-INF/spring.components` index at compile time so the scanner does not walk the + classpath. It is worth knowing about; Spring's own direction of travel is AOT instead. +- The AOT cache is the bigger lever, and it is measured in + [chapter 08](08-what-actually-helps.md). + +--- + +← prev [05 — JFR instead of a buffer](05-jfr-instead-of-a-buffer.md) · next → [07 — Failure modes](07-failure-modes.md) diff --git a/spring-boot-startup-time/docs/07-failure-modes.md b/spring-boot-startup-time/docs/07-failure-modes.md new file mode 100644 index 0000000..5346caa --- /dev/null +++ b/spring-boot-startup-time/docs/07-failure-modes.md @@ -0,0 +1,89 @@ +# 07 — Failure modes + +← prev [06 — The classpath-scan tax](06-the-classpath-scan-tax.md) · next → [08 — What actually helps](08-what-actually-helps.md) + +--- + +## The buffer truncates silently + +`BufferingApplicationStartup` takes a capacity in its only constructor. Every guide picks +2048. Nothing tells you what happens when the application produces more steps than that — +so here it is, with 5,000 extra `@Component` classes on the classpath +([`docs/output/06-buffer-overflow.txt`](output/06-buffer-overflow.txt)): + +``` +--- capacity 2048 --- + started, recorded steps: 2048 +--- capacity 16384 --- + started, recorded steps: 5400 +``` + +The endpoint returns `200` with a well-formed answer. `grep -ic buffer app.log` returns +**0**. There is no warning and no exception. + +It is worse than losing a suffix. Steps are recorded **when they end**, so the buffer keeps +the *first* ones to finish — the innermost leaves — and drops the enclosing ones: + +``` + first 3: ['spring.boot.application.starting', + 'spring.boot.application.environment-prepared', + 'spring.boot.application.context-prepared'] + last 3 : ['spring.beans.instantiate', ...] + last tags: [{'key': 'beanName', 'value': 'bulk2718'}] +``` + +`spring.context.refresh`, `spring.boot.application.started` and +`spring.boot.application.ready` are absent from the truncated timeline. Any self-time +calculation is now missing its outer frame, and any "the whole refresh took N" figure is +simply not in the data. + +The capacity is the number of **steps**, not beans, and this application records slightly +more than one step per bean. 16384 costs a few megabytes that are freed on the first drain. +Pick the large number. + +`aFullBufferTruncatesSilentlyAndLosesTheOuterSteps` in +[`StartupTimelineContractTests`](../src/test/java/com/ankurm/startup/StartupTimelineContractTests.java) +pins this behaviour. + +## `POST` destroys the recording + +Covered in [chapter 02](02-turning-instrumentation-on.md), repeated here because it is the +most expensive one: `POST /actuator/startup` drains. The second call returns an empty +timeline, and so does every subsequent `GET`. If you are following a guide that pipes the +`POST` into `jq` and the `jq` expression is wrong, restart the application — the data is +gone. + +## Injecting the concrete type + +```java +public StartupDiagnosticsEndpoint(BufferingApplicationStartup startup) { ... } +``` + +compiles, works in every test, and stops the application from starting the first time +somebody runs it without `-Dstartup.tracking=buffering`, because the registered singleton +is then a `DefaultApplicationStartup`. Inject the interface, narrow with `instanceof`, and +answer honestly when tracking is off. + +## Killing the app by its main class + +Not a Spring problem, but it cost a run while producing this repository. `pkill -f +StartupDiagnosisApplication` also matches the shell that is running the script that contains +that string, and kills it. [`scripts/stop.sh`](../scripts/stop.sh) matches on the executable +being `java` **and** the jar name: + +```bash +ps -eo pid=,comm=,args= | awk '$2 == "java" && /startup-diagnosis-1\.0\.0\.jar/ { print $1 }' +``` + +## Trusting a single run + +Startup timings on a shared or containerised machine move by several hundred milliseconds +between runs of the same jar — see the per-run columns in +[`docs/output/05-what-helps.txt`](output/05-what-helps.txt), where the same configuration +produced 6.456 s and 7.473 s. Take a median of four or more, and treat any difference under +about 10% as noise. Every number in this repository that matters is a ratio between two +such medians, not a single measurement. + +--- + +← prev [06 — The classpath-scan tax](06-the-classpath-scan-tax.md) · next → [08 — What actually helps](08-what-actually-helps.md) diff --git a/spring-boot-startup-time/docs/08-what-actually-helps.md b/spring-boot-startup-time/docs/08-what-actually-helps.md new file mode 100644 index 0000000..a55100e --- /dev/null +++ b/spring-boot-startup-time/docs/08-what-actually-helps.md @@ -0,0 +1,98 @@ +# 08 — What actually helps + +← prev [07 — Failure modes](07-failure-modes.md) + +--- + +Same jar, same machine, four runs each, median in the last column. From +[`docs/output/05-what-helps.txt`](output/05-what-helps.txt): + +``` +variant | Started in (s), each run | median +-----------------------------------+----------------------------+--------- +no tracking | 6.871,6.456,7.473,6.992 | 6.9315 +BufferingApplicationStartup | 6.448,6.856,6.416,6.528 | 6.488 +FlightRecorder + recording | 6.496,6.739,6.343,6.475 | 6.4855 +lazy-initialization | 5.075,5.331,5.217,5.266 | 5.2415 +AOT cache (-XX:AOTCache) | 5.028,4.729,4.708,4.905 | 4.817 +AOT cache + lazy | 3.649,3.488,3.354,3.384 | 3.436 +``` + +## Measuring is free + +The two instrumented rows are *inside the noise band of the uninstrumented one* — the +buffering median is actually lower than the baseline median, which tells you the difference +is smaller than the run-to-run variance rather than that recording makes things faster. + +Whatever the reason people leave startup tracking off, cost is not one of it. It is +reasonable to ship `BufferingApplicationStartup` in a staging profile permanently. + +## Lazy initialisation: real, and it moves the cost + +~6.93 s to ~5.24 s, about 24%. But the work is deferred, not removed: the first request that +touches a deferred bean pays for it, and a readiness probe that returns `200` before those +beans exist will send traffic to an application that is not ready. It also +[shrinks the startup tree](06-the-classpath-scan-tax.md) — 324 steps against 400 — which +makes it a poor thing to enable while you are still diagnosing. + +Use it in development. Think carefully in production. + +## The JDK 25 AOT cache + +JDK 25 ships the Project Leyden AOT cache (JEP 483 class loading, JEP 515 method profiling). +It is a two-step build: a training run records what the application loads, an assembly run +turns that into a cache, and subsequent runs read it. + +```bash +java -XX:AOTMode=record -XX:AOTConfiguration=app.aotconf -jar app.jar # train, then stop +java -XX:AOTMode=create -XX:AOTConfiguration=app.aotconf -XX:AOTCache=app.aot -jar app.jar +java -XX:AOTCache=app.aot -jar app.jar # every run after +``` + +``` +AOTCache creation is complete: /tmp/app.aot 118001664 bytes +``` + +6.93 s to 4.82 s — **about 30%**, with no change to a line of application code. Combined +with lazy initialisation, 3.44 s: half the original. + +Where does it come from? Running the same tracker under both: + +``` +run | parse ms | inst ms | webserver +-----------------------+-----------+-----------+---------- +plain | 986.66 | 4344.21 | 150.69 +aotcache | 729.16 | 3155.96 | 100.96 +``` + +Every phase gets cheaper — parse by 26%, instantiation by 27%, web server creation by 33%. +The AOT cache does not remove a phase; it removes class loading and linking, and class +loading is distributed through all of them. That is a useful thing to know before you go +looking for the one phase it "fixed". + +The costs are real: the cache is 118 MB for this small application, it is tied to the exact +classpath that produced it, and a training run has to be part of your build. See the +[Project Leyden AOT cache post](https://ankurm.com/project-leyden-aot-cache-java/) for the +invalidation rules and the CI shape. + +## What did not make the list + +- **Tuning the JVM's heap or GC.** The JFR recording holds 39 `jdk.GCPhasePause` events + totalling **289.8 ms** across a 7.4 s startup — about 4%. Real, but it is not where the + seconds are, and it is the cheapest thing on this list to get wrong. +- **Switching web server.** `spring.boot.webserver.create` is 160 ms of 6,900. +- **Removing the diagnostics endpoint.** It costs nothing at startup. Remove it because it + exposes your wiring, not for speed. + +## The honest order of operations + +1. Turn on `BufferingApplicationStartup`, look at self time, and fix your own slow beans. + `keystoreLoader` and `tariffCacheWarmer` here are 830 ms between them and both could be + moved off the startup path. +2. Narrow the component scan if `classCount` is large. +3. Then, and only then, reach for the AOT cache — it is a build-pipeline change, and it is + much easier to justify once you know it is not hiding a 500 ms `@PostConstruct`. + +--- + +← prev [07 — Failure modes](07-failure-modes.md) diff --git a/spring-boot-startup-time/docs/output/00-versions.txt b/spring-boot-startup-time/docs/output/00-versions.txt new file mode 100644 index 0000000..c30f47b --- /dev/null +++ b/spring-boot-startup-time/docs/output/00-versions.txt @@ -0,0 +1,18 @@ +=== java -version === +openjdk version "25.0.4.1" 2026-08-18 LTS +OpenJDK Runtime Environment Temurin-25.0.4.1+1 (build 25.0.4.1+1-LTS) +OpenJDK 64-Bit Server VM Temurin-25.0.4.1+1 (build 25.0.4.1+1-LTS, mixed mode, sharing) + +=== mvn -version === +Apache Maven 3.9.11 (3e54c93a704957b63ee3494413a2b544fd3d825b) + +=== mvn dependency:list (selected) === + com.h2database:h2:jar:2.4.240:runtime -- module com.h2database [auto] + io.micrometer:micrometer-core:jar:1.17.1:compile -- module micrometer.core [auto] + org.apache.tomcat.embed:tomcat-embed-core:jar:11.0.24:compile -- module org.apache.tomcat.embed.core + org.hibernate.orm:hibernate-core:jar:7.4.5.Final:compile -- module org.hibernate.orm.core [auto] + org.springframework.boot:spring-boot:jar:4.1.1:compile -- module spring.boot [auto] + org.springframework.data:spring-data-jpa:jar:4.1.1:compile -- module spring.data.jpa [auto] + org.springframework:spring-beans:jar:7.0.9:compile -- module spring.beans [auto] + org.springframework:spring-context:jar:7.0.9:compile -- module spring.context [auto] + org.springframework:spring-core:jar:7.0.9:compile -- module spring.core [auto] diff --git a/spring-boot-startup-time/docs/output/01-api-corrections.txt b/spring-boot-startup-time/docs/output/01-api-corrections.txt new file mode 100644 index 0000000..72d978d --- /dev/null +++ b/spring-boot-startup-time/docs/output/01-api-corrections.txt @@ -0,0 +1,56 @@ +=== Where getApplicationStartup() actually lives (Spring Framework 7.0.9) === + +Injecting ApplicationContext and calling getApplicationStartup() does not compile: + + [ERROR] .../config/StartupBeans.java:[22,45] cannot find symbol + symbol: method getApplicationStartup() + location: variable context of type org.springframework.context.ApplicationContext + +javap says the accessor is declared one interface down, and also on the bean factory: + + $ javap -cp . org.springframework.context.ConfigurableApplicationContext | grep ApplicationStartup + public abstract void setApplicationStartup(org.springframework.core.metrics.ApplicationStartup); + public abstract org.springframework.core.metrics.ApplicationStartup getApplicationStartup(); + + $ javap -cp . org.springframework.beans.factory.config.ConfigurableBeanFactory | grep ApplicationStartup + public abstract void setApplicationStartup(org.springframework.core.metrics.ApplicationStartup); + public abstract org.springframework.core.metrics.ApplicationStartup getApplicationStartup(); + +=== The buffering API surface (spring-boot 4.1.1) === + + $ javap -cp . org.springframework.boot.context.metrics.buffering.BufferingApplicationStartup + public class BufferingApplicationStartup implements org.springframework.core.metrics.ApplicationStartup { + public BufferingApplicationStartup(int); + public void startRecording(); + public void addFilter(java.util.function.Predicate); + public org.springframework.core.metrics.StartupStep start(java.lang.String); + public StartupTimeline getBufferedTimeline(); + public StartupTimeline drainBufferedTimeline(); + } + + $ javap -cp . org.springframework.boot.context.metrics.buffering.StartupTimeline$TimelineEvent + public class StartupTimeline$TimelineEvent { + public java.time.Instant getStartTime(); + public java.time.Instant getEndTime(); + public java.time.Duration getDuration(); + public org.springframework.core.metrics.StartupStep getStartupStep(); + } + +Note: there is no setter for the buffer size and no Spring property that installs this. +The only constructor takes the capacity, and it must be handed to SpringApplication +before run(). + +=== You do not need a @Bean method for it === + +Declaring one produces a startup failure, because Boot has already registered the +instance as a singleton: + + Parameter 0 of constructor in com.ankurm.startup.web.StartupDiagnosticsEndpoint + required a single bean, but 2 were found: + - bufferingApplicationStartup: defined by method 'bufferingApplicationStartup' + in class path resource [com/ankurm/startup/config/StartupBeans.class] + - applicationStartup: a programmatically registered singleton + +So the correct move is to inject ApplicationStartup directly and narrow with instanceof. +Injecting BufferingApplicationStartup by its concrete type compiles and works -- until +somebody runs without tracking, at which point the application will not start at all. diff --git a/spring-boot-startup-time/docs/output/02-startup-tree.txt b/spring-boot-startup-time/docs/output/02-startup-tree.txt new file mode 100644 index 0000000..1be47ef --- /dev/null +++ b/spring-boot-startup-time/docs/output/02-startup-tree.txt @@ -0,0 +1,67 @@ +=== Boot's own startup line === +Started StartupDiagnosisApplication in 6.6 seconds (process running for 7.4) + +=== /diag/startup === +recorded steps: 400 + +-- self time by step name (self = duration minus direct children) -- + self ms count step + 4253.68 361 spring.beans.instantiate + 1014.51 1 spring.context.config-classes.parse + 402.81 1 spring.boot.application.environment-prepared + 160.39 1 spring.boot.webserver.create + 153.07 1 spring.boot.application.started + 113.74 1 spring.context.refresh + 95.72 1 spring.data.repository.proxy + 51.50 6 spring.beans.smart-initialize + 43.85 1 spring.data.repository.scanning + 35.02 1 spring.boot.application.starting + 31.10 9 spring.context.bean-factory.post-process + 22.48 1 spring.context.beandef-registry.post-process + 18.09 1 spring.context.beans.post-process + 13.78 1 spring.boot.application.context-loaded + 12.92 1 spring.data.repository.composition + 5.15 5 spring.data.repository.postprocessor + 4.70 1 spring.data.repository.init + 0.89 1 spring.data.repository.target + 0.68 1 spring.context.config-classes.enhance + 0.48 1 spring.boot.application.ready + 0.42 1 spring.data.repository.postprocessors + 0.26 1 spring.boot.application.context-prepared + 0.07 1 spring.data.repository.metadata + +-- slowest individual steps by SELF time (the culprits) -- + self ms total ms step / tags + 1413.83 1803.62 spring.beans.instantiate &entityManagerFactory + 1014.51 1066.42 spring.context.config-classes.parse + 503.84 503.84 spring.beans.instantiate tariffCacheWarmer + 402.81 402.81 spring.boot.application.environment-prepared + 326.96 326.96 spring.beans.instantiate keystoreLoader + 268.41 312.88 spring.beans.instantiate dataSourceScriptDatabaseInitializer + 204.92 470.83 spring.beans.instantiate orderRepository + 160.39 460.45 spring.boot.webserver.create + 153.07 153.07 spring.boot.application.started + 113.74 5829.88 spring.context.refresh + 95.72 101.29 spring.data.repository.proxy + 64.25 64.25 spring.beans.instantiate jpaMappingContext + +-- slowest individual steps by TOTAL time (the containers) -- + total ms self ms step / tags + 5829.88 113.74 spring.context.refresh + 1803.62 1413.83 spring.beans.instantiate &entityManagerFactory + 1344.76 18.09 spring.context.beans.post-process + 1088.90 22.48 spring.context.beandef-registry.post-process + 1066.42 1014.51 spring.context.config-classes.parse + 514.24 10.41 spring.beans.instantiate reportTemplateRegistry + 503.84 503.84 spring.beans.instantiate tariffCacheWarmer + 479.45 8.62 spring.beans.instantiate orderController + 470.83 204.92 spring.beans.instantiate orderRepository + 460.45 160.39 spring.boot.webserver.create + 402.81 402.81 spring.boot.application.environment-prepared + 326.96 326.96 spring.beans.instantiate keystoreLoader + +=== actuator's own endpoint: GET peeks, POST drains === + GET /actuator/startup -> events in response: 400 + POST /actuator/startup -> events in response: 400 + POST /actuator/startup -> events in response: 0 + GET /actuator/startup -> events in response: 0 diff --git a/spring-boot-startup-time/docs/output/03-jfr.txt b/spring-boot-startup-time/docs/output/03-jfr.txt new file mode 100644 index 0000000..6b1d449 --- /dev/null +++ b/spring-boot-startup-time/docs/output/03-jfr.txt @@ -0,0 +1,60 @@ +Started StartupDiagnosisApplication in 7.441 seconds (process running for 8.49) + +=== jfr summary (Spring rows only) === + + Version: 2.1 + Chunks: 1 +========================================================================================= + org.springframework.core.metrics.jfr.FlightRecorderStartupEvent 398 33261 + +=== the event type, in full === +@Name("org.springframework.core.metrics.jfr.FlightRecorderStartupEvent") +@Category("Spring Application") +@Label("Startup Step") +@Description("Spring Application Startup") +class FlightRecorderStartupEvent extends jdk.jfr.Event { + @Label("Start Time") + @Timestamp("TICKS") + long startTime; + + @Label("Duration") + @Timespan("TICKS") + long duration; + + @Label("Event Thread") + @Description("Thread in which event was committed in") + Thread eventThread; + + @Label("Stack Trace") + @Description("Stack Trace starting from the method the event was committed in") + StackTrace stackTrace; + + long eventId; + + +=== the selector matters: the event is named by its FQCN, not 'StartupEvent' === + --events StartupEvent -> 0 events + --events 'org.springframework.core.*' -> 398 events + +=== 8 slowest startup steps, straight out of the recording === +398 StartupEvent records in the recording + + duration name / tags +PT6.544849841S spring.context.refresh +PT2.263845435S spring.beans.instantiate beanName=&entityManagerFactory,beanType=interface org.springframework.context.weaving.LoadTimeWeaverAware, +PT1.500763631S spring.context.beans.post-process +PT1.202591188S spring.context.beandef-registry.post-process postProcessor=org.springframework.context.annotation.ConfigurationClassPostProcessor@76b224cd, +PT1.176668418S spring.context.config-classes.parse classCount=130, +PT0.538651275S spring.beans.instantiate beanName=reportTemplateRegistry, + PT0.53548451S spring.beans.instantiate beanName=tariffCacheWarmer,beanType=class com.ankurm.startup.slow.TariffCacheWarmer, +PT0.515340537S spring.boot.webserver.create factory=class org.springframework.boot.tomcat.servlet.TomcatServletWebServerFactory, + +=== what JFR gives you that the buffer does not: JVM context in the same file === + jdk.ExecutionSample 345 3787 + jdk.GCPhasePauseLevel1 132 5281 + jdk.GCPhasePauseLevel2 50 1744 + jdk.GCPhasePause 39 937 + jdk.Compilation 16 452 + jdk.ClassLoaderStatistics 10 260 + + total GC pause time during this startup: 39 events, 289.8 ms diff --git a/spring-boot-startup-time/docs/output/04-scan-tax.txt b/spring-boot-startup-time/docs/output/04-scan-tax.txt new file mode 100644 index 0000000..5cdde5c --- /dev/null +++ b/spring-boot-startup-time/docs/output/04-scan-tax.txt @@ -0,0 +1,10 @@ +runs per variant: 3 (first run of each also queried for phase self times) + +variant | Started in (s) | parse ms | instMs | steps +---------------------------+--------------------+-----------+-----------+------- +baseline | 7.293,6.685,6.86 | 1055.69 | 4854.73 | 400 ++5000 plain classes | 7.626,7.143,7.04 | 1617.38 | 4468.31 | 400 ++5000 @Component | 11.02,11.647,11.481 | 3221.82 | 6097.98 | 5400 ++5000 @Component, lazy | 9.688,9.374,9.609 | 3434.76 | 4982.61 | 324 + +bulk package removed; jar rebuilt at baseline. diff --git a/spring-boot-startup-time/docs/output/05-what-helps.txt b/spring-boot-startup-time/docs/output/05-what-helps.txt new file mode 100644 index 0000000..85e3584 --- /dev/null +++ b/spring-boot-startup-time/docs/output/05-what-helps.txt @@ -0,0 +1,32 @@ +variant | Started in (s), each run | median +-----------------------------------+----------------------------+--------- +no tracking | 6.871,6.456,7.473,6.992 | 6.9315 +BufferingApplicationStartup | 6.448,6.856,6.416,6.528 | 6.488 +FlightRecorder + recording | 6.496,6.739,6.343,6.475 | 6.4855 +lazy-initialization | 5.075,5.331,5.217,5.266 | 5.2415 + +=== JDK 25 AOT cache (Project Leyden) === +openjdk version "25.0.4.1" 2026-08-18 LTS +-- training run (-XX:AOTMode=record) -- +-rw-r--r-- 1 eloquent-blissful-maxwell eloquent-blissful-maxwell 119484416 Sep 4 23:44 /tmp/app.aotconf +-- assembly run (-XX:AOTMode=create) -- +Reading AOTConfiguration /tmp/app.aotconf and writing AOTCache /tmp/app.aot +AOTCache creation is complete: /tmp/app.aot 118001664 bytes +-rw-r--r-- 1 eloquent-blissful-maxwell eloquent-blissful-maxwell 118001664 Sep 4 23:44 /tmp/app.aot + +AOT cache (-XX:AOTCache) | 5.028,4.729,4.708,4.905 | 4.817 +AOT cache + lazy | 3.649,3.488,3.354,3.384 | 3.436 + +=== where the AOT cache takes the time from (same tracker, same jar) === +run | parse ms | inst ms | webserver +-----------------------+-----------+-----------+---------- +plain | 986.66 | 4344.21 | 150.69 +aotcache | 729.16 | 3155.96 | 100.96 + +Notes: + * Timings are from one machine (Temurin 25.0.4.1+1, Linux x86_64, container) and are + indicative. The ratios between rows are the point, not the absolute numbers. + * "no tracking" and the two instrumented rows overlap. Recording startup steps is not + measurably slower than not recording them on this application. + * The AOT cache was trained on this exact jar with -XX:AOTMode=record and assembled with + -XX:AOTMode=create. It is 118 MB and is invalidated by a classpath change. diff --git a/spring-boot-startup-time/docs/output/06-buffer-overflow.txt b/spring-boot-startup-time/docs/output/06-buffer-overflow.txt new file mode 100644 index 0000000..3443c9b --- /dev/null +++ b/spring-boot-startup-time/docs/output/06-buffer-overflow.txt @@ -0,0 +1,28 @@ +--- capacity 2048 --- + started, recorded steps: 2048 +--- capacity 16384 --- + started, recorded steps: 5400 + +=== which steps survive truncation (capacity 2048, 5400 available) === + + $ curl -s localhost:8080/actuator/startup | python3 -c '...' + events: 2048 + first 3: ['spring.boot.application.starting', + 'spring.boot.application.environment-prepared', + 'spring.boot.application.context-prepared'] + last 3 : ['spring.beans.instantiate', 'spring.beans.instantiate', 'spring.beans.instantiate'] + last tags: [{'key': 'beanName', 'value': 'bulk2718'}] + names: [('spring.beans.instantiate', 2029), + ('spring.context.bean-factory.post-process', 9), + ('spring.boot.application.starting', 1), + ('spring.boot.application.environment-prepared', 1)] + +The buffer keeps the FIRST 2048 steps and drops everything after. The timeline therefore +ends mid-instantiation, and 'spring.context.refresh', 'spring.boot.application.started' +and 'spring.boot.application.ready' -- the steps that bracket everything else -- are +absent, because a step is only recorded when it ENDS. + + $ grep -ic buffer app.log + 0 + +No warning. No exception. The endpoint returns 200 with a well-formed, truncated answer. diff --git a/spring-boot-startup-time/pom.xml b/spring-boot-startup-time/pom.xml new file mode 100644 index 0000000..2db3d98 --- /dev/null +++ b/spring-boot-startup-time/pom.xml @@ -0,0 +1,58 @@ + + + 4.0.0 + + + org.springframework.boot + spring-boot-starter-parent + 4.1.1 + + + + com.ankurm + startup-diagnosis + 1.0.0 + startup-diagnosis + Bean-by-bean diagnosis of Spring Boot startup time + + + 25 + UTF-8 + + + + + org.springframework.boot + spring-boot-starter-web + + + org.springframework.boot + spring-boot-starter-actuator + + + org.springframework.boot + spring-boot-starter-data-jpa + + + com.h2database + h2 + runtime + + + org.springframework.boot + spring-boot-starter-test + test + + + + + + + org.springframework.boot + spring-boot-maven-plugin + + + + diff --git a/spring-boot-startup-time/post/images/01-self-time-vs-total-time.svg b/spring-boot-startup-time/post/images/01-self-time-vs-total-time.svg new file mode 100644 index 0000000..686fd3e --- /dev/null +++ b/spring-boot-startup-time/post/images/01-self-time-vs-total-time.svg @@ -0,0 +1,38 @@ + + + + +Same 400 steps, sorted two ways + +SORTED BY TOTAL DURATION — ranks containers + +spring.context.refresh5829 ms + +&entityManagerFactory1804 ms + +reportTemplateRegistry514 ms + +tariffCacheWarmer504 ms + +SORTED BY SELF TIME — ranks culprits + +&entityManagerFactory1414 ms + +config-classes.parse1015 ms + +tariffCacheWarmer504 ms + +spring.context.refresh114 ms + +reportTemplateRegistry10 ms + +reportTemplateRegistry looks like the fifth-worst bean in the application. It costs 10 ms. +The other 504 ms belong to tariffCacheWarmer, which it happens to depend on and therefore triggers first. +Whichever bean is constructed first in a dependency chain inherits the whole chain in the total column. +That is an artefact of construction order. It is not a cost. + diff --git a/spring-boot-startup-time/post/images/02-buffer-truncation.svg b/spring-boot-startup-time/post/images/02-buffer-truncation.svg new file mode 100644 index 0000000..b3af361 --- /dev/null +++ b/spring-boot-startup-time/post/images/02-buffer-truncation.svg @@ -0,0 +1,29 @@ + + + + +What a 2048-step buffer keeps, and what it throws away +STEPS, IN THE ORDER THEY END → + + +2048 leaf steps: spring.beans.instantiate bulk1 … bulk2718 + +3352 more instantiate steps — dropped + + +spring.context.refresh — dropped + +application.started / ready — dropped + + +capacity reached + +The outermost steps end last, so they are the first casualties. Self-time arithmetic is now missing its outer frame, +and the “whole refresh took N” figure is simply not in the data — while the endpoint still answers 200. +The capacity counts steps, not beans. 16384 costs a few megabytes that are freed on the first drain. Pick the large number. + diff --git a/spring-boot-startup-time/post/meta.md b/spring-boot-startup-time/post/meta.md new file mode 100644 index 0000000..8a69270 --- /dev/null +++ b/spring-boot-startup-time/post/meta.md @@ -0,0 +1,57 @@ +# Post metadata + +## Title + +Why Your Spring Boot App Takes 8 Seconds to Start: A Bean-by-Bean Diagnosis + +## Slug + +`spring-boot-startup-time-bean-by-bean-diagnosis` + +## Excerpt + +Spring Boot logs one startup number and hides four phases behind it. This walks through +turning on the `ApplicationStartup` instrumentation that ships switched off, reading the step +tree by self time rather than total duration — the mistake that makes people optimise a bean +costing 10 ms instead of the one costing 504 — and then puts measured numbers on component +scanning (0.11 ms per class inspected, whether or not it is a bean), on the silent truncation +a 2048-step buffer performs on your recording, and on the JDK 25 AOT cache, which took +6.93 s to 4.82 s on the companion project without a line of application code changing. + +## Categories + +| Category | Term ID | +|---|---| +| Java | 328 | +| Spring | 355 | + +## Yoast + +| Field | Value | +|---|---| +| `_yoast_wpseo_title` | Spring Boot Startup Time: A Bean-by-Bean Diagnosis | +| `_yoast_wpseo_metadesc` | Turn on Spring Boot's built-in startup instrumentation, read the step tree by self time, and see measured numbers for component scanning, buffer truncation and the JDK 25 AOT cache. | +| `_yoast_wpseo_focuskw` | spring boot startup time | + +## Files + +| File | Contents | +|---|---| +| [`post.md`](post.md) | article body, Markdown | +| [`images/01-self-time-vs-total-time.svg`](images/01-self-time-vs-total-time.svg) | the same 400 steps ranked by total duration and by self time | +| [`images/02-buffer-truncation.svg`](images/02-buffer-truncation.svg) | what a 2048-step buffer keeps and what it silently drops | + +## Companion project + +[`spring-boot-startup-time/`](..) in `asmhatre/spring-boot-demo`. + +## Jira + +[BLOG-618](https://ankurm.atlassian.net/browse/BLOG-618) + +## Verified against + +Spring Boot 4.1.1 (GA 20 August 2026), Spring Framework 7.0.9, Spring Data JPA 4.1.1, +Hibernate ORM 7.4.5.Final, Tomcat 11.0.24, Micrometer 1.17.1, H2 2.4.240, +Temurin 25.0.4.1+1 LTS, Maven 3.9.11 — see +[`docs/output/00-versions.txt`](../docs/output/00-versions.txt). diff --git a/spring-boot-startup-time/post/post.md b/spring-boot-startup-time/post/post.md new file mode 100644 index 0000000..809eb3a --- /dev/null +++ b/spring-boot-startup-time/post/post.md @@ -0,0 +1,420 @@ +# Why Your Spring Boot App Takes 8 Seconds to Start: A Bean-by-Bean Diagnosis + +Your application logs one line at the end of startup, and it is the least useful line in the +whole log. + +```console +Started StartupDiagnosisApplication in 6.6 seconds (process running for 7.4) +``` + +Six and a half seconds. Doing what? The reflexive next move is to read the timestamps in the +log above it and look for a gap — and that quietly hands you the wrong answer, because the +log only shows you components that chose to log. The application this article is built on +spends half a second inside one bean's `@PostConstruct` and says nothing at all while doing +it. On the timeline that half second sits between two Hibernate lines, and you would blame +Hibernate. + +Spring already records the truth. It has recorded it since Framework 5.3, at about two dozen +named points, tagged with bean names and class counts, arranged as a tree. The default +implementation of the interface that collects it throws every event away, which is why +startup profiling feels like something you need a commercial agent for. + +This article turns that instrumentation on, reads it correctly — which is harder than it +sounds, and where most write-ups go wrong — and then puts numbers on the three things people +reach for afterwards. + +| Part | Read this if… | +|---|---| +| **1 — What the number hides** | you have never seen `/actuator/startup` and want the smallest thing that works | +| **2 — Reading the tree** | you have the JSON open and the slowest bean in it makes no sense | +| **3 — Scanning, truncation and the AOT cache** | you have already fixed your own beans and startup is still slow | + +> **Versions.** Spring Boot 4.1.1 (GA 20 August 2026), Spring Framework 7.0.9, Spring Data +> JPA 4.1.1, Hibernate ORM 7.4.5.Final, embedded Tomcat 11.0.24, Micrometer 1.17.1, H2 +> 2.4.240, on Temurin 25.0.4.1+1 LTS with Maven 3.9.11. Resolved by `mvn dependency:list` on +> the machine that produced every transcript below, not read out of documentation. +> +> Every millisecond figure here came from running the companion project. Timings are +> indicative and drift a few hundred milliseconds between runs on the same machine — the +> *ratios* are the result, not the absolute numbers. + +--- + +## Part 1 — What the number hides + +### Two numbers, and the gap between them + +`Started … in 6.6 seconds (process running for 7.4)` is measuring two different things. The +first is from the `SpringApplication.run()` call to the `ApplicationReadyEvent`. The second +is `RuntimeMXBean.getUptime()` — the whole JVM. The 0.8-second gap is jar opening, class +verification and JIT warm-up, which happens before a line of your code runs and which no +amount of Spring tuning will touch. + +The 6.6 seconds is yours. To split it up you need `ApplicationStartup`, an SPI in +`spring-core` with one method that matters: + +```java +public interface ApplicationStartup { + StartupStep start(String name); +} +``` + +Framework and Boot call it around the interesting moments — `spring.beans.instantiate`, +`spring.context.config-classes.parse`, `spring.data.repository.proxy` — tagging each step +with the bean name or class count involved. Steps nest, so what comes out is a tree. + +The default implementation, `DefaultApplicationStartup`, is a no-op. Two implementations +actually record: + +| Implementation | Module | Output | +|---|---|---| +| `BufferingApplicationStartup` | `spring-boot` | in-memory buffer, read over HTTP | +| `FlightRecorderApplicationStartup` | `spring-core` | JFR events in a `.jfr` file | + +### Turning it on: there is no property for this + +The most common wasted hour on this topic is looking for +`spring.application.startup=buffering` in `application.yaml`. It does not exist, and it +cannot: the steps you most want are recorded before any configuration file has been read. +The tracker has to be set on the `SpringApplication` before `run()`. + +```java +public static void main(String[] args) { + SpringApplication app = new SpringApplication(StartupDiagnosisApplication.class); + int capacity = Integer.getInteger("startup.buffer", 16384); + switch (System.getProperty("startup.tracking", "buffering")) { + case "buffering" -> app.setApplicationStartup(new BufferingApplicationStartup(capacity)); + case "jfr" -> app.setApplicationStartup(new FlightRecorderApplicationStartup()); + default -> { } + } + app.run(args); +} +``` + +> **Switching trackers is a redeploy, not a config change.** Worth internalising before an +> incident rather than during one. If you want the option available in production, ship it +> behind a system property as above and set it in the launch command. + +Then expose the endpoint, which is not web-exposed by default: + +```yaml +management: + endpoints: + web: + exposure: + include: health,info,startup,beans,conditions +``` + +Exposing it *without* installing a tracker gives you an endpoint that returns an empty +timeline instead of an error — a confusing way to lose another twenty minutes. + +### The one thing to remember from Part 1 + +> **A step is recorded when it ends, not when it starts.** That is why the outermost steps — +> `spring.context.refresh`, `spring.boot.application.ready` — appear *last* in the timeline +> despite bracketing everything else. It looks like trivia. It is the reason a too-small +> buffer destroys exactly the data you need, which Part 3 gets to. + +### And do not use POST + +```console +$ GET /actuator/startup -> events in response: 400 +$ POST /actuator/startup -> events in response: 400 +$ POST /actuator/startup -> events in response: 0 +$ GET /actuator/startup -> events in response: 0 +``` + +`POST` calls `drainBufferedTimeline()` and empties the buffer so the memory can be reclaimed. +Every guide shows the `POST`. If you pipe it into a `jq` expression and the expression is +wrong, the recording is gone and the application has to be restarted. Peek with `GET` until +you know what you want. + +--- + +## Part 2 — Reading the tree without fooling yourself + +You now have four hundred steps of JSON, each with a `duration`. The obvious move is to sort +by duration. The obvious move is wrong, and it is wrong in a way that reliably sends people +to optimise a bean that costs nothing. + +### Steps nest, so durations double-count + +![Two rankings of the same four hundred startup steps. Sorted by total duration the top entries are spring.context.refresh at 5830 ms and reportTemplateRegistry at 514 ms. Sorted by self time those fall to 114 ms and 10 ms, and the real costs are the entity manager factory at 1414 ms, configuration class parsing at 1015 ms, and tariffCacheWarmer at 504 ms.](images/01-self-time-vs-total-time.svg) + +The fix is one pass over the timeline. Steps carry `id` and `parentId`, so subtracting each +step's direct children gives its self time: + +```java +Map childNanos = new HashMap<>(); +for (TimelineEvent event : timeline.getEvents()) { + Long parent = event.getStartupStep().getParentId(); + if (parent != null) { + childNanos.merge(parent, event.getDuration().toNanos(), Long::sum); + } +} +long self = total - childNanos.getOrDefault(step.getId(), 0L); +``` + +That is the whole trick, and neither `/actuator/startup` nor JFR does it for you. The +companion project wraps it in a ninety-line `/diag/startup` endpoint. + +> **The ampersand is not a typo.** `&entityManagerFactory` is Spring's `FactoryBean` +> dereference prefix, so that step is the *factory* being built, not the object it produces. +> When a slow bean name starts with `&`, look inside a `FactoryBean` — here, +> `LocalContainerEntityManagerFactoryBean` bootstrapping Hibernate. + +### Four phases, four different fixes + +Grouping the same 400 steps by name and summing self time gives the shape of a startup: + +```console + self ms count step + 4253.68 361 spring.beans.instantiate + 1014.51 1 spring.context.config-classes.parse + 402.81 1 spring.boot.application.environment-prepared + 160.39 1 spring.boot.webserver.create + 153.07 1 spring.boot.application.started + 113.74 1 spring.context.refresh + 95.72 1 spring.data.repository.proxy + 51.50 6 spring.beans.smart-initialize + 43.85 1 spring.data.repository.scanning +``` + +**`spring.beans.instantiate`** — 361 steps, 4.25 s. Constructors, `@PostConstruct`, +`FactoryBean.getObject()`, proxy creation. The only phase you can fix by changing your own +code. Note that `@PostConstruct` gets no step of its own, so a cache warm hides inside the +owning bean's instantiate step and the timeline cannot tell you which half of the bean was +slow. + +**`spring.context.config-classes.parse`** — one step, 1.01 s. Component scanning plus +`@Conditional` evaluation across every auto-configuration your classpath drags in. Under JFR +it carries the cost driver as a tag: `classCount=130`. Part 3 measures what that number is +worth. + +**`spring.boot.application.environment-prepared`** — 403 ms before a single bean exists. +Property sources, profiles, config data imports. This is why the application appears to do +nothing for the first half second. + +**Everything else** — web server creation at 160 ms, five Spring Data step names totalling +about 150 ms, `smart-initialize` at 51 ms. Individually small, collectively a second. The +Spring Data contribution scales with repository interfaces and derived query methods, since +each is parsed and proxied. + +### The same startup, as JFR events + +Swap the tracker and start a recording. No dependency to add — +`FlightRecorderApplicationStartup` is in `spring-core`. + +```console +$ java -XX:StartFlightRecording=filename=startup.jfr,settings=profile,dumponexit=true \ + -Dstartup.tracking=jfr -jar app.jar +``` + +Then read it with the JDK's own tool. There is one trap, and it is silent: + +```console +$ jfr print --events StartupEvent --json startup.jfr + -> 0 events + +$ jfr print --events 'org.springframework.core.metrics.jfr.FlightRecorderStartupEvent' \ + --json startup.jfr + -> 398 events +``` + +`jfr print --events` matches the event's `@Name`, which is the fully qualified class name. +The short form returns nothing at all, with no error — which reads exactly like "Spring did +not record anything". In JDK Mission Control the same events are filed under the category +**Spring Application**. + +```console +@Name("org.springframework.core.metrics.jfr.FlightRecorderStartupEvent") +@Category("Spring Application") +@Label("Startup Step") +@Description("Spring Application Startup") +class FlightRecorderStartupEvent extends jdk.jfr.Event { ... } +``` + +What JFR buys you is correlation. The same file holds the JVM's own view of those seconds — +345 `jdk.ExecutionSample` records, 39 `jdk.GCPhasePause` events totalling 289.8 ms, 16 +`jdk.Compilation`. The buffer tells you a bean was slow; JFR can tell you a young collection +landed in the middle of its constructor. It also survives a startup that fails before the web +server is up, when the buffer is unreachable by definition. + +What it costs you: the tags are flattened into one `String` attribute because JFR events only +carry base types, so you get to parse `beanName=x,beanType=y,` yourself; and the file lands +on the machine rather than on an HTTP endpoint, which in a container means a volume or a copy +out. + +--- + +## Part 3 — Scanning, truncation, and what actually helps + +### What component scanning really costs + +"Narrow your component scan" is standard advice that nobody attaches a number to. So: add +classes to the package `@SpringBootApplication` already scans, change nothing else, and +measure. The `plain` classes carry no annotation at all, which separates the cost of +*scanning* from the cost of *creating beans*. + +```console +variant | Started in (s) | parse ms | instMs | steps +---------------------------+---------------------+-----------+-----------+------- +baseline | 7.293,6.685,6.86 | 1055.69 | 4854.73 | 400 ++5000 plain classes | 7.626,7.143,7.04 | 1617.38 | 4468.31 | 400 ++5000 @Component | 11.02,11.647,11.481 | 3221.82 | 6097.98 | 5400 ++5000 @Component, lazy | 9.688,9.374,9.609 | 3434.76 | 4982.61 | 324 +``` + +Five thousand classes that are *not beans* cost about 560 ms — roughly **0.11 ms per class +inspected** on this machine — while the step count stays at exactly 400 and instantiation is +unchanged. The scanner has to open every `.class` file under the base package and read its +annotation metadata before it can decide the class is uninteresting. Classes you never +annotated are still on the bill. + +Turning the same five thousand into `@Component`s roughly triples the tax and pushes startup +from 6.9 s to 11.5 s. + +> **Lazy initialisation does not touch the scan.** With the same 5,000 components, +> `spring.main.lazy-initialization=true` leaves parsing at 3.4 s — statistically unchanged — +> and buys back only the instantiation. Scanning is paid at startup no matter what you defer +> at runtime, because Spring cannot know whether a class is a bean without looking at it. The +> only fix for the scan tax is to scan less: set `scanBasePackages` explicitly instead of +> inheriting the package of your main class. + +There is a second, quieter cost in that last row. Lazy initialisation records **324 steps +against a baseline of 400**: the beans it defers never produce a `spring.beans.instantiate` +step at all. It makes your startup tree less informative at exactly the moment you are trying +to read it. + +### The buffer truncates silently + +Here is where Part 1's piece of trivia comes due. `BufferingApplicationStartup` takes a +capacity in its only constructor, every guide picks 2048, and nothing anywhere says what +happens when the application produces more steps than that. + +```console +--- capacity 2048 --- + started, recorded steps: 2048 +--- capacity 16384 --- + started, recorded steps: 5400 + +$ grep -ic buffer app.log +0 +``` + +Status 200. Well-formed JSON. No warning, no exception, no log line. And because *a step is +recorded when it ends*, the buffer keeps the first steps to finish — the innermost leaves — +and discards the ones that enclose them: + +![A truncated startup buffer. With a capacity of 2048 the buffer keeps the first 2048 steps to finish, all inner leaves, and silently drops the remaining 3352 instantiation steps along with spring.context.refresh, application.started and application.ready, because those steps end last.](images/02-buffer-truncation.svg) + +`spring.context.refresh`, `spring.boot.application.started` and +`spring.boot.application.ready` are all absent from the truncated timeline. Every self-time +calculation you do on it is missing its outer frame, and you have no way to notice. + +### Measuring is free. Really. + +Same jar, same machine, four runs each: + +```console +variant | Started in (s), each run | median +-----------------------------------+----------------------------+--------- +no tracking | 6.871,6.456,7.473,6.992 | 6.9315 +BufferingApplicationStartup | 6.448,6.856,6.416,6.528 | 6.488 +FlightRecorder + recording | 6.496,6.739,6.343,6.475 | 6.4855 +lazy-initialization | 5.075,5.331,5.217,5.266 | 5.2415 +AOT cache (-XX:AOTCache) | 5.028,4.729,4.708,4.905 | 4.817 +AOT cache + lazy | 3.649,3.488,3.354,3.384 | 3.436 +``` + +The two instrumented rows sit *inside* the noise band of the uninstrumented one — the +buffering median is lower than the baseline median, which tells you the difference is smaller +than run-to-run variance, not that recording makes things faster. Whatever the reason to +leave startup tracking off, cost is not one of them. Leaving `BufferingApplicationStartup` on +permanently in a staging profile is a defensible default. + +### The JDK 25 AOT cache + +JDK 25 ships the Project Leyden AOT cache. Two build steps, then every run reads it: + +```console +$ java -XX:AOTMode=record -XX:AOTConfiguration=app.aotconf -jar app.jar # train, then stop +$ java -XX:AOTMode=create -XX:AOTConfiguration=app.aotconf -XX:AOTCache=app.aot -jar app.jar +AOTCache creation is complete: /tmp/app.aot 118001664 bytes +$ java -XX:AOTCache=app.aot -jar app.jar # every run after +``` + +6.93 s to 4.82 s — about 30% — with no change to a line of application code, and 3.44 s +combined with lazy initialisation. Running the same tracker under both configurations says +where it comes from: + +```console +run | parse ms | inst ms | webserver +-----------------------+-----------+-----------+---------- +plain | 986.66 | 4344.21 | 150.69 +aotcache | 729.16 | 3155.96 | 100.96 +``` + +Parse down 26%, instantiation down 27%, web server creation down 33%. The AOT cache does not +remove a phase — it removes class loading and linking, and class loading is distributed +through all of them. Worth knowing before you go hunting for the one phase it fixed. The +costs are equally real: 118 MB for a small application, tied to the exact classpath that +produced it, and a training run that has to become part of your build. I wrote up the +invalidation rules and the CI shape separately in +[the Project Leyden AOT cache post](https://ankurm.com/project-leyden-aot-cache-java/). + +### Should you even do this? + +> **Mostly, no.** A monolith that restarts twice a week and takes eight seconds to do it is +> costing you sixteen seconds a week. The honest reasons to care are a Kubernetes rollout +> where the readiness gate is on the critical path of every deploy, a scale-to-zero or +> serverless deployment where startup is user-visible latency, or a test suite that builds +> forty application contexts and has become the reason nobody runs it locally. If none of +> those is you, read Part 2, fix the one `@PostConstruct` that turns out to cost half a +> second, and go do something else. +> +> And if one of them *is* you: do it in the order below. The AOT cache is a build-pipeline +> change, and it is far easier to justify once you already know it is not hiding a 500 ms +> cache warm. + +1. Turn on `BufferingApplicationStartup`, sort by **self** time, fix your own beans. In this + application `keystoreLoader` and `tariffCacheWarmer` are 830 ms between them and both + belong off the startup path. +2. Check the `classCount` tag on `spring.context.config-classes.parse`. If it is in the + hundreds, most of them came with a starter you are not using. Set `scanBasePackages`. +3. Then reach for the AOT cache. + +### The long tail + +Things that did not earn a section here, each reproducible in the companion project: + +- Injecting `BufferingApplicationStartup` by its concrete type compiles, passes tests, and + stops the application booting the first time someone runs without tracking — + [chapter 07](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/spring-boot-startup-time/docs/07-failure-modes.md) +- Boot already registers the tracker as a singleton named `applicationStartup`; declaring + your own `@Bean` produces *required a single bean, but 2 were found* — + [chapter 02](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/spring-boot-startup-time/docs/02-turning-instrumentation-on.md) +- `getApplicationStartup()` is declared on `ConfigurableApplicationContext`, not + `ApplicationContext` — the compiler found that one — + [the javap transcript](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/spring-boot-startup-time/docs/output/01-api-corrections.txt) +- `spring-context-indexer` still ships at 7.0.9 and writes a `META-INF/spring.components` + index at build time; Spring's own direction of travel is AOT instead — + [chapter 06](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/spring-boot-startup-time/docs/06-the-classpath-scan-tax.md) +- `pkill -f YourMainClass` also matches the shell running the script that contains that + string. Match on `java` plus the jar name — + [stop.sh](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/spring-boot-startup-time/scripts/stop.sh) + +### Further reading + +- [The companion project](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/spring-boot-startup-time) + — eight chapters, seven captured transcripts, and `./scripts/run-all.sh` to regenerate all + of them +- [Project Leyden's AOT cache in Java](https://ankurm.com/project-leyden-aot-cache-java/) — + the training run, invalidation, and what it does to a CI pipeline +- [Spring Boot Actuator in production](https://ankurm.com/spring-boot-actuator-production-endpoints-security-health-indicators/) + — how to expose `startup` without exposing everything else +- [`BufferingApplicationStartup`](https://docs.spring.io/spring-boot/api/java/org/springframework/boot/context/metrics/buffering/BufferingApplicationStartup.html) + and [`FlightRecorderApplicationStartup`](https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/core/metrics/jfr/FlightRecorderApplicationStartup.html) + Javadoc +- [JEP 483: Ahead-of-Time Class Loading & Linking](https://openjdk.org/jeps/483) and + [JEP 515: Ahead-of-Time Method Profiling](https://openjdk.org/jeps/515) diff --git a/spring-boot-startup-time/scripts/demo-buffer-overflow.sh b/spring-boot-startup-time/scripts/demo-buffer-overflow.sh new file mode 100755 index 0000000..fcc1289 --- /dev/null +++ b/spring-boot-startup-time/scripts/demo-buffer-overflow.sh @@ -0,0 +1,25 @@ +#!/usr/bin/env bash +# What a too-small buffer does. Every guide picks 2048; nobody says what happens when +# an application produces more steps than that. +set -uo pipefail +source "$(dirname "$0")/env.sh" + +for cap in 2048 16384; do + "$(dirname "$0")/stop.sh" + "$JAVA_HOME/bin/java" -Dstartup.tracking=buffering -Dstartup.buffer=$cap \ + -jar "$JAR" > /tmp/buf.log 2>&1 & + PID=$! + for _ in $(seq 1 240); do curl -fs -o /dev/null localhost:8080/actuator/health && break; sleep 0.5; done + ok=$? + echo "--- capacity $cap ---" + if grep -q 'Started StartupDiagnosisApplication' /tmp/buf.log; then + echo -n " started, recorded steps: " + curl -s 'localhost:8080/diag/startup?top=1' \ + | python3 -c "import sys,json;print(json.load(sys.stdin)['recordedSteps'])" + else + echo " application did not start. Last lines of the log:" + grep -E 'ERROR|Exception|Caused by' /tmp/buf.log | head -5 | sed 's/^/ /' + fi + kill -9 $PID 2>/dev/null; wait $PID 2>/dev/null +done +true diff --git a/spring-boot-startup-time/scripts/demo-jfr.sh b/spring-boot-startup-time/scripts/demo-jfr.sh new file mode 100755 index 0000000..bc43648 --- /dev/null +++ b/spring-boot-startup-time/scripts/demo-jfr.sh @@ -0,0 +1,69 @@ +#!/usr/bin/env bash +# Records the same startup as JFR events instead of an in-memory buffer, then reads the +# recording with the JDK's own `jfr` tool -- no Mission Control, no extra dependency. +set -uo pipefail +source "$(dirname "$0")/env.sh" +REC=/tmp/startup.jfr +rm -f "$REC" + +"$(dirname "$0")/stop.sh" +"$JAVA_HOME/bin/java" \ + -XX:StartFlightRecording=filename=$REC,settings=profile,dumponexit=true \ + -Dstartup.tracking=jfr -jar "$JAR" > /tmp/startup-app.log 2>&1 & +PID=$! +for _ in $(seq 1 180); do curl -fs -o /dev/null localhost:8080/actuator/health && break; sleep 0.5; done +grep -h 'Started StartupDiagnosisApplication' /tmp/startup-app.log | sed 's/^.*: //' +kill -TERM $PID 2>/dev/null; wait $PID 2>/dev/null +sleep 2 + +echo +echo "=== jfr summary (Spring rows only) ===" +"$JAVA_HOME/bin/jfr" summary "$REC" | head -3 +"$JAVA_HOME/bin/jfr" summary "$REC" | grep -i -E 'spring|Event Count|=====' | head -10 + +echo +echo "=== the event type, in full ===" +"$JAVA_HOME/bin/jfr" metadata "$REC" | grep -A22 '@Name("org.springframework' | head -24 + +echo +echo "=== the selector matters: the event is named by its FQCN, not 'StartupEvent' ===" +echo -n " --events StartupEvent -> " +"$JAVA_HOME/bin/jfr" print --events StartupEvent --json "$REC" \ + | python3 -c "import sys,json;print(len(json.load(sys.stdin)['recording']['events']),'events')" +echo -n " --events 'org.springframework.core.*' -> " +"$JAVA_HOME/bin/jfr" print --events 'org.springframework.core.metrics.jfr.FlightRecorderStartupEvent' --json "$REC" \ + | python3 -c "import sys,json;print(len(json.load(sys.stdin)['recording']['events']),'events')" + +echo +echo "=== 8 slowest startup steps, straight out of the recording ===" +"$JAVA_HOME/bin/jfr" print --events 'org.springframework.core.metrics.jfr.FlightRecorderStartupEvent' \ + --json "$REC" > /tmp/startup-jfr.json 2>/dev/null +python3 - <<'PY' +import json +d = json.load(open('/tmp/startup-jfr.json')) +ev = d['recording']['events'] +print(f"{len(ev)} StartupEvent records in the recording\n") +rows = [] +for e in ev: + v = e['values'] + rows.append((v.get('duration', 0), v.get('name'), v.get('tags') or '')) +rows.sort(reverse=True) +print(f"{'duration':>14} name / tags") +for dur, name, tags in rows[:8]: + print(f"{dur!s:>14} {name} {tags}") +PY + +echo +echo "=== what JFR gives you that the buffer does not: JVM context in the same file ===" +"$JAVA_HOME/bin/jfr" summary "$REC" | grep -E 'GCPhasePause|ClassLoad|JavaMonitorEnter|ExecutionSample|Compilation ' | head -6 +echo +echo -n " total GC pause time during this startup: " +"$JAVA_HOME/bin/jfr" print --events jdk.GCPhasePause --json "$REC" | python3 -c " +import sys, json, re +ev = json.load(sys.stdin)['recording']['events'] +tot = 0.0 +for e in ev: + m = re.match(r'PT(?:(\d+)M)?([\d.]+)S', e['values']['duration']) + tot += (int(m.group(1) or 0) * 60 + float(m.group(2))) +print(f'{len(ev)} events, {tot*1000:.1f} ms')" +true diff --git a/spring-boot-startup-time/scripts/demo-scan-tax.sh b/spring-boot-startup-time/scripts/demo-scan-tax.sh new file mode 100755 index 0000000..bbaa19d --- /dev/null +++ b/spring-boot-startup-time/scripts/demo-scan-tax.sh @@ -0,0 +1,71 @@ +#!/usr/bin/env bash +# Quantifies what component scanning costs, by adding classes to the scanned package +# and changing nothing else. +# +# baseline : the application as committed +# +5000 plain : 5000 classes with no annotations -- pure scan cost +# +5000 @Component : the same 5000, now bean definitions -- scan + define + instantiate +# +5000 @Component, lazy : lazy init removes the instantiation, not the scan +# +# Each variant is a full rebuild. Budget about ten minutes. +set -uo pipefail +source "$(dirname "$0")/env.sh" +cd "$ROOT" +RUNS="${RUNS:-3}" + +measure() { # measure