Vivek1106-04 commented on PR #12418: URL: https://github.com/apache/seatunnel/pull/12418#issuecomment-6135494803
@nzw921rx Thanks for running it on Linux. You were right: the warmup is not sufficient. Below are the cause, the evidence, a proposed fix, and the full sweep you asked for. I have not opened a PR for the fix yet; there is a question for you at the end. ### What the score contains The measured window runs from the time a trigger is due until its body has incremented `pendingCounter`. To split it, I ran a diagnostic build (fork branch [`bench-diag-12418`](https://github.com/Vivek1106-04/seatunnel/tree/bench-diag-12418), never proposed) that timestamps every trigger at its due time, at the start of its body, and at the increment. JDK 17, `dev`, 30 x 10 s iterations, p50 in microseconds: | JVM uptime | 1 pipeline: due -> body start | body | 10 pipelines: due -> body start | body | |---|---|---|---|---| | 0-30 s | 130 | 59 | 83 | 17 | | 30-60 s | 112 | 45 | 73 | 13 | | 60-90 s | 109 | 34 | 71 | 12 | | 90-120 s | 96 | 22 | 71 | 12 | | 120-150 s | 114 | 24 | 70 | 7.5 | | 150-300 s | 92-98 | 19-23 | 70 | 6.4-6.8 | Both parts fall for the first two minutes. "Due -> body start" is not only the OS wake-up: it also covers `ScheduledThreadPoolExecutor`'s queue and the `MDCContext` wrapper around every scheduled task, which compile late for the same reason. ### Why it trends: the JIT compiles by invocation count The trigger path runs 5 to 50 times a second, so it is compiled by how often it ran, not by how long the fork has run. From `-XX:+PrintCompilation` on the same runners, JDK 11 and 17 alike: - **One pipeline**: `tryTriggerPendingCheckpoint` and `createPendingCheckpoint` are interpreted until about 80 s of uptime (C1 tier 3) and never reach C2 within a 300 s trial. The `ScheduledThreadPoolExecutor` path reaches C2 at about 100 s. - **Ten pipelines or more**: the same methods reach C1 at 7 to 11 s and C2 at 110 to 130 s. - CI warms up for 30 s and then measures from roughly 30 to 100 s of uptime, so it records the curve on its way down. A causal check: with `-XX:TieredStopAtLevel=1` (C1 only), the one-pipeline body drops from 68 to 23 us in a single step at 54 s, exactly when those methods compile, and stays flat afterwards. The one-pipeline point is hit hardest because of the 200 ms interval floor. The class Javadoc says every point sees the same trigger rate, but at one pipeline the member triggers 5 checkpoints a second where every other point triggers 50. Its code warms up ten times slower. Even once settled, its body runs at a lower tier (about 21 us against 6.6 us at ten pipelines), and its trigger wakes up on an otherwise idle 4-vCPU VM, which costs about 25 us more (about 95 against 70 us). That is why one pipeline scores higher than ten. ### Why CV shrinks as pipelines grow: three separate effects Decomposing your run's CV (computed, like the report, from the 15 iteration means): | JDK | pipelineNum | CV | from sampling alone | trend per iteration, per fork | fork-to-fork offset | |---|---|---|---|---|---| | 8 | 1 | 6.9% | 2.6% | -5.3, -2.4, -2.1% | 2.3% | | 8 | 10 | 4.4% | 4.7% | +0.9, -1.0, -2.0% | 1.4% | | 8 | 100 | 6.2% | 6.4% | -3.0, +0.1, +2.2% | 2.2% | | 8 | 500 | 1.5% | 1.1% | -0.3, -0.7, -0.8% | 0.3% | | 11 | 1 | 8.4% | 2.5% | -2.9, -6.7, -3.7% | 2.0% | | 11 | 10 | 2.2% | 1.2% | -0.6, -0.8, -0.2% | 1.6% | | 11 | 100 | 2.6% | 1.2% | -1.3, -1.2, -0.3% | 1.5% | | 11 | 500 | 3.8% | 1.4% | +0.4, +0.8, -1.4% | 2.6% | 1. **Drift**, at one pipeline: every fork falls 2 to 7% per iteration. This is the warmup problem. 2. **Sampling noise from a heavy tail**, e.g. JDK 8 at 10 and 100 pipelines: the CV there is fully explained by sampling (single samples spread 24 to 35% around the mean, and one 2 ms sample moves a 100-sample mean by about 20%). No drift. 3. **Fork-to-fork offsets** of 1 to 7%: each JVM compiles this code a little differently. So CV is not monotonic in the pipeline count; the one-pipeline point is worst because it has the drift, 50 samples per iteration instead of 100, and the noisiest wake-ups. ### Proposed fix On branch [`fix-12418-benchmark-warmup`](https://github.com/Vivek1106-04/seatunnel/tree/fix-12418-benchmark-warmup), commit [`1914eabf6`](https://github.com/Vivek1106-04/seatunnel/commit/1914eabf6), benchmark code and tests only: - Forks run with `-XX:CompileThresholdScaling=0.05`. (`0.01` compiles so much at once in the first iteration that more than 10% of triggers come due unmeasured, and the skip limit fails the run.) - Each trial lets its own coordinators trigger 1,000 checkpoints, for at least 60 s, before JMH's warmup. Counting triggers rather than seconds gives the one-pipeline point the same compiled code as the others: about 200 s there, 60 s elsewhere. - The Javadoc documents the one-pipeline point as an idle-member point, to compare across revisions rather than against the other pipeline counts. A first attempt, warming up on throwaway coordinators and cancelling them, did not work: cancelling them made the JIT deoptimise `tryTriggerPendingCheckpoint` right before the measurement started. ### Full sweep, `dev` against the fix Exact command of `tools/benchmarks/run_benchmarks.sh`, all pipeline counts, 3 forks, 3 warmup and 5 measurement iterations of 10 s. `dev` and the fix ran on the **same runner**, in both orders, on JDK 11 and 17: 12 forks per side and point. Run: https://github.com/Vivek1106-04/seatunnel/actions/runs/38295747109 | pipelineNum | mean trend per iteration, dev | fix | forks falling > 2% per iteration, dev | fix | CV, dev | fix | score range (us), dev | fix | |---|---|---|---|---|---|---|---|---| | 1 | -3.5% | -0.3% | 8 / 12 | 5 / 12, scattered both ways | 10.5% | 9.4% | 166-200 | 94-130 | | 10 | -1.9% | +1.0% | 3 / 12 | 0 / 12 | 7.0% | 3.9% | 87-105 | 77-95 | | 100 | -1.5% | +0.3% | 3 / 12 | 0 / 12 | 4.5% | 3.6% | 82-103 | 73-90 | | 500 | -1.0% | -0.2% | 2 / 12 | 1 / 12 | 4.5% | 4.3% | 100-121 | 93-111 | No run of the fix hit the skip limit; one earlier `dev` run did, at 100 pipelines on JDK 11 (19 triggers came due while another was being measured). **What remains, and is not a warmup effect:** at one pipeline, iteration-to-iteration variation stays around 9 to 10% on both sides, because that trigger's wake-up latency on an idle VM wanders by tens of microseconds over minutes. Forks still settle 1 to 5% apart. The per-iteration median is much steadier than the mean (CV 2 to 4% at ten pipelines or more with the fix), because the mean carries the occasional millisecond sample; reporting it would be a separate change to `save_jmh_result.py`. ### Commands and environment ``` # Build, from each checkout ./mvnw -B -q -Pbenchmark -pl seatunnel-benchmarks -am -DskipTests -Dskip.spotless=true package # Run, same as tools/benchmarks/run_benchmarks.sh java -jar seatunnel-benchmarks/target/benchmarks.jar CheckpointSchedulingBenchmark -f 3 -wi 3 -i 5 -foe true -rf json -rff <side>.json ``` - GitHub-hosted `ubuntu-24.04`, Linux 6.17.0-1022-azure x86_64, AMD EPYC 7763, 4 vCPU - Temurin 11.0.32.1 and 17.0.20.1. JDK 8 is no longer in the comparison because `dev` now builds for Java 11, and `benchmarks.yml` runs 11 and 17. - `dev` = `b3898b62d`; fix = `738f372e4` on the throwaway verification branch, identical benchmark code to `1914eabf6` - The fork JVM options are the benchmark's own `@Fork` settings. These ran on GitHub's runners in my fork rather than on my machine: on macOS every timed wait fires about 5 ms late, and Docker Desktop's Linux VM inherits that (one pipeline measured about 2.5 ms there against about 150 us on the runners), so a local run cannot show a microsecond-scale trend. <details> <summary>Per-iteration means (us), all forks</summary> **JDK 11, runner job `j11-dev-then-fix` (ran dev then fix)** | side | pipelineNum | fork | iter 1 | iter 2 | iter 3 | iter 4 | iter 5 | |---|---|---|---|---|---|---|---| | dev | 1 | 1 | 205.7 | 210.8 | 187.5 | 184.6 | 191.7 | | dev | 1 | 2 | 202.7 | 169.8 | 175.9 | 169.8 | 166.1 | | dev | 1 | 3 | 180.0 | 157.1 | 152.8 | 169.7 | 153.7 | | dev | 10 | 1 | 91.4 | 89.4 | 91.0 | 90.3 | 92.6 | | dev | 10 | 2 | 99.3 | 98.2 | 99.2 | 95.1 | 97.2 | | dev | 10 | 3 | 121.3 | 99.4 | 102.4 | 99.4 | 97.5 | | dev | 100 | 1 | 111.9 | 107.7 | 106.0 | 98.1 | 95.8 | | dev | 100 | 2 | 115.2 | 97.5 | 111.1 | 97.0 | 95.7 | | dev | 100 | 3 | 101.7 | 95.1 | 96.1 | 99.1 | 102.5 | | dev | 500 | 1 | 123.0 | 114.3 | 116.9 | 117.0 | 115.4 | | dev | 500 | 2 | 143.1 | 106.7 | 106.3 | 106.7 | 110.9 | | dev | 500 | 3 | 128.1 | 133.2 | 139.4 | 128.1 | 120.7 | | fix | 1 | 1 | 117.7 | 121.7 | 139.0 | 109.4 | 108.8 | | fix | 1 | 2 | 109.2 | 106.5 | 130.2 | 104.9 | 96.0 | | fix | 1 | 3 | 107.1 | 131.2 | 132.6 | 126.2 | 104.4 | | fix | 10 | 1 | 85.9 | 85.1 | 88.2 | 87.5 | 88.2 | | fix | 10 | 2 | 88.1 | 87.4 | 88.1 | 88.1 | 88.9 | | fix | 10 | 3 | 87.7 | 87.6 | 89.7 | 91.1 | 114.7 | | fix | 100 | 1 | 86.1 | 87.5 | 88.4 | 86.0 | 82.7 | | fix | 100 | 2 | 86.0 | 83.7 | 85.5 | 84.3 | 98.5 | | fix | 100 | 3 | 84.4 | 83.2 | 94.8 | 85.5 | 84.8 | | fix | 500 | 1 | 97.8 | 99.1 | 99.1 | 98.0 | 98.7 | | fix | 500 | 2 | 99.7 | 104.3 | 102.1 | 101.2 | 105.2 | | fix | 500 | 3 | 98.9 | 101.1 | 101.5 | 103.3 | 99.6 | **JDK 11, runner job `j11-fix-then-dev` (ran fix then dev)** | side | pipelineNum | fork | iter 1 | iter 2 | iter 3 | iter 4 | iter 5 | |---|---|---|---|---|---|---|---| | dev | 1 | 1 | 239.7 | 226.5 | 188.2 | 168.1 | 179.8 | | dev | 1 | 2 | 199.6 | 190.7 | 195.3 | 178.2 | 206.0 | | dev | 1 | 3 | 226.4 | 215.8 | 221.1 | 183.8 | 179.1 | | dev | 10 | 1 | 104.6 | 102.2 | 101.4 | 98.1 | 99.3 | | dev | 10 | 2 | 102.7 | 104.4 | 103.4 | 102.9 | 99.5 | | dev | 10 | 3 | 103.8 | 112.0 | 140.4 | 100.7 | 101.7 | | dev | 100 | 1 | 98.5 | 118.1 | 99.1 | 100.6 | 100.8 | | dev | 100 | 2 | 108.7 | 110.5 | 115.3 | 96.7 | 103.7 | | dev | 100 | 3 | 100.2 | 98.6 | 95.6 | 100.7 | 99.6 | | dev | 500 | 1 | 124.6 | 120.4 | 111.7 | 115.3 | 121.3 | | dev | 500 | 2 | 118.3 | 117.7 | 115.8 | 116.1 | 121.0 | | dev | 500 | 3 | 123.3 | 120.4 | 113.4 | 112.8 | 114.8 | | fix | 1 | 1 | 121.1 | 142.2 | 137.7 | 130.3 | 145.2 | | fix | 1 | 2 | 127.9 | 120.1 | 124.0 | 115.5 | 114.6 | | fix | 1 | 3 | 135.7 | 146.9 | 153.1 | 126.8 | 111.5 | | fix | 10 | 1 | 97.0 | 94.3 | 93.6 | 93.8 | 95.8 | | fix | 10 | 2 | 93.1 | 90.8 | 100.4 | 96.4 | 95.7 | | fix | 10 | 3 | 98.8 | 94.6 | 94.0 | 95.2 | 94.1 | | fix | 100 | 1 | 90.3 | 89.5 | 95.5 | 91.5 | 88.8 | | fix | 100 | 2 | 91.8 | 93.4 | 89.8 | 87.9 | 87.0 | | fix | 100 | 3 | 90.1 | 90.2 | 91.7 | 89.4 | 87.4 | | fix | 500 | 1 | 109.5 | 110.5 | 113.4 | 111.4 | 110.9 | | fix | 500 | 2 | 106.5 | 109.7 | 115.2 | 110.0 | 107.4 | | fix | 500 | 3 | 121.3 | 108.0 | 107.8 | 113.6 | 112.0 | **JDK 17, runner job `j17-dev-then-fix` (ran dev then fix)** | side | pipelineNum | fork | iter 1 | iter 2 | iter 3 | iter 4 | iter 5 | |---|---|---|---|---|---|---|---| | dev | 1 | 1 | 154.2 | 154.7 | 159.1 | 165.1 | 139.7 | | dev | 1 | 2 | 170.6 | 173.2 | 182.8 | 162.6 | 169.1 | | dev | 1 | 3 | 191.2 | 227.1 | 171.8 | 154.7 | 181.4 | | dev | 10 | 1 | 104.3 | 102.3 | 102.1 | 93.9 | 107.0 | | dev | 10 | 2 | 120.1 | 112.5 | 111.8 | 105.3 | 92.0 | | dev | 10 | 3 | 102.6 | 101.7 | 97.0 | 92.8 | 90.9 | | dev | 100 | 1 | 96.7 | 91.5 | 88.9 | 89.7 | 89.4 | | dev | 100 | 2 | 91.7 | 87.9 | 88.2 | 87.7 | 86.7 | | dev | 100 | 3 | 95.8 | 94.0 | 89.6 | 91.5 | 90.7 | | dev | 500 | 1 | 105.3 | 103.7 | 105.5 | 107.3 | 106.4 | | dev | 500 | 2 | 101.4 | 101.0 | 104.6 | 104.0 | 101.1 | | dev | 500 | 3 | 99.5 | 100.0 | 103.8 | 102.6 | 99.6 | | fix | 1 | 1 | 99.4 | 105.2 | 122.8 | 121.4 | 101.0 | | fix | 1 | 2 | 111.9 | 108.8 | 98.0 | 110.7 | 104.6 | | fix | 1 | 3 | 102.9 | 93.9 | 95.0 | 115.6 | 121.7 | | fix | 10 | 1 | 85.2 | 85.7 | 84.0 | 84.6 | 83.4 | | fix | 10 | 2 | 85.2 | 86.1 | 87.7 | 88.8 | 85.8 | | fix | 10 | 3 | 84.3 | 84.4 | 85.0 | 84.0 | 87.7 | | fix | 100 | 1 | 86.1 | 83.1 | 85.9 | 83.7 | 86.9 | | fix | 100 | 2 | 84.2 | 80.3 | 87.4 | 91.3 | 90.1 | | fix | 100 | 3 | 93.1 | 82.1 | 83.1 | 84.2 | 84.2 | | fix | 500 | 1 | 94.5 | 92.6 | 94.3 | 95.8 | 93.6 | | fix | 500 | 2 | 97.1 | 93.7 | 97.1 | 96.3 | 98.1 | | fix | 500 | 3 | 99.2 | 129.4 | 94.9 | 95.6 | 94.4 | **JDK 17, runner job `j17-fix-then-dev` (ran fix then dev)** | side | pipelineNum | fork | iter 1 | iter 2 | iter 3 | iter 4 | iter 5 | |---|---|---|---|---|---|---|---| | dev | 1 | 1 | 175.5 | 163.0 | 156.3 | 152.1 | 145.3 | | dev | 1 | 2 | 187.5 | 178.0 | 169.5 | 144.6 | 188.4 | | dev | 1 | 3 | 179.3 | 173.9 | 160.0 | 153.0 | 159.5 | | dev | 10 | 1 | 91.1 | 88.6 | 88.5 | 86.7 | 86.5 | | dev | 10 | 2 | 88.4 | 89.0 | 85.6 | 85.8 | 84.7 | | dev | 10 | 3 | 90.5 | 89.1 | 85.4 | 85.4 | 85.2 | | dev | 100 | 1 | 84.6 | 82.6 | 81.6 | 81.8 | 80.4 | | dev | 100 | 2 | 84.0 | 82.8 | 81.1 | 81.9 | 80.0 | | dev | 100 | 3 | 83.5 | 82.6 | 81.0 | 82.8 | 80.0 | | dev | 500 | 1 | 103.2 | 97.9 | 97.0 | 98.4 | 98.0 | | dev | 500 | 2 | 105.5 | 101.0 | 100.3 | 100.5 | 100.8 | | dev | 500 | 3 | 98.8 | 97.5 | 100.6 | 98.1 | 97.3 | | fix | 1 | 1 | 89.7 | 90.0 | 93.9 | 91.7 | 90.6 | | fix | 1 | 2 | 99.3 | 109.1 | 100.3 | 91.6 | 92.8 | | fix | 1 | 3 | 85.3 | 89.2 | 91.7 | 109.6 | 91.6 | | fix | 10 | 1 | 73.6 | 73.1 | 78.4 | 77.2 | 77.2 | | fix | 10 | 2 | 76.2 | 76.5 | 80.4 | 80.1 | 80.6 | | fix | 10 | 3 | 74.2 | 72.6 | 75.7 | 76.4 | 76.2 | | fix | 100 | 1 | 70.5 | 69.7 | 73.8 | 73.9 | 74.6 | | fix | 100 | 2 | 75.2 | 74.4 | 74.4 | 74.7 | 76.0 | | fix | 100 | 3 | 70.7 | 70.5 | 73.8 | 74.1 | 72.7 | | fix | 500 | 1 | 91.6 | 90.4 | 90.1 | 92.4 | 91.6 | | fix | 500 | 2 | 94.6 | 96.4 | 95.7 | 94.7 | 94.4 | | fix | 500 | 3 | 89.6 | 92.6 | 96.1 | 92.5 | 93.9 | </details> ### Before I open a PR Two choices in the proposed fix change how this benchmark runs, so I would like your view first: 1. **`-XX:CompileThresholdScaling=0.05`** changes the JIT's thresholds inside the benchmark. The alternative is to keep JVM defaults and warm up for about 150 s per trial instead. In the 300 s trajectories above that is where ten pipelines stops drifting, though I have not run it as a full sweep, and it leaves the one-pipeline body at a lower compilation tier than the other points. Which would you prefer? 2. **Cost**: the trigger-count warmup adds about 19 minutes per JDK to the `CheckpointSchedulingBenchmark` sweep in `benchmarks.yml` (about 200 s per fork at one pipeline, 60 s per fork elsewhere). The one-pipeline point is kept and documented as an idle-member point. If you would rather drop it and start the sweep at ten pipelines, that removes the noisiest point and about half of the added time. If this direction works for you, I will open it as a PR, or file an issue first if you prefer that. The fixed-interval scenario and longer measurement runs for tail percentiles stay a separate follow-up, which I will open as an issue once this is settled. -- 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]
