Skip to content

feat(servermonitor): dedupe sub-process report, add cursor + in-memory merge - #33

Merged
szhatchenko merged 6 commits into
mainfrom
feature/subprocess-report-dedup-cursor-v2
Sep 1, 2026
Merged

szhatchenko merged 6 commits into
mainfrom
feature/subprocess-report-dedup-cursor-v2

Conversation

@szhatchenko

Copy link
Copy Markdown
Contributor

Summary

The "Slow Sub-Processes (during profile window)" section of the profile summary
previously printed one line per scan, so a process alive across many scan ticks was
repeated dozens of times, a process that finished between two scans was missed
entirely, and a process that outlived the profile window was not attributable to that
profile at all.

This PR makes the section per-pid and cumulative:

  1. Deduplicate per pid across scans. Each entry now carries first/last observation
    time plus an estimated lifetime (observed interval + age delta) instead of a single
    snapshot age.

  2. Cumulative report cursor. A high-water mark (subProcessLogCursor) is persisted
    in the profile's .json metadata sidecar. The first report covers the profile's time
    window; each subsequent report shows only what was observed since the previous
    report
    , so long-running external processes are still attributed to the profile that
    triggered them. The cursor survives server restarts (worst case: a few lines shown
    twice, harmless because entries are deduplicated per pid).

  3. In-memory observation registry. MonitoringService now tracks each pid's
    first/last-seen and max age across scans (pruned after 2 consecutive missed scans, so
    one transient /proc read failure does not drop a process). The report merges this
    live view with the persistent subprocesses.jsonl log, covering processes still
    observable right now — including ones that started after the profile window ended.

Example new report line

2026-08-31 14:02:11 → 2026-08-31 14:26:47  pid=1234 lifetime~1476s (max observed age 1450s)  perl script.pl --opt1

Files

  • MonitoringService.javaSubProcessObservation registry, updateSubProcessObservations(), getObservedSubProcesses()
  • SubProcessMonitor.java — first/last-seen + age fields, estimatedLifetimeSec()
  • SupportServlet.javaappendSubProcessSummary() rewrite (dedup + cursor + memory merge), persistSubProcessCursor(), SubProcessEntry

Verification

  • mvn -pl src compile — clean
  • ant -f src/build.xml compile — BUILD SUCCESSFUL (the unchecked-operations note on SupportServlet is pre-existing)
  • TestSubProcessLog — OK (8 tests)
  • TestAsyncProfilerWrapper — OK (5 tests)

