commit c7eccd1db51cca96274931aeda9838366d6b357a Author: Ankur Mhatre Date: Thu Oct 1 04:37:26 2026 +0000 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. diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..b2e433c --- /dev/null +++ b/.gitignore @@ -0,0 +1,4 @@ +target/ +*.class +.idea/ +*.iml diff --git a/LICENSE b/LICENSE new file mode 100644 index 0000000..8794d57 --- /dev/null +++ b/LICENSE @@ -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. diff --git a/README.md b/README.md new file mode 100644 index 0000000..0572500 --- /dev/null +++ b/README.md @@ -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 ` reproduces just the flagship recording. +`scripts/reproduce-dump-bug.sh ` reproduces the dump/stop duplication +trap documented in `docs/output/09-dump-duplication-bug.txt` — 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 — 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 | — (delete before shipping) | +| `GET /api/jfr/event-types` | Diagnostic: lists registered `com.ankurm.*` event types | — (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 — 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 — 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` — the flagship recording referenced throughout the post +- `mid-flight-snapshot.jfr` — a snapshot taken while `live-demo.jfr`'s + recording was still running, proving you can inspect without stopping +- `dump-duplication-bug.jfr` — 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` — + the isolated threshold comparison (`docs/output/07`) +- `compare-default.jfr`, `compare-profile.jfr` — 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). diff --git a/docs/output/01-order-event-test.txt b/docs/output/01-order-event-test.txt new file mode 100644 index 0000000..8e8db14 --- /dev/null +++ b/docs/output/01-order-event-test.txt @@ -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 diff --git a/docs/output/02-start-recording-and-diagnostics.txt b/docs/output/02-start-recording-and-diagnostics.txt new file mode 100644 index 0000000..a2fdca3 --- /dev/null +++ b/docs/output/02-start-recording-and-diagnostics.txt @@ -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 diff --git a/docs/output/03-hot-method-samples.txt b/docs/output/03-hot-method-samples.txt new file mode 100644 index 0000000..31f4944 --- /dev/null +++ b/docs/output/03-hot-method-samples.txt @@ -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 + ... + ] +} diff --git a/docs/output/04-allocation-samples.txt b/docs/output/04-allocation-samples.txt new file mode 100644 index 0000000..9cd8fcc --- /dev/null +++ b/docs/output/04-allocation-samples.txt @@ -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.(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.(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). diff --git a/docs/output/05-lock-contention-live-demo.txt b/docs/output/05-lock-contention-live-demo.txt new file mode 100644 index 0000000..4122f57 --- /dev/null +++ b/docs/output/05-lock-contention-live-demo.txt @@ -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. diff --git a/docs/output/06-custom-event-live-demo.txt b/docs/output/06-custom-event-live-demo.txt new file mode 100644 index 0000000..bc8622d --- /dev/null +++ b/docs/output/06-custom-event-live-demo.txt @@ -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. diff --git a/docs/output/07-threshold-isolated-comparison.txt b/docs/output/07-threshold-isolated-comparison.txt new file mode 100644 index 0000000..f35aa74 --- /dev/null +++ b/docs/output/07-threshold-isolated-comparison.txt @@ -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. diff --git a/docs/output/08-concurrent-recordings-shared-threshold.txt b/docs/output/08-concurrent-recordings-shared-threshold.txt new file mode 100644 index 0000000..1a66215 --- /dev/null +++ b/docs/output/08-concurrent-recordings-shared-threshold.txt @@ -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. diff --git a/docs/output/09-dump-duplication-bug.txt b/docs/output/09-dump-duplication-bug.txt new file mode 100644 index 0000000..41c3ae7 --- /dev/null +++ b/docs/output/09-dump-duplication-bug.txt @@ -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. diff --git a/docs/output/10-final-summary.txt b/docs/output/10-final-summary.txt new file mode 100644 index 0000000..4d32250 --- /dev/null +++ b/docs/output/10-final-summary.txt @@ -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. diff --git a/docs/output/11-broken-event-pattern.txt b/docs/output/11-broken-event-pattern.txt new file mode 100644 index 0000000..31eff6c --- /dev/null +++ b/docs/output/11-broken-event-pattern.txt @@ -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. diff --git a/pom.xml b/pom.xml new file mode 100644 index 0000000..d70e385 --- /dev/null +++ b/pom.xml @@ -0,0 +1,47 @@ + + + 4.0.0 + + + org.springframework.boot + spring-boot-starter-parent + 4.1.1 + + + + com.ankurm + jfr-demo + 1.0.0 + jar + jfr-demo + Companion project for "Java Flight Recorder and Mission Control: Profiling a Live Spring Boot App in 20 Minutes" (ankurm.com) + + + 25 + + + + + org.springframework.boot + spring-boot-starter-web + + + + org.springframework.boot + spring-boot-starter-test + test + + + + + jfr-demo + + + org.springframework.boot + spring-boot-maven-plugin + + + + diff --git a/recordings/compare-default.jfr b/recordings/compare-default.jfr new file mode 100644 index 0000000..86d8e88 Binary files /dev/null and b/recordings/compare-default.jfr differ diff --git a/recordings/compare-profile.jfr b/recordings/compare-profile.jfr new file mode 100644 index 0000000..796b187 Binary files /dev/null and b/recordings/compare-profile.jfr differ diff --git a/recordings/dump-duplication-bug.jfr b/recordings/dump-duplication-bug.jfr new file mode 100644 index 0000000..94d1ab7 Binary files /dev/null and b/recordings/dump-duplication-bug.jfr differ diff --git a/recordings/live-demo.jfr b/recordings/live-demo.jfr new file mode 100644 index 0000000..025b09c Binary files /dev/null and b/recordings/live-demo.jfr differ diff --git a/recordings/mid-flight-snapshot.jfr b/recordings/mid-flight-snapshot.jfr new file mode 100644 index 0000000..fa32872 Binary files /dev/null and b/recordings/mid-flight-snapshot.jfr differ diff --git a/recordings/solo-default-longhold.jfr b/recordings/solo-default-longhold.jfr new file mode 100644 index 0000000..835128b Binary files /dev/null and b/recordings/solo-default-longhold.jfr differ diff --git a/recordings/solo-default.jfr b/recordings/solo-default.jfr new file mode 100644 index 0000000..b9970d3 Binary files /dev/null and b/recordings/solo-default.jfr differ diff --git a/recordings/solo-profile.jfr b/recordings/solo-profile.jfr new file mode 100644 index 0000000..8e4c887 Binary files /dev/null and b/recordings/solo-profile.jfr differ diff --git a/scripts/capture-jfr.sh b/scripts/capture-jfr.sh new file mode 100755 index 0000000..7bcbbbb --- /dev/null +++ b/scripts/capture-jfr.sh @@ -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 +set -euo pipefail +cd "$(dirname "$0")/.." +PID="${1:?usage: capture-jfr.sh }" +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" diff --git a/scripts/load.sh b/scripts/load.sh new file mode 100755 index 0000000..231c9e0 --- /dev/null +++ b/scripts/load.sh @@ -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 diff --git a/scripts/reproduce-dump-bug.sh b/scripts/reproduce-dump-bug.sh new file mode 100755 index 0000000..972be19 --- /dev/null +++ b/scripts/reproduce-dump-bug.sh @@ -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 +set -euo pipefail +cd "$(dirname "$0")/.." +PID="${1:?usage: reproduce-dump-bug.sh }" +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" diff --git a/scripts/run-all.sh b/scripts/run-all.sh new file mode 100755 index 0000000..afc1085 --- /dev/null +++ b/scripts/run-all.sh @@ -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/" diff --git a/scripts/run.sh b/scripts/run.sh new file mode 100755 index 0000000..585192e --- /dev/null +++ b/scripts/run.sh @@ -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 diff --git a/src/main/java/com/ankurm/jfr/JfrDemoApplication.java b/src/main/java/com/ankurm/jfr/JfrDemoApplication.java new file mode 100644 index 0000000..a1716ed --- /dev/null +++ b/src/main/java/com/ankurm/jfr/JfrDemoApplication.java @@ -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". + * + *

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 — it exists so that a real {@code jcmd JFR.start} / + * {@code jcmd JFR.stop} cycle against this process has something genuine to + * record.

