asmhatre
c7eccd1db5
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.
50 lines
3.0 KiB
Plaintext
50 lines
3.0 KiB
Plaintext
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.
|