Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 19 additions & 0 deletions .investigations/jfr-mcp-diagnose-deadline/INDEX.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@
# Investigation Index

## Findings (confirmed)
- find-deadline-vs-real-cost | diagnose( full ) response 13-21s vs 15s deadline; fixed 15s->60s + property forwarding | [jfr-mcp, diagnose, timeout, e2e]

## Hypotheses
(none open)

## Dead ends
- dead-env-classification | Calling it 'environmental/flaky' without measuring | [classification] | REFUTED
- dead-heap-gc-logging | Heap, GC pressure and logging config as causes | [heap, gc, logging] | REFUTED

## Evidence
- ev-run-timings | Three failing 15s runs + three green raised-deadline runs + heap-ablation runs | [timings, runs]
- ev-parse-bench | Warm full untyped parses of the 2.2MB test recording, agent-laden vs agent-free | [parser, bench, agents]
- ev-jfr-profile | jfr ExecutionSample attribution + GC view: parser internals on top, 6 GCs/26ms max | [jfr, profile, gc]

## Questions
- q-parser-perf | Parser/analysis cost shape: hasConstantPool share, per-parse 14-thread daemon pools leaking until session close, agent tax on every test JVM | [parser, perf, follow-up]
34 changes: 34 additions & 0 deletions .investigations/jfr-mcp-diagnose-deadline/STATE.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,34 @@
# Current State

## Active investigation
None — concluded 2026-10-03. Status `done` in meta.yaml; root cause found, fix merged in
`259a0da` (MCP transport tests: raise the response deadline to 60s).

