Ankur Mhatre
958b401f0f
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.
87 lines
3.9 KiB
Markdown
87 lines
3.9 KiB
Markdown
# 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<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);
|
|
```
|
|
|
|
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)
|