An open-source PKCS#11 v3.2 cryptographic module under Simorgh Labs
Status: decided and built.
The previous measurement left this as the largest open question in #111: one
fsync per event caps the whole module at ~250 signatures/s, against ~1350
when the durable write is removed. A factor of five, traded against the
property the log exists for. docs/RATE_LIMIT.md recorded it; this settles it.
In C_Sign the audit line is written after the signature is computed and
before the function returns. So on a power loss the two possible states are
not symmetric:
| what is lost | |
|---|---|
Today — fsync before returning |
At worst a record of an operation whose result the caller never received. A record with no delivery. |
| Batched — return, sync later | At worst a signature the client is holding, with no record that it was ever made. A delivery with no record. |
The first is harmless and self-evident on inspection: an entry exists for something nobody used. The second is precisely the failure the log exists to prevent, and it is undetectable afterwards — the missing line looks exactly like an operation that never happened.
That asymmetry, not the throughput, is what makes this decidable. A signature must not reach a client before the record of it is durable.
Per 302-byte append, 300 appends, on the same host as probes/rest/:
write only, no durability |
0.001 ms — 1 844 000 lines/s |
write + fsync (today) |
2.764 ms — 362 lines/s |
write + fdatasync |
2.474 ms — 404 lines/s |
write + fdatasync, file preallocated |
3.274 ms — 305 lines/s |
O_DSYNC, no explicit sync |
2.832 ms — 353 lines/s |
O_DSYNC, preallocated |
2.799 ms — 357 lines/s |
Everything lands between 2.5 and 3.3 ms. fdatasync is marginally cheaper than
fsync; preallocating — the trick that helps databases — did not help here and
was slightly worse. The cost is the durability barrier itself, not the call
used to request it. There is no cheaper syscall.
The table above reads as though it were about the audit log. It is not.
tests/bench_fsync_floor does one 300-byte append and one fdatasync with no
FreeHSM code in the loop at all, on the same filesystem:
filesystem ext4 on /dev/sdc (/sessions)
min 2.058 ms
p50 2.553 ms
p90 3.155 ms
p99 4.165 ms
max 4.421 ms
mean 2.635 ms -> 379 lines/s
That is one run of 300 samples. Five runs of 200 gave means of 2.360, 2.424, 2.463, 2.562 and 2.420 ms — an 8 % spread, so the floor is about 2.4–2.6 ms and no single decimal in it should be quoted on its own. The habit is deliberate: a first run of 3.735 ms was once taken as fact and turned out to be a cold-cache outlier.
The module’s 2.49–2.86 ms per line sits on that floor. Formatting the line and computing its HMAC cost almost nothing next to the barrier, which is the finding that matters for anyone tempted to optimise the log: there is nothing there to optimise. The same loop with the barrier removed runs at 0.000 ms; the barrier is the whole cost, and it belongs to the disk.
It is worth reading the distribution rather than the mean, which is why the tool prints one. On the sandbox, one run of 200 samples had a maximum of 76.4 ms against a median of 2.70. An operator feels the tail.
The barrier is expensive and the same barrier serves every write that is
already pending. Writers that arrive while one fsync is in flight can wait
for the next one instead of queueing their own — and still return only after a
barrier that covered their own write. The guarantee is unchanged; what changes
is how many barriers it takes.
| threads | fsync per writer |
group commit | barriers used |
|---|---|---|---|
| 1 | 392 lines/s | 358 lines/s | 60 for 60 |
| 2 | 373 lines/s | 488 lines/s | 90 for 120 |
| 4 | 399 lines/s | 783 lines/s | 113 for 240 |
| 8 | 363 lines/s | 1469 lines/s | 118 for 480 |
At eight concurrent writers: four times the throughput, 118 barriers instead of 480, and every writer still returned after a barrier that covered it.
At one writer it is 9 % slower — the mutex and condition variable cost something when there is nobody to share with. Worth stating plainly: this helps a concurrent service and mildly penalises a single-threaded tool.
So the ~250 sig/s plateau was never the price of durability. It was the price
of not sharing the barrier. The current code holds the audit mutex across the
fsync, which is what serialises every other writer behind it.
fhsm_audit_event releases the audit mutex
across the barrier and lets concurrent writers be covered by one already in
flight. Lines are still written under the mutex, so file order and HMAC
order still agree — but the chain is not simply unaffected, as this point
claimed before it was built: releasing the mutex means another writer reads
the chain head mid-barrier, so the head has to advance before the barrier
rather than after. See below.fdatasync rather than fsync, as the marginally cheaper call with the
same meaning for an append-only file. Worth ~10 %, and free.| threads | before | after | with no durable write at all |
|---|---|---|---|
| 1 | 199 sig/s | 222 sig/s | 558 sig/s |
| 2 | 267 sig/s | 324 sig/s | 859 sig/s |
| 4 | 247 sig/s | 493 sig/s | 1359 sig/s |
| 8 | 242 sig/s | 674 sig/s | 1145 sig/s |
2.8× at eight concurrent signers, and the median latency there fell from 30.3 to 10.8 ms. The remaining gap to the third column is the rest of the module’s locking plus the barriers that still have to happen — this closed most of the distance, not all of it.
The single-writer figure came out slightly better here and slightly worse in the microbenchmark. Both are inside the run-to-run spread; the honest statement is that group commit does not measurably help one writer and may cost it a little, which is the trade named above.
The ordering is the delicate part, and it is not the waiting. The mutex is
released while the barrier runs, so another writer takes the lock and reads
g_prev_hmac in the middle of it. The chain therefore has to advance before
the barrier rather than after. Get that wrong and two lines claim the same
predecessor: every event still returns OK, the log still looks well-formed,
and only the verifier disagrees.
tests/test_audit_concurrent.c, eight threads × forty events. It asserts that
every event succeeded, that the barriers were shared (79 for 320, so the
sharing is observable rather than assumed), that the chain verifies over the
whole file, and that no line was lost. Two mutations, each caught by the
assertion meant for it:
Clean under SANITIZE=1, and clean under ThreadSanitizer — which needs
setarch -R in a container, otherwise TSAN aborts on the memory layout before
it runs a single line.
fhsm_audit_event checked write() and latched ERROR when it failed, then
called fsync() and threw the answer away.
On most filesystems a deferred write error is reported at fsync and nowhere
else. So the control that exists to stop the module when the log cannot be
written was wired to the call that usually succeeds, and not to the call that
usually reports. Both fsync calls in the key-provisioning code check their
return; this was the third and the only one that did not — the same shape as
#61, #49 and the ulPinLen defect.
Fixed: a failed fsync reports failure and latches ERROR, exactly as a failed
write does.
tests/test_audit_fsync.c stages it portably. fsync on a pipe returns
EINVAL while write to it succeeds, so the log is pointed at a FIFO with a
reader draining it: every write lands, every barrier fails, and nothing in the
audit code knows it is not a file. Four assertions; two fail with the check
removed.
A hash chain has exactly one author by construction. Nothing here required it. Two processes each opened the log, each resumed the chain from the tail of the file, and from then on each believed itself the successor of the same line:
lines written by two processes : 60 (expected 60)
chain verifies : NO
first broken line : 2
Sequentially, the same two processes produce a chain that verifies. So it is
the concurrency, not the resume. Found through p11-kit server, which forks a
child per client and makes the situation systematic — but two fhsm-sign
invocations in a script do the same thing, so this is not a p11-kit problem.
Note what the group commit above does not do: it orders writers within one process. It says nothing about two processes, and looking at the wrong axis is why this was not seen while that work was being done.
That was the first instinct and it was wrong. C_Initialize opens the log, so
an exclusive lock would make fhsm-sign fail while fhsm-ca is running.
Concurrent tools are a Monday-morning script, not a corner case. Locking
between processes instead would put a file lock on a path that already costs
3 ms. So: each opening creates its own file, base.NNNNNN, with O_EXCL.
Every file then has a single author from line 1 and needs no coordination at
all — no lock, no restriction on concurrency, nothing on the hot path.
chain_resume() went with it. Resuming existed only to share one file between
openings; each log now starts at the chain head, and the function that made the
sharing possible is the function that made it dangerous.
With one file, deleting the middle breaks the chain and deleting the tail is undetectable — a gap already recorded. With per-file logs, deleting a whole file would remove a process’s entire history while every remaining chain still verified. That would be a new way to erase history, and a worse one.
Sequence numbers make it a hole between 6 and 8, which `freehsm-audit verify