+ */ +@SpringBootApplication +public class JfrDemoApplication { + + public static void main(String[] args) { + SpringApplication.run(JfrDemoApplication.class, args); + } +} diff --git a/src/main/java/com/ankurm/jfr/events/BrokenEventPattern.java b/src/main/java/com/ankurm/jfr/events/BrokenEventPattern.java new file mode 100644 index 0000000..7eac4a8 --- /dev/null +++ b/src/main/java/com/ankurm/jfr/events/BrokenEventPattern.java @@ -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()}. + * + *

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 — 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); + } + } +} diff --git a/src/main/java/com/ankurm/jfr/events/BrokenEventPatternDemo.java b/src/main/java/com/ankurm/jfr/events/BrokenEventPatternDemo.java new file mode 100644 index 0000000..14a1a26 --- /dev/null +++ b/src/main/java/com/ankurm/jfr/events/BrokenEventPatternDemo.java @@ -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)"); + } +} diff --git a/src/main/java/com/ankurm/jfr/events/OrderProcessedEvent.java b/src/main/java/com/ankurm/jfr/events/OrderProcessedEvent.java new file mode 100644 index 0000000..ce43faf --- /dev/null +++ b/src/main/java/com/ankurm/jfr/events/OrderProcessedEvent.java @@ -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. + * + *

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 — see {@link + * com.ankurm.jfr.service.OrderService} for which one this demo uses and why). + * + *

