Rangsh commented on issue #12058: URL: https://github.com/apache/seatunnel/issues/12058#issuecomment-5595397918
@SEZ9 @nzw921rx @DanielLeens following up on the four baseline asks. This still does **not** validate any production fix; #12081 stays separate (Related only). ### Artifacts (gist) Full A/A + GC + local Diagnostics bundle: https://gist.github.com/Rangsh/e21302908815c2954edf4392eafc62c8 | File | Contents | | --- | --- | | `run-a-results.json` / `run-b-results.json` | JMH `-rf json` | | `run-a-jmh.log` / `run-b-jmh.log` | full `-v EXTRA` console (all forks) | | `run-*-gc-fork{1,2,3}.log` | per-fork `-Xlog:gc*=info` | | `profile-gc-summary.md` / `profile-gc-result.jmh.json` | local `tools/benchmarks/profile_benchmarks.sh profile gc` | **Note on the Sep 8 run (190.087 ± 65.997):** those raw `results.json` / EXTRA files were cleaned from `/tmp` before this follow-up. Numbers and per-iteration table remain in the earlier comment; today’s posts are fresh A/A with attachable artifacts on the **same** machine / JDK / settings / commit. ### Scope (unchanged) - Method: `CheckpointStorageBenchmark.checkpointOverviewIncrementalUpdate$` only - Code: `origin/dev` @ `8bea8c681` (**not** #12081) - Same JMH defaults + `file:///` MapStore (`write-delay-seconds: 0`) - Machine: Apple M1 / 16 GB / macOS 14.7.4 - JDK: Corretto **11.0.26** - Extra fork JVM arg for A/A: `-Xlog:gc*=info:file=.../gc-%p.log:time,uptime,level,tags` ### 1–3. A/A with GC logging | Run | Score ± Error | CV (raw n=15) | min–max (us/op) | clear outliers (>1.2× median) | | --- | ---: | ---: | --- | --- | | Sep 8 (prior comment) | 190.087 ± 65.997 | ~32.5% | 128.4–393.3 | 240.3, 393.3 | | **A** (2026-09-09) | 160.462 ± 17.184 | ~10.0% | 129.0–190.1 | none at 1.2× threshold | | **B** (A/A, same day) | 164.446 ± 19.687 | ~11.2% | 115.3–205.6 | 205.6 only | **Run A raw:** | Fork | Iterations (us/op) | | --- | --- | | 0 | 190.14, 163.25, 149.36, 158.78, 154.95 | | 1 | 186.91, 151.44, 157.22, 151.59, 149.17 | | 2 | 182.77, 168.43, 156.37, 157.53, 129.03 | **Run B raw:** | Fork | Iterations (us/op) | | --- | --- | | 0 | 164.05, 158.20, 163.12, 115.29, 164.44 | | 1 | 183.08, **205.64**, 159.89, 158.82, 157.41 | | 2 | 162.73, 166.09, 163.26, 169.84, 174.83 | **A/A stability takeaway:** on this laptop, **outlier count and CV are not stable day-to-day**. Same host/JDK/settings/commit can show ~32% CV with 393 us spikes one day and ~10–11% CV with max ~190–206 us the next. That weakens any claim that a single local Score/Error proves a production mechanism, and it is why we need causal evidence before proposing a change. ### GC correlation (asks 2 + outliers) Per-fork G1 logs (attached in gist): - Most young pauses are ~2–8 ms. - Run B fork 2 (`run-b-gc-fork2.log`) has one large **35.772 ms** young pause (`Metadata GC Threshold`) at ~4.3s uptime — that aligns with **warmup/init**, not with a ~200 µs measurement sample (a 35 ms STW inside a measured op would dominate far beyond +40 µs). - Later young pauses in that fork are ~3–8 ms; JMH does not timestamp each measurement iteration to the GC log, so I **cannot** honestly claim the 205.64 sample landed on a specific pause. - Therefore: **GC is present and can matter in principle**, but these logs do **not** yet prove that the Sep 8 240.3 / 393.3 (or today’s milder 205.6) are GC-caused. Need tighter correlation (JFR / per-iteration timestamps / wall profile on a noisy run). ### 4. Benchmarks Diagnostics **Local** (`profile_benchmarks.sh profile gc`, `-f 1` for a quick signal; primary Score **not** comparable to normal runs): - Alloc/op ≈ **288,515 B/op** - GC count = **1**, GC time = **5 ms** across the measured iterations - Summary in gist: `profile-gc-summary.md` **Fork Actions** (same workflow nzw921rx pointed at; currently still **queued** on free runners — will update when artifacts are ready): - GC + JFR: https://github.com/Rangsh/seatunnel/actions/runs/34307448217 - Wall: https://github.com/Rangsh/seatunnel/actions/runs/34307450954 I do not have `ASYNC_PROFILER_HOME` on this machine yet, so local `profile wall/cpu/lock` is blocked until that is installed or the Actions wall run completes. ### Observations (repost — full section) SEZ9 noted the prior comment looked cut off after “Within-fork spikes ex”; reposting the full Observations from that baseline (Sep 8) for readability: 1. **Within-fork spikes exist** (not only between forks): Fork 0 had one ~240 us/op sample; Fork 2 had one ~393 us/op sample (~2.2× that fork’s median). 2. Fork 1 was comparatively tight (~155–177 us/op) — dispersion is **bursty**, not uniformly noisy. 3. Using median **175.1** and “slower = >1.2× median”: clear slower samples were **240.3** and **393.3**. Removing only the 393 outlier dropped CV from ~32.5% to ~**15.1%** — a small number of heavy iterations dominate Error/CV. 4. Warmup Iteration 1 on each fork was visually polluted by `SeaTunnelConfig` INFO lines (no clean us/op for WI1). Measurement iterations looked clean; still a **measurement-boundary** note (warmup/setup logging vs timed phase). Today’s A/A adds: 5. **CV magnitude is itself unstable** across same-machine repeats (~32% → ~10–11%). 6. Without per-iteration GC timestamps, young-gen pauses of several ms are a **plausible** spike source but **not yet demonstrated** for the µs-scale outliers in these runs. ### Hypotheses update | Hypothesis | Status | Notes | | --- | --- | --- | | High CV only on Actions | Ruled out | Local Sep 8 reproduction | | Variance only between forks | Partially ruled out | Within-fork outliers on noisy days | | Stable local CV usable as a fix gate | **Weakened** | A/A shows large day-to-day CV change | | Spikes = GC pauses (causal) | **Still open** | GC logs present; no tight iteration↔pause match yet | | Spikes = `file:///` MapStore sync path | Still open | Needs wall/JFR attribution | | #12081 sync-collapse explains / fixes this CV | **Not supported** | Separate correctness PR; no A/A-before/after on a noisy baseline yet | ### Proposed next narrow experiment (seeking agreement) Before any candidate change: 1. Wait for / download the queued fork Diagnostics (wall + GC/JFR) artifacts and post the top stacks / JFR pause overlap here. 2. Optionally install async-profiler locally and re-run `profile wall` on a day when CV is high again (or force noise with controlled load) so we can contrast a normal vs slow iteration. 3. Only after we agree on a measurable mechanism, design one narrowly scoped A/B (e.g. isolate MapStore write path vs overview CPU vs GC) — still separate from #12081 correctness merge. Happy to change the isolation order if you prefer GC/JFR-first analysis of the Actions artifacts before another local wall profile. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
