Skip to content

Commit cd651b1

Browse files
bedaHovorkaclaude
andcommitted
fix(ci): move flaky controlled-loop overhead check from JUnit gate to JMH
`:core:integrationTest` failed on run 29165254178 (725 tests, 1 failed). The failure was DefaultSimulationContextControllerTest.controlledLoopOverheadIsNegligible, a wall-clock microbenchmark living inside the CI correctness gate: it timed one 300s ShuntingLoop run per arm and asserted the ratio was < 5%. It measured 5.33%. It could not have held up. One sample per arm, no JIT warmup (the baseline arm ran first and absorbed it, biasing the ratio negative, so it passed for a reason unrelated to the property it claimed to test), and a 5% threshold on a shared runner whose CPU-steal variance far exceeds 5%. Note TwoTrainConcurrencyTest passed 150/150 in that run and is not implicated; the simulation is a single-threaded kDisco discrete-event loop with a seeded RNG, so there is no race here to serialize. - Delete the wall-clock assertion. The class keeps its four deterministic tests (throttle invoked per event, non-negative deltas, StopSimulation propagates, awaitIfPaused called), which is what a correctness gate should assert. - Add ControlledLoopOverheadBenchmark to the existing :desktop-ui JMH harness, with two independently reported arms instead of one fragile ratio. Only ctx.run(controller) is timed; context construction sits in @setup(Level.Invocation). Mode is SingleShotTime: the payload is a single-use, millisecond-scale run, and under AverageTime the resulting context churn collides Koin scope ids, since DefaultSimulationContext derives its scope id from a (non-unique) identity hash code. Measured: baseline 0.699 +/- 0.103 ms/op, with-controller 0.685 +/- 0.062 ms/op. Indistinguishable -- the hook overhead is below the noise floor, so the original claim was true; only the instrument was broken. - Fix a latent order-dependent bug in TwoTrainConcurrencyTest found en route. It matched train names by substring, and Train.countValue is a process-global counter that is never reset, so once names reach two digits "Train #1" matches "Train #12". Now compares extracted whole tokens and indexes by identity rather than List.indexOf. Verified: :core:integrationTest 724/724 (was 725/1 failed), :core:jvmTest 2194/2194, :desktop-ui:test + integrationTest green, detekt + ktlintCheck clean. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent dba2c6e commit cd651b1

3 files changed

Lines changed: 226 additions & 42 deletions

File tree

core/src/jvmTest/kotlin/cz/vutbr/fit/interlockSim/context/DefaultSimulationContextControllerTest.kt

Lines changed: 14 additions & 38 deletions
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,6 @@ import assertk.assertThat
1313
import assertk.assertions.isEqualTo
1414
import assertk.assertions.isGreaterThan
1515
import assertk.assertions.isGreaterThanOrEqualTo
16-
import assertk.assertions.isLessThan
1716
import cz.vutbr.fit.interlockSim.sim.ShuntingLoop
1817
import cz.vutbr.fit.interlockSim.testutil.FakeSimulationController
1918
import cz.vutbr.fit.interlockSim.testutil.KoinTestBase
@@ -187,41 +186,18 @@ class DefaultSimulationContextControllerTest : KoinTestBase() {
187186
assertThat(controller.awaitCalls).isGreaterThanOrEqualTo(1)
188187
}
189188

