Vivek1106-04 commented on PR #12165: URL: https://github.com/apache/seatunnel/pull/12165#issuecomment-6381578986
@nzw921rx thanks for running the benchmark on top of #12896 and attaching the raw data. @DanielLeens thanks for the read. I went through the raw data and then traced the slowdown down to the line that causes it. Short version: the whole difference comes from the timer -> dispatcher hand-off, which I'm keeping deliberately. Details and evidence below. ### What the raw data shows The run used 1 fork x 5 iterations x 10 s, which is about 100 samples per iteration. In those JSON files there are two separate effects: - **A steady shift.** If you drop the samples above 500 us, the candidate is +28-35 us at P=10/100 and +10-15 us at P=500. That shows up in every run, on both JDKs. The candidate is flat across P (about 110-120 us), while dev rises at P=500. - **Rare 1-4 ms samples.** There are 22 of them in the candidate (out of about 6,000) and 1 in dev. These cause all of the extra CV. Without them the candidate's per-iteration CV is 0.7-2.9%, the same as dev. In the 12.42% row (P=10, JDK 11), one iteration with a 4.2 ms sample moves the mean of its 100 samples by about 40 us. More rounds would not fix that CV; the spikes would just land in different iterations. ### Where the time goes I rebuilt exactly the two commits you compared (`4dcfa28cc` and `771fce221`), added a throwaway per-stage tracer (`System.nanoTime` at each step of the trigger path, plus `/proc/thread-self/schedstat` for the threads that carry it), and ran them on fork runners in the same alternating order. The tracer patches and workflow are on [`bench-diag-12165`](https://github.com/Vivek1106-04/seatunnel/tree/bench-diag-12165/.github/diag). The tracer adds the same overhead to both sides. [Run 40061505634](https://github.com/Vivek1106-04/seatunnel/actions/runs/40061505634) (JDK 11 + 17, P=10/100/500) reproduced both effects: - Timer lateness (due -> timer thread runs) is the same on both sides: about 80 us at p50. - The steady difference is the hop itself: timer fires -> dispatcher thread starts the body is 22-25 us at p50. Lock wait and `createPendingCheckpoint` are the same on both sides. - During every candidate spike the dispatch pool was idle (8 threads, 0 active, 0 queued). So it is not thread creation, not a backlog, and not other pipelines. - The spikes that aren't safepoints (those hit both sides) are run-queue wait: the dispatcher thread was runnable but had no CPU. The kernel's `run_delay` for that thread matches the spike, for example 1853 us of run-queue wait in a 1868 us hand-off. A scheduler trace (bpftrace on `sched_wakeup`/`sched_switch`, [run 40064392859](https://github.com/Vivek1106-04/seatunnel/actions/runs/40064392859)) showed what held the CPU. That run's latencies are inflated by the tracing itself, so I only use it for this. For slow dispatcher wakes, the thread that ran just before the dispatcher on its CPU was most often the JMH worker (40 cases), which busy-spins from about 1 ms before each due time until `pendingCounter` moves. Next most common were the JIT compiler threads. For dev's coordinator threads the JMH worker shows up once. On a 4-vCPU runner there is often no idle CPU at the moment the dispatcher wakes, so it waits for the running thread's time slice to end, about 0.5-3 ms, which is the spike range. To confirm the cause rather than just correlate it, [run 40071856278](https://github.com/Vivek1106-04/seatunnel/actions/runs/40071856278) adds a third build: `771fce221` with only `timer.schedule(() -> submit(task), ...)` changed to `timer.schedule(task, ...)`. Same shared scheduler and same two timer threads, just no hand-off. The three builds alternated on one runner, two rounds each (us/op; spikes are samples over 500 us): | JDK | pipelineNum | dev | PR | PR without hand-off | |---|---|---|---|---| | 11 | 10 | 96.0-97.0, 0 spikes | 124.7-138.7, 1-2 | 95.8-96.5, 0 | | 11 | 100 | 92.6, 0 | 131.6-137.6, 3-6 | 93.8-94.1, 0 | | 17 | 10 | 87.5-89.5, 0 | 126.0-138.6, 1-6 | 85.8-89.7, 0-1 | | 17 | 100 | 83.6-83.9, 0 | 118.4-122.1, 2-5 | 84.0-84.4, 0 | Over all ~4,000 triggers per trial in the trace, p99.9 is 0.2-0.4 ms for dev and for the no-hand-off build (one no-hand-off trial: 1.4 ms), and 0.65-2.1 ms for the PR. The same results on both runner CPUs this run got (EPYC 7763 and 9V74). So the shared timer itself costs nothing, and the whole delta is the hand-off. ### Why I'm keeping the hand-off The hand-off is there so timer threads never run checkpoint bodies. Those bodies take the coordinator lock, and on `dev` `startSavepoint` holds that lock across its sleep loop (#12441). The expiry path also does IMap work. If the 2 shared timer threads ran those bodies, one slow coordinator would delay timers for every pipeline on the member. That is the coupling Issue 1 is about, so the hand-off makes the worst case smaller. The cost is one extra thread wake per trigger: about 25 us, plus an occasional wait of up to one scheduler time slice when every CPU is busy. Against checkpoint intervals in seconds that is negligible, and it does not grow with the number of pipelines. I'd rather keep that trade than move lock-taking work onto the timer threads. If you'd prefer the periodic trigger to run on the timer thread once #12511 has taken the savepoint wait off the lock, the change is the one line above, and I can do that as a follow-up. ### The benefit, measured in the same traces From the safepoint logs of the JDK 17 run (`-Xlog:safepoint`, whole JVM run), dev's time-to-safepoint grows with its timer threads (2 per pipeline), while the PR stays flat: | pipelineNum | reach safepoint p50, dev / PR | total pause p50, dev / PR | max pause, dev / PR | |---|---|---|---| | 10 | 10.0 / 8.6 us | 1.35 / 1.33 ms | 7.4-8.4 / 6.8-7.4 ms | | 100 | 17.6-18.2 / 7.8-8.1 us | 1.74-1.87 / 1.50-1.53 ms | 8.9-9.4 / 7.2-9.3 ms | | 500 | 56-57 / 8.4-8.6 us | 3.27-3.34 / 1.76-1.80 ms | 33.6-37.3 / 6.6-6.9 ms | The scheduler thread count is 1,000 on dev at P=500, and on the PR it is 2 timer threads plus at most `max(8, 2 x cores)` dispatchers (8 on these runners), regardless of P. ### The `RejectedExecutionException` This is not a lost trigger. The fixture's teardown calls `coordinatorExecutor.shutdownNow()` before `manager.cancelCheckpoint(...)`, so a trigger that was already handed to a dispatcher in that gap hits a terminated executor. dev has the same race, but there the body runs inside its own `ScheduledThreadPoolExecutor`, which stores the exception in the future and prints nothing. On this PR it shows up only because `PipelineCheckpointTask.run()` rethrows. That is @DanielLeens's Issue 2. The same iteration reports 100 of 100 due triggers measured, 0 skipped. I'll fix Issue 2 in the next push: log with job/pipeline context and don't rethrow, since `completion` already carries the error. That also removes the stderr noise. ### CI on `771fce221` [Fork run 39773641731](https://github.com/Vivek1106-04/seatunnel/actions/runs/39773641731): the only failure is `unit-test (17, ubuntu-latest)`, `SavePointTest#testSavePointButJobGoingToFail` (the job stays RUNNING instead of FAILED within 120 s). JDK 11 and both Windows unit-test legs passed. That is the SubPlan restore-wait race described in #12441 and fixed by #12511 / #12623, not this diff. Kept separate from the benchmark question, as you asked. ### Next push - Issue 2 fix with a test for a throwing body - PR description refresh: bounded dispatch pool, current test counts, and a short "cost of the hand-off" section with the table above - New CI link on the new head -- 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]
