User tickets & software testing related to slow faults

[ruiming-lu]

System	Created	Feature	Fixed?	Testing	Others
HBase	2019.04	Log roll on slow sync	✔️	TestLogRolling.java	Explicitly mentioned 'gray failure'.
HBase	2017.09	Alert slow reads on a block	Stale	x	x
etcd	2023.02	Leader stuck in handling raft Ready due to slow fdatasync or high CPU	✔️	v3_lease_no_proxy_test.go	Still active
crdb	2023.01	Adapt charybdefs-based roachtest to allow for indefinite stalls. Also discussed in etcd-issues	✔️	commit history, disk_stall.go, pebble_test.go	x
crdb	2022.05	Initial discussion on handling of degraded storage devices.	🚫	x	Developers said "not clear to me what the best mechanism nor policy for this would be". Marked as stale 18 months later.
crdb	2020.10	Throw warning on slow log write, fatal on engine disk stall.	✔️	They found this to be incomplete and thus move to the above mentioned solutions	Developers intend to be "conservative" to respond to disk stalls (>20s) and only print a warning on disk slow (>10s).
cassandra	2016.08	Slow query detecting.	✔️	stef1927/cql_test.py and riptano/cql_test.py	By setting slow_query_log_timeout_in_ms to a small value (i.e., 10ms and 30ms) so that it's easily triggered (NOT INJECTING SLOW FAULTS)
kafka	-	Mitigating Kafka Broker ‘Gray’ Failures.
kafka	-	SRECON'23: Improving Kafka Resilience - Gray Failures Mitigation.

Misc:

• CRDB is actually using charbydefs but only simulate & test disk stalls. See this ticket for how developers use charybdefs.

Generally, developers are accessible to and intentionally use tools to inject slow faults, but rather targeting the worst-case scenario: disk stalls; they did not iterate through different severity levels even if they are able to.

[ruiming-lu]

Testing - HBase slow sync log roll

• TestLogRolling.java: checkSlowSync =>

      void checkSlowSync(AbstractFSWAL<?> log, Table table, int slowSyncLatency,
                                          int writeCount, boolean slowSync
      // Set default log writer, no additional latency to any sync on the hlog.
      checkSlowSync(log, table, -1, 10, false);
  
      // Adds 200 ms of latency to any sync on the hlog. This should be more than sufficient to
      // trigger slow sync warnings.
      // Write some data.
      // We need to write at least 5 times, but double it. We should only request
      // a SLOW_SYNC roll once in the current interval.
      checkSlowSync(log, table, 200, 10, true);
  
      // Adds 5000 ms of latency to any sync on the hlog. This will trip the other threshold.
      // Write some data. Should only take one sync.
      checkSlowSync(log, table, 5000, 1, true);
  
      // Set default log writer, no additional latency to any sync on the hlog.
      checkSlowSync(log, table, -1, 10, false);

• AbstractTestLogRolling: checkSlowSync =>

  setSyncLatencyMillis(slowSyncLatency); // could be -1, 200ms, or 5000ms

• AbstractTestLogRolling: wait for =>

    if (slowSync) {
      TEST_UTIL.waitFor(10000, 100, new Waiter.ExplainingPredicate<Exception>() {
        @Override
        public boolean evaluate() throws Exception {
          return log.getWriter() != oldWriter;
        }
  
        @Override
        public String explainFailure() throws Exception {
          return "Waited too long for our test writer to get rolled out";
        }
      });
  
      assertTrue("Should have triggered log roll due to SLOW_SYNC", slowSyncHookCalled.get());
    } else {
      assertFalse("Should not have triggered log roll due to SLOW_SYNC", slowSyncHookCalled.get());
    }

• HBaseCommonTestingUtil: waitFor() =>
• Waiter.java: Waiter.waitfor()

   /**
   * Waits up to the duration equal to the specified timeout multiplied by the
   * {@link #getWaitForRatio(Configuration)} for the given {@link Predicate} to become
   * <code>true</code>, failing the test if the timeout is reached, the Predicate is still
   * <code>false</code> and failIfTimeout is set as <code>true</code>.
   * <p/>
   * @param conf          the configuration
   * @param timeout       the timeout in milliseconds to wait for the predicate.
   * @param interval      the interval in milliseconds to evaluate predicate.
   * @param failIfTimeout indicates if should fail current test case when times out.
   * @param predicate     the predicate to evaluate.
   * @return the effective wait, in milli-seconds until the predicate becomes <code>true</code> or
   *         wait is interrupted otherwise <code>-1</code> when times out
   */
  waitFor(conf, timeout, 100, true, predicate);
  long waitFor(Configuration conf, long timeout, long interval,
                        boolean failIfTimeout, Predicate<E> predicate)

[ruiming-lu]

Testing - CRDB disk slow/stall

Test starts with DiskSlowInfo (see testcases).

[ruiming-lu]

Testing - Cassandra slow query

• MonitoringTaskTest.java: testReportSlow():

    private static final long timeout = MILLISECONDS.toNanos(100);
    private static final long slowTimeout = MILLISECONDS.toNanos(10);
    private static final long MAX_SPIN_TIME_NANOS = TimeUnit.SECONDS.toNanos(5);

    public void testReportSlow() throws InterruptedException
    {
        Monitorable operation = new TestMonitor("Test report slow", nanoTime(), false, timeout, slowTimeout);
        waitForOperationsToBeReportedAsSlow(operation);

        assertTrue(operation.isSlow());
        operation.complete();
        assertFalse(operation.isAborted());
        assertTrue(operation.isCompleted());
        assertEquals(1, MonitoringTask.instance.getSlowOperations().size());
    }

• waitForOperationsToBeReportedAsSlow():

    private static void waitForOperationsToBeReportedAsSlow(List<Monitorable> operations) throws InterruptedException
    {
        long timeout = operations.stream().map(Monitorable::slowTimeoutNanos).reduce(0L, Long::max);
        Thread.sleep(NANOSECONDS.toMillis(timeout * 2 + approxTime.error()));

        long start = nanoTime();
        while(nanoTime() - start <= MAX_SPIN_TIME_NANOS)
        {
            long numSlow = operations.stream().filter(Monitorable::isSlow).count();
            if (numSlow == operations.size())
                return;
        }
    }

• In Monitorableimpl.java:

    public boolean isSlow()
    {
        check();
        return isSlow;
    }


    private void check()
    {
        if (approxCreationTimeNanos < 0 || state != MonitoringState.IN_PROGRESS)
            return;

        long minElapsedNanos = (approxTime.now() - approxCreationTimeNanos) - approxTime.error();

        if (minElapsedNanos >= slowTimeoutNanos && !isSlow)
            isSlow = true;

        if (minElapsedNanos >= timeoutNanos)
            abort();
    }

[ruiming-lu]

User complaints (search for email threads using https://lists.apache.org/)

HBase - slow sync

In this email thread, users complain that they observe a "log spam" because the default 100ms threshold is easily triggered. However, the users did not work on tuning the threshold values; they instead correlated this with JVM GC pauses and discussed how to control most GCs under 100ms to not trigger the warning.
In this email thread, people asked "how to optimize for heavy writes scenario". Although not directly mentioned slowSyncDuration, they still investigated how to tune other parameters.