diff --git a/opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-tuning.adoc b/opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-tuning.adoc index aa14039150..bf0a5c195d 100644 --- a/opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-tuning.adoc +++ b/opendj-doc-generated-ref/src/main/asciidoc/admin-guide/chap-tuning.adoc @@ -248,6 +248,8 @@ Import task 20120917100628767 scheduled to start Sep 17, 2012 10:06:28 AM CEST ---- If write traffic to your directory service occurs in short bursts, and you use database backends of type `pdb`, you can potentially improve short-term performance during the bursts by increasing the `db-checkpointer-wakeup-interval` setting. This setting specifies the maximum length of time between attempts to write a checkpoint to the journal. Longer intervals allow more updates to accumulate in buffers before they are required to be written to disk. The transaction log is still written to disk, but the modified pages are kept in memory longer before being written. Longer intervals potentially cause recovery from an abrupt termination to take more time. +Database backends of type `pdb` resolve two concurrent updates of the same record by rolling one of them back and running it again. This is routine under concurrent write load, for example while index keys shared by many entries, such as their object classes, hold fewer entries than the index entry limit. By default, an update is run again for as long as it keeps being rolled back. The `db-txn-retry-time-limit` setting bounds that time: once it is spent, the operation fails with result code 80 (`other`). Set it only when a bounded wait matters more than the update, for example while you change the indexes or base DNs of a busy backend, which hold their suffix exclusively while they write. The change takes effect without a restart. + [#perf-import] ==== LDIF Import Settings diff --git a/opendj-maven-plugin/src/main/resources/config/xml/org/forgerock/opendj/server/config/PDBBackendConfiguration.xml b/opendj-maven-plugin/src/main/resources/config/xml/org/forgerock/opendj/server/config/PDBBackendConfiguration.xml index 9f8b1b57c2..6181e645f1 100644 --- a/opendj-maven-plugin/src/main/resources/config/xml/org/forgerock/opendj/server/config/PDBBackendConfiguration.xml +++ b/opendj-maven-plugin/src/main/resources/config/xml/org/forgerock/opendj/server/config/PDBBackendConfiguration.xml @@ -194,6 +194,42 @@ + + + Specifies how long a write transaction which the database rolled back is + run again before the operation which issued it fails. + + + Persistit resolves two transactions which write the same record by rolling + one of them back once the other commits, and the transaction rolled back is + then run again. Under concurrent writes this is routine rather than a + failure: every entry added or deleted rewrites the index keys it shares + with other entries, such as its object classes, for as long as those keys + hold fewer entries than the index entry limit. A value of 0 runs the + transaction again for as long as it keeps being rolled back, the way a + writer of a JE backend waits for a lock. A positive value bounds that time: + once it is spent, the operation fails with the result code "other". The + bound is checked between two runs of the transaction, so a single run can + outlast it, and a transaction rolled back is always run once more. A bound + matters to the configuration changes of an index or of a base DN, which + write while they hold their suffix exclusively, so that every operation on + that suffix waits for them. Changes to this property take effect with the + next write transaction. + + + + 0s + + + + + + + + ds-cfg-db-txn-retry-time-limit + + + Low disk threshold to limit database updates diff --git a/opendj-server-legacy/resource/schema/02-config.ldif b/opendj-server-legacy/resource/schema/02-config.ldif index 029d64d123..1d2612dd9c 100644 --- a/opendj-server-legacy/resource/schema/02-config.ldif +++ b/opendj-server-legacy/resource/schema/02-config.ldif @@ -4112,6 +4112,12 @@ attributeTypes: ( 1.3.6.1.4.1.60142.2.1.1.1 SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 SINGLE-VALUE X-ORIGIN 'OpenDJ Directory Server' ) +attributeTypes: ( 1.3.6.1.4.1.60142.2.1.1.2 + NAME 'ds-cfg-db-txn-retry-time-limit' + EQUALITY caseIgnoreMatch + SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 + SINGLE-VALUE + X-ORIGIN 'OpenDJ Directory Server' ) objectClasses: ( 1.3.6.1.4.1.26027.1.2.1 NAME 'ds-cfg-access-control-handler' SUP top @@ -5970,7 +5976,8 @@ objectClasses: ( 1.3.6.1.4.1.36733.2.1.2.23 ds-cfg-db-txn-no-sync $ ds-cfg-disk-full-threshold $ ds-cfg-disk-low-threshold $ - ds-cfg-db-checkpointer-wakeup-interval ) + ds-cfg-db-checkpointer-wakeup-interval $ + ds-cfg-db-txn-retry-time-limit ) X-ORIGIN 'OpenDJ Directory Server' ) objectClasses: ( 1.3.6.1.4.1.36733.2.1.2.24 NAME 'ds-cfg-backend-index' diff --git a/opendj-server-legacy/src/main/java/org/opends/server/backends/pdb/PDBStorage.java b/opendj-server-legacy/src/main/java/org/opends/server/backends/pdb/PDBStorage.java index cdcccf895e..ed60bc1310 100644 --- a/opendj-server-legacy/src/main/java/org/opends/server/backends/pdb/PDBStorage.java +++ b/opendj-server-legacy/src/main/java/org/opends/server/backends/pdb/PDBStorage.java @@ -104,27 +104,6 @@ public final class PDBStorage implements Storage, Backupable, ConfigurationChang { private static final int IMPORT_DB_CACHE_SIZE = 32 * MB; - /** - * Number of attempts a {@link WriteableStorageImpl#write} makes before it propagates the conflict to the caller. - *

- * It is a budget of attempts and not of time, so it is only ever reached by the conflicts that report quickly. - * PersistIt reports a write-write conflict only once it has waited on it, up to - * {@code SharedResource.DEFAULT_MAX_WAIT_TIME} - a minute, which this backend never lowers - so a conflict slower - * to report than {@link #MAX_RETRY_WINDOW_NANOS} spends the whole window inside its first attempt, is granted the - * single replay that window's exemption guarantees, and gives up on the window after two attempts rather than - * after this many. - */ - static final int MAX_RETRIES = 10; - - /** - * Wall-clock budget the replays of a {@link WriteableStorageImpl#write} may spend, in nanoseconds. It is checked - * between attempts, so an attempt already running is never interrupted, and never before one replay has been - * made: the loop returns after at most this window plus two attempts. It bounds the conflicts that are slow to - * report, which {@link #MAX_RETRIES} alone does not - an operation whose own work takes seconds would otherwise - * multiply that wait by the attempt count. - */ - static final long MAX_RETRY_WINDOW_NANOS = 10L * 1000L * 1000L * 1000L; //10 s - /** * Upper bound of the random delay before the second attempt, in milliseconds; it doubles with every attempt. This * is the bound of the flat sleep this loop took before it was bounded, so the first replay is delayed exactly as @@ -135,6 +114,10 @@ public final class PDBStorage implements Storage, Backupable, ConfigurationChang /** Upper bound the doubled delay is capped at, in milliseconds. */ private static final double MAX_SLEEP_ON_RETRY_MS = 1000.0; + /** Name of the property which bounds the replays of a {@link WriteableStorageImpl#write}, for the reports of it. */ + private static final String RETRY_TIME_LIMIT_PROPERTY = + PDBBackendCfgDefn.getInstance().getDBTxnRetryTimeLimitPropertyDefinition().getName(); + private static final String VOLUME_NAME = "dj"; private static final String JOURNAL_NAME = VOLUME_NAME + "_journal"; /** The buffer / page size used by the PersistIt storage. */ @@ -671,7 +654,10 @@ public void write(WriteOperation operation) throws Exception { final Transaction txn = db.getTransaction(); final long startedAt = System.nanoTime(); - final long giveUpAt = startedAt + retryWindowNanos; + //read once, so that a change of the property applies from the next write on rather than to one in flight; + //0 replays for as long as the conflict lasts + final long retryTimeLimitMs = config.getDBTxnRetryTimeLimit(); + final long giveUpAt = startedAt + TimeUnit.MILLISECONDS.toNanos(retryTimeLimitMs); for (int attempt = 1;; attempt++) { final RollbackException conflict; @@ -705,24 +691,26 @@ public void write(WriteOperation operation) throws Exception // decided and slept for outside the try statement: the sleep used to run before the finally ended the // rolled back transaction, holding it open for the whole backoff and lengthening the window every other // writer collides with + //Bounded by time alone, and not by a count of attempts: a rollback is how persistit resolves two + //transactions writing the same key - it waits for the other one to end and rolls this one back if that + //one committed - so under concurrent writes to a hot key, such as an index key shared by entries below + //the index entry limit, a healthy write loses several of these races in a row (#1149) //System.nanoTime() - giveUpAt is the overflow safe form of the comparison, and attempt > 1 keeps the - //window from ending the loop before a single replay: persistit reports a write-write conflict only once + //limit from ending the loop before a single replay: persistit reports a write-write conflict only once //it has waited on it, up to SharedResource.DEFAULT_MAX_WAIT_TIME - a minute, which this backend never - //lowers - so one attempt can outlast the window on its own, and it is the attempt after that one which + //lowers - so one attempt can outlast the limit on its own, and it is the attempt after that one which //is likeliest to succeed, the transaction that blocked it having just finished //one clock sample for both, so that the elapsed time reported is the one the give up was decided on final long now = System.nanoTime(); - final boolean capSpent = attempt >= maxRetries; - if (capSpent || (attempt > 1 && now - giveUpAt >= 0)) + if (retryTimeLimitMs > 0 && attempt > 1 && now - giveUpAt >= 0) { final long elapsedMs = TimeUnit.NANOSECONDS.toMillis(now - startedAt); - //which of the two bounds was spent, so that the config change paths - which report this as the trailing - //cause of a message of their own - say whether raising the attempts or the window is what would have helped - final String boundSpent = capSpent ? "attempt cap" : "retry window"; + //names the property, so that the config change paths - which report this as the trailing cause of a + //message of their own - say what would have helped final StorageRuntimeException spent = new StorageRuntimeException( "pdb: backend '" + config.getBackendId() + "' did not apply the transaction after " + attempt - + " attempts in " + elapsedMs + " ms, the " + boundSpent + " being spent; the last conflict was " - + conflict); + + " attempts in " + elapsedMs + " ms, the " + RETRY_TIME_LIMIT_PROPERTY + " of " + retryTimeLimitMs + + " ms being spent; the last conflict was " + conflict); // the conflict is suppressed rather than made the cause, because a cause is what every caller strips // this message off with: write(WriteOperation) below unwraps a StorageRuntimeException that carries one // and throws the cause in its place, and EntryContainer.throwAllowedExceptionTypes:1121 rethrows a @@ -732,17 +720,17 @@ public void write(WriteOperation operation) throws Exception spent.addSuppressed(conflict); //warned once, at exhaustion only, unlike JDBCStorage which warns on every replay: a conflict is routine //on the ordinary add and modify path of this engine and a line per replay would flood the log. It names - //the bound that was spent for the same reason the exception does, and it is the only rendering that can - //carry the stack of the conflict: stackTraceToSingleLineString, the form the config change paths report - //this exception with, walks the causes and never prints a suppressed exception + //the property that was spent for the same reason the exception does, and it is the only rendering that + //can carry the stack of the conflict: stackTraceToSingleLineString, the form the config change paths + //report this exception with, walks the causes and never prints a suppressed exception logger.warn(LocalizableMessage.raw("pdb: giving up on the transaction of backend '%s' after %d attempts" - + " in %d ms, the %s being spent: %s", config.getBackendId(), attempt, elapsedMs, boundSpent, - stackTraceToSingleLineString(conflict))); + + " in %d ms, the %s of %d ms being spent: %s", config.getBackendId(), attempt, elapsedMs, + RETRY_TIME_LIMIT_PROPERTY, retryTimeLimitMs, stackTraceToSingleLineString(conflict))); throw spent; } if (logger.isTraceEnabled()) { - logger.trace("pdb: replaying the transaction after %s, attempt %d of %d", conflict, attempt, maxRetries); + logger.trace("pdb: replaying the transaction after %s, attempt %d", conflict, attempt); } try { @@ -1030,10 +1018,6 @@ private StorageImpl newStorageImpl() { private long configuredCacheSize; private long reservedCacheSize; private StorageStatus storageStatus = StorageStatus.working(); - /** Attempt bound of a {@link WriteableStorageImpl#write}, {@link #MAX_RETRIES} outside the tests. */ - private final int maxRetries; - /** Wall-clock bound of a {@link WriteableStorageImpl#write}, {@link #MAX_RETRY_WINDOW_NANOS} outside the tests. */ - private final long retryWindowNanos; /** * Creates a new persistit storage with the provided configuration. @@ -1046,35 +1030,8 @@ private StorageImpl newStorageImpl() { */ // FIXME: should be package private once importer is decoupled. public PDBStorage(final PDBBackendCfg cfg, ServerContext serverContext) throws ConfigException - { - this(cfg, serverContext, MAX_RETRIES, MAX_RETRY_WINDOW_NANOS); - } - - /** - * Creates a new persistit storage whose replay bounds are the given ones rather than {@link #MAX_RETRIES} and - * {@link #MAX_RETRY_WINDOW_NANOS}. - *

- * Only a test builds one of these, and it does so to stop the two bounds racing each other: with the shipped - * values a run of replays spends a random share of the window on backoff alone, so a test of the attempt cap - * can be ended by the window on a loaded machine, and a test of the window has to spend seconds of build time - * to reach it. - * - * @param cfg - * The configuration. - * @param serverContext - * This server instance context - * @param maxRetries - * Number of attempts a write makes before it propagates the conflict to the caller. - * @param retryWindowNanos - * Wall-clock budget the replays of a write may spend, in nanoseconds. - * @throws ConfigException if memory cannot be reserved - */ - PDBStorage(final PDBBackendCfg cfg, ServerContext serverContext, int maxRetries, long retryWindowNanos) - throws ConfigException { this.serverContext = serverContext; - this.maxRetries = maxRetries; - this.retryWindowNanos = retryWindowNanos; backendDirectory = getBackendDirectory(cfg); runningDirectoryPermissions = cfg.getDBDirectoryPermissions(); config = cfg; @@ -1293,15 +1250,17 @@ public Importer startImport() throws ConfigException, StorageRuntimeException /** * {@inheritDoc} *

- * A transaction the engine rolled back is replayed, bounded twice: by {@link #MAX_RETRIES} attempts and by the - * {@link #MAX_RETRY_WINDOW_NANOS} wall-clock window, whichever is spent first - except that the window alone - * never ends the replays before one has been made. It is bounded because the - * configuration change paths of the pluggable backend hold an entry container's exclusive lock across this - * method, and every reader of that suffix then waits - untimed and uninterruptibly - until it returns, so a - * conflict that never clears would park every worker thread of that suffix rather than fail one operation. + * A transaction the engine rolled back is replayed for as long as the {@code db-txn-retry-time-limit} of the + * backend allows - without limit when it is 0, its default - except that the limit never ends the replays before + * one has been made. A rollback is how persistit resolves two transactions writing the same key, so a healthy + * write under concurrent load can lose several of them in a row: a count of attempts failed such writes (#1149), + * and the replays are bounded by time alone. Without a limit a write waits for its conflict to clear the way a + * JE writer waits for a lock. A limit is for the configuration change paths of the pluggable backend, which hold + * an entry container's exclusive lock across this method: every reader of that suffix then waits - untimed and + * uninterruptibly - until it returns. *

- * Once the bound is spent the conflict is reported as a {@link StorageRuntimeException} naming the backend, the - * attempts spent, the time they took and which of the two bounds ran out. It carries the conflict as a + * Once the limit is spent the conflict is reported as a {@link StorageRuntimeException} naming the backend, the + * attempts spent, the time they took and the property whose value ran out. It carries the conflict as a * suppressed exception rather than as its cause: a cause is unwrapped below and thrown in its place, and * {@code EntryContainer.throwAllowedExceptionTypes} likewise passes a {@link StorageRuntimeException} through * untouched only while it has no cause. Given a cause, both hand the caller a bare RollbackException instead, diff --git a/opendj-server-legacy/src/main/java/org/opends/server/backends/pluggable/spi/Storage.java b/opendj-server-legacy/src/main/java/org/opends/server/backends/pluggable/spi/Storage.java index 2164d2efc1..58837866ca 100644 --- a/opendj-server-legacy/src/main/java/org/opends/server/backends/pluggable/spi/Storage.java +++ b/opendj-server-legacy/src/main/java/org/opends/server/backends/pluggable/spi/Storage.java @@ -75,10 +75,12 @@ public interface Storage extends Closeable /** * Executes a write operation. In case of a write operation rollback, implementations may replay the write * operation rather than propagate the failure: a {@link WriteOperation} is required to be idempotent for - * exactly that reason. A replay must be bounded - by a number of attempts, by a window of time, or by both - - * so that a conflict which does not clear reaches the caller instead of being retried forever. The pluggable - * backend holds locks across this method, up to the exclusive lock of an entry container, and every thread - * waiting on one of those locks waits for as long as this method does. + * exactly that reason. A replay may be bounded - by a number of attempts, by a window of time, or by both - so + * that a conflict which does not clear reaches the caller, or may go on for as long as the conflict lasts, the + * way a writer of a lock based engine waits for a lock; an engine which resolves every conflict by a rollback + * should bound it by time only, since a healthy write under concurrent load loses several in a row. The + * pluggable backend holds locks across this method, up to the exclusive lock of an entry container, and every + * thread waiting on one of those locks waits for as long as this method does. *

* A caller that mutates state around this method must handle that bound being spent. Removing an entry from an * in-memory map before the write so that a replay still finds the work to do, or reading configuration back out diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/pdb/PDBStorageTest.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/pdb/PDBStorageTest.java index 7a40fb49f9..2b82cff580 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/pdb/PDBStorageTest.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/pdb/PDBStorageTest.java @@ -71,12 +71,12 @@ public class PDBStorageTest extends DirectoryServerTestCase { - /** A window no run of replays can spend, so that a test of the attempt cap is only ever ended by the cap. */ - private static final long UNREACHABLE_RETRY_WINDOW_NANOS = 300L * 1000L * 1000L * 1000L; //5 min - /** A window a single attempt outlasts, so that a test of the window reaches it without seconds of build time. */ - private static final long SHORT_RETRY_WINDOW_NANOS = 200L * 1000L * 1000L; //200 ms - /** An attempt long enough to outlast {@link #SHORT_RETRY_WINDOW_NANOS} on its own, in milliseconds. */ - private static final long ATTEMPT_LONGER_THAN_SHORT_WINDOW_MS = 300; + /** A retry time limit a single attempt outlasts, so that a test of the limit reaches it in under a second. */ + private static final long SHORT_RETRY_TIME_LIMIT_MS = 200; + /** An attempt long enough to outlast {@link #SHORT_RETRY_TIME_LIMIT_MS} on its own, in milliseconds. */ + private static final long ATTEMPT_LONGER_THAN_SHORT_LIMIT_MS = 300; + /** The attempt cap #937 shipped, which ordinary concurrent writes spent (#1149). */ + private static final int FORMER_ATTEMPT_CAP = 10; /** The buffer pool {@link #testCanAddLargeValues()} writes through, well under the 20% of the other methods. */ private static final long LARGE_VALUES_DB_CACHE_SIZE = 16L * MB; @@ -151,19 +151,35 @@ private static void closeAndRemove(PDBStorage storage) } } - /** - * Replaces the storage under test with one bounded by the given values, so that the bound a test is about is - * the one that ends its replays. With the shipped values the two race: the nine backoffs of a full ladder draw - * from 50+100+200+400+800+1000x4, so an attempt cap test can be ended by the ten second window instead, and a - * window test has to make every attempt outlast seconds of that window to reach it. - */ - private void reopenWithReplayBounds(int maxRetries, long retryWindowNanos) throws Exception + /** Replaces the storage under test with one whose db-txn-retry-time-limit is the given one. */ + private void reopenWithRetryTimeLimit(long retryTimeLimitMs) throws Exception { closeAndRemove(storage); - storage = new PDBStorage(createBackendCfg(), serverContext, maxRetries, retryWindowNanos); + storage = new PDBStorage(createBackendCfgWithRetryTimeLimit(retryTimeLimitMs), serverContext); storage.open(AccessMode.READ_WRITE); } + private static PDBBackendCfg createBackendCfgWithRetryTimeLimit(long retryTimeLimitMs) + { + final PDBBackendCfg cfg = createBackendCfg(0L); + when(cfg.getDBTxnRetryTimeLimit()).thenReturn(retryTimeLimitMs); + return cfg; + } + + /** + * Fails an attempt of a conflict that never clears once {@link #SHORT_RETRY_TIME_LIMIT_MS} should long have ended + * the replays, with something other than a rollback: a write that ignores the limit would otherwise replay for as + * long as the default allows, and hang the test rather than fail it. + */ + private static void failIfReplayedPastTheLimit(int attempt) + { + if (attempt > 4) + { + throw new IllegalStateException( + "replayed " + attempt + " times past a retry time limit of " + SHORT_RETRY_TIME_LIMIT_MS + " ms"); + } + } + /** * The sources are wrapped rather than copied, and the storage is reopened with a buffer pool of * {@link #LARGE_VALUES_DB_CACHE_SIZE}: in a JVM of 512 MB each 63 MB array needs a free run of 64 regions, @@ -318,36 +334,36 @@ public void run(WriteableTransaction txn) throws Exception assertThat(storage.getNewExchange(treeName, true)).isNotSameAs(initial); } + /** + * A rollback is how persistit resolves two transactions writing the same key, so a healthy write under concurrent + * load loses several in a row - ADD and DELETE did, on the index keys their entries shared, and failed with + * result 80 once they had lost ten (#1149). With the default configuration, nothing but the conflict clearing + * ends the replays: neither a count of attempts nor a limit of 0 read as a window already spent. + */ @Test - public void testWriteGivesUpAfterTheAttemptCap() throws Exception + public void testWriteOutlastsAnyNumberOfConflictsByDefault() throws Exception { - // the shipped cap, against a window the ladder of backoffs cannot reach: on the shipped window those nine - // backoffs draw from up to 5550 ms, so a loaded machine ends this loop on the window and the cap goes untested - reopenWithReplayBounds(PDBStorage.MAX_RETRIES, UNREACHABLE_RETRY_WINDOW_NANOS); + assertThat(createBackendCfg().getDBTxnRetryTimeLimit()).isZero(); createTree(); - final RollbackException conflict = new RollbackException(); + final int conflicts = FORMER_ATTEMPT_CAP + 1; final AtomicInteger attempts = new AtomicInteger(); - try + storage.write(new WriteOperation() { - storage.write(new WriteOperation() + @Override + public void run(WriteableTransaction txn) throws Exception { - @Override - public void run(WriteableTransaction txn) throws Exception + // written before the conflict, as a rolled back attempt of a real write would have + txn.put(treeName, valueOfUtf8("contended"), valueOfUtf8("attempt " + attempts.incrementAndGet())); + if (attempts.get() <= conflicts) { - attempts.incrementAndGet(); - txn.put(treeName, valueOfUtf8("abandoned"), valueOfUtf8("value")); - throw conflict; + throw new RollbackException(); } - }); - failBecauseExceptionWasNotThrown(StorageRuntimeException.class); - } - catch (StorageRuntimeException e) - { - assertThat(e.getSuppressed()).contains(conflict); - } - assertThat(attempts.get()).isEqualTo(PDBStorage.MAX_RETRIES); - assertThat(read("abandoned")).isNull(); + } + }); + + assertThat(attempts.get()).isEqualTo(conflicts + 1); + assertThat(read("contended")).isEqualTo(valueOfUtf8("attempt " + (conflicts + 1))); } @Test @@ -376,13 +392,13 @@ public void run(WriteableTransaction txn) throws Exception /** * PersistIt reports a write-write conflict only once it has waited on it - up to * {@code SharedResource.DEFAULT_MAX_WAIT_TIME}, a minute, which this backend never lowers - so a single attempt - * can outlast the whole window. Giving up on the window alone would then replay nothing, in the very case where - * the replay is likeliest to succeed: the transaction that was blocking this one has just finished. + * can outlast the whole retry time limit. Giving up on the limit alone would then replay nothing, in the very + * case where the replay is likeliest to succeed: the transaction that was blocking this one has just finished. */ @Test - public void testWriteIsReplayedOnceWhenTheFirstAttemptOutlastsTheWindow() throws Exception + public void testWriteIsReplayedOnceWhenTheFirstAttemptOutlastsTheRetryTimeLimit() throws Exception { - reopenWithReplayBounds(PDBStorage.MAX_RETRIES, SHORT_RETRY_WINDOW_NANOS); + reopenWithRetryTimeLimit(SHORT_RETRY_TIME_LIMIT_MS); createTree(); final AtomicInteger attempts = new AtomicInteger(); @@ -393,7 +409,7 @@ public void run(WriteableTransaction txn) throws Exception { if (attempts.incrementAndGet() == 1) { - Thread.sleep(ATTEMPT_LONGER_THAN_SHORT_WINDOW_MS); + Thread.sleep(ATTEMPT_LONGER_THAN_SHORT_LIMIT_MS); throw new RollbackException(); } txn.put(treeName, valueOfUtf8("outlasted"), valueOfUtf8("written")); @@ -407,11 +423,10 @@ public void run(WriteableTransaction txn) throws Exception @Test public void testExhaustedWriteNamesTheAttemptsItSpent() throws Exception { - // the message is the same at any cap, so this one is spent in two backoffs rather than in the shipped ladder - final int maxRetries = 3; - reopenWithReplayBounds(maxRetries, UNREACHABLE_RETRY_WINDOW_NANOS); + reopenWithRetryTimeLimit(SHORT_RETRY_TIME_LIMIT_MS); createTree(); + final AtomicInteger attempts = new AtomicInteger(); try { storage.write(new WriteOperation() @@ -419,6 +434,8 @@ public void testExhaustedWriteNamesTheAttemptsItSpent() throws Exception @Override public void run(WriteableTransaction txn) throws Exception { + failIfReplayedPastTheLimit(attempts.incrementAndGet()); + Thread.sleep(ATTEMPT_LONGER_THAN_SHORT_LIMIT_MS); throw new RollbackException(); } }); @@ -426,9 +443,9 @@ public void run(WriteableTransaction txn) throws Exception } catch (StorageRuntimeException e) { - assertThat(e.getMessage()).contains("PDBStorageTest").contains(maxRetries + " attempts"); - // and which of the two bounds ran out, since the attempt count alone does not say - assertThat(e.getMessage()).contains("attempt cap"); + assertThat(e.getMessage()).contains("PDBStorageTest").contains("2 attempts"); + // and the property whose value ran out, since that is what an operator would raise + assertThat(e.getMessage()).contains("db-txn-retry-time-limit of " + SHORT_RETRY_TIME_LIMIT_MS + " ms"); // write() unwraps a StorageRuntimeException that carries a cause, which would replace this message with // the bare RollbackException, and it is the message the config change paths report assertThat(e.getCause()).isNull(); @@ -436,11 +453,12 @@ public void run(WriteableTransaction txn) throws Exception } @Test - public void testWriteGivesUpOnTheWindowWhenAttemptsAreSlow() throws Exception + public void testWriteGivesUpOnTheRetryTimeLimitWhenAttemptsAreSlow() throws Exception { - reopenWithReplayBounds(PDBStorage.MAX_RETRIES, SHORT_RETRY_WINDOW_NANOS); + reopenWithRetryTimeLimit(SHORT_RETRY_TIME_LIMIT_MS); createTree(); + final RollbackException conflict = new RollbackException(); final AtomicInteger attempts = new AtomicInteger(); try { @@ -449,9 +467,50 @@ public void testWriteGivesUpOnTheWindowWhenAttemptsAreSlow() throws Exception @Override public void run(WriteableTransaction txn) throws Exception { - attempts.incrementAndGet(); - // a conflict this slow to report spends the wall clock window long before the attempt cap - Thread.sleep(ATTEMPT_LONGER_THAN_SHORT_WINDOW_MS); + failIfReplayedPastTheLimit(attempts.incrementAndGet()); + txn.put(treeName, valueOfUtf8("abandoned"), valueOfUtf8("value")); + Thread.sleep(ATTEMPT_LONGER_THAN_SHORT_LIMIT_MS); + throw conflict; + } + }); + failBecauseExceptionWasNotThrown(StorageRuntimeException.class); + } + catch (StorageRuntimeException e) + { + assertThat(e.getSuppressed()).contains(conflict); + } + // one attempt beyond the first: the first spends the limit, the exemption grants the replay, and the check + // after that replay is the one that gives up - an assertion on the failure alone would also pass for a give up + // on attempt 1, which is the regression the attempt > 1 exemption exists to prevent + assertThat(attempts.get()).isEqualTo(2); + // and what the attempts wrote is rolled back with them + assertThat(read("abandoned")).isNull(); + } + + /** + * The limit is read by every write rather than once by the open, so that an administrator who sets it on a + * running backend - to bound a configuration change about to be made - has it apply without a restart. + */ + @Test + public void testRetryTimeLimitChangedWhileOpenAppliesToTheNextWrite() throws Exception + { + createTree(); + + final ConfigChangeResult ccr = + storage.applyConfigurationChange(createBackendCfgWithRetryTimeLimit(SHORT_RETRY_TIME_LIMIT_MS)); + assertThat(ccr.getResultCode()).isEqualTo(ResultCode.SUCCESS); + assertThat(ccr.adminActionRequired()).isFalse(); + + final AtomicInteger attempts = new AtomicInteger(); + try + { + storage.write(new WriteOperation() + { + @Override + public void run(WriteableTransaction txn) throws Exception + { + failIfReplayedPastTheLimit(attempts.incrementAndGet()); + Thread.sleep(ATTEMPT_LONGER_THAN_SHORT_LIMIT_MS); throw new RollbackException(); } }); @@ -459,12 +518,8 @@ public void run(WriteableTransaction txn) throws Exception } catch (StorageRuntimeException e) { - // the window is what ended it, and it says so: an assertion on the attempt count alone would also pass for - // a give up on attempt 1, which is the regression the attempt > 1 exemption exists to prevent - assertThat(e.getMessage()).contains("retry window"); + assertThat(e.getMessage()).contains("db-txn-retry-time-limit of " + SHORT_RETRY_TIME_LIMIT_MS + " ms"); } - // one attempt beyond the first: the first spends the window, the exemption grants the replay, and the check - // after that replay is the one that gives up assertThat(attempts.get()).isEqualTo(2); } @@ -521,7 +576,7 @@ public void run(WriteableTransaction txn) throws Exception public void testRetryDelayGrowsAndStaysBounded() { long previousBound = 0; - for (int attempt = 1; attempt <= PDBStorage.MAX_RETRIES; attempt++) + for (int attempt = 1; attempt <= FORMER_ATTEMPT_CAP; attempt++) { long bound = 0; for (int i = 0; i < 100; i++) @@ -543,7 +598,7 @@ public void testRetryDelayGrowsAndStaysBounded() long grown = 0; for (int i = 0; i < 100; i++) { - grown = Math.max(grown, PDBStorage.retryDelayMillis(PDBStorage.MAX_RETRIES)); + grown = Math.max(grown, PDBStorage.retryDelayMillis(FORMER_ATTEMPT_CAP)); } assertThat(grown).as("the last attempts still sleep within the first attempt's bound").isGreaterThan(500); }