Evidence of using static thresholds

[ruiming-lu]

This is NOT about software testing. It is a collection of evidence on how systems use static rules to handle slow faults in the master branch.

HBase

• slow sync.
  
  

CRDB (slow/stall storage engine (disk))

Important files:

• pebble.go#L1528
• pebble.go#L65
• engine.go#L1194
• pebble/event.go#502-#509
• pebble/vfs/disk_health.go#669
• pebble/vfs/disk_health.go#255

Logic:

• diskHealthCheckInterval := 5 * time.Second (see code)
• Pebble checks if last writes exceed diskSlowThreshold (if-condition). If so, return DiskSlowInfo.
• The diskSlowThreshold is passed explicitly as 5s (cannot be altered by users!) in this function call; the function (WithDiskHealthChecks is defined here)
• For all DiskSlowInfo (triggered by makeMetricEtcEventListener), fatal the process (fatalOnExceeded, default True) if disk slow duration is above maxSyncDuration (default: 20s). (see the if-condition, maxSyncDurationDefault=20s, fatalOnExceeded=True)
• Otherwise (between 5s and 20s) trigger an ERROR log (log.Errorf(ctx, "disk stall detected: %s", info))

CRDB (slow logging)

Important files:

• cockroach/pkg/util/log/file.go#L251-L277

Logic:

• Scenario 1: Flush all pending log file I/O
  • Always sync: doSync=True)
  • Triggered per function call
• Scenario 2: Manage background (async) flushes
  • Triggered every 1s in flushdaemon
• Try to flush the current log. If doSync == True:
  • If sync time exceeds maxSyncDuration (default: 20s), fatal the process (if-condition, maxSyncDuration=20s)
  • If sync time exceeds syncWarnDuration (default: 10s), print a warning (if-condition, syncWarnDuration=10s)
• Tests 1, 2

The common logic

At least the logic of handling slow faults in HBase and CRDB is very similar. Need to further organize.

[ruiming-lu]

Cassandra - Slow query

	CASSANDRA-12403	CASSANDRA-6226
Created	2016-08-07	2013-10-21
Updated	2020-01-14	2019-04-16
Resolved	2016-08-17	2014-10-25

• DEBUG-level

• "Meant to catch user misbehavior (users sometimes build anti-pattern tables and throw queries in inefficient manners)"

• "The feature can help cassandra operators to identify bad query patterns"

• "Then operators can give advices about queries and data model to users who don't know cassandra so much"

• the default value increased from 200 to 500 milliseconds; I know this is very high but I prefer to be on the safe side

• The default value of query_log_timeout_in_ms is ok for me because most of problematic queries take more than 1,000 msec in production environment of my company.

• In config/Config.java#L115:

  public volatile long slow_query_log_timeout_in_ms = 500L;

• In service/StorageProxy.java#2127:

  # Register slowquerytimeout = 500ms
  command.setMonitoringTime(…, SlowQueryTimeout);
  # Later will check if command is completed
  if (command.complete())
  {
    handler.response(response);
  }

• Logged in db/monitoring/MonitoringTask.java#L166 by noSpamLogger (def here) which logs at most once every 5 minutes (fixed).

  // function: logSlowOperations(long approxCurrentTimeNanos)
   long approxElapsedNanos = approxCurrentTimeNanos - approxLastLogTimeNanos;
   noSpamLogger.info("Some operations were slow, details available at debug level (debug.log)");
  
   if (logger.isDebugEnabled())
       logger.debug("{} operations were slow in the last {} msecs:{}{}",
                             slowOperations.num(),
                             NANOSECONDS.toMillis(approxElapsedNanos),
                             LINE_SEPARATOR,
                             slowOperations.getLogMessage());
  
  //function: getLogMessage()
  if (numTimesReported == 1)
      return String.format("<%s>, time %d msec - slow timeout %d %s",
                                     name(),
                                     NANOSECONDS.toMillis(totalTimeNanos),
                                     NANOSECONDS.toMillis(operation.slowTimeoutNanos()),
                                     operation.isCrossNode() ? "msec/cross-node" : "msec");
  else
      return String.format("<%s>, was slow %d times: avg/min/max %d/%d/%d msec - slow timeout %d %s",
                                     name(),
                                     numTimesReported,
                                     NANOSECONDS.toMillis(totalTimeNanos/ numTimesReported),
                                     NANOSECONDS.toMillis(minTime),
                                     NANOSECONDS.toMillis(maxTime),
                                     NANOSECONDS.toMillis(operation.slowTimeoutNanos()),
                                     operation.isCrossNode() ? "msec/cross-node" : "msec");
        }

Testing here

[ruiming-lu]

HDFS (v3.3.6)

User tickets:

• Solution for "slow readprocessor" warnings
• HDFS Slow Put

1. In DataStreamer.java -> ResponseProcessor (processing responses from the datanodes), if current response duration exceeds dfsclientSlowLogThresholdMs (default: 30s , defined here and here), print an INFO log
2. In waitForAckedSeqno, when client writes a file:
   1. if it takes > dfsclientSlowLogThresholdMs to get ACK, print a warning.
   2. if it takes too long (> writeTimeout, see if-condition), print an error message and throw InterruptedIOException

The default value of writeTimeout:

• dataStreamer.java#914:

  int writeTimeout = dfsClient.getDatanodeWriteTimeout(dnodes);

• DFSClient.java#477:

  int getDatanodeWriteTimeout(int numNodes) {
    final int t = dfsClientConf.getDatanodeSocketWriteTimeout(); // equals to WRITE_TIMEOUT
    return t > 0? t + HdfsConstants.WRITE_TIMEOUT_EXTENSION*numNodes: 0;
  }

• HdfsConstants.java (unit: ms)

  // Timeouts for communicating with DataNode for streaming writes/reads
  public static final int READ_TIMEOUT = 60 * 1000;
  public static final int READ_TIMEOUT_EXTENSION = 5 * 1000;
  public static final int WRITE_TIMEOUT = 8 * 60 * 1000;
  //for write pipeline
  public static final int WRITE_TIMEOUT_EXTENSION = 5 * 1000;

Testing:

1. Set DFS_CLIENT_SLOW_IO_WARNING_THRESHOLD_KEY to be 10s (here)
2. Intentionally sleep 15s between writes to cross the threshold.
3. Check if the warning log entry is printed

JIRA issue: https://issues.apache.org/jira/browse/HDFS-14878?jql=text%20~%20%22dfsclientSlowLogThresholdMs%22

[ruiming-lu]

Kafka

Retry if exceed doc - request.timeout.ms, defined in code here

Report success or failure if exceed doc - delivery.timeout.ms, defined in code here

[ruiming-lu]

etcd

Developers discussed the necessity to detect stalled writes in etcd-issue-15247. Later in March 2023, developers opened a pull request and implemented a watchdog for stalled writes. It is still under construction now.

The default storage watchdog duration is 10s.

1. Create a watchdog for a certain operation/activity
2. If the operation/activity takes more than 0.5 * 10s = 5s, then print a warning log
3. If it takes more than 10s, the node panics (crash) and print a panic log

[ruiming-lu]

Ruochong has helped to incorporate more detection/alert/testing cases for Kafka and HDFS here.