Added optional read/prog/erase delays to testbd

These have no real purpose other than slowing down the simulation
for inspection/fun.

Note this did reveal an issue in pretty_asserts.py which was clobbering
feature macros. Added explicit, and maybe a bit hacky, #undef _FEATURE_H
to avoid this.

bd/lfs_testbd.c

@@ -7,12 +7,17 @@
  * SPDX-License-Identifier: BSD-3-Clause
  */
 
+#ifndef _POSIX_C_SOURCE
+#define _POSIX_C_SOURCE 199309L
+#endif
+
 #include "bd/lfs_testbd.h"
 
 #include <stdlib.h>
 #include <fcntl.h>
 #include <unistd.h>
 #include <errno.h>
+#include <time.h>
 
 #ifdef _WIN32
 #include <windows.h>
@@ -238,6 +243,18 @@ int lfs_testbd_read(const struct lfs_config *cfg, lfs_block_t block,
                 size);
     }
 
+    if (bd->cfg->read_delay) {
+        int err = nanosleep(&(struct timespec){
+                .tv_sec=bd->cfg->read_delay/1000000000,
+                .tv_nsec=bd->cfg->read_delay%1000000000},
+            NULL);
+        if (err) {
+            err = -errno;
+            LFS_TESTBD_TRACE("lfs_testbd_read -> %d", err);
+            return err;
+        }
+    }
+
     LFS_TESTBD_TRACE("lfs_testbd_read -> %d", 0);
     return 0;
 }
@@ -306,6 +323,18 @@ int lfs_testbd_prog(const struct lfs_config *cfg, lfs_block_t block,
         }
     }
 
+    if (bd->cfg->prog_delay) {
+        int err = nanosleep(&(struct timespec){
+                .tv_sec=bd->cfg->prog_delay/1000000000,
+                .tv_nsec=bd->cfg->prog_delay%1000000000},
+            NULL);
+        if (err) {
+            err = -errno;
+            LFS_TESTBD_TRACE("lfs_testbd_prog -> %d", err);
+            return err;
+        }
+    }
+
     // lose power?
     if (bd->power_cycles > 0) {
         bd->power_cycles -= 1;
@@ -386,6 +415,18 @@ int lfs_testbd_erase(const struct lfs_config *cfg, lfs_block_t block) {
         }
     }
 
