Add jfr-demo: JFR + Mission Control profiling of a live Spring Boot app

Custom OrderProcessed event, CPU/allocation/lock workloads, a diagnostic
endpoint over the JVM's live FlightRecorder state, a JUnit test using the
jdk.jfr.Recording API, and nine captured recordings (flagship, mid-flight
snapshot, isolated vs concurrent threshold comparisons, and a real
dump+stop duplication bug) with their docs/output/*.txt transcripts.
This commit is contained in:
2026-10-01 04:37:26 +00:00
commit c7eccd1db5
40 changed files with 1326 additions and 0 deletions
+4
View File
@@ -0,0 +1,4 @@
target/
*.class
.idea/
*.iml
+21
View File
@@ -0,0 +1,21 @@
MIT License
Copyright (c) 2026 Ankur Mhatre
Permission is hereby granted, free of charge, to any person obtaining a copy
of this software and associated documentation files (the "Software"), to deal
in the Software without restriction, including without limitation the rights
to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
copies of the Software, and to permit persons to whom the Software is
furnished to do so, subject to the following conditions:
The above copyright notice and this permission notice shall be included in
all copies or substantial portions of the Software.
THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
THE SOFTWARE.
+101
View File
@@ -0,0 +1,101 @@
# jfr-demo
Companion project for the ankurm.com post **"Java Flight Recorder and Mission
Control: Profiling a Live Spring Boot App in 20 Minutes."** A small Spring Boot
app with three deliberately bad workloads (a CPU hot method, an
allocation-heavy method, and a lock-contention scenario), one custom JFR event
for a fictional "order processed" business operation, and a diagnostic
endpoint that prints the JVM's own live Flight Recorder state.
Every number in the post comes from a file under `docs/output/`, produced by
either the JUnit test suite or a real `jcmd` + `curl` session against a
running instance of this app — see the index below.
## Versions this was built and verified against
| Component | Version | Verified against |
|---|---|---|
| JDK | 25.0.4.1 (Temurin, LTS) | `java -version`; [Adoptium](https://api.adoptium.net/v3/info/available_releases) lists 25 as `most_recent_lts` |
| Spring Boot | 4.1.1 | Maven Central directory listing, uploaded 2026-08-20 |
| JUnit | 6.0.3 (pulled in by `spring-boot-starter-test`) | `mvn dependency:tree` |
| Maven | bundled in the sandbox | `mvn -v` |
## Quickstart
```bash
# JDK 25 (or any LTS 21+; JFR itself needs nothing newer than 17)
mvn -q -B -DskipTests package
java -jar target/jfr-demo.jar &
PID=$!
# start a profiling recording
jcmd $PID JFR.start name=live settings=profile filename=/tmp/live.jfr maxsize=256m
# generate real load (see scripts/load.sh for each kind individually)
scripts/load.sh all
# stop and inspect
jcmd $PID JFR.stop name=live
jfr summary /tmp/live.jfr
jfr print --events com.ankurm.jfr.OrderProcessed /tmp/live.jfr
```
`scripts/run-all.sh` regenerates every file under `docs/output/` in one
command (it runs the test suite, then drives the full live-app capture).
`scripts/capture-jfr.sh <pid>` reproduces just the flagship recording.
`scripts/reproduce-dump-bug.sh <pid>` reproduces the dump/stop duplication
trap documented in `docs/output/09-dump-duplication-bug.txt` &mdash; do not
copy that script's pattern into real code.
## Endpoints
| Method & path | What it does | JFR event(s) it produces |
|---|---|---|
| `GET /api/cpu/fibonacci?n=38` | Naive recursive Fibonacci &mdash; a CPU hot method | `jdk.ExecutionSample` |
| `GET /api/alloc/churn?iterations=400000` | Short-lived `String`/`byte[]`/boxed-`Byte` churn | `jdk.ObjectAllocationSample` |
| `GET /api/lock/contend?workers=16&holdMillis=20` | N threads fight over one synchronized block | `jdk.JavaMonitorEnter`, `jdk.ThreadPark` |
| `GET /api/orders/process?items=3` | Simulated order processing | `com.ankurm.jfr.OrderProcessed` (custom) |
| `GET /api/jfr/recordings` | Diagnostic: lists this JVM's own live recordings | &mdash; (delete before shipping) |
| `GET /api/jfr/event-types` | Diagnostic: lists registered `com.ankurm.*` event types | &mdash; (delete before shipping) |
## Captured output index (`docs/output/`)
| File | What it proves |
|---|---|
| `01-order-event-test.txt` | The custom event, driven purely through the `jdk.jfr.Recording` Java API in a JUnit test &mdash; no server, no jcmd |
| `02-start-recording-and-diagnostics.txt` | `jcmd JFR.start`, the live `/api/jfr/recordings` diagnostic, `jcmd JFR.stop` |
| `03-hot-method-samples.txt` | Top CPU stack frames: `fibonacci()` is 63% of samples |
| `04-allocation-samples.txt` | Top allocating classes and call sites during `churnAllocations` |
| `05-lock-contention-live-demo.txt` | 15 `jdk.JavaMonitorEnter` events from one 16-worker contention burst, escalating in ~20 ms steps |
| `06-custom-event-live-demo.txt` | 23 of 60 simulated orders kept by the event's 20 ms threshold |
| `07-threshold-isolated-comparison.txt` | `settings=default` misses a 12 ms lock wait entirely; `settings=profile` catches all of it; both catch a 35 ms wait |
| `08-concurrent-recordings-shared-threshold.txt` | The same `settings=default` recording DOES catch the 12 ms wait once a second, lower-threshold recording is also active &mdash; thresholds are effectively global across concurrent recordings |
| `09-dump-duplication-bug.txt` | `JFR.dump` to a recording's own configured destination, followed by `JFR.stop`, doubles every event in the file |
| `10-final-summary.txt` | Full `jfr summary` of the clean flagship recording |
| `11-broken-event-pattern.txt` | A missing `try/finally` around `event.commit()` silently drops exactly as many events as the exceptions thrown |
## Recordings (`recordings/`)
Real, unedited `.jfr` files, small enough to commit and open yourself in JDK
Mission Control or VisualVM:
- `live-demo.jfr` &mdash; the flagship recording referenced throughout the post
- `mid-flight-snapshot.jfr` &mdash; a snapshot taken while `live-demo.jfr`'s
recording was still running, proving you can inspect without stopping
- `dump-duplication-bug.jfr` &mdash; the buggy recording from
`docs/output/09-dump-duplication-bug.txt`, kept exactly as produced
- `solo-default.jfr`, `solo-profile.jfr`, `solo-default-longhold.jfr` &mdash;
the isolated threshold comparison (`docs/output/07`)
- `compare-default.jfr`, `compare-profile.jfr` &mdash; the concurrent-recordings
comparison (`docs/output/08`)
## What to delete before shipping
`DiagnosticsController` (`/api/jfr/recordings`, `/api/jfr/event-types`) has no
business being reachable from the internet. It exists here purely so the post
and this README could show real, live Flight Recorder state instead of a
description of it.
## License
MIT, see [`LICENSE`](LICENSE).
+16
View File
@@ -0,0 +1,16 @@
# docs/output/01-order-event-test.txt
# Generated by OrderProcessedEventTest.capturesOneEventPerOrder()
# jdk.jfr.Recording started in-process, 20 orders processed, recording stopped and dumped to a temp .jfr file,
# then read back with jdk.jfr.consumer.RecordingFile.
events recorded: 20
events with slowReason: 4
events without reason: 16
first event fields:
eventType = com.ankurm.jfr.OrderProcessed
orderId = TEST-0
warehouse = BLR-2
itemCount = 3
duration(ms) = 5
hasStackTrace = true
@@ -0,0 +1,14 @@
$ jcmd 5287 JFR.start name=demo settings=profile maxsize=256m
5287:
Started recording 15.
Use jcmd 5287 JFR.dump name=demo filename=FILEPATH to copy recording data to file.
$ curl -s localhost:8080/api/jfr/recordings
[{"id":15,"name":"demo","state":"RUNNING","startTime":"2026-10-01T04:30:41.255843977Z","maxSize":268435456,"maxAge":"null","destination":"null"}]
$ jcmd 5287 JFR.stop name=demo filename=/tmp/throwaway-demo.jfr
5287:
Stopped recording "demo", 251.6 kB written to:
/tmp/throwaway-demo.jfr
+39
View File
@@ -0,0 +1,39 @@
Top stack frames from jdk.ExecutionSample, live-demo.jfr, during six concurrent
GET /api/cpu/fibonacci?n=38 calls, aggregated by the top (leaf) frame only.
$ jfr print --events jdk.ExecutionSample --stack-depth 1 recordings/live-demo.jfr \
| grep -A1 stackTrace | grep -v 'stackTrace\|^--' | sed 's/^\s*//' | sort | uniq -c | sort -rn
62 com.ankurm.jfr.service.WorkloadService.fibonacci(int) line: 40
13 com.ankurm.jfr.service.WorkloadService.churnAllocations(int) line: 56
9 com.ankurm.jfr.service.WorkloadService.churnAllocations(int) line: 52
2 jdk.internal.util.DecimalDigits.uncheckedGetCharsLatin1(int, int, byte[]) line: 168
1 org.apache.tomcat.util.net.NioEndpoint$Poller.run() line: 941
1 org.apache.tomcat.util.http.MimeHeaders.addValue(byte[], int, int) line: 327
1 org.apache.catalina.mapper.Mapper.compareIgnoreCase(CharChunk, int, int, String) line: 1401
1 org.apache.catalina.core.ApplicationFilterFactory.createFilterChain(ServletRequest, Wrapper, Servlet) line: 75
1 jdk.internal.util.DecimalDigits.stringSize(int) line: 101
1 jdk.internal.misc.Unsafe.allocateUninitializedArray(Class, int) line: 1396
1 java.util.concurrent.locks.LockSupport.unpark(Thread) line: 181
1 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.signalAll() line: 1590
1 java.util.Arrays.copyOf(Object[], int) line: 3478
1 java.nio.Buffer.position(int) line: 325
1 java.lang.invoke.DirectMethodHandle.allocateInstance(Object) line: 500
total jdk.ExecutionSample events in recording: 98
fibonacci() share of samples: 62 / 98 = 63.3%
$ jfr print --events jdk.ExecutionSample recordings/live-demo.jfr | head -13
jdk.ExecutionSample {
startTime = 09:59:03.699 (2026-10-01)
sampledThread = "http-nio-8080-exec-1" (javaThreadId = 30)
state = "STATE_RUNNABLE"
stackTrace = [
com.ankurm.jfr.service.WorkloadService.fibonacci(int) line: 40
com.ankurm.jfr.service.WorkloadService.fibonacci(int) line: 40
com.ankurm.jfr.service.WorkloadService.fibonacci(int) line: 40
com.ankurm.jfr.service.WorkloadService.fibonacci(int) line: 40
com.ankurm.jfr.service.WorkloadService.fibonacci(int) line: 40
...
]
}
+35
View File
@@ -0,0 +1,35 @@
Allocation pressure from three concurrent GET /api/alloc/churn?iterations=400000
calls, captured by jdk.ObjectAllocationSample in recordings/live-demo.jfr.
$ jfr print --events jdk.ObjectAllocationSample recordings/live-demo.jfr | grep objectClass \
| sed 's/^\s*//' | sort | uniq -c | sort -rn
154 objectClass = java.lang.Object[] (classLoader = bootstrap)
111 objectClass = byte[] (classLoader = bootstrap)
21 objectClass = java.util.ArrayList (classLoader = bootstrap)
19 objectClass = java.lang.String (classLoader = bootstrap)
4 objectClass = java.time.Instant (classLoader = bootstrap)
2 objectClass = java.io.EOFException (classLoader = bootstrap)
1 objectClass = java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode (classLoader = bootstrap)
1 objectClass = java.util.concurrent.ConcurrentHashMap$KeyIterator (classLoader = bootstrap)
1 objectClass = java.util.LinkedHashMap$Entry (classLoader = bootstrap)
1 objectClass = java.util.HashSet (classLoader = bootstrap)
Top allocating stack frames (--stack-depth 1), same recording:
153 java.util.ArrayList.<init>(int) line: 157
58 java.lang.String.encodeUTF8(byte, byte[], boolean) line: 1305
49 jdk.internal.misc.Unsafe.allocateUninitializedArray(Class, int) line: 1396
21 com.ankurm.jfr.service.WorkloadService.churnAllocations(int) line: 55
18 com.ankurm.jfr.service.WorkloadService.churnAllocations(int) line: 53
4 java.time.Instant.create(long, int) line: 416
4 java.nio.HeapByteBuffer.<init>(int, int, MemorySegment) line: 75
The two biggest allocators by class (Object[] and byte[]) both trace back to one
line in WorkloadService.churnAllocations: `new ArrayList<>(bytes.length)` followed
by boxing each byte into the list. Object[] is the list's own backing array
(resized as autoboxed Byte objects are added); byte[] is `s.getBytes()`. Total
events: 317 (jdk.ObjectAllocationSample, throttled to 300/s by the "profile"
settings used for this recording -- see docs/output/08-concurrent-recordings-
shared-threshold.txt for why throttle and threshold settings between concurrently
active recordings interact in a way that is easy to misread).
@@ -0,0 +1,45 @@
One GET /api/lock/contend?workers=16&holdMillis=20 call: 16 threads release
simultaneously (via a CountDownLatch) and fight over one synchronized block that
holds for 20 ms. One thread enters immediately; 15 queue up. jdk.JavaMonitorEnter
records each waiter's queueing time.
$ jfr print --events jdk.JavaMonitorEnter recordings/live-demo.jfr | head -15
jdk.JavaMonitorEnter {
startTime = 09:59:07.393 (2026-10-01)
duration = 20.4 ms
monitorClass = java.lang.Object (classLoader = bootstrap)
previousOwner = "pool-135-thread-1" (javaThreadId = 365)
address = 0x7FCAB40A4860
eventThread = "pool-135-thread-16" (javaThreadId = 380)
stackTrace = [
com.ankurm.jfr.service.WorkloadService.holdLedger(int) line: 100
com.ankurm.jfr.service.WorkloadService.lambda$contend$0(CountDownLatch, CountDownLatch, AtomicLong, int) line: 89
java.util.concurrent.Executors$RunnableAdapter.call() line: 545
java.util.concurrent.FutureTask.run() line: 328
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: 1090
]
}
$ jfr print --events jdk.JavaMonitorEnter recordings/live-demo.jfr | grep duration | sort | uniq -c
1 duration = 101 ms
1 duration = 122 ms
1 duration = 142 ms
1 duration = 162 ms
1 duration = 182 ms
1 duration = 20.4 ms
1 duration = 203 ms
1 duration = 223 ms
1 duration = 243 ms
1 duration = 263 ms
1 duration = 283 ms
1 duration = 303 ms
1 duration = 40.6 ms
1 duration = 60.9 ms
1 duration = 81.0 ms
15 events, one per waiting thread, stepping up in ~20 ms increments (20.4, 40.6,
60.9, 81.0, 101, 122, ... 303 ms) -- exactly the signature of 16 threads queueing
one at a time for a monitor held 20 ms at a time: the Nth waiter waits roughly
(N-1) x 20 ms. The total wall-clock time the HTTP endpoint reported for this call
was 326 ms, consistent with the last waiter's ~303 ms queueing time plus its own
20 ms hold.
+38
View File
@@ -0,0 +1,38 @@
60 GET /api/orders/process calls against the live app while recording "live2"
(settings=profile) was running. OrderProcessedEvent has @Threshold("20 ms"), and
only ~1/3 of simulated orders take the slow path (35 ms, "inventory-lock-wait");
the rest are fast (0-5 ms) and should be filtered out before ever being written.
$ jfr print --events com.ankurm.jfr.OrderProcessed recordings/live-demo.jfr | head -21
com.ankurm.jfr.OrderProcessed {
startTime = 09:59:08.076 (2026-10-01)
duration = 35.2 ms
orderId = "ORD-61"
warehouse = "BOM-1"
amountCents = 0
itemCount = 4
slowReason = "inventory-lock-wait"
eventThread = "http-nio-8080-exec-2" (javaThreadId = 31)
stackTrace = [
com.ankurm.jfr.service.OrderService.processOrder(String, int) line: 39
com.ankurm.jfr.web.OrderController.process(int) line: 25
jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 104
java.lang.reflect.Method.invoke(Object, Object[]) line: 565
org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(Object[]) line: 252
]
}
com.ankurm.jfr.OrderProcessed {
startTime = 09:59:08.156 (2026-10-01)
duration = 35.1 ms
orderId = "ORD-63"
$ jfr print --events com.ankurm.jfr.OrderProcessed recordings/live-demo.jfr | grep -c '^com.ankurm'
23
23 of 60 orders were kept -- every one of them carries slowReason =
"inventory-lock-wait" and a duration at or above the 20 ms threshold. None of
the fast-path orders (duration well under 20 ms) appear at all: the threshold
discarded them before OrderProcessedEvent.commit() ever ran, which is the whole
point of checking event.shouldCommit() after event.end() instead of always
calling commit() unconditionally.
@@ -0,0 +1,43 @@
Same workload (40 rounds of GET /api/lock/contend?workers=2&holdMillis=12, each
round producing exactly one waiter blocked for ~12 ms) run against three
ISOLATED recordings, one at a time, so each sees its own settings only.
--- settings=default (jdk.JavaMonitorEnter threshold = 20 ms) ---
$ jcmd 5287 JFR.start name=soloDefault settings=default
$ for i in $(seq 1 40); do curl -s "localhost:8080/api/lock/contend?workers=2&holdMillis=12" -o /dev/null; done
$ jcmd 5287 JFR.stop name=soloDefault filename=recordings/solo-default.jfr
$ jfr print --events jdk.JavaMonitorEnter recordings/solo-default.jfr | grep -c duration
0
--- settings=profile (jdk.JavaMonitorEnter threshold = 10 ms) ---
$ jcmd 5287 JFR.start name=soloProfile settings=profile
$ for i in $(seq 1 40); do curl -s "localhost:8080/api/lock/contend?workers=2&holdMillis=12" -o /dev/null; done
$ jcmd 5287 JFR.stop name=soloProfile filename=recordings/solo-profile.jfr
$ jfr print --events jdk.JavaMonitorEnter recordings/solo-profile.jfr | grep -c duration
40
$ jfr print --events jdk.JavaMonitorEnter recordings/solo-profile.jfr | grep duration | sort | uniq -c
1 duration = 10.2 ms
13 duration = 12.1 ms
11 duration = 12.2 ms
9 duration = 12.3 ms
1 duration = 12.4 ms
1 duration = 12.6 ms
1 duration = 13.6 ms
1 duration = 14.2 ms
1 duration = 14.9 ms
1 duration = 30.3 ms
--- settings=default again, this time with a 35 ms hold (above BOTH thresholds) ---
$ jcmd 5287 JFR.start name=soloDefault2 settings=default
$ for i in $(seq 1 10); do curl -s "localhost:8080/api/lock/contend?workers=2&holdMillis=35" -o /dev/null; done
$ jcmd 5287 JFR.stop name=soloDefault2 filename=recordings/solo-default-longhold.jfr
$ jfr print --events jdk.JavaMonitorEnter recordings/solo-default-longhold.jfr | grep -c duration
10
Conclusion, with real counts to back it: a monitor hold of ~12 ms is invisible to
"settings=default" (0 of 40 waits captured) but fully visible to "settings=profile"
(40 of 40). The same default recording catches every wait once the hold is raised
to 35 ms (10 of 10). This is `jdk.JavaMonitorEnter`'s threshold doing exactly what
the shipped default.jfc / profile.jfc files say (20 ms vs 10 ms) -- see
docs/output/08-concurrent-recordings-shared-threshold.txt for what happens to this
picture the moment a SECOND recording with a lower threshold is also running.
@@ -0,0 +1,32 @@
The same 40-round, ~12 ms-wait workload as 07-threshold-isolated-comparison.txt,
but this time two recordings are started AT THE SAME TIME on the same JVM: one
with settings=default (JavaMonitorEnter threshold 20 ms) and one with
settings=profile (threshold 10 ms).
$ jcmd 5287 JFR.start name=cmpA settings=default
$ jcmd 5287 JFR.start name=cmpB settings=profile
$ for i in $(seq 1 40); do curl -s "localhost:8080/api/lock/contend?workers=2&holdMillis=12" -o /dev/null; done
$ jcmd 5287 JFR.stop name=cmpA filename=recordings/compare-default.jfr
$ jcmd 5287 JFR.stop name=cmpB filename=recordings/compare-profile.jfr
$ jfr summary recordings/compare-default.jfr | grep JavaMonitorEnter
jdk.JavaMonitorEnter 40 1080
$ jfr summary recordings/compare-profile.jfr | grep JavaMonitorEnter
jdk.JavaMonitorEnter 40 1080
Both recordings show all 40 events -- including in "compare-default.jfr", the one
configured with a 20 ms threshold, for waits that are only ~12 ms long. Compare
this to 07-threshold-isolated-comparison.txt, where the exact same default
settings, run ALONE with the exact same workload, captured zero of these waits.
The difference is that the two recordings were active at the same time. Duration
thresholds for events like jdk.JavaMonitorEnter are implemented as a single
instrumentation check shared by the JVM across every currently-active recording,
not a private filter per recording -- the effective threshold the running code
uses is the MINIMUM threshold requested by any active recording. A second,
unrelated recording (a colleague's ad hoc `jcmd JFR.start`, an APM agent's own
continuous recording) with a lower threshold for an event type silently widens
what every other concurrently running recording captures for that same event
type. "My recording uses the default profile" is not, by itself, enough to know
what your recording actually contains on a box where something else might also be
recording.
+49
View File
@@ -0,0 +1,49 @@
While building the main walkthrough, this exact sequence was run against recording
"live" (settings=profile, filename=recordings/profile-run.jfr set at JFR.start):
$ jcmd 5287 JFR.start name=live settings=profile filename=recordings/profile-run.jfr maxsize=256m
$ # ... cpu, allocation, lock-contention and 60 order calls ...
$ jcmd 5287 JFR.dump name=live filename=recordings/profile-run.jfr # same path as JFR.start's filename=
$ jcmd 5287 JFR.stop name=live # no filename -> falls back to the
# recording's own configured destination,
# which is that SAME path
$ jfr summary recordings/profile-run.jfr | grep -i 'Chunks\|JavaMonitorEnter\|OrderProcessed'
Chunks: 3
jdk.JavaMonitorEnter 30 768
com.ankurm.jfr.OrderProcessed 56 1988
The live app had exactly one lock/contend call with 16 workers (expected 15
JavaMonitorEnter events, one per waiting thread -- confirmed independently in
docs/output/05-lock-contention-live-demo.txt) and 60 order calls with a 20 ms
threshold (expected roughly a third to clear the threshold). 30 and 56 are both
suspiciously close to exactly double a plausible real count.
$ jfr print --events com.ankurm.jfr.OrderProcessed --json recordings/profile-run.jfr \
| python3 -c "import json,sys; d=json.load(sys.stdin); e=d['recording']['events']; \
print('printed:', len(e)); \
print('unique (orderId,startTime):', len({(x['values']['orderId'], x['values']['startTime']) for x in e}))"
printed: 56
unique (orderId,startTime): 28
Every one of the 56 printed events is an exact duplicate of one of 28 real
events -- same orderId, same startTime, same duration, same stack trace, each
appearing exactly twice. The same 2x duplication shows up in every other event
type in this file, including jdk.JavaMonitorEnter (30 printed, 15 real -- matching
the independently-confirmed count of 15 waiters for a 16-worker contend call).
The cause: `JFR.dump` was pointed at the SAME file path the recording was already
configured to write to via `filename=` on `JFR.start`. The subsequent `JFR.stop`,
given no filename of its own, fell back to that same configured destination and
wrote the complete recording there again, on top of the file the mid-flight dump
had already written -- doubling every event from before the dump. The fix used
for the rest of this companion project's recordings: either never set `filename=`
on `JFR.start` at all (only ever name a file explicitly on `JFR.dump` / `JFR.stop`,
each one a distinct path -- see recordings/live-demo.jfr and
recordings/mid-flight-snapshot.jfr, produced this way with zero duplication), or
if a recording does have a configured destination, never `JFR.dump` to that exact
same path mid-flight.
recordings/dump-duplication-bug.jfr is kept in this repository, unedited, as a
real example a reader can open in JDK Mission Control and see the doubled events
for themselves.
+42
View File
@@ -0,0 +1,42 @@
The complete, correctly-produced flagship recording for this post:
recordings/live-demo.jfr. Produced by one JFR.start, one mid-flight JFR.dump to a
DIFFERENT file (recordings/mid-flight-snapshot.jfr, to demonstrate inspecting a
running recording without stopping it), and one final JFR.stop with its own
filename= -- the pattern that avoids the duplication bug documented in
docs/output/09-dump-duplication-bug.txt.
$ jfr summary recordings/live-demo.jfr | head -19
Version: 2.1
Chunks: 2
Start: 2026-10-01 04:29:03 (UTC)
Duration: 6 s
Event Type Count Size (bytes)
=============================================================
jdk.ModuleExport 1756 20764
jdk.ActiveSetting 1137 30480
jdk.BooleanFlag 992 31418
jdk.GCPhaseParallel 570 15793
jdk.InitialEnvironmentVariable 360 46224
jdk.ModuleRequire 318 3498
jdk.ObjectAllocationSample 317 5081
jdk.LongFlag 274 9074
jdk.NativeMethodSample 211 2532
jdk.UnsignedLongFlag 186 6468
jdk.ThreadPark 130 5283
jdk.ThreadAllocationStatistics 116 1337
The four event types this post is actually about, pulled out of the same file:
$ jfr summary recordings/live-demo.jfr | grep -E 'ExecutionSample|ObjectAllocationSample|JavaMonitorEnter|OrderProcessed'
jdk.ObjectAllocationSample 317 5081
jdk.ExecutionSample 98 1176
com.ankurm.jfr.OrderProcessed 23 809
jdk.JavaMonitorEnter 15 414
317 allocation samples, 98 CPU samples (63% of them in the one hot method --
docs/output/03-hot-method-samples.txt), 23 kept custom business events out of 60
calls (docs/output/06-custom-event-live-demo.txt), and 15 monitor-enter events
from one 16-worker contention burst (docs/output/05-lock-contention-live-demo.txt)
-- all from a recording six seconds long, on an application that otherwise just
sits idle.
+15
View File
@@ -0,0 +1,15 @@
$ java -cp target/classes com.ankurm.jfr.events.BrokenEventPatternDemo
calls: 200
exceptions thrown: 41
events committed: 159
expected if lossless: 200
events missing: 41 (== exceptions thrown)
BrokenEventPattern.processWithoutTryFinally() has no try/finally around
event.commit(); when riskyStep() throws (about one call in five, by design),
execution leaves the method from the catch in the demo driver, not from the line
that would have called commit(). The event threshold was forced to 0 ms for this
run specifically to rule out "the event was just too fast to pass the default
threshold" as an alternative explanation -- every one of the 41 missing events is
attributable to the missing try/finally, not to filtering. No exception, log line,
or JFR.check output calls this out: the only way to notice is to count.
+47
View File
@@ -0,0 +1,47 @@
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>4.1.1</version>
<relativePath/>
</parent>
<groupId>com.ankurm</groupId>
<artifactId>jfr-demo</artifactId>
<version>1.0.0</version>
<packaging>jar</packaging>
<name>jfr-demo</name>
<description>Companion project for "Java Flight Recorder and Mission Control: Profiling a Live Spring Boot App in 20 Minutes" (ankurm.com)</description>
<properties>
<java.version>25</java.version>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-test</artifactId>
<scope>test</scope>
</dependency>
</dependencies>
<build>
<finalName>jfr-demo</finalName>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
</plugin>
</plugins>
</build>
</project>
Binary file not shown.
Binary file not shown.
Binary file not shown.
Binary file not shown.
Binary file not shown.
Binary file not shown.
Binary file not shown.
Binary file not shown.
+25
View File
@@ -0,0 +1,25 @@
#!/usr/bin/env bash
# Reproduces the main flagship recording: start a profile-settings recording,
# drive real load, take a mid-flight snapshot to a DIFFERENT file (never the
# recording's own destination -- see docs/output/09-dump-duplication-bug.txt
# for what goes wrong if you do), then stop with its own filename.
#
# Usage: scripts/capture-jfr.sh <pid>
set -euo pipefail
cd "$(dirname "$0")/.."
PID="${1:?usage: capture-jfr.sh <pid>}"
mkdir -p recordings
jcmd "$PID" JFR.start name=live settings=profile maxsize=256m
scripts/load.sh cpu
scripts/load.sh alloc
scripts/load.sh lock
jcmd "$PID" JFR.dump name=live filename="$(pwd)/recordings/mid-flight-snapshot.jfr"
scripts/load.sh orders
jcmd "$PID" JFR.stop name=live filename="$(pwd)/recordings/live-demo.jfr"
echo "wrote recordings/live-demo.jfr and recordings/mid-flight-snapshot.jfr"
+39
View File
@@ -0,0 +1,39 @@
#!/usr/bin/env bash
# Generates the same real load used to produce docs/output/*.txt against a
# running instance of the app (localhost:8080 by default).
#
# Usage: scripts/load.sh {cpu|alloc|lock|orders|all}
set -euo pipefail
HOST="${HOST:-localhost:8080}"
cpu() {
echo "6 concurrent fibonacci(38) calls..."
for i in 1 2 3 4 5 6; do curl -s "$HOST/api/cpu/fibonacci?n=38" -o /dev/null & done
wait
}
alloc() {
echo "3 concurrent allocation-churn calls..."
for i in 1 2 3; do curl -s "$HOST/api/alloc/churn?iterations=400000" -o /dev/null & done
wait
}
lock() {
echo "one 16-worker, 20ms-hold lock-contention burst..."
curl -s "$HOST/api/lock/contend?workers=16&holdMillis=20"; echo
}
orders() {
echo "60 order-processing calls (custom JFR event)..."
for i in $(seq 1 60); do curl -s "$HOST/api/orders/process?items=$((3 + i % 5))" -o /dev/null; done
echo "done"
}
case "${1:-all}" in
cpu) cpu ;;
alloc) alloc ;;
lock) lock ;;
orders) orders ;;
all) cpu; alloc; lock; orders ;;
*) echo "usage: $0 {cpu|alloc|lock|orders|all}" >&2; exit 1 ;;
esac
+19
View File
@@ -0,0 +1,19 @@
#!/usr/bin/env bash
# Reproduces the dump/stop duplication trap documented in
# docs/output/09-dump-duplication-bug.txt. Do not copy this pattern.
#
# Usage: scripts/reproduce-dump-bug.sh <pid>
set -euo pipefail
cd "$(dirname "$0")/.."
PID="${1:?usage: reproduce-dump-bug.sh <pid>}"
mkdir -p recordings
DEST="$(pwd)/recordings/dump-duplication-bug.jfr"
jcmd "$PID" JFR.start name=live settings=profile filename="$DEST" maxsize=256m
scripts/load.sh all
# BUG: dumping to the SAME path the recording is already configured to write to...
jcmd "$PID" JFR.dump name=live filename="$DEST"
# ...then stopping with no filename, which falls back to that same path.
jcmd "$PID" JFR.stop name=live
echo "wrote $DEST -- every event in it is duplicated. See docs/output/09-dump-duplication-bug.txt"
+54
View File
@@ -0,0 +1,54 @@
#!/usr/bin/env bash
# Regenerates every file under docs/output/.
#
# 01 comes from the JUnit test suite (jdk.jfr.Recording API, in-process).
# 02-10 come from starting the real app and driving it with jcmd + curl,
# exactly as described in the post. 11 comes from a standalone driver class.
#
# This script assumes JAVA_HOME points at a JDK with jfr/jcmd on PATH, and
# that no other jfr-demo.jar is already running on port 8080.
set -euo pipefail
cd "$(dirname "$0")/.."
echo "== 01: in-process custom-event test =="
mvn -q -B test
echo "== 11: broken-event-pattern standalone demo =="
mvn -q -B -DskipTests package
java -cp target/classes com.ankurm.jfr.events.BrokenEventPatternDemo \
| tee /tmp/broken-event-output.txt
# docs/output/11-broken-event-pattern.txt is written by hand from this run's
# output plus commentary; regenerate it manually if the numbers change.
echo "== starting app for the live jcmd-driven captures =="
scripts/run.sh -d
PID=$(ps -eo pid,cmd | grep '[j]fr-demo.jar' | awk '{print $1}' | head -1)
echo "app pid: $PID"
echo "== 02-10: live recording capture =="
scripts/capture-jfr.sh "$PID"
# docs/output/02 through 10 are written by hand from the jfr print/summary
# output of recordings/live-demo.jfr and the comparison recordings below;
# regenerate them manually if the workload or JDK version changes.
echo "== threshold-comparison recordings (docs/output/07, 08) =="
jcmd "$PID" JFR.start name=soloDefault settings=default
for i in $(seq 1 40); do curl -s "localhost:8080/api/lock/contend?workers=2&holdMillis=12" -o /dev/null; done
jcmd "$PID" JFR.stop name=soloDefault filename="$(pwd)/recordings/solo-default.jfr"
jcmd "$PID" JFR.start name=soloProfile settings=profile
for i in $(seq 1 40); do curl -s "localhost:8080/api/lock/contend?workers=2&holdMillis=12" -o /dev/null; done
jcmd "$PID" JFR.stop name=soloProfile filename="$(pwd)/recordings/solo-profile.jfr"
jcmd "$PID" JFR.start name=soloDefault2 settings=default
for i in $(seq 1 10); do curl -s "localhost:8080/api/lock/contend?workers=2&holdMillis=35" -o /dev/null; done
jcmd "$PID" JFR.stop name=soloDefault2 filename="$(pwd)/recordings/solo-default-longhold.jfr"
jcmd "$PID" JFR.start name=cmpA settings=default
jcmd "$PID" JFR.start name=cmpB settings=profile
for i in $(seq 1 40); do curl -s "localhost:8080/api/lock/contend?workers=2&holdMillis=12" -o /dev/null; done
jcmd "$PID" JFR.stop name=cmpA filename="$(pwd)/recordings/compare-default.jfr"
jcmd "$PID" JFR.stop name=cmpB filename="$(pwd)/recordings/compare-profile.jfr"
for p in $(ps -eo pid,cmd | grep '[j]fr-demo.jar' | awk '{print $1}'); do kill -9 "$p"; done
echo "all recordings regenerated under recordings/"
Executable
+26
View File
@@ -0,0 +1,26 @@
#!/usr/bin/env bash
# Build and start the demo app in the foreground (or detached with -d).
# Usage: scripts/run.sh [-d]
set -euo pipefail
cd "$(dirname "$0")/.."
for p in $(ps -eo pid,cmd | grep '[j]fr-demo.jar' | awk '{print $1}'); do
echo "killing previous instance: $p"
kill -9 "$p"
done
mvn -q -B -DskipTests package
if [[ "${1:-}" == "-d" ]]; then
setsid nohup java -jar target/jfr-demo.jar > /tmp/jfr-demo.log 2>&1 < /dev/null &
echo "started detached, pid $!"
for i in $(seq 1 30); do
code=$(curl -s -o /dev/null -w '%{http_code}' localhost:8080/api/jfr/recordings || true)
[[ "$code" == "200" ]] && { echo "up after ${i}s"; exit 0; }
sleep 1
done
echo "app did not come up in time, see /tmp/jfr-demo.log" >&2
exit 1
else
exec java -jar target/jfr-demo.jar
fi
@@ -0,0 +1,25 @@
package com.ankurm.jfr;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
/**
* Companion application for the ankurm.com post "Java Flight Recorder and
* Mission Control: Profiling a Live Spring Boot App in 20 Minutes".
*
* <p>This app is intentionally small: three endpoints that create real,
* observable load (a CPU-bound hot method, an allocation-heavy method, and a
* lock-contention scenario), one endpoint that emits a custom JFR event for a
* fictional "order" business operation, and one diagnostic endpoint that
* prints the JVM's own live Flight Recorder state. None of it is a
* benchmark harness &mdash; it exists so that a real {@code jcmd JFR.start} /
* {@code jcmd JFR.stop} cycle against this process has something genuine to
* record.</p>
*/
@SpringBootApplication
public class JfrDemoApplication {
public static void main(String[] args) {
SpringApplication.run(JfrDemoApplication.class, args);
}
}
@@ -0,0 +1,41 @@
package com.ankurm.jfr.events;
import java.util.concurrent.ThreadLocalRandom;
/**
* Not wired into the application. This class exists purely so the post can
* link to a real, compiled file for the "how to lose your own event" trap:
* {@code begin()} without a {@code try/finally} around {@code commit()}.
*
* <p>If {@code riskyStep()} throws, execution never reaches
* {@code event.commit()} below, the method exits via the exception, and the
* event silently never gets written to the recording &mdash; no error, no
* log line, nothing in the stream. Compare this to
* {@link com.ankurm.jfr.service.OrderService#processOrder}, which wraps the
* same begin/end/commit sequence in {@code try/finally} so the event is
* written (with {@code slowReason} noting the failure) even when the
* simulated downstream call fails.
*/
public final class BrokenEventPattern {
private BrokenEventPattern() {
}
/** Demonstrates the bug. Never call this from production code. */
public static void processWithoutTryFinally(String orderId) {
OrderProcessedEvent event = new OrderProcessedEvent();
event.begin();
riskyStep(orderId); // if this throws, the lines below never run
event.end();
if (event.shouldCommit()) {
event.orderId = orderId;
event.commit();
}
}
private static void riskyStep(String orderId) {
if (ThreadLocalRandom.current().nextInt(5) == 0) {
throw new IllegalStateException("simulated downstream failure for " + orderId);
}
}
}
@@ -0,0 +1,50 @@
package com.ankurm.jfr.events;
import java.nio.file.Files;
import java.nio.file.Path;
import java.time.Duration;
import java.util.List;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordingFile;
/**
* Standalone driver that proves {@link BrokenEventPattern} silently drops
* events on the unhappy path. Run with:
* {@code java -cp target/classes com.ankurm.jfr.events.BrokenEventPatternDemo}
* See docs/output/11-broken-event-pattern.txt for a captured run.
*/
public final class BrokenEventPatternDemo {
private BrokenEventPatternDemo() {
}
public static void main(String[] args) throws Exception {
Path dump = Files.createTempFile("broken-event", ".jfr");
Recording recording = new Recording();
// Threshold forced to zero so this demo isolates "lost to the missing
// try/finally" from "filtered by the 20 ms default threshold" -- the
// two are easy to conflate if you do not pin one of them down.
recording.enable("com.ankurm.jfr.OrderProcessed").withThreshold(Duration.ZERO);
recording.start();
int total = 200;
int exceptions = 0;
for (int i = 0; i < total; i++) {
try {
BrokenEventPattern.processWithoutTryFinally("ORD-" + i);
} catch (IllegalStateException e) {
exceptions++;
}
}
recording.stop();
recording.dump(dump);
List<?> events = RecordingFile.readAllEvents(dump);
System.out.println("calls: " + total);
System.out.println("exceptions thrown: " + exceptions);
System.out.println("events committed: " + events.size());
System.out.println("expected if lossless: " + total);
System.out.println("events missing: " + (total - events.size()) + " (== exceptions thrown)");
}
}
@@ -0,0 +1,58 @@
package com.ankurm.jfr.events;
import jdk.jfr.Category;
import jdk.jfr.Description;
import jdk.jfr.Event;
import jdk.jfr.Label;
import jdk.jfr.Name;
import jdk.jfr.StackTrace;
import jdk.jfr.Threshold;
/**
* A custom JFR event for one fictional "order processed" business operation.
*
* <p>This is the whole API surface a custom event needs: extend
* {@link Event}, annotate it, add fields, then {@code begin()} / set fields /
* {@code commit()} (or {@code end()} + {@code commit()} if you want JFR to
* measure the duration for you &mdash; see {@link
* com.ankurm.jfr.service.OrderService} for which one this demo uses and why).
*
* <p>{@code @Threshold("20 ms")} is a <em>default</em>. It only takes effect
* when the recording's settings do not mention this event type at all. Both
* {@code default.jfc} and {@code profile.jfc} (the two settings files that
* ship inside the JDK) are silent about
* {@code com.ankurm.jfr.OrderProcessed} &mdash; they only know about
* {@code jdk.*} events &mdash; so this annotation is what actually governs
* the event when you run {@code jcmd <pid> JFR.start settings=profile}. See
* the post's "what the defaults do not do" section for what happens if you
* forget this annotation exists and expect every order to show up.
*/
@Name("com.ankurm.jfr.OrderProcessed")
@Label("Order Processed")
@Category({"ankurm.com demo", "Orders"})
@Description("Emitted once per simulated order. Duration is measured by JFR "
+ "between begin() and commit(); only orders slower than the "
+ "threshold are kept unless the threshold is overridden at "
+ "recording time.")
@StackTrace(true)
@Threshold("20 ms")
public class OrderProcessedEvent extends Event {
@Label("Order ID")
public String orderId;
@Label("Warehouse")
@Description("Which fictional warehouse fulfilled the order")
public String warehouse;
@Label("Amount (cents)")
public long amountCents;
@Label("Item Count")
public int itemCount;
@Label("Slow Reason")
@Description("Non-null when processing was deliberately slowed down to "
+ "simulate an inventory-lock wait or a pricing-service call")
public String slowReason;
}
@@ -0,0 +1,83 @@
package com.ankurm.jfr.service;
import java.util.concurrent.ThreadLocalRandom;
import org.springframework.stereotype.Service;
import com.ankurm.jfr.events.OrderProcessedEvent;
/**
* Emits one {@link OrderProcessedEvent} per call. This is the custom-event
* half of the post: everything here is ordinary Spring code, the only JFR
* API used is {@code begin()/end()/shouldCommit()/commit()} on the event
* object itself.
*/
@Service
public class OrderService {
private static final String[] WAREHOUSES = {"BOM-1", "BLR-2", "DEL-3", "PNQ-1"};
public OrderResult processOrder(String orderId, int itemCount) {
OrderProcessedEvent event = new OrderProcessedEvent();
event.begin();
String slowReason = null;
long amountCents;
try {
amountCents = priceItems(itemCount);
slowReason = maybeSimulateSlowPath();
} finally {
// try/finally is what guarantees this event is written even if
// priceItems() or the slow-path simulation throws. Compare to
// BrokenEventPattern, which skips the finally and loses events
// on the unhappy path.
event.end();
if (event.shouldCommit()) {
event.orderId = orderId;
event.warehouse = WAREHOUSES[ThreadLocalRandom.current().nextInt(WAREHOUSES.length)];
event.itemCount = itemCount;
event.slowReason = slowReason;
event.commit();
}
}
return new OrderResult(orderId, event.warehouse);
}
/** Pure CPU + a little allocation, standing in for a pricing calculation. */
private long priceItems(int itemCount) {
long total = 0;
for (int i = 0; i < itemCount; i++) {
total += 199 + (i % 7) * 50;
}
return total;
}
/**
* About one order in three is slowed down to simulate an inventory-lock
* wait, so a mix of orders land above and below the event's 20&nbsp;ms
* default threshold (see {@link OrderProcessedEvent}). Returns the
* reason text recorded on the event, or {@code null} for the fast path.
*/
private String maybeSimulateSlowPath() {
int roll = ThreadLocalRandom.current().nextInt(3);
if (roll == 0) {
sleepQuietly(35);
return "inventory-lock-wait";
}
if (roll == 1) {
sleepQuietly(5);
return null;
}
return null;
}
private void sleepQuietly(int millis) {
try {
Thread.sleep(millis);
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
}
public record OrderResult(String orderId, String warehouse) {
}
}
@@ -0,0 +1,108 @@
package com.ankurm.jfr.service;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;
import org.springframework.stereotype.Service;
/**
* Three deliberately-shaped workloads, one per JFR event family the post
* covers: a CPU hot method ({@code jdk.ExecutionSample}), allocation
* pressure ({@code jdk.ObjectAllocationSample}), and lock contention
* ({@code jdk.JavaMonitorEnter} / {@code jdk.ThreadPark}).
*
* <p>Every method here is intentionally naive. This is a demo of what JFR
* shows you, not an example of well-tuned Java.</p>
*/
@Service
public class WorkloadService {
/** A single shared lock. Every {@link #contend} call fights over this one object. */
private final Object sharedLedger = new Object();
/**
* The hot method. Naive recursive Fibonacci is exponential in {@code n};
* at n=38 it burns several hundred million stack frames on a
* contemporary core, which is exactly the kind of self-inflicted
* CPU cost {@code jdk.ExecutionSample} is built to surface by stack
* sampling &mdash; see docs/output/02-hot-method.txt for the actual
* top frames captured from a real run.
*/
public long fibonacci(int n) {
if (n <= 1) {
return n;
}
return fibonacci(n - 1) + fibonacci(n - 2);
}
/**
* Allocation pressure: builds {@code iterations} short-lived
* {@code String} objects through naive concatenation (no
* {@link StringBuilder}) so each loop turn allocates a new backing
* array that dies almost immediately. Returns a checksum so the JIT
* cannot prove the result is unused and optimize the loop away.
*/
public long churnAllocations(int iterations) {
long checksum = 0;
for (int i = 0; i < iterations; i++) {
String s = "order-" + i + "-" + (i * 31) + "-padding-padding-padding";
byte[] bytes = s.getBytes();
List<Byte> boxed = new ArrayList<>(bytes.length);
for (byte b : bytes) {
boxed.add(b); // autoboxing on purpose: one more short-lived object per byte
}
checksum += boxed.size() + s.hashCode();
}
return checksum;
}
/**
* Lock contention: {@code workers} threads all call
* {@link #holdLedger(int)}, which is {@code synchronized} on
* {@link #sharedLedger} and holds it for {@code holdMillis}. With
* enough workers and a hold time above the recording's
* {@code jdk.JavaMonitorEnter} threshold, most callers queue up
* waiting for the monitor &mdash; that queueing is what the event
* records. Returns total wall-clock time for all workers to finish.
*/
public long contend(int workers, int holdMillis) throws InterruptedException {
ExecutorService pool = Executors.newFixedThreadPool(workers);
CountDownLatch ready = new CountDownLatch(workers);
CountDownLatch go = new CountDownLatch(1);
AtomicLong started = new AtomicLong();
long t0 = System.nanoTime();
for (int i = 0; i < workers; i++) {
pool.submit(() -> {
ready.countDown();
try {
go.await();
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
return;
}
started.incrementAndGet();
holdLedger(holdMillis);
});
}
ready.await(5, TimeUnit.SECONDS);
go.countDown(); // release all workers at once to maximize contention
pool.shutdown();
pool.awaitTermination(30, TimeUnit.SECONDS);
return (System.nanoTime() - t0) / 1_000_000;
}
private void holdLedger(int holdMillis) {
synchronized (sharedLedger) {
try {
Thread.sleep(holdMillis);
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
}
}
}
@@ -0,0 +1,55 @@
package com.ankurm.jfr.web;
import java.util.List;
import java.util.stream.Collectors;
import jdk.jfr.EventType;
import jdk.jfr.FlightRecorder;
import jdk.jfr.Recording;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
/**
* Prints the JVM's own live Flight Recorder state. This is the diagnostic
* endpoint the companion-repo guidance asks for: instead of trusting
* documentation about what a recording is doing, ask the running process.
* Delete this endpoint (or put it behind an internal-only profile) before
* shipping &mdash; it has no business being reachable from the internet in a
* real service.
*/
@RestController
public class DiagnosticsController {
@GetMapping("/api/jfr/recordings")
public String recordings() {
List<Recording> recordings = FlightRecorder.getFlightRecorder().getRecordings();
if (recordings.isEmpty()) {
return "[]";
}
return recordings.stream()
.map(r -> "{\"id\":" + r.getId()
+ ",\"name\":\"" + r.getName() + "\""
+ ",\"state\":\"" + r.getState() + "\""
+ ",\"startTime\":\"" + r.getStartTime() + "\""
+ ",\"maxSize\":" + r.getMaxSize()
+ ",\"maxAge\":\"" + r.getMaxAge() + "\""
+ ",\"destination\":\"" + r.getDestination() + "\"}")
.collect(Collectors.joining(",", "[", "]"));
}
@GetMapping("/api/jfr/event-types")
public String eventTypes() {
List<EventType> types = FlightRecorder.getFlightRecorder().getEventTypes().stream()
.filter(t -> t.getName().startsWith("com.ankurm"))
.toList();
return types.stream()
.map(t -> "{\"name\":\"" + t.getName() + "\""
+ ",\"label\":\"" + t.getLabel() + "\""
+ ",\"categories\":" + t.getCategoryNames().stream()
.map(c -> "\"" + c + "\"")
.collect(Collectors.joining(",", "[", "]"))
+ "}")
.collect(Collectors.joining(",", "[", "]"));
}
}
@@ -0,0 +1,46 @@
package com.ankurm.jfr.web;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;
import com.ankurm.jfr.service.WorkloadService;
/**
* HTTP front door for the three synthetic workloads. Every endpoint returns
* timing so the load-generator script can log what it drove, but the
* interesting output is always the JFR recording taken while these run, not
* the HTTP response itself.
*/
@RestController
public class LoadController {
private final WorkloadService workload;
public LoadController(WorkloadService workload) {
this.workload = workload;
}
@GetMapping("/api/cpu/fibonacci")
public String fibonacci(@RequestParam(defaultValue = "38") int n) {
long t0 = System.nanoTime();
long result = workload.fibonacci(n);
long ms = (System.nanoTime() - t0) / 1_000_000;
return "{\"n\":" + n + ",\"result\":" + result + ",\"elapsedMs\":" + ms + "}";
}
@GetMapping("/api/alloc/churn")
public String churn(@RequestParam(defaultValue = "200000") int iterations) {
long t0 = System.nanoTime();
long checksum = workload.churnAllocations(iterations);
long ms = (System.nanoTime() - t0) / 1_000_000;
return "{\"iterations\":" + iterations + ",\"checksum\":" + checksum + ",\"elapsedMs\":" + ms + "}";
}
@GetMapping("/api/lock/contend")
public String contend(@RequestParam(defaultValue = "8") int workers,
@RequestParam(defaultValue = "30") int holdMillis) throws InterruptedException {
long totalMs = workload.contend(workers, holdMillis);
return "{\"workers\":" + workers + ",\"holdMillis\":" + holdMillis + ",\"totalMs\":" + totalMs + "}";
}
}
@@ -0,0 +1,28 @@
package com.ankurm.jfr.web;
import java.util.concurrent.atomic.AtomicLong;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;
import com.ankurm.jfr.service.OrderService;
/** The custom-event endpoint: one call = one {@code OrderProcessedEvent}. */
@RestController
public class OrderController {
private final OrderService orders;
private final AtomicLong sequence = new AtomicLong();
public OrderController(OrderService orders) {
this.orders = orders;
}
@GetMapping("/api/orders/process")
public String process(@RequestParam(defaultValue = "3") int items) {
String orderId = "ORD-" + sequence.incrementAndGet();
OrderService.OrderResult result = orders.processOrder(orderId, items);
return "{\"orderId\":\"" + result.orderId() + "\",\"warehouse\":\"" + result.warehouse() + "\"}";
}
}
+11
View File
@@ -0,0 +1,11 @@
server:
port: 8080
spring:
application:
name: jfr-demo
logging:
level:
root: INFO
com.ankurm.jfr: INFO
@@ -0,0 +1,83 @@
package com.ankurm.jfr.events;
import java.nio.file.Files;
import java.nio.file.Path;
import java.time.Duration;
import java.util.List;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordingFile;
import org.junit.jupiter.api.Test;
import com.ankurm.jfr.service.OrderService;
import com.ankurm.jfr.support.Transcript;
import static org.assertj.core.api.Assertions.assertThat;
/**
* Proves the custom event end to end using only the {@code jdk.jfr} Java
* API &mdash; no Spring context, no jcmd, no running server. This is the
* "smallest correct thing" from the post: start a {@link Recording},
* generate events, stop, read them back with {@link RecordingFile}.
*
* <p>The recording overrides {@code com.ankurm.jfr.OrderProcessed#threshold}
* to {@code 0 ms} so every order is kept regardless of the
* {@code @Threshold(20 ms)} default on {@link OrderProcessedEvent} &mdash;
* that override is exactly how you would widen capture for one event type
* from {@code jcmd} too: {@code jcmd <pid> JFR.start
* settings=profile,com.ankurm.jfr.OrderProcessed#threshold=0ms}.</p>
*/
class OrderProcessedEventTest {
@Test
void capturesOneEventPerOrder() throws Exception {
OrderService service = new OrderService();
Path dumpFile = Files.createTempFile("order-events", ".jfr");
Recording recording = new Recording();
recording.enable("com.ankurm.jfr.OrderProcessed").withThreshold(Duration.ZERO);
recording.start();
int orderCount = 20;
for (int i = 0; i < orderCount; i++) {
service.processOrder("TEST-" + i, 3 + (i % 4));
}
recording.stop();
recording.dump(dumpFile);
List<RecordedEvent> events = RecordingFile.readAllEvents(dumpFile);
assertThat(events).hasSize(orderCount);
long withSlowReason = events.stream()
.filter(e -> e.getValue("slowReason") != null)
.count();
long withoutSlowReason = orderCount - withSlowReason;
StringBuilder out = new StringBuilder();
out.append("# docs/output/01-order-event-test.txt\n");
out.append("# Generated by OrderProcessedEventTest.capturesOneEventPerOrder()\n");
out.append("# jdk.jfr.Recording started in-process, ").append(orderCount)
.append(" orders processed, recording stopped and dumped to a temp .jfr file,\n");
out.append("# then read back with jdk.jfr.consumer.RecordingFile.\n\n");
out.append("events recorded: ").append(events.size()).append('\n');
out.append("events with slowReason: ").append(withSlowReason).append('\n');
out.append("events without reason: ").append(withoutSlowReason).append('\n');
out.append("\nfirst event fields:\n");
RecordedEvent first = events.get(0);
out.append(" eventType = ").append(first.getEventType().getName()).append('\n');
out.append(" orderId = ").append(first.getValue("orderId").toString()).append('\n');
out.append(" warehouse = ").append(first.getValue("warehouse").toString()).append('\n');
out.append(" itemCount = ").append(first.getValue("itemCount").toString()).append('\n');
out.append(" duration(ms) = ").append(first.getDuration().toMillis()).append('\n');
out.append(" hasStackTrace = ").append(first.getStackTrace() != null).append('\n');
Transcript.write("01-order-event-test.txt", out.toString());
assertThat(withSlowReason).isGreaterThan(0);
assertThat(withoutSlowReason).isGreaterThan(0);
assertThat(first.getStackTrace()).isNotNull();
}
}
@@ -0,0 +1,34 @@
package com.ankurm.jfr.support;
import java.io.IOException;
import java.io.UncheckedIOException;
import java.nio.charset.StandardCharsets;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.nio.file.StandardOpenOption;
/**
* Writes test output straight to {@code docs/output/*.txt}. Every number in
* the blog post that is attributed to this test comes from a file this class
* wrote while the assertions in the same test passed &mdash; if the assertion
* ever stops being true, the build fails before a stale transcript could be
* committed.
*/
public final class Transcript {
private Transcript() {
}
public static void write(String fileName, String content) {
try {
Path dir = Paths.get("docs", "output");
Files.createDirectories(dir);
Path file = dir.resolve(fileName);
Files.writeString(file, content, StandardCharsets.UTF_8,
StandardOpenOption.CREATE, StandardOpenOption.TRUNCATE_EXISTING);
} catch (IOException e) {
throw new UncheckedIOException(e);
}
}
}