{@code @Threshold("20 ms")} is a default. 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} — they only know about + * {@code jdk.*} events — so this annotation is what actually governs + * the event when you run {@code jcmd 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; +} diff --git a/src/main/java/com/ankurm/jfr/service/OrderService.java b/src/main/java/com/ankurm/jfr/service/OrderService.java new file mode 100644 index 0000000..da03bab --- /dev/null +++ b/src/main/java/com/ankurm/jfr/service/OrderService.java @@ -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 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) { + } +} diff --git a/src/main/java/com/ankurm/jfr/service/WorkloadService.java b/src/main/java/com/ankurm/jfr/service/WorkloadService.java new file mode 100644 index 0000000..a269986 --- /dev/null +++ b/src/main/java/com/ankurm/jfr/service/WorkloadService.java @@ -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}). + * + *

Every method here is intentionally naive. This is a demo of what JFR + * shows you, not an example of well-tuned Java.

+ */ +@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 — 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 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 — 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(); + } + } + } +} diff --git a/src/main/java/com/ankurm/jfr/web/DiagnosticsController.java b/src/main/java/com/ankurm/jfr/web/DiagnosticsController.java new file mode 100644 index 0000000..b662103 --- /dev/null +++ b/src/main/java/com/ankurm/jfr/web/DiagnosticsController.java @@ -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 — 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 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 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(",", "[", "]")); + } +} diff --git a/src/main/java/com/ankurm/jfr/web/LoadController.java b/src/main/java/com/ankurm/jfr/web/LoadController.java new file mode 100644 index 0000000..6e70aa9 --- /dev/null +++ b/src/main/java/com/ankurm/jfr/web/LoadController.java @@ -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 + "}"; + } +} diff --git a/src/main/java/com/ankurm/jfr/web/OrderController.java b/src/main/java/com/ankurm/jfr/web/OrderController.java new file mode 100644 index 0000000..a62ca7a --- /dev/null +++ b/src/main/java/com/ankurm/jfr/web/OrderController.java @@ -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() + "\"}"; + } +} diff --git a/src/main/resources/application.yml b/src/main/resources/application.yml new file mode 100644 index 0000000..6022a3c --- /dev/null +++ b/src/main/resources/application.yml @@ -0,0 +1,11 @@ +server: + port: 8080 + +spring: + application: + name: jfr-demo + +logging: + level: + root: INFO + com.ankurm.jfr: INFO diff --git a/src/test/java/com/ankurm/jfr/events/OrderProcessedEventTest.java b/src/test/java/com/ankurm/jfr/events/OrderProcessedEventTest.java new file mode 100644 index 0000000..7fbad86 --- /dev/null +++ b/src/test/java/com/ankurm/jfr/events/OrderProcessedEventTest.java @@ -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 — 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}. + * + *

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} — + * that override is exactly how you would widen capture for one event type + * from {@code jcmd} too: {@code jcmd JFR.start + * settings=profile,com.ankurm.jfr.OrderProcessed#threshold=0ms}.

+ */ +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 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(); + } +} diff --git a/src/test/java/com/ankurm/jfr/support/Transcript.java b/src/test/java/com/ankurm/jfr/support/Transcript.java new file mode 100644 index 0000000..4609eb2 --- /dev/null +++ b/src/test/java/com/ankurm/jfr/support/Transcript.java @@ -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 — 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); + } + } +}