+    if (bd->cfg->erase_delay) {
+        int err = nanosleep(&(struct timespec){
+                .tv_sec=bd->cfg->erase_delay/1000000000,
+                .tv_nsec=bd->cfg->erase_delay%1000000000},
+            NULL);
+        if (err) {
+            err = -errno;
+            LFS_TESTBD_TRACE("lfs_testbd_erase -> %d", err);
+            return err;
+        }
+    }
+
     // lose power?
     if (bd->power_cycles > 0) {
         bd->power_cycles -= 1;

bd/lfs_testbd.h

@@ -57,6 +57,10 @@ typedef int32_t lfs_testbd_swear_t;
 typedef uint32_t lfs_testbd_powercycles_t;
 typedef int32_t lfs_testbd_spowercycles_t;
 
+// Type for delays in nanoseconds
+typedef uint64_t lfs_testbd_delay_t;
+typedef int64_t lfs_testbd_sdelay_t;
+
 // testbd config, this is required for testing
 struct lfs_testbd_config {
     // 8-bit erase value to use for simulating erases. -1 does not simulate
@@ -93,6 +97,18 @@ struct lfs_testbd_config {
     // Path to file to use as a mirror of the disk. This provides a way to view
     // the current state of the block device.
     const char *disk_path;
+
+    // Artificial delay in nanoseconds, there is no purpose for this other
+    // than slowing down the simulation.
+    lfs_testbd_delay_t read_delay;
+
+    // Artificial delay in nanoseconds, there is no purpose for this other
+    // than slowing down the simulation.
+    lfs_testbd_delay_t prog_delay;
+
+    // Artificial delay in nanoseconds, there is no purpose for this other
+    // than slowing down the simulation.
+    lfs_testbd_delay_t erase_delay;
 };
 
 // A reference counted block

runners/test_runner.c

@@ -247,6 +247,9 @@ static size_t test_step = 1;
 
 static const char *test_disk = NULL;
 FILE *test_trace = NULL;
+static lfs_testbd_delay_t test_read_delay = 0.0;
+static lfs_testbd_delay_t test_prog_delay = 0.0;
+static lfs_testbd_delay_t test_erase_delay = 0.0;
 
 
 // how many permutations are there actually in a test case
@@ -611,6 +614,9 @@ static void run_powerloss_none(
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
         .disk_path          = test_disk,
+        .read_delay         = test_read_delay,
+        .prog_delay         = test_prog_delay,
+        .erase_delay        = test_erase_delay,
     };
 
     int err = lfs_testbd_createcfg(&cfg, test_disk, &bdcfg);
@@ -674,6 +680,9 @@ static void run_powerloss_linear(
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
         .disk_path          = test_disk,
+        .read_delay         = test_read_delay,
+        .prog_delay         = test_prog_delay,
+        .erase_delay        = test_erase_delay,
         .power_cycles       = i,
         .powerloss_behavior = POWERLOSS_BEHAVIOR,
         .powerloss_cb       = powerloss_longjmp,
@@ -751,6 +760,9 @@ static void run_powerloss_exponential(
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
         .disk_path          = test_disk,
+        .read_delay         = test_read_delay,
+        .prog_delay         = test_prog_delay,
+        .erase_delay        = test_erase_delay,
         .power_cycles       = i,
         .powerloss_behavior = POWERLOSS_BEHAVIOR,
         .powerloss_cb       = powerloss_longjmp,
@@ -826,6 +838,9 @@ static void run_powerloss_cycles(
         .erase_cycles       = ERASE_CYCLES,
         .badblock_behavior  = BADBLOCK_BEHAVIOR,
         .disk_path          = test_disk,
+        .read_delay         = test_read_delay,
+        .prog_delay         = test_prog_delay,
+        .erase_delay        = test_erase_delay,
         .power_cycles       = (i < cycle_count) ? cycles[i] : 0,
         .powerloss_behavior = POWERLOSS_BEHAVIOR,
         .powerloss_cb       = powerloss_longjmp,
@@ -1018,6 +1033,9 @@ enum opt_flags {
     OPT_STOP             = 8,
     OPT_DISK             = 'd',
     OPT_TRACE            = 't',
+    OPT_READ_DELAY       = 9,
+    OPT_PROG_DELAY       = 10,
+    OPT_ERASE_DELAY      = 11,
 };
 
 const char *short_opts = "hYlLD:G:p:nrVd:t:";
@@ -1040,6 +1058,9 @@ const struct option long_opts[] = {
     {"step",             required_argument, NULL, OPT_STEP},
     {"disk",             required_argument, NULL, OPT_DISK},
     {"trace",            required_argument, NULL, OPT_TRACE},
+    {"read-delay",       required_argument, NULL, OPT_READ_DELAY},
+    {"prog-delay",       required_argument, NULL, OPT_PROG_DELAY},
+    {"erase-delay",      required_argument, NULL, OPT_ERASE_DELAY},
     {NULL, 0, NULL, 0},
 };
 
@@ -1061,6 +1082,9 @@ const char *const help_text[] = {
     "Only run every n tests, calculated after --start and --stop.",
     "Redirect block device operations to this file.",
     "Redirect trace output to this file.",
+    "Artificial read delay in seconds.",
+    "Artificial prog delay in seconds.",
+    "Artificial erase delay in seconds.",
 };
 
 int main(int argc, char **argv) {
@@ -1374,6 +1398,36 @@ powerloss_next:
                     }
                 }
                 break;
+            case OPT_READ_DELAY: {
+                char *parsed = NULL;
+                double read_delay = strtod(optarg, &parsed);
+                if (parsed == optarg) {
+                    fprintf(stderr, "error: invalid read-delay: %s\n", optarg);
+                    exit(-1);
+                }
+                test_read_delay = read_delay*1.0e9;
+                break;
+            }
+            case OPT_PROG_DELAY: {
+                char *parsed = NULL;
+                double prog_delay = strtod(optarg, &parsed);
+                if (parsed == optarg) {
+                    fprintf(stderr, "error: invalid prog-delay: %s\n", optarg);
+                    exit(-1);
+                }
+                test_prog_delay = prog_delay*1.0e9;
+                break;
+            }
+            case OPT_ERASE_DELAY: {
+                char *parsed = NULL;
+                double erase_delay = strtod(optarg, &parsed);
+                if (parsed == optarg) {
+                    fprintf(stderr, "error: invalid erase-delay: %s\n", optarg);
+                    exit(-1);
+                }
+                test_erase_delay = erase_delay*1.0e9;
+                break;
+            }
             // done parsing
             case -1:
                 goto getopt_done;

scripts/pretty_asserts.py

@@ -48,11 +48,14 @@ def write_header(f, limit=LIMIT):
     f.writeln("//")
     f.writeln()
 
-    f.writeln("#include <stdio.h>")
     f.writeln("#include <stdbool.h>")
     f.writeln("#include <stdint.h>")
     f.writeln("#include <inttypes.h>")
+    f.writeln("#include <stdio.h>")
+    f.writeln("#include <string.h>")
     f.writeln("#include <signal.h>")
+    # give source a chance to define feature macros
+    f.writeln("#undef _FEATURES_H")
     f.writeln()
 
     # write print macros

scripts/test.py

@@ -498,6 +498,7 @@ def list_(**args):
     if args.get('list_cases'):       cmd.append('--list-cases')
     if args.get('list_paths'):       cmd.append('--list-paths')
     if args.get('list_defines'):     cmd.append('--list-defines')
+    if args.get('list_defaults'):    cmd.append('--list-defaults')
     if args.get('list_geometries'):  cmd.append('--list-geometries')
     if args.get('list_powerlosses'): cmd.append('--list-powerlosses')
 
@@ -641,8 +642,15 @@ def run_stage(name, runner_, **args):
             cmd.append('--disk=%s' % args['disk'])
         if args.get('trace'):
             cmd.append('--trace=%s' % args['trace'])
+        if args.get('read_delay'):
+            cmd.append('--read-delay=%s' % args['read_delay'])
+        if args.get('prog_delay'):
+            cmd.append('--prog-delay=%s' % args['prog_delay'])
+        if args.get('erase_delay'):
+            cmd.append('--erase-delay=%s' % args['erase_delay'])
         if args.get('verbose'):
             print(' '.join(shlex.quote(c) for c in cmd))
+
         mpty, spty = pty.openpty()
         proc = sp.Popen(cmd, stdout=spty, stderr=spty)
         os.close(spty)
@@ -1010,6 +1018,12 @@ if __name__ == "__main__":
         help="Redirect trace output to this file.")
     test_parser.add_argument('-o', '--output',
         help="Redirect stdout and stderr to this file.")
+    test_parser.add_argument('--read-delay',
+        help="Artificial read delay in seconds.")
+    test_parser.add_argument('--prog-delay',
+        help="Artificial prog delay in seconds.")
+    test_parser.add_argument('--erase-delay',
+        help="Artificial erase delay in seconds.")
     test_parser.add_argument('--runner', default=[RUNNER_PATH],
         type=lambda x: x.split(),
         help="Path to runner, defaults to %r" % RUNNER_PATH)