Single commit on top of main (replaces the superseded #32, which was mistakenly based on a gxp_dev-side cherry-pick branch and therefore carried 50 unrelated commits).

Co-Authored-By: Claude Code noreply@anthropic.com

…y merge

The "Slow Sub-Processes" section of the profile summary previously printed
one line per scan, so a process alive across many scan ticks was repeated
dozens of times, and a process that finished between two scans was missed
entirely. Worse, a process that outlived the profile window was not
attributable to that profile at all.

Three changes, per-pid:

1. Deduplicate per pid across scans. Each entry now carries first/last
   observation time plus the estimated lifetime (observed interval + age
   delta), instead of a single snapshot age.

2. Cumulative report cursor. The high-water mark (subProcessLogCursor) is
   persisted in the profile's .json metadata sidecar. The first report
   covers the profile's time window; each subsequent report shows only what
   was observed since the previous report, so long-running external
   processes are still attributed to the profile that triggered it.

3. In-memory observation registry. MonitoringService now tracks each pid's
   first/last-seen and max age across scans (pruned after 2 consecutive
   missed scans, so one transient /proc read failure does not drop a
   process). The report merges this live view with the persistent
   subprocesses.jsonl log, covering processes still observable right now —
   including ones that started after the profile window ended.

Verified: mvn -pl src compile, ant -f src/build.xml compile,
TestSubProcessLog (8), TestAsyncProfilerWrapper (5) all pass.

Co-Authored-By: Claude Code <noreply@anthropic.com>
@szhatchenko
szhatchenko force-pushed the feature/subprocess-report-dedup-cursor-v2 branch from 389330e to ae26f26 Compare August 31, 2026 11:33
@szhatchenko

Copy link
Copy Markdown
Contributor Author

Review fixes — addressed in amended commit ae26f269

Thanks for the thorough review. All points addressed:

Blockers

  • Exchange some tracks formats #1 (first report pulls in unrelated in-memory processes)getObservedSubProcesses now filters by interval overlap (lastSeen >= intervalStart && firstSeen <= intervalEnd) instead of an unbounded "since service start" read. The first report uses the same ±120 s effective window for both the log read and the in-memory test. A process observed at 15:00 but still alive at 17:05 now only appears if it overlaps the profile window; one that started before and is gone by the window is excluded.
  • Feature/cram track importer #3 (lifetime double-counted)ageSeconds is now − startInstant (total elapsed since process start), so the total-lifetime estimate is simply lastAgeSec. The old interval + (lastAge−firstAge) double-counted the same wall-clock span. Fixed in estimatedLifetimeSec().
  • solve problem wth cram #4 (log entries showed lifetime~-1s) — each log snapshot now passes its own ageSeconds as the lifetime estimate, so a process present only in the persistent log (no longer in memory) still gets a real lifetime (the max observed age), not -1.
  • Translate web interface into russian language #2 (cursor semantics contradicted the filter) — resolved by the same overlap fix: a follow-up report uses [cursor, now], and a process alive at the cursor instant overlaps it (lastSeen >= cursor) so it is included, matching the documented intent.

Non-blockers

  • add CRAM format #5 (PID-only identity) — documented as an accepted limitation in appendSubProcessSummary / SubProcessEntry / mergeSubProcessEntry Javadoc (PID reuse within the short window can merge two unrelated processes).
  • Gxp stable #6 (everSlow semantics) — field renamed in spirit to slow but documented as "exceeded the threshold at least once"; the report header now states everSlow = exceeded the slow threshold at least once.
  • Gxp stable #7 (empty-scan interpretation) — verified SubProcessMonitor.check() swallows per-process exceptions and returns what it can, so the grace period (2 consecutive missed scans) tolerates a transient /proc failure; an empty scan is treated as authoritative only for pruning, never for the report.
  • perf(profiler): optimize CRClusterAnalysis hot paths from async-profiler #8 (non-atomic cursor write)persistSubProcessCursor now writes to a temp file in the same directory and atomically renames over the sidecar (with a non-atomic fallback), and works on a copy so the caller's JSONObject is never mutated.
  • fix(server): pass oldValue instead of property to correctBeanOptions #9 (cursor naming/semantics) — renamed subProcessLogCursorsubProcessReportCursor and documented it as a report-time cursor (the instant the report was generated), not a log offset.
  • perf(profiler): optimize hot paths from async-profiler #10 (O(n) truncation count) — slow count is now computed once before the render loop.

Tests added (TestSubProcessLog, now 12 tests, all passing):

  • testEstimatedLifetimeUsesLastAgeOnly — lifetime = last observed age, not interval+ageDelta; single snapshot → -1.
  • testObservationOverlapFilter — the four attribution scenarios (started-before-alive-in-window, ended-before-window, started-after-window, spans-window).
  • testMergeLifetimeAndCommand — merging log snapshots yields a real lifetime (max age), earliest firstSeen / latest lastSeen, sticky everSlow, kept command.
  • testPersistCursorAtomicAndCopy — cursor file written, original meta not mutated, no temp files left, non-advancing cursor is a no-op, missing parent dir leaves no partial file.

Verification: mvn -pl src compile clean; ant -f src/build.xml compile BUILD SUCCESSFUL; TestSubProcessLog OK (12); TestAsyncProfilerWrapper OK (5).

Sergey Zhatchenko and others added 5 commits September 1, 2026 09:14
…ecar, half-open interval

Address review of the sub-process dedup/cursor feature:

1. (blocker) appendSubProcessSummary returned early when >20 slow entries
   were shown, skipping persistSubProcessCursor — so a busy system repeated
   the same report forever. Now breaks out of the loop so the cursor is
   always advanced after a report is generated.

2. (high) A malformed-but-present metadata sidecar (meta==null) was being
   atomically replaced with a cursor-only JSON, destroying startTime/endTime
   and other fields. persistSubProcessCursor now skips the write when the
   sidecar exists but failed to parse.

3. Make the follow-up cursor interval half-open (cursor, now] so an
   observation exactly at the cursor is reported once: the summary passes
   cursor+1 to the (inclusive) log reader, and the in-memory overlap filter
   excludes lastSeen <= qStart. Javadocs updated to match.

4. Remove the dead firstAgeSec field from SubProcess/SubProcessObservation
   (stored and propagated but never read after the lifetime fix).

5. Add testCursorIntervalIsHalfOpen (log reader + in-memory boundary) and a
   malformed-sidecar case to the cursor persistence test.

Co-Authored-By: Claude <noreply@anthropic.com>
…ater mark

Address the concurrency review of the sub-process cursor feature:

1. (high) Two concurrent appendSubProcessSummary() calls for the same profile
   could read the same cursor, generate overlapping reports, and persist their
   report-time values out of order — moving the cursor backwards and re-reporting
   a range. Fix:
     - serialize the read -> generate -> persist sequence per profile with a
       lock keyed by (sidecar path, base name);
     - persistSubProcessCursor now re-reads the on-disk cursor and refuses to
       write a value that would not advance it (monotonic high-water guard), as
       defense in depth against any caller writing outside the lock.

2. Document that the cursor is a true high-water mark: the monitor appends the
   log synchronously in the same checkSubProcesses() call that records the
   observation timestamp, so every log line with timestamp <= now is on disk
   before a report generated at `now` reads it.

3. Soften the getObservedSubProcesses "still alive" doc: the in-memory registry
   is an approximation (pruned after SUB_PROCESS_MISS_GRACE missed scans), not a
   live guarantee.

7. Log a WARNING (once per request) when the cursor is skipped due to a malformed
   sidecar, so an admin can tell why the cursor is not advancing.

Add testCursorNeverMovesBackwards: an out-of-order persist (300 then 200) must
not regress the persisted cursor, and a newer value still advances it.

Co-Authored-By: Claude <noreply@anthropic.com>
…d lock map, real concurrency test

Address the review of the sub-process cursor high-water guard:

1. (high) readSubProcessCursor conflated "absent cursor" (0) with "file
   exists but malformed" (also 0), so the high-water guard could treat a
   malformed sidecar as cursor 0 and clobber it. It now returns Long: 0 for
   absent, the stored value if parseable, null if exists-but-unreadable.
   persistSubProcessCursor skips the write on null, mirroring the existing
   meta == null guard, so the malformed file is left intact even if it
   appeared/changed between the summary's read and the persist.

2. (medium) The per-profile lock map was an unbounded ConcurrentHashMap that
   retained a lock per profile forever. It is now reference-counted: the last
   thread to leave the synchronized block removes its entry, so the map does
   not grow with the number of profiles. The lock key uses canonicalPath so
   the same profile reached via different path spellings/symlinks shares one
   lock.

3. Move the plugin check INSIDE the per-profile lock: the early return was
   previously before the lock was taken, so the lock only covered the happy
   path. The whole method body is now serialized per profile.

4. (low) Correct the high-water Javadoc: it is guaranteed because (a) the scan
   timestamp is taken before the append, and (b) both append and read are
   serialized on MonitoringService.subProcessLogLock, so a read sees a log
   closed under "append completed" — a line cannot land behind the cursor with
   timestamp <= now.

Add a real concurrency regression test (testConcurrentReportsAreSerializedPerProfile)
driving appendSubProcessSummary through the actual lock via a small in-lock test
hook; asserts same-profile reports never overlap in the lock and the registry is
empty afterward.

Co-Authored-By: Claude <noreply@anthropic.com>
…profile lock registry

The reference-counted sub-process report lock registry only counted threads
that had entered the monitor (holders), so an entry could be evicted while a
thread still blocked on its monitor was about to enter. A later thread would
then create a second lock object for the same profile, and two reports for
the same profile could run concurrently — defeating the per-profile
serialization that keeps the high-water cursor from regressing.

The fix acquires the registry reference (users++) *before* entering the
monitor via an atomic compute, so a waiting thread keeps the entry alive, and
releases it (users--, evict at 0) in a finally after the monitor is released.
The field is renamed holders -> users to reflect that it counts waiters too.

Also:
- log the (rare) I/O failure in readSubProcessCursor at FINE level
- document in checkSubProcesses that the append and the log reader both take
  subProcessLogLock, which is what makes the high-water cursor invariant hold
- rewrite the concurrency regression test to drive the full happy path (a real
  MonitoringService via a plugin test hook) and to use latches instead of
  timing sleeps so the eviction race is created deterministically

Co-Authored-By: Claude <noreply@anthropic.com>
…e the concurrency test a real seam

Two substantive issues from the latest review:

1. The report cursor's high-water invariant was not actually guaranteed.
   The scan's log-line timestamp was captured *before* the monitor took
   subProcessLogLock, so a line appended after a report's read could carry a
   timestamp <= the report's now and land behind the cursor. Capture the
   timestamp *inside* subProcessLogLock (in the same critical section that
   writes the line), and rewrite the Javadoc to state the two conditions that
   must hold together (timestamp under the lock + append/read on the same
   lock). Split appendSubProcessLog into a production entry point that
   captures the time under the lock and a Locked core that the test calls with
   a pinned timestamp.

2. The concurrency regression test did not actually create the eviction race:
   the in-lock hook cannot observe a thread that has acquired the registry
   entry but is still waiting on the monitor, and the counter it used reset to
   zero between reports so B always re-entered with cur==1. Add a beforeEnter
   seam (a Consumer<Object> called between acquireSubProcessReportLock and the
   monitor) so the test can (a) count distinct lock objects per profile and (b)
   order a waiting thread. The test now deterministically stages
   A-holds / B-waiting / A-releases / C-arrives, asserts C saw the same lock
   object as B, and uses bounded waits throughout. Verified the test FAILS
   against the old holders-only registry (distinct objects == 2) and passes
   against the waiter-counting one.

Also:
- Move the plugin test seam off the global ServerMonitorPlugin singleton onto a
  per-instance field on SupportServlet (setServerMonitorPluginForTest), so the
  test no longer mutates process-wide state.
- Distinguish malformed JSON (concise FINE, no stack trace) from a genuine
  I/O/security failure (FINE with stack trace) in readSubProcessCursor.

Co-Authored-By: Claude <noreply@anthropic.com>
@szhatchenko
szhatchenko merged commit bb4546f into main Sep 1, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant