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.
104 lines
4.1 KiB
Markdown
104 lines
4.1 KiB
Markdown
# 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)
|