diff --git a/shenandoah-jdk28/README.md b/shenandoah-jdk28/README.md index 12222dc..d7317d0 100644 --- a/shenandoah-jdk28/README.md +++ b/shenandoah-jdk28/README.md @@ -41,6 +41,7 @@ scripts/more-reps.sh 4 5 # append more reps and re-summarise | [`scripts/bench-one.sh`](scripts/bench-one.sh) | One run: 30 s warm-up, 60 s open-loop window, 20 s closed loop; pauses from `-Xlog:gc*`; peak RSS from `VmHWM` | | [`scripts/gc_pauses.py`](scripts/gc_pauses.py) | Stop-the-world pauses inside the measure window | | [`scripts/summarize.py`](scripts/summarize.py) | Median per configuration | +| [`scripts/log-events.sh`](scripts/log-events.sh) | Counts `Cancelling GC`, `Pause Full`, degenerated pauses and allocation failures per run; output is [`output/04-gc-events.txt`](output/04-gc-events.txt) | ## Results (median of 5 interleaved runs, JDK 28+21 EA) @@ -55,7 +56,7 @@ scripts/more-reps.sh 4 5 # append more reps and re-summarise **Read the last row carefully.** Per-run p99 for generational Shenandoah was 1,557, 3,077, 24.5, 1,658 and 692 ms: four of five runs contain a multi-second latency episode while the recorded stop-the-world pauses stay at a few milliseconds -(one run had a 209 ms `Pause Full`). The GC logs do not show allocation failures (`Trigger: Failed to allocate` count is 0), and +(one run had a 209 ms `Pause Full`). [`output/04-gc-events.txt`](output/04-gc-events.txt) shows no allocation failures and no degenerated pauses in any run, and the `Cancelling GC: Concurrent GC` lines are old-generation marking being preempted for a young collection, which is normal. So the cause of the stalls is **not established** here. One SATB run (811 ms p99) also stalled with no GC event at all, which says this 2-vCPU machine produces stalls of its own. Treat the generational result as "did not behave on this box diff --git a/shenandoah-jdk28/output/04-gc-events.txt b/shenandoah-jdk28/output/04-gc-events.txt new file mode 100644 index 0000000..8beb93b --- /dev/null +++ b/shenandoah-jdk28/output/04-gc-events.txt @@ -0,0 +1,18 @@ +run cancelling_gc pause_full pause_degenerated failed_to_allocate +shenandoah-satb-1 0 0 0 0 +shenandoah-satb-2 0 0 0 0 +shenandoah-satb-3 0 0 0 0 +shenandoah-satb-4 0 0 0 0 +shenandoah-satb-5 0 0 0 0 +shenandoah-generational-1 4 1 0 0 +shenandoah-generational-2 7 1 0 0 +shenandoah-generational-3 5 0 0 0 +shenandoah-generational-4 9 0 0 0 +shenandoah-generational-5 6 0 0 0 + +== shenandoah-generational-4.log: what a 'Cancelling GC' line is (old marking preempted for a young cycle) +[22.999s] Preempting old generation mark to allow Young GC +[22.999s] Cancelling GC: Concurrent GC + +== shenandoah-generational-1.log: the Pause Full +[34.040s] GC(62) Pause Full 737M->214M(1024M) 239.022ms diff --git a/shenandoah-jdk28/scripts/log-events.sh b/shenandoah-jdk28/scripts/log-events.sh new file mode 100755 index 0000000..b1b953b --- /dev/null +++ b/shenandoah-jdk28/scripts/log-events.sh @@ -0,0 +1,16 @@ +#!/usr/bin/env bash +# Counts stall-related events in the Shenandoah GC logs left in target/gclogs by bench-one.sh, and prints the +# verbatim log lines for two of them. Output is committed as output/04-gc-events.txt. +cd "$(dirname "$0")/../target/gclogs" +echo "run cancelling_gc pause_full pause_degenerated failed_to_allocate" +for f in shenandoah-satb-[1-5].log shenandoah-generational-[1-5].log; do + printf "%-27s %13d %11d %18d %19d\n" "${f%.log}" \ + "$(grep -c 'Cancelling GC' "$f")" "$(grep -c 'Pause Full [0-9]' "$f")" \ + "$(grep -c 'Pause Degenerated.*ms$' "$f")" "$(grep -ci 'Failed to allocate' "$f")" +done +echo +echo "== shenandoah-generational-4.log: what a 'Cancelling GC' line is (old marking preempted for a young cycle)" +grep -m1 -B1 'Cancelling GC' shenandoah-generational-4.log | sed -E 's/^\[[^]]*\]//' +echo +echo "== shenandoah-generational-1.log: the Pause Full" +grep -m1 'Pause Full [0-9]' shenandoah-generational-1.log | sed -E 's/^\[[^]]*\]//'