allthingssecurity opened a new pull request, #28382:
URL: https://github.com/apache/camel/pull/28382
## What
Stage 2 of CAMEL-25738, as discussed on dev@ ("[DISCUSS] An internal time
source in camel-util (for deterministic
simulation tests)", +1 from Claus).
1. **`org.apache.camel.util.TimeSource`** in camel-util: a small static,
internal class with `currentTimeMillis()`,
`nanoTime()`, `instant()` and `sleep(long)`. The default provider
delegates to `System.currentTimeMillis()`,
`System.nanoTime()`, `Instant.now()` and `Thread.sleep(long)`. A test
harness installs another provider with
`install(Provider)` (which returns the previous one, to put back) and
`reset()` puts the default back; the field is
`volatile`. The javadoc says it is internal and only for test harnesses
such as camel-test-dst. Static rather than
per `CamelContext`, because `StopWatch` and `MonotonicClock` have no
context.
2. **The core call sites that wait, time tasks or throttle** read the clock
and sleep through it (49 call sites in 20
classes, the list from the JIRA plus one identical neighbour, below).
Event timestamps, the clock of an exchange
(`ResetableClock`) and the direct clock reads of the debugger, the
tracer, management and the consoles stay on
`System`. The durations they measure with `StopWatch` or `MonotonicClock`
follow `TimeSource`, because both classes
are on the list: for example the processor statistics of management (one
`StopWatch` per processor and exchange
when statistics are on), the backlog debugger and tracer, and the message
history. With the default provider that
is the same `System.nanoTime()`; the `StopWatch` row under Cost is its
price.
3. **camel-test-dst** installs its virtual clock (`DstClock`) as the
provider when a run is created and puts the
previous provider back when the run is closed. The core waits then run in
virtual time without rewriting core
classes, so the `@DstInstrument(alsoRewrite)` stop-gap is no longer
needed for them (three waits are not clock
reads and stay outside, see camel-test-dst below); the byte code
rewriting of the component under test is
unchanged. A sleep through `TimeSource` is traced with its call site, as
a rewritten sleep
is.
No behaviour change with the default provider: every moved call is the same
JDK call, one static method further away.
No option, default or public signature changes, so there is no upgrade guide
entry.
## Moved call sites
| Area | Class | Calls |
|---|---|---|
| waits | `RedeliveryPolicy.sleep` | 1 `Thread.sleep` |
| | `RedeliveryErrorHandler` (the synchronous redelivery sleep loop) | 1
`Thread.sleep` |
| | `ForegroundTask` | 4 `Thread.sleep`, 2 `currentTimeMillis` |
| | `DefaultShutdownStrategy` (the wait loop for in-flight exchanges) | 1
`Thread.sleep` |
| | `DelayProcessorSupport` (synchronous delay) | 1 `Thread.sleep`, 1
`currentTimeMillis` (the protected `currentSystemTime()`, which nothing in the
repository calls; moved so that a subclass gets the same clock) |
| | `MulticastProcessor` (delay without a scheduled executor) | 1
`Thread.sleep` |
| | `OptimisticLockRetryPolicy` | 1 `Thread.sleep` |
| | `DefaultStartupConditionStrategy` | 1 `Thread.sleep` |
| task timing | `StopWatch` | 5 `nanoTime` |
| | `MonotonicClock` | 1 `currentTimeMillis`, 2 `nanoTime` |
| | `AbstractTask` | 1 `currentTimeMillis` |
| | `BackgroundTask` | 2 `currentTimeMillis` |
| | `TimeBoundedBudget` | 2 `Instant.now` |
| | `IterationBoundedBudget` (identical neighbour, see below) | 3
`Instant.now` |
| | `BackOffTimerTask` | 1 `currentTimeMillis` |
| | `DefaultTimeoutMap` | 1 `currentTimeMillis` |
| throttling | `TotalRequestsThrottler` | 5 `currentTimeMillis`, 1
`nanoTime` |
| | `ConcurrentRequestsThrottler` | 4 `nanoTime` |
| | `SamplingThrottler` | 1 `nanoTime` |
| | `ThrottlingExceptionRoutePolicy` | 6 `currentTimeMillis` |
Beyond the JIRA list: `IterationBoundedBudget`, the sibling of
`TimeBoundedBudget` with the same `Instant.now()` start
time and `elapsed()`. `IterationTimeBoundedBudget` (the budget
`ForegroundTask` usually gets) combines the two, and
`ForegroundTask.elapsed()` comes from it, so leaving it on `System` would
mix virtual and real time in one task.
Every listed class had its calls on current `main`; none was skipped.
`ResetableClock`, which the dev@ draft listed
next to `MonotonicClock`, is the clock of every exchange (its created
timestamp), so it stays on `System` like the
other timestamps; `@DstInstrument(alsoRewrite)` still covers it when a world
needs it.
## Cost
From the JMH benchmark posted to the dev@ thread (JMH 1.37, JDK 21, AArch64
laptop, 3 forks, average ns/op; a local
copy of the class, not a CI run):
| | 1 thread | 8 threads |
|---|---|---|
| `System.nanoTime()` | 8.92 | 356.1 |
| `TimeSource.nanoTime()`, volatile field | 9.10 | 354.9 |
| `TimeSource.nanoTime()`, after a second provider was used (bimorphic call
site) | 9.22 | 355.7 |
| `System.currentTimeMillis()` | 13.59 | 186.5 |
| `TimeSource.currentTimeMillis()` | 13.62 | 185.2 |
| `new StopWatch().taken()`, before / with `TimeSource` | 19.96 / 20.52 |
709.6 / 710.8 |
About 0.2 ns more per `nanoTime()` and 0.5 ns per `StopWatch` on one thread,
nothing measurable for
`currentTimeMillis()` and nothing measurable with 8 threads; a volatile
field was not measurably slower than a plain
one. For scale, the simplest `direct -> log` route takes about 410 ns per
message. Only AArch64 was measured. The
`StopWatch` row is also the cost on the processor statistics path of
management, which times each processor with a
`StopWatch` when statistics are on. The dev@ mail set aside a time source
for all of core partly because of hot paths
such as the processor statistics; with `StopWatch` on the list they still
pass through `TimeSource`, at about 0.5 ns
per `StopWatch`.
## camel-test-dst
- `Dst` installs `DstClock.TIME_SOURCE` when a run is created and puts the
previous provider back in `close()`; the
extension closes each seed's run, so the default is back after every test.
Outside a run nothing is installed.
- A core clock read or sleep from a thread outside the harness while a run
is open is an escape, as for the rewritten
calls (strict mode fails the seed). A sleep keeps the semantics of
`Thread.sleep`: a negative value throws
`IllegalArgumentException`, an interrupted thread gets
`InterruptedException` with the flag cleared.
- `DstCoreWaitsTest` no longer lists core classes in `alsoRewrite`; it adds
a `ForegroundTask` that gives up when its
time budget is spent (30 s of virtual time, which only holds when
`TimeBoundedBudget` reads the virtual clock) and a
synchronous delayer. `DstTimeSourceTest` covers the install and restore
(also of a provider installed before the
run), the core clocks without rewriting, the traced sleep, the
`Thread.sleep` semantics and the off-loop escape.
`DstAlsoRewriteTest` now uses `ResetableClock`, which stays on `System`.
- Three waits in these classes are not clock reads and stay outside the
virtual clock; `test-dst.adoc` lists them:
- `TotalRequestsThrottler` waits for a permit with `DelayQueue.take()`.
The delay of a permit is now virtual, but the
wait is a real one on the loop thread, where the virtual clock does not
move, so a seed that has to wait for a
permit ends on the watchdog. Before this PR the permit came due after
the real time period, so such a seed waited
in real time with mixed clocks; this only changes DST runs, production
is unchanged. `asyncDelayed()` does not avoid it (a delayed
exchange that finds its permit taken by another one waits on the same
queue). With
`@DstInstrument(alsoRewrite =
"org.apache.camel.processor.TotalRequestsThrottler")` the wait is virtual.
Checked
locally with a probe test that is not committed:
`throttle(1).timePeriodMillis(1000)` and three exchanges end on the
watchdog, with and without `asyncDelayed()`, and pass at virtual 0, 1000
and 2000 ms in 9 ms with that `alsoRewrite`.
- The half-open check of `ThrottlingExceptionRoutePolicy` runs on a
`java.util.Timer` thread: it fires after
`halfOpenAfter` of real time and its clock read is an escape. Only the
counters, `openedAt` and `lastFailure` are
virtual.
- `BackgroundTask.run` waits on a latch; `BackgroundTask.schedule` and the
attempts are virtual.
- `DstExtension` closes the run of a seed also when its replay trace cannot
be written, and after a test class it
closes a run that was left open and fails the class: with this PR an open
run would keep the virtual clock installed
for all of Camel core in the later tests of the JVM.
- `test-dst.adoc` (and its catalog copy): the harness controls Camel core
through `TimeSource`, and `alsoRewrite` is for
classes outside it.
- Not in this PR, each a follow-up JIRA: loading the agent with `-javaagent`
instead of attaching it at runtime
([CAMEL-26103](https://issues.apache.org/jira/browse/CAMEL-26103), named
in the JIRA proposal), and creating the
half-open timer of `ThrottlingExceptionRoutePolicy` through the
`ExecutorServiceManager`
([CAMEL-26104](https://issues.apache.org/jira/browse/CAMEL-26104); that
would also stop a new `Timer` thread being
created on every open and reopen in production). The forbidden-apis rule
for new `Thread.sleep` / `Instant.now()` in
consumers stays for later, as the JIRA says.
- Seen in the diff and left as is, so that this stays a mechanical swap:
`TotalRequestsThrottler` stores the queued
timestamp of an `asyncDelayed()` exchange as `nanoTime()` and subtracts it
from `currentTimeMillis()` values in two
TRACE lines ("Queued for {}ms"), so those numbers are wrong. TRACE only
and older than this PR; for a follow-up.
## The SQS world with core waits
`SqsRedeliveryDstTest` (new, 500 seeds) runs the SQS world of
`SqsVisibilityDstTest` with synchronous redelivery: a
failed message is retried twice by the default error handler after a
redelivery delay that the seed picks between 1x
and 3x the visibility timeout, so the visibility timeout extender has to
keep the message invisible while
`RedeliveryErrorHandler` sleeps on the consumer's thread. The consumer holds
the message during that wait, and the
world checks that no message is delivered again meanwhile and that each
redelivery came at least the redelivery delay
after the failure (by exchange). The world without redelivery draws nothing
new, so its seeds keep their configuration.
Results (strict mode, no runtime escape in any world):
| | with this PR | the same branch with a real-time provider installed
instead of the virtual clock (local negative control, not committed) |
|---|---|---|
| `SqsRedeliveryDstTest` | 500 of 500 seeds pass, 7.6 ms per seed | seeds 2
and 3 of the first 3 fail: the redelivery came 0 ms of virtual time after the
failure (the error handler slept 8.9 s and 6.4 s of real time on the test
thread); 9.7 s per seed |
A replay of seeds 1 to 40 (`-Ddst.seed=1,...,40`) writes their traces: 20 of
the 40 seeds go through the redelivery
wait, with 730 one-second sleeps traced as `sleep at
RedeliveryErrorHandler$RedeliveryTask.sleep:2079`, and the 40
seeds take 0.88 s of real time. The other worlds pass unchanged with the
core waits now virtual: `SqsVisibilityDstTest`
1000 of 1000, `EventHubsCheckpointDstTest` 1002 of 1002 (with its in-JVM
replay test), `SlackSuspendDstTest`
1000 of 1000.
## Testing
```
./mvnw test -pl
core/camel-util,core/camel-support,core/camel-core-model,core/camel-core
./mvnw test -pl
components/camel-test/camel-test-dst,components/camel-aws/camel-aws2-sqs,\
components/camel-azure/camel-azure-eventhubs,components/camel-slack
-Dtest='Dst*Test,*DstTest' \
-Dsurefire.failIfNoSpecifiedTests=false
```
- camel-util: 305 tests pass, 8 of them the new `TimeSourceTest` (the
default provider against `System`, `sleep`
with 0, a negative value and an interrupted thread, install / reset / the
previous provider, `StopWatch` on an
installed provider). camel-support: 139 pass; camel-core-model: 11 pass.
The other touched modules have no tests of
their own (their tests are in camel-core).
- camel-core: 8265 tests run in three parts (the `processor` sub packages,
the rest of `processor`, everything else),
54 skipped, 0 failures caused by this change. The third part had 4
failures, all in tests of changes on `main`
newer than the camel-bean and camel-file snapshots used locally
(CAMEL-25871 / CAMEL-25900 in
`SimpleSyntaxHintsTest`, CAMEL-25930 in
`FilePollEnrichDynamicFileNameTest`); with camel-bean and camel-file built
from this branch both classes pass (34 tests). `ControlBusFailRouteTest`
failed once and passed on the rerun (it is
disabled on CI as flaky).
- camel-test-dst: 57 self-tests pass (`DstCoreWaitsTest` 6,
`DstTimeSourceTest` 6). With a real-time provider
installed instead of the virtual clock (local negative control) all 6 of
`DstCoreWaitsTest` and all 6 of
`DstTimeSourceTest` fail.
- The worlds, strict mode, no runtime escape: `SqsRedeliveryDstTest` 500,
`SqsVisibilityDstTest` 1000,
`EventHubsCheckpointDstTest` 1002, `SlackSuspendDstTest` 1000 (seeds or
tests), all pass. The whole camel-aws2-sqs
suite passes (1595 tests, 16 skipped).
- In virtual time this PR tests the synchronous redelivery, `ForegroundTask`
with both budgets, the synchronous
delayer, the shutdown wait loop, `StopWatch` and `MonotonicClock`. The
other moved call sites (the throttlers,
`MulticastProcessor`, `OptimisticLockRetryPolicy`,
`DefaultStartupConditionStrategy`, `BackgroundTask`,
`BackOffTimerTask`, `DefaultTimeoutMap`, `ThrottlingExceptionRoutePolicy`)
are the same one-line swap; their camel-core
tests cover them on the default provider. The waits of the throttler, the
circuit breaker policy and `BackgroundTask`
that stay outside the virtual clock are listed under camel-test-dst above.
- `formatter:format impsort:sort` applied (the build runs them).
_Claude Code on behalf of allthingssecurity_
🤖 Generated with [Claude Code](https://claude.com/claude-code)
--
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]
