PDBStorage.write() fails ordinary concurrent ADD/DELETE with result 80: the attempt cap from #937 is spent under single-suffix write load

[vharseko]

Describe the bug

Since #937 (fix for #921), PDBStorage.WriteableStorageImpl.write() gives up after MAX_RETRIES = 10 attempts
and the operation fails with result code 80 (other):

pdb: backend 'userRoot' did not apply the transaction after 10 attempts in 2830 ms, the attempt cap being spent;
the last conflict was com.persistit.exception.RollbackException

This bound was designed for the configuration change paths, which hold an entry container's exclusive lock
across write(). But it applies to every write, and ordinary concurrent ADD/DELETE traffic in a single suffix
reaches it. Before #937 the same operations were replayed until they went through and succeeded.

Evidence: the JE vs PDB benchmark in build-docker

The benchmark runs 200 threads with rampup=0 for 150 s. Each iteration does ADD, SEARCH, COMPARE, MODIFY,
BIND and DELETE of its own mail=u_<thread>_<iter> entry under ou=People, then a READD of a UUID entry.
The figures below come from the benchmark-pdb-vs-je artifacts, parsed as CSV:

Run	Side	Samples	Result 80, attempt cap spent	Cascade
36845050319 (01.10, #1145)	JE	649 030	0	—
	PDB	715 578	6 (DELETE 3, ADD 2, READD 1)	2 × COMPARE 32, MODIFY 32, BIND 49
36738515054 (30.09, #1086)	JE	538 600	0	—
	PDB	581 568	8 (READD 4, DELETE 2, ADD 2)	2 × COMPARE 32, MODIFY 32, BIND 49

• Every result-80 failure falls in the first ~20 s of the PDB run, between +0.5 s and +19.5 s.
• Each failed operation took 1.8–3.9 s, which is the backoff ladder of 10 attempts (at most 5.5 s, ~2.8 s
  expected). The bound that ran out is the attempt cap, not the 10 s window.
• The cascade follows from each failed ADD: the entry is missing, so the COMPARE and MODIFY of that iteration
  fail with 32, and its BIND fails with 49.

The master runs of build.yml show when this started. The benchmark has printed its error lines since #655
(06.07):

• the 10 runs from 25.08 to 08.09, before [#921] Bound the transaction replay of PDBStorage.write() #937 was merged on 09.09: no PDB errors at all;
• 34603662889 (11.09) and
  34692235136 (12.09), the first
  runs after the merge: PDB prints 2 BIND | 49 | Invalid Credentials, the visible end of the same cascade.

The step log shows only the BIND line because of a separate defect in the benchmark script.
.github/benchmark/compare-opendj.sh splits the JTL with awk -F','. The result-80 message and the DNs in the
32 messages contain commas, which shift the success column, so those rows never print. The err columns of
the step summary are read from statistics.json, and they show all of the errors.

Why JE is not affected by the same cap

JEStorage has the same MAX_RETRIES = 10 and the same 10 s window, added by #1065 (#1064). There the cap is
practically unreachable. je.lock.timeout is 0, so a writer waits for a lock instead of failing, and the only
conflict JE raises is a deadlock.

persistit works optimistically instead. Two transactions that write the same key collide, and one of them is
rolled back. The code already acknowledges this: the comment above the exhaustion WARN in PDBStorage.write()
says "a conflict is routine on the ordinary add and modify path of this engine". So on PDB, 10 attempts means
losing 10 races in a row for a hot key. When 200 writers start at once under one parent, that happens
reproducibly.

What #921 / #937 assumed

The sizing discussion in #937 went like this. The conflicts that drive the loop "come from other base DNs of
the same backend", "the page-level conflicts persistit reports resolve in microseconds", and 10 attempts
within 10 s "leaves a genuinely contended write ample room". The window was copied from JDBCStorage and was
not measured, because #921's question was about the configuration change paths. The data above is the
measurement #921 asked for. Under ordinary single-suffix load, the attempt cap runs out well before the window
does.

What it needs

Settle on a bound that a contended but healthy write does not spend, while the configuration change paths
still get a finite wait. Options, none of them measured yet:

1. Let only the wall-clock window end the replay for PDB, and drop the attempt cap or raise it well beyond what
   the backoff ladder can spend in 10 s. PDBStorage.write() replays a rolled-back transaction without any bound, and configuration changes hold an entry container's exclusive lock across it #921 asked for a finite stall under the exclusive lock, and the window
   already provides that.
2. Make the bounds configurable on pdb-backend, keeping the current defaults.
3. Find which key the ADD/DELETE transactions collide on, for example the parent's children count or an index
   key shared by all entries, and reduce the contention there.

Whatever is chosen, the JE vs PDB benchmark should show zero result-80 failures on PDB, as it did before #937.
PDBStorageTest.testWriteGivesUpAfterTheAttemptCap pins the shipped MAX_RETRIES and would need to follow.

Related

• PDBStorage.write() replays a rolled-back transaction without any bound, and configuration changes hold an entry container's exclusive lock across it #921 / [#921] Bound the transaction replay of PDBStorage.write() #937: introduced the bound
• JEStorage.write makes one attempt: a transaction JE ends as the victim of a deadlock is given up rather than replayed #1064 / [#1064] Replay a JE transaction ended by a lock conflict instead of giving it up at once #1065: the same bound in JEStorage, unreachable there with the shipped configuration
• Config change paths do not flag an admin action when a bounded storage write gives up #962: what the configuration change paths report when the bound is spent
• Benchmark BIND fails with "LDAP connection has been closed" once docker-proxy runs out of ephemeral ports #1144 / [#1144] Widen the ephemeral port range before the benchmark runs #1145: the other benchmark failure in the same runs (BIND "LDAP connection has been closed",
  ephemeral port exhaustion); it is unrelated to the backend

[vharseko]

Analysis

Where the transactions collide: index keys below index-entry-limit

Every entry of the benchmark carries objectClass: top, locality, extensibleObject and a mail ending in
@test.com. The default indexes of a pluggable backend include objectClass (equality) and mail (equality and
substring), so every entry shares the three objectClass keys and the substring keys of the @test.com tail.
DefaultIndex.update() rewrites the whole ID list of such a key on every ADD and DELETE. Under persistit's snapshot
isolation, two transactions that write the same key collide, and one of them is rolled back.

The contention ends by itself. Once a key holds index-entry-limit IDs (4000 by default) it becomes undefined, and
DefaultIndex.update() returns before writing an undefined key, on purpose: "Avoid taking a write lock on a record
which has hit all IDs because it is likely to be a point of contention". The READD entries of the benchmark are
never deleted, so the live entry count reaches 4000 about 20 s into the run.

The parent's children count is not the hot key. ShardedCounter spreads it over 256 shards keyed by
Thread.getId(), so different worker threads do not write the same record.

Evidence: the knee at 4000 live entries

From the JTL of both runs (live entries = successful ADD + READD − DELETE, by completion time):

Run	Side	4000 live entries at	Writes per 2 s, before → after	Write p99, before → after	Result 80
36845050319	PDB	22.2 s	~850 → ~3600	1.9 s → 0.16 s	6, started at 0.5–17.5 s
36738515054	PDB	22.0 s	~890 → ~3800	2.0 s → 0.16 s	8, started at 5.9–17.2 s, ended by 20.3 s
36845050319	JE	19.3 s	~1900 → ~3750	0.6 s → 0.08 s	0

Write throughput quadruples exactly when the index keys reach the limit, on both backends. JE has the same hot keys,
but there a writer waits for the lock. On PDB it is rolled back. No result-80 failure happens after the knee.

Why 10 attempts are not enough on PDB

Before the knee the PDB run made about 11.7k writes, and 6 of them spent the cap. That is 5·10⁻⁴, which puts the
chance of losing one attempt at about 0.47, assuming the attempts are independent. Ten attempts take about 2.8 s on
the backoff ladder, matching the 1.7–3.9 s in the failure messages. The 10 s window alone would allow about 24
attempts, and 0.47²⁴ ≈ 10⁻⁸.

This is not specific to the benchmark. A value shared by fewer than 4000 entries keeps its key defined, and so hot,
for good. Examples are objectClass: inetOrgPerson in a directory of up to 4000 users, or an indexed attribute with
few distinct values (l, departmentNumber, …). Since #937, any concurrent ADD or DELETE in such a directory on PDB
can fail with result 80.

Where the 10 comes from

The pair of 10 attempts and a 10 s window was introduced by #867 for JDBCStorage, to replay deadlocks. Its stated
reason was that the database may be shared with writers outside this server, so a conflict is not guaranteed to
clear. #937 copied the pair into PDBStorage for #921, and #1065 copied it into JEStorage. None of them measured
the count. #867's reason does not apply to PDB, an embedded store that only this server writes.

The cap is harmless on JE and harmful on PDB because the engines resolve a conflict differently:

• JE uses two-phase locking. A writer waits for the lock (je.lock.timeout is 0, without limit), takes it and
  carries on in the same transaction. Only a deadlock victim has to replay.
• persistit uses snapshot isolation. A writer that meets an uncommitted version of a key also waits for the other
  transaction to end, up to SharedResource.DEFAULT_MAX_WAIT_TIME. If that transaction commits, the writer's snapshot
  is stale and persistit has to roll it back (first committer wins). It cannot carry on after the wait. Running the
  transaction again is the only way through.

On PDB a rollback is the normal resolution of a conflict, not a failure. A cap of 10 attempts means "lose the race
for a hot key no more than 10 times in a row".

Direction

• Drop the attempt cap from PDBStorage.write(), so that only the wall-clock window can end a replay.
• Make the window a property of pdb-backend, applied without a restart. Its default is 0, meaning no limit, like
  JE's je.lock.timeout=0. That is the behaviour before [#921] Bound the transaction replay of PDBStorage.write() #937 for every write.
• An operator who wants a bounded stall on the configuration change paths (PDBStorage.write() replays a rolled-back transaction without any bound, and configuration changes hold an entry container's exclusive lock across it #921) sets the window. With the default,
  those paths wait as long as the conflict lasts, like a JE writer waiting for a lock. Under the exclusive lock no
  user write reaches the suffix's trees, so a conflict there has to come from shared structures and is short-lived.
  Each rollback in persistit also means another transaction committed, so the system as a whole keeps making progress.
• Reword the contract of Storage.write(). Since [#921] Bound the transaction replay of PDBStorage.write() #937 it says "A replay must be bounded". It should say that a
  replay may be unbounded unless a bound is configured.
• Rewrite the tests that pin MAX_RETRIES (testWriteGivesUpAfterTheAttemptCap and the backoff test). Add a test
  that fails on master: with the default configuration, a write that loses more than 10 fast conflicts still
  commits.

The JE vs PDB benchmark should then show no result-80 failures on PDB. The knee at 4000 live entries stays, since
it comes from how index keys are stored, not from this bug.

The error lines the step log does not show are a separate defect of the benchmark script, filed as #1150.