[#915] Bound the wait of a write transaction for a row lock another session holds

[vharseko]

Fixes #915, and with it #903 on the three engines that have a setting for this wait.

Rebased onto master now that #936 and #904 are in: the diff is the change alone, in one commit. armLockBound() is #936's withDdlLockBound() split into an arm and a release, so that a bound can be held around a whole transaction rather than around one statement; how the change sits on #904 is its own section below.

Problem

JDBCStorage.write() bounds its replays twice - by MAX_RETRIES and by a 10 s wall-clock window - and a clock bounds replays only while an attempt is shorter than it. What makes an attempt long is the lock wait ahead of the conflict, charged to the attempt that hit it, and nothing this backend sets ends that wait:

• LOCK_TIMEOUT is -1 on sql server, lock_timeout is 0 on postgres, and oracle's row-lock enqueue is unlimited;
• mysql bounds it itself, at innodb_lock_wait_timeout - 50 s, five times the window, which as far as the window is concerned is the same thing.

So an attempt alone outlasts the window and the operation gets no replay at all, however transient its conflict. That is #903, and the CI failure it was filed on: a sql server deadlock victim picked ~12 s into the first attempt of testConcurrentWritersInsertingDistinctKeys.

StatementBound.OPERATION does bound such a statement today, at 120 s - twelve times the window, and its failure is a cancel that isConflict() does not match, so it is not replayed either.

Change

org.openidentityplatform.opendj.jdbc.row.lock.timeout, in seconds, default 3. The session of a write attempt is told to give up on a row lock at that value, and is given its own value back before the connection goes back to the pool. 0 or negative leaves the wait exactly where it was; a value that is not a number keeps the default, and one past MAX_BOUND_SECONDS is clamped, through the same boundSeconds() every bound of this backend reads.

The default is a third of the window on purpose: an attempt that ends at this bound spends that much of it, so the replays a conflicted write gets are the window divided by this value - three at both defaults. A bound at or past the window leaves exactly one attempt, which is the shape #903 describes; the suite asserts that invariant rather than leaving the two constants to drift apart.

Per engine, in the unit its own setting takes:

Engine	read back first	set around the transaction	put back afterwards
PostgreSQL	nothing	a savepoint, then set local lock_timeout = <ms>	nothing - a set local goes with the transaction
MySQL	select @@session.innodb_lock_wait_timeout	set session innodb_lock_wait_timeout = <s>	the value read back
SQL Server	select @@lock_timeout	set lock_timeout <ms>	the value read back
Oracle	nothing	nothing	—

MySQL gets innodb_lock_wait_timeout and never lock_wait_timeout. The first is the row lock a write waits for; the second is the metadata lock a DDL waits for, which is what #936 sets and which bounds nothing of this. Two settings, two defaults - the issue names Dialect.lockTimeoutSql as if it already carried this statement for all four engines, and on this engine it carries the other one.

Oracle is left alone because it has nothing to set. ddl_lock_timeout is the DDL lock, distributed_lock_timeout the distributed transaction, and the only place the wait of plain DML can be named is select ... for update wait n, which this backend does not issue. An attempt there stays bounded by StatementBound.OPERATION alone, whose cancel a session blocked in that enqueue does not act on - what ends such a wait is the socket read timeout, which takes the connection with it. On oracle what answers #903 is therefore not this property but the grant of #904 (see below), and the property's javadoc says so rather than implying four engines are fixed.

The bound is scoped to the transaction, never left on the pooled session. That is the placement #936 rejected for the DDL and rejects here for the same reason: postgres and sql server bound every lock wait of a session, and a read borrowing the connection next replays nothing at all, deliberately (ExportJob and VerifyJob are not idempotent), so it would see the 55P03 or the error 1222 as a hard failure. Armed after the connection is borrowed and taken off in the finally that closes the stamp and catalog sessions - after the rollback of a failed attempt, before the release hands the connection on.

A lock timeout is replayable only where this backend bounded that wait. 55P03 and error 1222 are no conflict: the engine rolled nothing back and the blocker is still holding the lock. What makes them replayable is the rollback write() issues before it asks, and what makes them worth replaying is that the wait they cost fits inside the window. Where nothing bounded that wait - the property at 0, oracle, a session that would not take the setting - they stay exactly as unreplayable as they were: a bound an operator set for themselves is not a licence for this loop to take that wait again. ArmedLockBound.bounded is that answer, and replayReason() reads it rather than re-deriving it from the property. Such a failure is deliberately no class of #904's Conflict: its verdict stays NONE, so it is replayed on the window alone and never granted past it.

A mysql lock wait timeout arrives in class 40 and stays the conflict it has been since #867; it is now reported at 3 s instead of 50 s, so it is replayed within the window rather than never.

The readback is paid once per pooled connection. This bound is armed around every write of the server where the DDL bound is armed around an open, so the value a session carries is remembered on the CachedConnection: only this backend writes that setting, every write puts it back, and a connection whose restore failed is kept out of the pool - so a remembered value cannot outlive the session that answered it. The DDL bound still reads every time, because it runs inside a write that may be carrying this bound on the very same setting (sql server has one LOCK_TIMEOUT for both). What a write costs on top of what it cost before is two round trips on mysql and sql server, one plus a savepoint on postgres, none on oracle.

One mechanism, two bounds. LockBound is the enum of the waits this backend bounds - DDL and ROW - carrying the property, the default and what each engine is told; armLockBound()/releaseLockBound() are #936's helper split in two, and withDdlLockBound() is now three lines over them. The warn-once latches are per bound rather than per storage: reported through one latch, the first open that could not take its bound would silence every write of that backend.

What it costs a deployment

A write blocked behind a long writer of another session now fails once the window is spent, where it used to wait as long as it took and then succeed. That is the trade this bound is, and it is the reason the property exists: an operation held for the length of somebody else's transaction cannot be told from one that is never coming back, and the caller of a write is an LDAP client with a timeout of its own. A deployment that would rather wait sets the property to 0 and keeps the old behaviour - #903 along with it.

What it does not change

• the failure a caller finally sees, where the replays run out: it is the engine's own 55P03 / 1222 / class 40, as before. The DDL rewrite that names the property is [#885] Bound the wait of a JDBC DDL for a lock another session holds #936's and stays on the DDL path - naming a property in a failure whose transaction did minutes of work before it queued would claim more than the elapsed time can prove;
• read(), which arms no bound and replays nothing;
• the importer and every StatementBound.BULK statement - clearTree()'s delete from among them - which take row locks and are deliberately left waiting;
• MAX_RETRIES, RETRY_WINDOW_NANOS and the retry delay, all unchanged. RETRY_WINDOW_NANOS is package-private now, so the suite can assert the one invariant tying the two constants together.

Relationship to #904

#904 is the other answer to #903, and it landed first: it grants the first replay of a prompt conflict because "no clock can bound a wait that nothing else bounds". This PR sits on its machinery rather than beside it and leaves all of it in place - the Conflict classes, the one walk of conflictVerdict(), replayableWithin() and grantedPastTheWindow().

The two fit together like this. A wait this backend bounded ends in a failure that is no conflict - 55P03, error 1222 - so its verdict is Conflict.NONE: replayReason() replays it on the strength of ArmedLockBound.bounded, and replayableWithin() then holds it to the window with no grant, since the grant exists for the waits nothing bounds and this one is not. A mysql lock wait timeout stays AFTER_LOCK_WAIT, refused the grant as before, and now arrives at 3 s rather than 50 s, so the window governs it. What the grant is left with is exactly what this bound does not reach - oracle, the property at 0, a session that would not take the setting, and a driver dialectOf() does not recognise, under which nothing is armed - where the wait is as unbounded as it was when #904 was written, and one replay past the window is what remains of #903's answer there.

#904's comments described #915 as a future change - "#915 adds one" class, "#915 removes the trade", "#915 retires this method" - and they are brought up to date here rather than left describing a plan that did not happen: the row lock wait is no Conflict class, the trade of UNKNOWN_ENGINE stays because the bound arms nothing under an unrecognised driver, and the grant is kept rather than retired, for the engines and settings above. Nothing of #904's behaviour changes: its cases in JDBCStorageRetryTest pass as they are, the test-side replayReason() helper handing the widened signature the bound its cases were written under.

Testing

JDBCRowLockBoundTestCase - 26 cases, no database: what each engine is told and in what order, the property and every misconfiguration of it, a session already tighter (mysql at 1, sql server at 0 against its -1), a session that will not say what it carries, a setting refused, a restore that fails and the connection kept out of the pool, postgres in auto-commit and the savepoint in front of the setting, the readback paid once per pooled connection and every time off it, and the replay verdict for a lock timeout with and without a bound of ours - including one reported by commit(), one on an attempt that had committed part of its work, and one read from the release of the connection.

JDBCStorageRetryTest - two cases driving write() end to end through the stub driver: a 55P03 replayed with the bound armed once per attempt, and the same failure not replayed with the property at 0. Its existing cases, #904's among them, pass the bound they were written under (ArmedLockBound.none) through the test's own replayReason() helper, which composes the verdict the way write() does.

JDBCDdlLockBoundTestCase - one expectation updated: the drop of a tree now runs inside a write that arms this bound first, so the set local lock_timeout = 3000 of the attempt precedes the search path and the DDL bound of that case.

TestCase - the container suites of all four engines get testAWriteBlockedByARowLockIsReplayedInsideTheWindow: another session takes an exclusive lock on the row a write wants and lets it go after twice the bound. The write must give up on its first attempt and go through on its replay, both inside the window - and on oracle, which has no setting for that wait, it must go through on the first attempt instead, which is the one place the difference this bound makes can be read. assertBoundedWhileRowsAreLocked - the harness of the two statement-bound cases of #877 - turns this property off while it runs, since a bound tighter than the one under test is what would end their wait.

mvn -o -pl opendj-server-legacy -Pprecommit \
    -Dit.test='JDBCRowLockBoundTestCase,JDBCDdlLockBoundTestCase,JDBCStorageRetryTest,JDBCStatementBoundTestCase' \
    -Dfailsafe.failIfNoSpecifiedTests=false verify

The javadoc goal is deliberately not skipped in that command. attach-javadocs runs on every leg of the build workflow, for every module, under the root pom's doclint=all,-missing and failOnWarnings=true - and at an earlier head a @link still naming the five-parameter replayReason() this branch widened is what took build-maven (macos-latest, 11) and (windows-latest, 26) down. Those two legs only failed first: -P precommit is set on Linux alone, so they reach this module's package phase in ~2.5 min while the ubuntu legs are still in integration tests, which would have failed on the same line.

At the rebased head, with the javadoc goal on: the four suites above, 210 run, 0 failures - and the postgres and mysql container suites, the case above giving up at the bound and replaying on both:

PgSqlTestCase   82 run, 0 failures   (the case: 4.10 s)
MySqlTestCase   81 run, 0 failures   (4.26 s)

All four container suites were run at the head before the rebase, oracle waiting the holder out on its first attempt; sql server and oracle are left to CI at this one:

PgSqlTestCase   82 run, 0 failures   (the case: 4.34 s)
MySqlTestCase   81 run, 0 failures   (4.20 s)
MsSqlTestCase   81 run, 0 failures   (4.13 s)
OracleTestCase  81 run, 0 failures, 1 skipped - #936's own DDL case, which oracle is left out of   (4.53 s)

Four mutants, each measured at the head before the rebase - the code they mutate is what the rebase carried over unchanged:

• mysql told the metadata lock instead of the row lock (lock_wait_timeout for innodb_lock_wait_timeout) -> 3 failures, among them mysql bounds the row lock, not the metadata lock;
• replayReason ignoring bounded -> 3 failures, including a wait this backend put no bound on was replayed on a clock that cannot bound it and the end-to-end testARowLockWaitNothingBoundedIsNotReplayed;
• write() arming nothing -> 2 failures, the end-to-end replay and the statement order of the drop case;
• the release never putting the value back -> 12 failures across both bound suites, a connection left carrying our bound was handed back to the pool among them.

[vharseko]

The two red legs were maven-javadoc-plugin:attach-javadocs on opendj-server-legacy, not the change under review:

JDBCStorage.java:3901: error: reference not found
 * {@link #replayReason(Throwable, String, boolean, boolean, boolean)}.

replayReason() grew a Dialect and an ArmedLockBound in this branch, and the fully qualified @link in write()'s javadoc still named the five-parameter signature - the one that resolves on master. The line itself is unchanged, so it sits in the diff as context, which is how it got past me.

Fixed in 5b1db9a by reducing it to the bare {@link #replayReason} the other three references in this file already use: there is no overload to disambiguate, and it does not rot the next time the signature moves.

Two things worth recording, because the failure reads as platform-specific and is not:

• attach-javadocs is bound in the root pom for every module and runs on every leg, under doclint=all,-missing and failOnWarnings=true. macOS and Windows only failed first: -P precommit is set on Linux alone, so they reach this module's package phase in ~2.5 min while the ubuntu legs are still in integration tests. The ubuntu legs of that run were queued, not green, and would have failed on the same line. (Set Aggregate Javadoc Goal is the Linux/java-11 step, so if anything ubuntu runs more javadoc than the legs that caught this, not less.)
• -Dmaven.javadoc.skip=true in the Testing command of the description is what hid it locally. Dropped from the description, together with a stale 24 cases for JDBCRowLockBoundTestCase - the suite reports 26.

Verified locally under JDK 11 against the same plugin configuration:

run	result
the broken link put back, mvn -o -pl opendj-server-legacy package	BUILD FAILURE - JDBCStorage.java:3901: error: reference not found, the CI error verbatim
as pushed, same command	BUILD SUCCESS, no javadoc error, ...-javadoc.jar built
as pushed, -Pprecommit -Dit.test=JDBCRowLockBoundTestCase ... verify, javadoc not skipped	Tests run: 26, Failures: 0, Errors: 0, Skipped: 0, BUILD SUCCESS

The first row is there on purpose: without it a green run only proves the build passed, not that it ran the reference check at all.

[vharseko]

Rebased onto master, which now carries both #936 and #904: one commit, 9b167eb, and the diff is the change alone - the "sits on top of #936" preamble of the description is gone with it.

What the rebase had to decide is how this bound sits on #904, which landed first. Nothing of #904 is changed or removed. A wait this backend bounded ends in a failure that is no conflict - 55P03, error 1222 - so its verdict is Conflict.NONE: replayReason() replays it on ArmedLockBound.bounded, and replayableWithin() then holds it to the window with no grant. grantedPastTheWindow() is kept for exactly what this bound does not reach - oracle, the property at 0, a session that would not take the setting, a driver dialectOf() does not recognise - where the wait is as unbounded as it was when #904 was written. The four comments of #904 that described #915 as a future change ("#915 adds one" class, "#915 removes the trade", "#915 retires this method") are brought up to date with what actually happened, and the description has a rewritten "Relationship to #904" section saying the same. MAX_RETRY_WINDOW_NANOS of this branch is #904's RETRY_WINDOW_NANOS, package-private for the same one invariant.

Also carried over: the RuntimeException catch #936's last round put into withDdlLockBound() (9cc5a0e), kept across the split into armLockBound()/releaseLockBound().

At this head, JDK 11, javadoc goal on:

run	result
JDBCRowLockBoundTestCase 26, JDBCDdlLockBoundTestCase 39, JDBCStorageRetryTest 101, JDBCStatementBoundTestCase 44	210 run, 0 failures, BUILD SUCCESS
PgSqlTestCase 82, MySqlTestCase 81	0 failures; the new case 4.1 s / 4.3 s, giving up at the bound and replaying

sql server and oracle are left to CI at this head; both were green at the one before the rebase.