190-
// ── Overhead test ─────────────────────────────────────────────────────────
191-
192-
/**
193-
* Verifies that the controlled loop overhead (FakeSimulationController with no sleep)
194-
* is less than 5% compared to the [NoOpSimulationController] baseline.
195-
*
196-
* Both runs use a 300s ShuntingLoop at maximum speed. The FakeSimulationController
197-
* does nothing in [throttle] and [awaitIfPaused], so any overhead is purely from the
198-
* additional method dispatch and bookkeeping in the `beforeEvent` hook.
199-
*/
200-
@Test
201-
@Timeout(120, unit = TimeUnit.SECONDS)
202-
@DisplayName("controlled loop overhead vs NoOpSimulationController is < 5%")
203-
fun controlledLoopOverheadIsNegligible() {
204-
// Baseline: NoOpSimulationController (zero overhead by definition)
205-
val baselineNs = System.nanoTime()
206-
loadShuntingLoop(300L).use { ctx ->
207-
ctx.run(NoOpSimulationController)
208-
}
209-
val baselineMs = (System.nanoTime() - baselineNs) / 1_000_000.0
210-
211-
// With FakeSimulationController that does nothing (no sleep)
212-
val fakeController = FakeSimulationController()
213-
val withLoopNs = System.nanoTime()
214-
loadShuntingLoop(300L).use { ctx ->
215-
ctx.run(fakeController)
216-
}
217-
val withLoopMs = (System.nanoTime() - withLoopNs) / 1_000_000.0
218-
219-
val overheadPct = (withLoopMs - baselineMs) / baselineMs * 100.0
220-
logger.info {
221-
"Controlled loop overhead: ${"%.2f".format(overheadPct)}% " +
222-
"(baseline=${"%.1f".format(baselineMs)}ms, withLoop=${"%.1f".format(withLoopMs)}ms, " +
223-
"throttleCalls=${fakeController.throttleCalls})"
224-
}
225-
assertThat(overheadPct).isLessThan(5.0)
226-
}
189+
// ── Overhead ──────────────────────────────────────────────────────────────
190+
//
191+
// Controlled-loop overhead is a *performance* claim and is measured by
192+
// `ControlledLoopOverheadBenchmark` in `desktop-ui/src/jmh`, not here.
193+
//
194+
// It previously lived in this class as `controlledLoopOverheadIsNegligible`,
195+
// which timed two single ShuntingLoop runs and asserted the wall-clock ratio
196+
// was < 5%. That is not a property a shared CI runner can honour: one sample
197+
// per arm, no JIT warmup (the baseline arm ran first and absorbed it, biasing
198+
// the ratio negative), and runner CPU-steal variance well above the 5%
199+
// threshold. It failed CI at 5.33% on run 29165254178.
200+
//
201+
// Run the benchmark with:
202+
// ./gradlew :desktop-ui:jmh -Pjmh.includes='ControlledLoopOverhead'
227203
}

core/src/jvmTest/kotlin/cz/vutbr/fit/interlockSim/sim/TwoTrainConcurrencyTest.kt