## What was concluded
`jfr_diagnose` (default `depth=full`, `includeAnalysis=true`) re-parses the whole recording for
each of its six sub-analyses; a warm full untyped parse of the 2.2 MB test recording measures
0.45–0.73 s (0.53–0.73 s under the test JVM's jacoco/mockito agents). ~10–12 passes ⇒ 13–21 s
real response time, vs the harness's 15 s deadline — the boundary is inside the natural range,
so the test failed whenever the box was loaded (including on pristine origin/main) and passed
under any raised deadline. Fix: default 60 s + forward `-Dmcp.test.timeout.ms`.

## Open questions (for a successor)
- q-parser-perf — the diagnose cost shape is architectural: `MetadataField.hasConstantPool`
≈ 15 % of CPU in the profile; each parse spawns a fresh fixed pool of
`availableProcessors()-2` unnamed daemon threads (`StreamingChunkParser` thread factory has no
naming/teardown until session close); agents tax every test JVM 15–40 % (paired measurements).
Any redesign is a planned-effort item, not a gate blocker.

## Ruled out (don't re-investigate)
- Heap: 8 GB vs 2 GB — identical timings.
- GC pressure: JFR profile run — 6 collections / 45 s, longest pause 26 ms.
- Logging: one shared main/resources/logback.xml on both in-process and child paths; parser at WARN.
- Hang: three 120–180 s deadline runs all returned 13–21 s responses.
- Backend/wiring mismatch: both paths register the same `JafarMcpServer` tool specs and the same
jf shell-jafar backend (checked harness construction, `McpServer.sync`).

## Fix that landed
`McpTransportHarness.RESPONSE_TIMEOUT_MS` 15_000 → 60_000; `:jfr-mcp:test` forwards
`-Dmcp.test.timeout.ms` (the harness failure message advertises it, the task used to ignore it).
R5 two-sided proof: 2000 ms fails the named test; default passes the whole class.
Case file: doc/agents/Verification.md under R6 ("the diagnose deadline between green and failure").
Original file line number Diff line number Diff line change
@@ -0,0 +1,37 @@
---
id: ev-jfr-profile
type: evidence
created: 2026-10-03
updated: 2026-10-03
---

# JFR method profile + GC view of the focused class run

Test JVM temporarily recorded with `-XX:StartFlightRecording=filename=/tmp/diag.jfr,settings=profile`
(run green, 18s-class). `jfr print --events jdk.ExecutionSample --json` → 4417 runnability samples.

Deepest-frame (self) attribution — top 12:

| samples | frame |
|---|---|
| 695 | io/jafar/parser/internal_api/metadata/MetadataField.hasConstantPool |
| 432 | io/jafar/parser/internal_api/RecordingStreamReader$BufferBackedRecordingStreamReader.readVarint |
| 278 | io/jafar/parser/ParsingUtils.parseLongSWAR |
| 274 | java/util/Objects.equals |
| 218 | io/jafar/parser/internal_api/RecordingStreamReader$BufferBackedRecordingStreamReader.readVarintSeq |
| 205 | java/util/HashMap.putVal |
| 168 | io/jafar/parser/internal_api/GenericValueReader.readValue |
| 166 | io/jafar/parser/internal_api/metadata/AbstractMetadataElement.getName |
| 140 | io/jafar/parser/internal_api/metadata/AbstractMetadataElement.getId |
| 114 | java/util/concurrent/ConcurrentHashMap.get |
| 114 | java/util/concurrent/ConcurrentHashMap.computeIfAbsent |
| 95 | io/jafar/parser/impl/MapValueBuilder.onLongValue |

Also visible: `$jacocoInit` probes inside parser metadata classes (52 samples on
AbstractMetadataElement alone) — agent probes sit inside the hot loop.

GC view: 6 collections over the 45s window, longest pause 26.3ms — GC pressure excluded.
Full stack (jstack during jfr_use): handler runs on Reactor `boundedElastic-1` parked in
`FutureTask.get` inside `StreamingChunkParser.parse:325`; chunk work on parser-pool threads
(unnamed `Thread-N` pairs — the custom thread factory in StreamingChunkParser does not name
threads; pool size = availableProcessors()-2 per parser instance).
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
---
id: ev-parse-bench
type: evidence
created: 2026-10-03
updated: 2026-10-03
---

# Warm full untyped parse of the 2.2MB test recording (in-executor bench)

Throwaway JUnit bench (`io.jafar.mcp.TmpParseBench`, deleted after the runs) driving
`ParsingContext.create().newUntypedParser(test-dd.jfr)` + `handle` + `run()` inside the real
Gradle test executor — no transport, no harness:

| Config | runs (events=67657) |
|---|---|
| With agents (default test task: jacoco + mockito agents, `cores=12`) | 1.793s cold, 0.727s, 0.529s |
| Agents stripped (init script removed both `-javaagent` flags) | 1.980s cold, 0.588s, 0.449s |

Agent cost at the parser level ≈ 15–25%; at the tool level (use/tsa/diagnose) the paired
test runs showed 15–40% — the analysis layer pays per-method-entry probes too, not just the
parse loop.

Implication used for the fix: diagnose(full) ≈ six sequential sub-analyses, each re-running
whole-recording queries (USE fans out over ~4 event families, TSA ~4); ~10–12 parse-equivalents
× ~0.5s ⇒ 6–10s ideal CPU, 13–21s observed with agents + load. The 15s harness deadline was
inside the tool's natural range.
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
---
id: ev-run-timings
type: evidence
created: 2026-10-03
updated: 2026-10-03
---

# Test-run timing series for McpJfrTransportTest.jfrDiagnoseReturnsReport

All runs `:jfr-mcp:test --tests io.jafar.mcp.McpJfrTransportTest` unless noted; testcase wall
time from JUnit XML (includes jfr_open + harness teardown).

| Run context | Deadline | Result |
|---|---|---|
| Branch-tip full suite (`:jfr-mcp:test`, 306 tests) | 15s | FAILED (only this test) — pre-rebase baseline |
| Focused, branch tip | 15s | FAILED at 17.8s testcase time (open ≈2.3s + 15s expiry) |
| Pristine origin/main worktree (`/tmp/jafar-main-wt`) | 15s | FAILED at 20.5s — same assertion, same message |
| Focused, `-Dmcp.test.timeout.ms=60000` (NOT forwarded at the time — no-op) | 15s | FAILED identically → forwarded-property gap discovered (R4) |
| Focused, `-Dmcp.test.timeout.ms=120000` (forwarding added) | 120s | green, 17.9s testcase |
| Focused under sampling, 180s | 180s | green, 20.9s (use 8.1s — box loaded: concurrent drydock-guided-tour suite observed with top) |
| Focused, agents stripped via init script | 180s | green, 13.1s (use 4.5s, tsa 2.3s, help 3.9s) |
| Heap ablation: `-Xmx8g` (2g default) | 15s | FAILED 18.4s — heap not the cause |
| Default after fix (60s) 2 | 60s | green, `:jfr-mcp:test --rerun-tasks` 404/404 |

Evidence sources: /tmp/baseline_test.log, /tmp/main_diag_test.log, /tmp/diag_timeout.log,
/tmp/diag_120s.log, /tmp/diag_sampling_run.log, /tmp/noagents_run.log, /tmp/final_test.log.
13 changes: 13 additions & 0 deletions .investigations/jfr-mcp-diagnose-deadline/meta.yaml
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
name: jfr-mcp-diagnose-deadline
description: >
McpJfrTransportTest.jfrDiagnoseReturnsReport failed on every run with no response within the
15s harness deadline. Investigation established it was slow-not-hung (jfr_diagnose depth=full
re-parses the whole recording ~10-12x), ruled heap/GC/logging out with data, measured the
agent tax, and fixed it by raising the default deadline to 60s + forwarding the advertised
-Dmcp.test.timeout.ms. Parser perf cost profile left as an open follow-up question.
status: done
created: 2026-10-03
updated: 2026-10-03
completed: 2026-10-03
last_commit: 292056b8350f1204a73bcad16d350650883d9005
last_session: jafar-mcp-guidance-agent-workflows
Original file line number Diff line number Diff line change
@@ -0,0 +1,21 @@
---
id: dead-env-classification
type: deadend
depends_on: [ev-run-timings]
status: refuted
created: 2026-10-03
updated: 2026-10-03
---

# 'Environmental/flaky' — refuted by measurement

The initial classification (recorded in the session report) treated the failure as a
pre-existing environmental issue with an honest NOT-VERIFIED note. The user pushed to
investigate; three cheap probes refuted it:
- A raised deadline made the SAME runs pass (3/3) — a stable failure, not a race.
- Pristine origin/main reproduced it identically — pre-existing, yes, but not environmental.
- Method profiling + an in-executor parse bench located the cost inside the tool's own
re-parse fan-out — a load-independent floor of ~6–10s that only *crosses* the 15s deadline
when the box is loaded.

Lesson: 'environmental' means proven environmental; otherwise it is an unmeasured boundary.
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
---
id: dead-heap-gc-logging
type: deadend
depends_on: [ev-jfr-profile, ev-run-timings]
status: refuted
tags: [heap, gc, logging]
created: 2026-10-03
updated: 2026-10-03
---

# Heap, GC and logging causes — refuted with data

- Heap: `-Xmx8g` ablation produced identical failing timings (18.4s testcase at the 15s
deadline) vs the 2g baseline (17.9s) — no meaningful change (ev-run-timings).
- GC: JFR `profile` run of the focused class recorded 6 collections in 45s, longest pause
26.3ms — nowhere near the seconds-scale cost being explained (ev-jfr-profile).
- Logging: one shared `jfr-mcp/src/main/resources/logback.xml` serves BOTH the in-process test
classpath and the shadow-jar child; `io.jafar.parser` is WARN in both, `io.jafar.mcp` DEBUG
(the DEBUG lines are tiny single lines per JSON-RPC message). A per-event DEBUG theory would
also have to explain why the child JVM is fast — it isn't per-event (ev-jfr-profile,
harness config).

