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.
421 lines
21 KiB
Markdown
421 lines
21 KiB
Markdown
# 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
|
|
|
|

|
|
|
|
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<Long, Long> 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:
|
|
|
|

|
|
|
|
`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)
|