allthingssecurity commented on PR #29528:
URL: https://github.com/apache/camel/pull/29528#issuecomment-6766128431
Here are the two results you asked for: a TLA+ model of the pending table
and the JMH run with the sanitizer on. Each found a problem, and 64d0f88520c7
fixes both. That commit also has the doc nit from your last review.
**TLA+ model of `PendingCalls`**
The model follows the table as the code has it. Each method that takes the
table's lock is one atomic step that does what the method does: `called`,
`returned`, `threw`, `callback`, `done` and the checker's `stalled`. That
includes `remove`, `unlink`, the drop at done, `dropOldest`, `touch`, the
parent pointers, `partOf`/`partIds`, the insertion order and the bound. The
checker logs its warning after it has released the lock, so that is two steps.
Since this commit the model also has the stripes (below). It keeps one table
per stripe, and an exchange goes to the stripe it is in, else to the stripe of
the exchange its correlation id names, else to the stripe of its own hash. The
checker scans one stripe per step.
The routing threads run exchange P, a filter around a split whose two parts
run in parallel, and an independent exchange Q. Every call can have its
callback before or after `process` returns, never get it, or have `process`
throw. Ghost state records what is really pending, which exchanges are done,
and how long nothing has happened in an exchange and its parts. Each warning is
checked against that ghost state.
Properties:
- no warning for a call whose callback has come, or whose exchange is done,
or whose exchange (with its parts) was active within the timeout;
- only the innermost call is reported, and not while the exchange waits for
parts that have a pending call;
- the table stays consistent: sizes, owners, one entry per id, and an id in
one stripe only;
- once an exchange's done event has come, nothing of that exchange is left;
- the table is empty once every exchange is done;
- nothing is kept with `pendingTimeout=0`;
- liveness: a callback that never comes is eventually warned about.
Abstractions:
- a bound of 3 per stripe;
- time as an age per entry, capped at the timeout (exact for the one
comparison the code makes);
- one route shape;
- no step timeout;
- no seda copy;
- `called()` is one step. The code reads the stripe map without the lock,
then claims the id under the stripe lock and retries if another stripe has it,
so the claim is the linearization point.
Results (TLC, 2 workers):
| config | result | distinct states |
|---|---|---|
| parts with their own done event | no error | 5,127,828 |
| timeout of 2 ticks | no error | 12,817,344 |
| `pendingTimeout=0` | no error | 50,028 |
| liveness, under fairness | no error | 1,166,352 |
| parts without a done event (`shareUnitOfWork`) | violated on 39a5da11b25b;
no error now | 2,520,588 |
Seven mutants, each caught:
- `done` without the drop;
- `callback` without the remove;
- `touch` without the parent;
- no part linked;
- the old `unlink`;
- a new exchange that ignores the stripe of its correlation id;
- `done` that keeps what the parts threw.
Witnesses show that each kind of warning, the eviction, and a split warned
after its parts are all reachable.
**The gap the model found.** With `split().shareUnitOfWork()` the parts have
no done event of their own. A part whose `process` threw stayed in the table.
The exchange's entry left the table when its own calls were called back, so the
exchange's done event found nothing to drop. A small program on 39a5da11b25b
confirmed this: the part was reported as still pending after the exchange was
done, and it stayed until the context stopped. The fix has three parts:
- An exchange now stays in the table while one of its parts has a pending
call.
- The exchange's done event drops its own calls and the calls its parts
threw. A part call that did not throw stays and is reported, because a part can
hang after a split with a `timeout` has given up on it.
- An exchange is skipped for its parts only while its innermost call is the
step that runs them.
New tests cover the route case, which fails on 39a5da11b25b, and the table
cases with a test clock.
**JMH with the sanitizer on**
Setup:
- JMH 1.37, JDK 21, 2 forks, 3 × 2 s warmup, 5 × 2 s measurement, `-Xmx1g`,
NOP logging, Apple M-series with 12 cores;
- `ProducerTemplate.requestBody` on one shared context;
- `off` means camel-sanitizer is on the classpath with `enabled=false`, `t0`
means `pendingTimeout=0`, and `t60` means `pendingTimeout=60s`;
- `steps` makes 6 step calls per message;
- `split` splits a 4-element list and then makes an InOnly send to seda: 11
step calls and 6 exchanges per message.
After each `t60` trial the table was empty, nothing had been dropped, and
there was no warning.
ns/op per thread (avgt, ± 99.9% CI). Before is 39a5da11b25b (one lock);
after is this commit (32 stripes on this machine).
| route | mode | stackDepth | 1 thread, before | 1 thread, after | 4
threads, before | 4 threads, after |
|---|---|---|---|---|---|---|
| steps | off | – | 945 ± 16 | 924 ± 13 | 2,441 ± 461 | 2,319 ± 48 |
| steps | t0 | 0 | 1,115 ± 33 | 1,088 ± 20 | 1,735 ± 307 | 1,864 ± 184 |
| steps | t60 | 0 | 1,481 ± 17 | 1,634 ± 135 | 11,002 ± 644 | 3,252 ± 168 |
| split | off | – | 4,024 ± 156 | 3,999 ± 79 | 7,921 ± 3,125 | 5,599 ± 162 |
| split | t0 | 0 | 4,395 ± 165 | 4,494 ± 61 | 8,890 ± 3,511 | 6,552 ± 293 |
| split | t60 | 0 | 7,102 ± 144 | 6,950 ± 222 | 35,109 ± 1,511 | 13,225 ±
443 |
| steps | t0 | 32 | 64,486 ± 2,411 | not re-run | 71,995 ± 9,447 | not
re-run |
| steps | t60 | 32 | 63,549 ± 380 | not re-run | 86,912 ± 18,721 | not
re-run |
| split | t0 | 32 | 115,743 ± 2,568 | not re-run | 115,938 ± 4,886 | not
re-run |
| split | t60 | 32 | 119,485 ± 1,373 | not re-run | 142,069 ± 2,903 | not
re-run |
The `stackDepth=32` rows were measured on 39a5da11b25b only. The stack walk
dominates them (see below), and the table change does not touch it. `off` with
`stackDepth=32` measured the same as with 0.
**Reading**
- **Throughput.** Before, `steps` with `t60` on 4 threads routed about 364k
messages/s in all, fewer than one thread alone (about 675k/s). With the
stripes, 4 threads route about 1.23M messages/s, against about 612k/s on one
thread. `split` with `t60` on 4 threads went from 35.1 to 13.2 µs per message
per thread.
- **Thread dumps.** I took 12 samples × 4 workers during the 4-thread `t60`
runs:
- `steps`: 26 of 48 samples were BLOCKED on the `PendingCalls` monitor
before, and 0 of 48 are now;
- `split`: 4 of 48 are BLOCKED now, each on a stripe that another worker
held because its exchange hashed to the same stripe;
- `t0`: no BLOCKED thread.
- **One thread.** The stripes cost a little on one thread: `steps` `t60`
went from 1.48 to 1.63 µs, and `split` is within the noise.
- **The bound.** Each stripe keeps 10 000 / stripes calls (312 with 32
stripes), so the table still keeps at most 10 000. An exchange and its parts
share one stripe, so they can hold 312 pending calls before the oldest is
dropped, with the WARN. A global count would put one shared counter back on
every call.
**`stackDepth=32`** costs far more than the table: about 10 µs per step
call. That is R1's stack walk at every first callback (#29409), and it slows a
short route by about 60 times. On 4 threads the walks run in parallel. It
changes timing much more than the table's lock did, so I suggest a follow-up
JIRA for cheaper or opt-in stacks rather than handling it in this PR. One
option is to take a stack only for a call that turns out to matter.
**Doc nit.** The chaos sentence in "Still pending" now says:
- a `route=` entry delay acts at the first step, like a `step=` delay;
- an `endpoint=` or `component=` delay shows at the `to` step only at a send
(`at=send`);
- at a poll there is no exchange yet;
- an `at=dlq` delay runs in the error handler after the failed step, so it
shows like a `step=` delay.
I checked this against camel-chaos (`ChaosStepHook.beforeStep` handles the
entry fault). The catalog copy is identical.
**Tests**
- The sanitizer tests of camel-core, camel-management, camel-main and
camel-test-main-junit6, together with `SimpleEventNotifierEventsTest`, pass
with and without `-Psanitizer`: 82 tests, 0 failures each.
- `SanitizerPendingCallsTest` and `SanitizerStillPendingTest` ran 20 times
in one JVM, with and without the switch: 640/640 each.
Whether the table needs its model, and whether this step goes ahead of R2/R3
and the console, is your call. The spec is about 430 lines, and I can attach it
here or add it next to the design.
_Claude Code on behalf of allthingssecurity_
--
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]