Each probe was one command; together they closed the space so the parser-attribution evidence
could carry the conclusion alone.
Original file line number Diff line number Diff line change
@@ -0,0 +1,37 @@
---
id: find-deadline-vs-real-cost
type: finding
depends_on: [ev-run-timings, ev-parse-bench, ev-jfr-profile]
status: confirmed
tags: [jfr-mcp, diagnose, timeout, e2e, fix]
created: 2026-10-03
updated: 2026-10-03
---

# diagnose(full) response cost vs the 15s harness deadline

## Reasoning chain
1. Failure signature: harness returns null on deadline — identical on branch tip AND pristine
origin/main (ev-run-timings) ⇒ not branch-induced.
2. Raised-deadline runs always completed 13–21s and were never above 30s ⇒ slow-not-hung.
3. Heap ablation (8 GB) unchanged ⇒ not memory; JFR GC view (6 collections, ≤26 ms pauses) ⇒ not GC;
shared logback config with parser at WARN both contexts ⇒ not logging overhead.
4. Method profile: cycles concentrate in raw parser internals (MetadataField.hasConstantPool 695,
readVarint 650, SWAR 278) — i.e. the recording being re-parsed, repeatedly (ev-jfr-profile).
5. In-executor bench: one warm full untyped parse 0.45–0.73 s (ev-parse-bench); diagnose(full)
= summary + exceptions + GC + hotmethods + USE(~4 queries) + TSA(~4 queries) ⇒ ~10–12
parse-equivalents ⇒ 6–10 s ideal, 13–21 s with agents+load.
6. The 15 s deadline is below the tool's real cost ⇒ deterministic failure under load, flake
elsewhere. Sibling tools (use 4.5–8.1 s, tsa 2.3–3.2 s) fit under it; only diagnose crossed.

## Fix (landed in 259a0da)
- McpTransportHarness.RESPONSE_TIMEOUT_MS 15_000 → 60_000 (3× worst measured; a hang still fails).
- :jfr-mcp:test forwards -Dmcp.test.timeout.ms (advertised in the harness failure message, until
now silently ignored by the build).
- Two-sided R5: 2000 ms → the named test FAILS again; 60 s default → class and full module green.

