[#903] Grant the first replay of a conflict, and bound the rest by its class

maximthomas

6 days ago 4486d18e9fde441a438fc9d345675aabb33dface

[#903] Grant the first replay of a conflict, and bound the rest by its class

 opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java

@@ -53,15 +53,28 @@
    private static final int MAX_RETRIES = 10;

    /**
     * Wall-clock budget the replays of a {@link #write} may spend, in nanoseconds. It is checked between attempts,
     * so an attempt already running is never interrupted: the loop returns after at most this window plus one
     * attempt. It bounds the conflicts that are slow to report, which {@link #MAX_RETRIES} alone does not - MySQL
     * reports a lock wait timeout only after innodb_lock_wait_timeout, 50 s by default and not overridden here, so
     * ten attempts would park a worker thread for eight minutes where a single one released it after 50 s. The
     * deadlocks this retry exists for keep their full attempt budget, since every engine reports one in well under
     * a second.
     * Wall-clock budget the replays of a {@link #write} may spend on a {@link Conflict#AFTER_LOCK_WAIT} conflict,
     * in nanoseconds. It is checked between attempts, so an attempt already running is never interrupted, and it
     * bounds the replays after the first, which is granted unconditionally: the loop returns after two attempts,
     * or after this window plus one attempt, whichever comes later. It bounds what {@link #MAX_RETRIES} alone does
     * not - MySQL reports a lock wait timeout only after innodb_lock_wait_timeout, 50 s by default and not
     * overridden here, so ten attempts would park a worker thread for eight minutes where two release it after
     * 100 s.
     */
    private static final long MAX_RETRY_WINDOW_NANOS = 10L * 1000L * 1000L * 1000L; //10 s
    private static final long LOCK_WAIT_RETRY_WINDOW_NANOS = 10L * 1000L * 1000L * 1000L; //10 s

    /**
     * Wall-clock budget the replays of a {@link #write} may spend on a {@link Conflict#PROMPT} conflict, in
     * nanoseconds. Wider, because an attempt ending in a deadlock is not short either, for a reason of its own:
     * detection is prompt, but the victim is charged the lock wait that precedes it, and SQL Server, Oracle and
     * PostgreSQL all leave that wait unbounded - a victim of concurrent writers took some 12 s to be picked in CI,
     * and under the window above the replays that followed the first were disarmed by a wait that belongs to the
     * attempt rather than to them. Widening it is paid for by the caller, which holds a worker thread for up to
     * this window plus one attempt where it held one for ten seconds plus an attempt before - six times as long in
     * the worst case, and still preferable to failing an operation the engine asked to have rerun, with
     * {@link #MAX_RETRIES} capping the attempts made inside it.
     */
    private static final long PROMPT_CONFLICT_RETRY_WINDOW_NANOS = 60L * 1000L * 1000L * 1000L; //60 s

    /** Upper bound of the random delay before the second attempt, in milliseconds; it doubles with every attempt. */
    private static final double BASE_SLEEP_ON_RETRY_MS = 50.0;
@@ -79,6 +92,15 @@
    private static final int ORACLE_DEADLOCK_DETECTED = 60;

    /**
     * MySQL error number of a lock wait timeout, ER_LOCK_WAIT_TIMEOUT. Connector/J maps it to the same class 40
     * state as a deadlock, so it is a conflict like any other and this number is only what tells the two apart:
     * of every conflict handled here it is the one an engine reports late rather than promptly. It is keyed by the
     * driver like the numbers above, since the engines collide on it - the same 1205 is the deadlock victim of
     * SQL Server and a fatal "not a data file" on Oracle.
     */
    private static final int MYSQL_LOCK_WAIT_TIMEOUT = 1205;

    /**
     * Class 40 states that are transaction rollbacks but must not be replayed. 40003 leaves the outcome of the
     * transaction unknown, so replaying an add that in fact committed would answer the client with
     * "entry already exists", and 40002 is an integrity constraint violation, which a replay repeats rather than
@@ -837,11 +859,17 @@
     * exactly that reason; {@link org.opends.server.backends.pdb.PDBStorage#write(WriteOperation)} already does so
     * on the conflict exception of its own engine. The loop is bounded here, unlike PDBStorage: the database may be
     * shared with writers outside this server, so a conflict is not guaranteed to clear and failing the operation is
     * better than never returning. It is bounded twice - by {@link #MAX_RETRIES} attempts and by the
     * {@link #MAX_RETRY_WINDOW_NANOS} wall-clock window - because an attempt is not guaranteed to be short: a
     * conflict an engine reports only after its own lock wait timeout would otherwise multiply that wait by the
     * attempt count. A conflict that slow consumes the whole window in one attempt and is not replayed, which is
     * what master did with it.
     * better than never returning. It is bounded twice - by {@link #MAX_RETRIES} attempts and by a wall-clock
     * window - because an attempt is not guaranteed to be short: a conflict an engine reports only after its own
     * lock wait timeout would otherwise multiply that wait by the attempt count. The window is the one the class
     * of the conflict is given - {@link #LOCK_WAIT_RETRY_WINDOW_NANOS} or
     * {@link #PROMPT_CONFLICT_RETRY_WINDOW_NANOS} - because a window shorter than the wait that precedes a conflict
     * does not bound that wait but only leaves the operation with no replay at all; see
     * {@link #replayable(int, long, Throwable, String)}. Either window is checked between attempts, so an attempt
     * already running is never interrupted, and it bounds the replays after the first: a conflicted operation holds
     * its caller for two attempts, or for the window of its class plus one attempt, whichever is later - a minute
     * plus an attempt for a deadlock, and for a MySQL lock wait timeout the two waits of 50 s the engine takes to
     * report it twice.
     * <p>
     * Only the operation itself is replayed: a failure of {@link #getConnection()} or of the implicit
     * {@link Connection#close()} - which returns the connection to the pool after a rollback - leaves the loop, so
@@ -849,7 +877,7 @@
     */
    @Override
    public void write(WriteOperation writeOperation) throws Exception {
        final long giveUpAt=System.nanoTime()+MAX_RETRY_WINDOW_NANOS;
        final long startedAt=System.nanoTime();
        for (int attempt=1;;attempt++) {
            Exception failure=null;
            String driver=null;
@@ -879,8 +907,8 @@
                    throw e;
                }
            }
            //System.nanoTime()-giveUpAt is the overflow safe form of the comparison
            if (attempt>=MAX_RETRIES || System.nanoTime()-giveUpAt>=0 || !isRetryableConflict(failure,driver)) {
            //System.nanoTime()-startedAt is the overflow safe form of the elapsed time
            if (!replayable(attempt, System.nanoTime()-startedAt, failure, driver)) {
                throw failure;
            }
            //logged rather than silently absorbed, so that a deployment retrying most of its writes stays observable;
@@ -924,16 +952,81 @@
     * no replay can resolve, while 1205 is exactly the deadlock victim of SQL Server. The SQL Server number is
     * matched beyond its class 40 state because a deployment may add {@code xopenStates=true} to its connection
     * URL, which reports the same deadlock as 42000. MySQL needs no number of its own, since its driver has already
     * mapped both conditions into class 40; see {@link #NON_REPLAYABLE_ROLLBACK_STATES} for the two class 40 states
     * that are excluded from that match.
     * mapped both conditions into class 40 - its number is read by {@link #conflictOf} alone, and only to tell the
     * two apart; see {@link #NON_REPLAYABLE_ROLLBACK_STATES} for the two class 40 states that are excluded from
     * that match.
     */
    static boolean isRetryableConflict(Throwable t, String driver) {
        return conflictOf(t, driver)!=Conflict.NONE;
    }

    /**
     * The class of a failure. Whether it is a conflict at all is what decides that the operation is replayed;
     * which of the two remaining classes it is decides only how long the replays may go on for, since the wait an
     * engine spends before reporting a conflict is charged to the attempt that hit it.
     */
    enum Conflict {
        /** Not a conflict: no replay resolves it. */
        NONE,
        /** A conflict reported as soon as the engine detects it, however long the attempt waited to reach it. */
        PROMPT,
        /** A conflict an engine reports only once a lock wait timeout of its own has elapsed. */
        AFTER_LOCK_WAIT
    }

    /**
     * Returns the class of the first conflict of the given cause chain, walked as
     * {@link #isRetryableConflict(Throwable, String)} describes, or {@link Conflict#NONE} if it carries none.
     */
    static Conflict conflictOf(Throwable t, String driver) {
        for (int hop=0; t!=null && hop<MAX_CAUSE_HOPS; t=t.getCause(), hop++) {
            if (t instanceof SQLException && isConflict((SQLException) t, driver)) {
                return true;
            if (t instanceof SQLException) {
                final Conflict conflict=classOf((SQLException) t, driver);
                if (conflict!=Conflict.NONE) {
                    return conflict;
                }
            }
        }
        return false;
        return Conflict.NONE;
    }

    /**
     * Returns the class of a single failure. The vendor number only refines a failure {@link #isConflict} has
     * already matched and never widens that match, which the engines colliding on 1205 do not allow: the number is
     * read here to tell the late conflict of MySQL from the deadlock its driver reports under the same state.
     */
    private static Conflict classOf(SQLException e, String driver) {
        if (!isConflict(e, driver)) {
            return Conflict.NONE;
        }
        return String.valueOf(driver).contains("mysql") && e.getErrorCode()==MYSQL_LOCK_WAIT_TIMEOUT
                ? Conflict.AFTER_LOCK_WAIT : Conflict.PROMPT;
    }

    /**
     * Returns whether the failure of the given attempt is replayed: the decision {@link #write} takes after every
     * attempt, made here apart from the clock so that it can be tested without a database. The first replay of a
     * conflict is never denied, because the wait an engine spends before reporting one is charged to the attempt
     * that hit it and is unbounded on three of the four engines here, so there is no window that some wait does not
     * outlast; bounding that wait itself would take a session lock timeout on the transaction connection. The
     * replays after it are bounded by the window of the class of the conflict, against the time elapsed since the
     * first attempt began.
     */
    static boolean replayable(int attempt, long elapsedNanos, Throwable failure, String driver) {
        final Conflict conflict=conflictOf(failure, driver);
        if (conflict==Conflict.NONE || attempt>=MAX_RETRIES) {
            return false;
        }
        //the engine asked for the transaction to be rerun: no clock denies that first rerun
        if (attempt==1) {
            return true;
        }
        return elapsedNanos<windowOf(conflict);
    }

    /** Returns the window the replays of the given conflict are bounded by; {@link Conflict#NONE} never gets here. */
    private static long windowOf(Conflict conflict) {
        return conflict==Conflict.AFTER_LOCK_WAIT ? LOCK_WAIT_RETRY_WINDOW_NANOS : PROMPT_CONFLICT_RETRY_WINDOW_NANOS;
    }

    private static boolean isConflict(SQLException e, String driver) {

 opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/JDBCStorageRetryTest.java

@@ -16,6 +16,7 @@
package org.opends.server.backends.jdbc;

import org.opends.server.DirectoryServerTestCase;
import org.opends.server.backends.jdbc.JDBCStorage.Conflict;
import org.opends.server.backends.pluggable.spi.StorageRuntimeException;
import org.opends.server.types.DirectoryException;
import org.testng.annotations.DataProvider;
@@ -25,12 +26,16 @@

import static org.forgerock.i18n.LocalizableMessage.raw;
import static org.forgerock.opendj.ldap.ResultCode.OTHER;
import static org.opends.server.backends.jdbc.JDBCStorage.Conflict.AFTER_LOCK_WAIT;
import static org.opends.server.backends.jdbc.JDBCStorage.Conflict.NONE;
import static org.opends.server.backends.jdbc.JDBCStorage.Conflict.PROMPT;
import static org.testng.Assert.assertEquals;
import static org.testng.Assert.assertTrue;

/**
 * Tests how a failure is classified as a transaction conflict, which is what decides whether
 * {@link JDBCStorage#write} replays the operation, and how long it waits before it does.
 * {@link JDBCStorage#write} replays the operation, how long the replays may go on for, and how long it waits
 * before each of them.
 * <p>
 * Runs without a database: the failures the drivers report are reproduced as synthetic
 * {@link SQLException}s carrying the same vendor error number and SQLState.
@@ -57,62 +62,128 @@
    }
  }

  /**
   * The failures the engines report, and the class each of them belongs to: {@link Conflict#NONE} for a failure no
   * replay resolves, and otherwise how promptly the engine reporting it does so, which is all the class decides.
   */
  @DataProvider
  public Object[][] failures()
  {
    return new Object[][] {
      // SQL Server picking a transaction as the deadlock victim: the failure this retry exists for
      { "mssql deadlock victim", sql(1205, "40001"), MSSQL, true },
      // SQL Server picking a transaction as the deadlock victim: the failure this retry exists for. It is reported
      // as promptly as the deadlock monitor runs, but only once the victim has waited out a lock wait of its own,
      // which SQL Server leaves unbounded - the wait belongs to the attempt, not to the reporting
      { "mssql deadlock victim", sql(1205, "40001"), MSSQL, PROMPT },
      // a deployment may add xopenStates=true to its connection URL, which reports the same deadlock as 42000
      { "mssql deadlock victim, xopenStates", sql(1205, "42000"), MSSQL, true },
      { "mssql deadlock victim, xopenStates", sql(1205, "42000"), MSSQL, PROMPT },
      // the conflict of most other engines is carried by the SQLState, under a vendor number of their own
      { "postgres serialization failure", sql(0, "40001"), POSTGRES, true },
      { "postgres deadlock detected", sql(0, "40P01"), POSTGRES, true },
      { "postgres serialization failure", sql(0, "40001"), POSTGRES, PROMPT },
      { "postgres deadlock detected", sql(0, "40P01"), POSTGRES, PROMPT },
      // Connector/J replaces the server side HY000 of both conditions with 40001, so neither needs a number here
      { "mysql deadlock", sql(1213, "40001"), MYSQL, true },
      // not a deadlock, but transient in the same way and equally resolved by a replay
      { "mysql lock wait timeout", sql(1205, "40001"), MYSQL, true },
      { "mysql deadlock", sql(1213, "40001"), MYSQL, PROMPT },
      // not a deadlock, but transient in the same way and equally resolved by a replay - and the one conflict of
      // them all that an engine reports only after a lock wait timeout of its own, innodb_lock_wait_timeout
      { "mysql lock wait timeout", sql(1205, "40001"), MYSQL, AFTER_LOCK_WAIT },
      // the rollback a MySQL group replication conflict reports, error 3101, which the driver maps to 40000
      { "mysql group replication rollback", sql(3101, "40000"), MYSQL, true },
      { "mysql group replication rollback", sql(3101, "40000"), MYSQL, PROMPT },
      // Oracle maps ORA-00060 to SQLState 61000, so only its error number identifies the deadlock
      { "oracle deadlock detected", sql(60, "61000"), ORACLE, true },
      { "oracle deadlock detected", sql(60, "61000"), ORACLE, PROMPT },

      // the conflict reaches JDBCStorage.write() wrapped, so the whole cause chain has to be walked
      { "wrapped once", new StorageRuntimeException(sql(1205, "40001")), MSSQL, true },
      { "wrapped once", new StorageRuntimeException(sql(1205, "40001")), MSSQL, PROMPT },
      { "wrapped twice",
        new DirectoryException(OTHER, raw("unchecked"), new StorageRuntimeException(sql(1205, "40001"))), MSSQL,
        true },
        PROMPT },

      // the vendor numbers collide across engines, so they must not be matched driver-independently:
      // ORA-01205 "not a data file" is fatal, and no replay resolves it
      { "oracle not a data file", sql(1205, "64000"), ORACLE, false },
      { "oracle not a data file", sql(1205, "64000"), ORACLE, NONE },
      // and a lock wait timeout is a MySQL number: 1205 means nothing of the kind to PostgreSQL
      { "postgres unrelated 1205", sql(1205, "22001"), POSTGRES, false },
      { "postgres unrelated 1205", sql(1205, "22001"), POSTGRES, NONE },

      // two class 40 states are rollbacks that a replay must not repeat: 40003 leaves the outcome of the
      // transaction unknown, and 40002 is an integrity constraint violation that a replay would only hit again
      { "statement completion unknown", sql(0, "40003"), POSTGRES, false },
      { "transaction integrity constraint violation", sql(0, "40002"), POSTGRES, false },
      { "statement completion unknown", sql(0, "40003"), POSTGRES, NONE },
      { "transaction integrity constraint violation", sql(0, "40002"), POSTGRES, NONE },
      // ... but the state of a conflict is still matched whatever vendor number carries it
      { "class 40 is driver independent", sql(0, "40001"), null, true },
      { "class 40 is driver independent", sql(0, "40001"), null, PROMPT },
      // the number that makes a conflict slow is a MySQL number too, so a class 40 state carrying it under any
      // other driver is classified by its state alone, and keeps the window of a conflict reported promptly
      { "class 40 with 1205, no driver", sql(1205, "40001"), null, PROMPT },

      // nothing a replay can resolve
      { "primary key violation", sql(2627, "23000"), MSSQL, false },
      { "syntax error", sql(102, "S0001"), MSSQL, false },
      { "no SQLState", sql(0, null), MSSQL, false },
      { "not a SQLException", new IllegalStateException("connection closed"), MSSQL, false },
      { "wrapped, not a conflict", new StorageRuntimeException(sql(2627, "23000")), MSSQL, false },
      { "no failure at all", null, MSSQL, false },
      { "primary key violation", sql(2627, "23000"), MSSQL, NONE },
      { "syntax error", sql(102, "S0001"), MSSQL, NONE },
      { "no SQLState", sql(0, null), MSSQL, NONE },
      { "not a SQLException", new IllegalStateException("connection closed"), MSSQL, NONE },
      { "wrapped, not a conflict", new StorageRuntimeException(sql(2627, "23000")), MSSQL, NONE },
      { "no failure at all", null, MSSQL, NONE },
      // a vendor number is never matched without a driver to key it off, since the engines collide on it
      { "unknown driver", sql(1205, "HY000"), null, false },
      { "cyclic cause chain", new SelfCausedException(), MSSQL, false },
      { "unknown driver", sql(1205, "HY000"), null, NONE },
      // the state the MySQL server itself gives a lock wait timeout, before Connector/J remaps it to class 40: the
      // number read to date that conflict refines a match its state has already made, and never makes one of its own
      { "mysql lock wait timeout, server state", sql(1205, "HY000"), MYSQL, NONE },
      { "cyclic cause chain", new SelfCausedException(), MSSQL, NONE },
    };
  }

  /** Whether a failure is replayed at all is what the classification decides first; the class does not change it. */
  @Test(dataProvider = "failures")
  public void testIsRetryableConflict(String name, Throwable failure, String driver, boolean expected)
  public void testIsRetryableConflict(String name, Throwable failure, String driver, Conflict expected)
  {
    assertEquals(JDBCStorage.isRetryableConflict(failure, driver), expected, name);
    assertEquals(JDBCStorage.isRetryableConflict(failure, driver), expected != NONE, name);
  }

  /** Which class it lands in decides only how long its replays may go on for. */
  @Test(dataProvider = "failures")
  public void testConflictClass(String name, Throwable failure, String driver, Conflict expected)
  {
    assertEquals(JDBCStorage.conflictOf(failure, driver), expected, name);
  }

  /**
   * Which replays happen. The first one is never denied, since the wait an engine spends before reporting a
   * conflict is charged to the attempt that hit it and no window can be chosen that some wait does not outlast;
   * the replays after it are bounded by the window of the class of the conflict.
   */
  @DataProvider
  public Object[][] replays()
  {
    return new Object[][] {
      // the engine asked for the transaction to be rerun, and no clock denies that first rerun. The failure of run
      // 33010633197 is the case: SQL Server leaves the lock wait unbounded, so its deadlock monitor picked a victim
      // ~12 s into the first attempt, and a window of any size is outlasted by some wait
      { "deadlock reported after a long lock wait", 1, seconds(12), sql(1205, "40001"), MSSQL, true },
      { "deadlock reported later than any window", 1, seconds(600), sql(1205, "40001"), MSSQL, true },
      // what granting it costs is one more wait of the engine that waits longest, and only once
      { "mysql lock wait timeout, first attempt", 1, seconds(50), sql(1205, "40001"), MYSQL, true },

      // the replays after the first are what the window bounds, so that a conflict which never clears is failed
      // rather than never returned
      { "deadlock within the window", 2, seconds(59), sql(1205, "40001"), MSSQL, true },
      { "deadlock at the window", 2, seconds(60), sql(1205, "40001"), MSSQL, false },
      { "deadlock past the window", 2, seconds(61), sql(1205, "40001"), MSSQL, false },
      // MySQL reports a lock wait timeout only after innodb_lock_wait_timeout, 50 s by default: ten attempts of
      // those park a worker thread for eight minutes, which is the wait the narrower window exists to bound
      { "mysql lock wait timeout within its window", 2, seconds(9), sql(1205, "40001"), MYSQL, true },
      { "mysql lock wait timeout at its window", 2, seconds(10), sql(1205, "40001"), MYSQL, false },
      { "mysql lock wait timeout past its window", 2, seconds(12), sql(1205, "40001"), MYSQL, false },
      // the two MySQL numbers part ways here: a deadlock is reported as promptly as any other engine reports one
      { "mysql deadlock", 2, seconds(12), sql(1213, "40001"), MYSQL, true },

      // the attempt count bounds every class, whatever the window has left
      { "last attempt left", 9, 0L, sql(1205, "40001"), MSSQL, true },
      { "attempts exhausted", 10, 0L, sql(1205, "40001"), MSSQL, false },
      // and nothing a replay resolves is replayed, the first attempt included
      { "not a conflict", 1, 0L, sql(2627, "23000"), MSSQL, false },
    };
  }

  @Test(dataProvider = "replays")
  public void testReplayable(String name, int attempt, long elapsedNanos, Throwable failure, String driver,
      boolean expected)
  {
    assertEquals(JDBCStorage.replayable(attempt, elapsedNanos, failure, driver), expected, name);
  }

  /** The delay grows with the attempt, so that the replays outlast a contention lasting more than a few ms. */
@@ -162,4 +233,9 @@
  {
    return new SQLException("synthetic failure", sqlState, errorCode);
  }

  private static long seconds(long seconds)
  {
    return seconds * 1000L * 1000L * 1000L;
  }
}