Lines changed: 17 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -138,13 +138,26 @@ class TwoTrainConcurrencyTest : KoinTestBase() {
138138

139139
// Per-train: each train's TRAIN_APPROVED must precede its own "ends" event.
140140
// Trains may run sequentially, so global ordering across both trains is not required.
141+
//
142+
// Train names come from a process-global counter that is never reset (Train.countValue),
143+
// so by the time this test runs the numbers may be multi-digit. Names must therefore be
144+
// compared as extracted whole tokens: a substring test would match "Train #1" inside
145+
// "Train #12". Likewise, positions must come from withIndex() rather than List.indexOf(),
146+
// which returns the first *equal* LogEntry rather than this one.
141147
val trainNameRegex = Regex("""Train #\d+""")
148+
149+
fun LogEntry.trainName(): String? = trainNameRegex.find(message)?.value
150+
151+
val indexOfEntry: (LogEntry) -> Int = { target ->
152+
log.withIndex().first { (_, entry) -> entry === target }.index
153+
}
154+
142155
for (approvalEntry in approvedEntries) {
143-
val trainName = trainNameRegex.find(approvalEntry.message)?.value ?: continue
144-
val approvalIdx = log.indexOf(approvalEntry)
145-
val endsEntry = endsEntries.firstOrNull { it.message.contains(trainName) }
156+
val trainName = approvalEntry.trainName() ?: continue
157+
val approvalIdx = indexOfEntry(approvalEntry)
158+
val endsEntry = endsEntries.firstOrNull { it.trainName() == trainName }
146159
requireNotNull(endsEntry) { "No 'ends' event found for $trainName" }
147-
val endsIdx = log.indexOf(endsEntry)
160+
val endsIdx = indexOfEntry(endsEntry)
148161
assertThat(endsIdx).isGreaterThan(approvalIdx)
149162
}
150163
}
Lines changed: 195 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,195 @@
1+
/* Brno University of Technology
2+
* Faculty of Information Technology
3+
*
4+
* BSc Thesis 2006/2007
5+
*
6+
* Railway Interlocking Simulator - Performance Benchmarks
7+
*
8+
* Bedrich Hovorka
9+
*/
10+
package cz.vutbr.fit.interlockSim.benchmarks
11+
12+
import cz.vutbr.fit.interlockSim.context.DefaultSimulationContext
13+
import cz.vutbr.fit.interlockSim.context.NoOpSimulationController
14+
import cz.vutbr.fit.interlockSim.context.SimulationContextFactory
15+
import cz.vutbr.fit.interlockSim.context.SimulationController
16+
import cz.vutbr.fit.interlockSim.di.interlockSimModule
17+
import cz.vutbr.fit.interlockSim.sim.ShuntingLoop
18+
import org.koin.core.context.startKoin
19+
import org.koin.core.context.stopKoin
20+
import org.koin.java.KoinJavaComponent
21+
import org.openjdk.jmh.annotations.Benchmark
22+
import org.openjdk.jmh.annotations.BenchmarkMode
23+
import org.openjdk.jmh.annotations.Fork
24+
import org.openjdk.jmh.annotations.Level
25+
import org.openjdk.jmh.annotations.Measurement
26+
import org.openjdk.jmh.annotations.Mode
27+
import org.openjdk.jmh.annotations.OutputTimeUnit
28+
import org.openjdk.jmh.annotations.Scope
29+
import org.openjdk.jmh.annotations.Setup
30+
import org.openjdk.jmh.annotations.State
31+
import org.openjdk.jmh.annotations.TearDown
32+
import org.openjdk.jmh.annotations.Warmup
33+
import org.openjdk.jmh.infra.Blackhole
34+
import java.io.InputStream
35+
import java.util.concurrent.TimeUnit
36+
37+
/**
38+
* Measures the cost of the controlled simulation loop in [DefaultSimulationContext.run].
39+
*
40+
* `run(controller)` invokes [SimulationController.throttle] and
41+
* [SimulationController.awaitIfPaused] from the `beforeEvent` hook on every simulation
42+
* event. The question this benchmark answers is: how much does that hook cost when the
43+
* controller does nothing at all?
44+
*
45+
* Two arms, reported independently rather than as a ratio:
46+
*
47+
* - [baselineNoOpController] passes [NoOpSimulationController], the `object` singleton.
48+
* Being a singleton it is monomorphic at the call site, so the JIT can devirtualize and
49+
* inline the empty bodies away.
50+
* - [withBenchmarkController] passes a fresh [BenchmarkController], a distinct class whose
51+
* method bodies are equally empty.
52+
*
53+
* The delta between the two arms is therefore the real dispatch/bookkeeping cost of the
54+
* hook, and it is exactly the asymmetry that the JUnit test which used to live in
55+
* `DefaultSimulationContextControllerTest` was silently measuring.
56+
*
57+
* ## Why this is a benchmark and not a test
58+
*
59+
* This measurement used to be a JUnit assertion (`controlledLoopOverheadIsNegligible`),
60+
* timing one run of each arm with [System.nanoTime] and asserting the wall-clock ratio was
61+
* below 5%. That cannot work on a shared CI runner: a single sample per arm, no JIT
62+
* warmup — the baseline arm ran first and absorbed it, biasing the ratio negative — and
63+
* runner CPU-steal variance far exceeding the 5% threshold. It failed CI at 5.33%.
64+
* JMH supplies the forks, warmup and measurement iterations that make the number mean
65+
* something. There is no threshold assertion here; read the numbers.
66+
*
67+
* ## Why SingleShotTime
68+
*
69+
* The payload is one whole simulation run against a single-use context, so each invocation
70+
* needs a freshly built [DefaultSimulationContext]. Under [Mode.AverageTime] JMH drives tens
71+
* of thousands of invocations per iteration, and that context churn hits a hard limit:
72+
* [DefaultSimulationContext] derives its Koin scope id from an identity hash code
73+
* (`platformIdentityCode(this)`), which is not unique, so at that volume ids collide and Koin
74+
* throws `ScopeAlreadyCreatedException`. [Mode.SingleShotTime] measures one full run per
75+
* invocation and keeps the number of contexts in the hundreds, which is both the honest shape
76+
* for a millisecond-scale payload and well clear of the collision threshold.
77+
*
78+
* Run with:
79+
* ```
80+
* ./gradlew :desktop-ui:jmh -Pjmh.includes='ControlledLoopOverhead'
81+
* ```
82+
*
83+
* @see DefaultSimulationContext.run
84+
* @see NoOpSimulationController
85+
*/
86+
@State(Scope.Benchmark)
87+
@BenchmarkMode(Mode.SingleShotTime)
88+
@OutputTimeUnit(TimeUnit.MILLISECONDS)
89+
@Warmup(iterations = 10)
90+
@Measurement(iterations = 20)
91+
@Fork(value = 3)
92+
open class ControlledLoopOverheadBenchmark {
93+
/**
94+
* Simulation end time, in simulated seconds.
95+
*
96+
* The retired JUnit test used 300s. 60s is used here to keep total benchmark
97+
* wall-time reasonable across 3 forks x (3 warmup + 5 measurement) iterations; the
98+
* per-event hook cost this benchmark isolates does not depend on the horizon.
99+
*/
100+
private val simulationEndTime: Long = 60L
101+
102+
@Setup(Level.Trial)
103+
fun startDi() {
104+
stopKoin() // Clean slate — a previous trial in this JVM may have left Koin running.
105+
startKoin { modules(interlockSimModule) }
106+
}
107+
108+
@TearDown(Level.Trial)
109+
fun stopDi() {
110+
stopKoin()
111+
}
112+
113+
/**
114+
* Railway network XML stream. Uses vyhybna.xml (shunting loop), the standard test network.
115+
*/
116+
private fun railwayNetworkXml(): InputStream =
117+
javaClass.getResourceAsStream("/cz/vutbr/fit/interlockSim/resource/vyhybna.xml")
118+
?: error("Railway network XML not found on the benchmark classpath")
119+
120+
/**
121+
* The context under measurement, rebuilt before every invocation.
122+
*
123+
* A [DefaultSimulationContext] is single-use — [DefaultSimulationContext.run] consumes it —
124+
* so each invocation needs a fresh one. It is built in [prepareContext] rather than inside
125+
* the `@Benchmark` body so that XML parsing and context construction, which cost far more
126+
* than the per-event hook under test, stay *outside* the timed region. JMH excludes
127+
* [Level.Invocation] fixture time from the measurement.
128+
*/
129+
private var context: DefaultSimulationContext? = null
130+
131+
@Setup(Level.Invocation)
132+
fun prepareContext() {
133+
val factory =
134+
KoinJavaComponent.get<SimulationContextFactory>(SimulationContextFactory::class.java)
135+
val ctx = railwayNetworkXml().use { factory.createContext(it) } as DefaultSimulationContext
136+
ctx.getInOuts()
137+
ctx.setMainProcess(ShuntingLoop(ctx, simulationEndTime))
138+
context = ctx
139+
}
140+
141+
@TearDown(Level.Invocation)
142+
fun releaseContext() {
143+
context?.close()
144+
context = null
145+
}
146+
147+
/**
148+
* A [SimulationController] that does nothing, as a distinct class rather than a singleton.
149+
*
150+
* Deliberately not an `object`: the point of the second arm is to present the call site
151+
* with an implementation the JIT cannot assume is the only one.
152+
*/
153+
private class BenchmarkController : SimulationController {
154+
override suspend fun awaitIfPaused() {
155+
// No-op: never paused.
156+
}
157+
158+
override fun throttle(simDeltaSeconds: Double) {
159+
// No-op: no wall-clock pacing.
160+
}
161+
162+
override fun isPaused(): Boolean = false
163+
164+
override fun pollStepEvent(): Boolean = false
165+
166+
override fun pollStepTime(): Double? = null
167+
168+
override fun requestPause() {
169+
// No-op: benchmark runs headless.
170+
}
171+
}
172+
173+
/**
174+
* Baseline: the controlled loop driven by the [NoOpSimulationController] singleton.
175+
*/
176+
@Benchmark
177+
fun baselineNoOpController(blackhole: Blackhole) {
178+
val ctx = requireNotNull(context) { "prepareContext() must run before the benchmark body" }
179+
ctx.run(NoOpSimulationController)
180+
blackhole.consume(ctx)
181+
}
182+
183+
/**
184+
* The controlled loop driven by a non-singleton no-op controller.
185+
*
186+
* The difference against [baselineNoOpController] is the hook's dispatch and bookkeeping
187+
* cost per simulation event.
188+
*/
189+
@Benchmark
190+
fun withBenchmarkController(blackhole: Blackhole) {
191+
val ctx = requireNotNull(context) { "prepareContext() must run before the benchmark body" }
192+
ctx.run(BenchmarkController())
193+
blackhole.consume(ctx)
194+
}
195+
}

0 commit comments

Comments
 (0)