## What this rules out
- 'Flaky/environmental' classification without measurement — the boundary flapped only because
load moved the tool's cost across the deadline; the tool itself was behaving correctly.
- Any production regression from #119/#120 in the diagnose path — the child-JVM e2e workflow
(fresh process, no agents) runs the same full diagnose inside a 10 s total.
30 changes: 30 additions & 0 deletions .investigations/jfr-mcp-diagnose-deadline/nodes/q-parser-perf.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,30 @@
---
id: q-parser-perf
type: question
status: open
related: [find-deadline-vs-real-cost, ev-parse-bench, ev-jfr-profile]
tags: [parser, perf, follow-up]
created: 2026-10-03
updated: 2026-10-03
---

# Parser/analysis cost follow-ups (data collected, redesign out of scope here)

Open threads a future perf effort owns, with numbers already on hand:

1. **`MetadataField.hasConstantPool` ≈ 15% of CPU** (695 of 4.4k samples in 45s) — metadata
lookups are hot in the parse loop; worth a look at caching the answer or restructuring the
call site (ev-jfr-profile).
2. **Per-parse executor churn**: each `JfrPathEvaluator` evaluation constructs a fresh
`UntypedJafarParser`/`StreamingChunkParser` with a fixed pool of
`availableProcessors()-2` (12 cores ⇒ 10 threads) unnamed daemon threads (factory in
`StreamingChunkParser` line ~29 does not name them; pools only tear down at session
`close()`). In long-lived MCP sessions that re-query, pools accumulate idle. Candidates:
shared/pooled executor + named threads (the repo's thread naming conventions), or a
reusable parser per session.
3. **Agent tax on every test JVM** (jacoco + mockito inline agents: 15–25% at parser,
15–40% at tool level, paired measurements). CI pays this on the whole suite; consider
coverage scope trims if CI time matters (ev-parse-bench).

None of these are correctness bugs and none block the e2e/eval gate; they are the follow-up
cost story the diagnose-deadline fix bought headroom for.
16 changes: 16 additions & 0 deletions doc/agents/Verification.md
Original file line number Diff line number Diff line change
Expand Up @@ -145,6 +145,22 @@ diff /tmp/fail_base.txt /tmp/fail_now.txt && echo "zero new failures"
Record the baseline **before** you start changing code. Report both numbers — total tests and the
named failing set — so a reader can tell growth from regression.

> **Case file — the diagnose deadline between green and failure.**
> `McpJfrTransportTest.jfrDiagnoseReturnsReport` failed on every run while every sibling passed.
> Not flaky, not environmental, not a hang: `jfr_diagnose` (default `depth=full`,
> `includeAnalysis=true`) legitimately re-parses the whole recording for each of its six
> sub-analyses. A warm full untyped parse of the 2.2 MB test recording measures 0.45–0.73 s
> (0.53–0.73 s with the coverage/mocking agents attached — their probes show up directly in the
> profile as `$jacocoInit` in the parse loop; agents cost 15–40 % measured paired), and diagnose
> makes ~10–12 such passes: 13–21 s under load, versus a 15 s harness deadline. Heap (unchanged at
> 8 GB), GC (longest pause 26 ms) and logging (parser at WARN in both contexts) were ruled out with
> data before anything was touched; three green runs under a raised deadline settled slow-not-hung.
> The fix was one number (deadline 15 s → 60 s). Two habits to keep: **classify a slow test by
> measuring its actual response time under a raised deadline before calling it flaky** — three
> measurements beat three hypotheses — and **when a harness advertises an override in its own
> failure message (`-Dmcp.test.timeout.ms`, "raise if the machine is loaded"), forward it from the
> Gradle task**: advice that the build silently ignores is R3's fallback in disguise.

## R7. One source of truth for any list two places must agree on

If a list is duplicated, the copies will disagree, and the disagreement will be invisible until a
Expand Down
14 changes: 8 additions & 6 deletions doc/cli/JFRPath.md
Original file line number Diff line number Diff line change
Expand Up @@ -241,16 +241,18 @@ For list and array fields, control how filters apply to elements:

**Syntax**:
```
[any:<listField>[condition]]
[all:<listField>[condition]]
[none:<listField>[condition]]
[any:<fieldPath> <op> <value>]
[all:<fieldPath> <op> <value>]
[none:<fieldPath> <op> <value>]
```

The condition applies when the field path resolves to a list; each element is tested in turn.

**Examples**:
```
events/jdk.ExecutionSample[any:stackTrace/frames[matches(method/name/string, ".*Foo.*")]]
events/jdk.ExecutionSample[all:stackTrace/frames[lineNumber>0]]
events/jdk.ExecutionSample[none:stackTrace/frames[matches(method/name/string, ".*Test.*")]]
events/jdk.ExecutionSample[any:stackTrace/frames/method/name/string ~ ".*Foo.*"]
events/jdk.ExecutionSample[all:stackTrace/frames/lineNumber > 0]
events/jdk.ExecutionSample[none:stackTrace/frames/method/name/string ~ ".*Test.*"]
```

### Interleaved Filters
Expand Down
Loading
Loading