[PATCH 6/6] fsx: Add mechanism to replay failed operations

Andreas Gruenbacher
2015-12-22T20:54:19Z

Create a $name.fsxops file next to $test.fsxlog. When a test fails,
dump the operations in the log into that file in a simple, parseable
format like:

fallocate 0x2e0f2 0xf04a 0x0 keep_size
truncate 0x0 0x11e00 0x0 *
write 0x73400 0x6c00 0x11e00
skip punch_hole 0x71539913 0xdf76 0x7a000 close_open
mapread 0x56000 0x16d08 0x7a000

Here, each operation is on a separate line. When the first word is
"skip", the operation will be skipped. The next parameters are offset,
length, and the current file size, followed by optional flags like
keep_size and clode_open. A trailing asterisk indicates that the
operation overlaps with the operation that has failed.

Add a --replay-ops option that allows to replay the operations recorded
in such a $name.fsxops file. (The log can be modified to easily narrow
down which operations are causing the failure.)

Signed-off-by: Andreas Gruenbacher <agruenba@redhat.com>
---
ltp/fsx.c | 246 +++++++++++++++++++++++++++++++++++++++++++++++++++++---------
1 file changed, 213 insertions(+), 33 deletions(-)

diff --git a/ltp/fsx.c b/ltp/fsx.c
index 50ca885..28f109c 100644
--- a/ltp/fsx.c
+++ b/ltp/fsx.c
@@ -166,7 +166,10 @@ int aio_rw(int rw, int fd, char *buf, unsigned len, unsigned offset);
#define fsxwrite(a,b,c,d) write(a,b,c)
#endif

+const char *replayops = NULL;
FILE * fsxlogf = NULL;
+FILE * replayopsf = NULL;
+char opsfile[1024];
int badoff = -1;
int closeopen = 0;

@@ -200,7 +203,7 @@ warn(const char * fmt, ...) {
#define BUF_SIZE 1024

void
-prt(char *fmt, ...)
+prt(const char *fmt, ...)
{
va_list args;
char buffer[BUF_SIZE];
@@ -214,12 +217,43 @@ prt(char *fmt, ...)
}

void
-prterr(char *prefix)
+prterr(const char *prefix)
{
prt("%s%s%s\n", prefix, prefix ? ": " : "", strerror(errno));
}

+static const char *op_names[] = {
+ [OP_READ] = "read",
+ [OP_WRITE] = "write",
+ [OP_MAPREAD] = "mapread",
+ [OP_MAPWRITE] = "mapwrite",
+ [OP_TRUNCATE] = "truncate",
+ [OP_FALLOCATE] = "fallocate",
+ [OP_PUNCH_HOLE] = "punch_hole",
+ [OP_ZERO_RANGE] = "zero_range",
+ [OP_COLLAPSE_RANGE] = "collapse_range",
+ [OP_INSERT_RANGE] = "insert_range",
+};
+
+static const char *op_name(int operation)
+{
+ if (operation >= 0 &&
+ operation < sizeof(op_names) / sizeof(op_names[0]))
+ return op_names[operation];
+ return NULL;
+}
+
+static int op_code(const char *name)
+{
+ int i;
+
+ for (i = 0; i < sizeof(op_names) / sizeof(op_names[0]); i++)
+ if (op_names[i] && strcmp(name, op_names[i]) == 0)
+ return i;
+ return -1;
+}
+
void
log4(int operation, int arg0, int arg1, enum opflags flags)
{
@@ -243,10 +277,16 @@ log4(int operation, int arg0, int arg1, enum opflags flags)
void
logdump(void)
{
+ FILE *logopsf;
int i, count, down;
struct log_entry *lp;

prt("LOG DUMP (%d total operations):\n", logcount);
+
+ logopsf = fopen(opsfile, "w");
+ if (!logopsf)
+ prterr(opsfile);
+
if (logcount < LOGSIZE) {
i = 0;
count = logcount;
@@ -255,12 +295,16 @@ logdump(void)
count = LOGSIZE;
}
for ( ; count > 0; count--) {
+ bool overlap;
int opnum;

opnum = i+1 + (logcount/LOGSIZE)*LOGSIZE;
prt("%d(%3d mod 256): ", opnum, opnum%256);
lp = &oplog[i];

+ overlap = badoff >= lp->args[0] &&
+ badoff < lp->args[0] + lp->args[1];
+
if (lp->flags & FL_SKIPPED) {
prt("SKIPPED (no operation)");
goto skipped;
@@ -271,24 +315,21 @@ logdump(void)
prt("MAPREAD 0x%x thru 0x%x\t(0x%x bytes)",
lp->args[0], lp->args[0] + lp->args[1] - 1,
lp->args[1]);
- if (badoff >= lp->args[0] && badoff <
- lp->args[0] + lp->args[1])
+ if (overlap)
prt("\t***RRRR***");
break;
case OP_MAPWRITE:
prt("MAPWRITE 0x%x thru 0x%x\t(0x%x bytes)",
lp->args[0], lp->args[0] + lp->args[1] - 1,
lp->args[1]);
- if (badoff >= lp->args[0] && badoff <
- lp->args[0] + lp->args[1])
+ if (overlap)
prt("\t******WWWW");
break;
case OP_READ:
prt("READ 0x%x thru 0x%x\t(0x%x bytes)",
lp->args[0], lp->args[0] + lp->args[1] - 1,
lp->args[1]);
- if (badoff >= lp->args[0] &&
- badoff < lp->args[0] + lp->args[1])
+ if (overlap)
prt("\t***RRRR***");
break;
case OP_WRITE:
@@ -299,16 +340,19 @@ logdump(void)
prt(" HOLE");
else if (lp->args[0] + lp->args[1] > lp->args[2])
prt(" EXTEND");
- if ((badoff >= lp->args[0] || badoff >=lp->args[2]) &&
- badoff < lp->args[0] + lp->args[1])
+ overlap = (badoff >= lp->args[0] ||
+ badoff >=lp->args[2]) &&
+ badoff < lp->args[0] + lp->args[1];
+ if (overlap)
prt("\t***WWWW");
break;
case OP_TRUNCATE:
down = lp->args[1] < lp->args[2];
prt("TRUNCATE %s\tfrom 0x%x to 0x%x",
down ? "DOWN" : "UP", lp->args[2], lp->args[1]);
- if (badoff >= lp->args[1 + !down] &&
- badoff < lp->args[1 + !!down])
+ overlap = badoff >= lp->args[1 + !down] &&
+ badoff < lp->args[1 + !!down];
+ if (overlap)
prt("\t******WWWW");
break;
case OP_FALLOCATE:
@@ -322,46 +366,43 @@ logdump(void)
prt("PAST_EOF");
else
prt("EXTENDING");
- if (badoff >= lp->args[0] &&
- badoff < lp->args[0] + lp->args[1])
+ if (overlap)
prt("\t******FFFF");
break;
case OP_PUNCH_HOLE:
prt("PUNCH 0x%x thru 0x%x\t(0x%x bytes)",
lp->args[0], lp->args[0] + lp->args[1] - 1,
lp->args[1]);
- if (badoff >= lp->args[0] && badoff <
- lp->args[0] + lp->args[1])
+ if (overlap)
prt("\t******PPPP");
break;
case OP_ZERO_RANGE:
prt("ZERO 0x%x thru 0x%x\t(0x%x bytes)",
lp->args[0], lp->args[0] + lp->args[1] - 1,
lp->args[1]);
- if (badoff >= lp->args[0] && badoff <
- lp->args[0] + lp->args[1])
+ if (overlap)
prt("\t******ZZZZ");
break;
case OP_COLLAPSE_RANGE:
prt("COLLAPSE 0x%x thru 0x%x\t(0x%x bytes)",
lp->args[0], lp->args[0] + lp->args[1] - 1,
lp->args[1]);
- if (badoff >= lp->args[0] && badoff <
- lp->args[0] + lp->args[1])
+ if (overlap)
prt("\t******CCCC");
break;
case OP_INSERT_RANGE:
prt("INSERT 0x%x thru 0x%x\t(0x%x bytes)",
lp->args[0], lp->args[0] + lp->args[1] - 1,
lp->args[1]);
- if (badoff >= lp->args[0] && badoff <
- lp->args[0] + lp->args[1])
+ if (overlap)
prt("\t******IIII");
break;
default:
prt("BOGUS LOG ENTRY (operation code = %d)!",
lp->operation);
+ continue;
}
+
skipped:
if (lp->flags & FL_CLOSE_OPEN)
prt("\n\t\tCLOSE/OPEN");
@@ -369,6 +410,30 @@ logdump(void)
i++;
if (i == LOGSIZE)
i = 0;
+
+ if (logopsf) {
+ if (lp->flags & FL_SKIPPED)
+ fprintf(logopsf, "skip ");
+ fprintf(logopsf, "%s 0x%x 0x%x 0x%x",
+ op_name(lp->operation),
+ lp->args[0], lp->args[1], lp->args[2]);
+ if (lp->flags & FL_KEEP_SIZE)
+ fprintf(logopsf, " keep_size");
+ if (lp->flags & FL_CLOSE_OPEN)
+ fprintf(logopsf, " close_open");
+ if (overlap)
+ fprintf(logopsf, " *");
+ fprintf(logopsf, "\n");
+ }
+ }
+
+ if (logopsf) {
+ if (fclose(logopsf) != 0)
+ prterr(opsfile);
+ else
+ prt("Log of operations saved to \"%s\"; "
+ "replay with --replay-ops\n",
+ opsfile);
}
}

@@ -1206,12 +1271,78 @@ do { \
TRIM_LEN(off, len, size); \
} while (0)

-void
+void cleanup();
+
+static int
+read_op(struct log_entry *log_entry)
+{
+ char line[256];
+
+ memset(log_entry, 0, sizeof(*log_entry));
+ log_entry->operation = -1;
+
+ while (log_entry->operation == -1) {
+ char *str;
+ int i;
+
+ do {
+ if (!fgets(line, sizeof(line), replayopsf)) {
+ if (feof(replayopsf)) {
+ replayopsf = NULL;
+ return 0;
+ }
+ goto fail;
+ }
+ str = strtok(line, " \t\n");
+ } while (!str);
+
+ if (strcmp(str, "skip") == 0) {
+ log_entry->flags |= FL_SKIPPED;
+ str = strtok(NULL, " \t\n");
+ if (!str)
+ goto fail;
+ }
+ log_entry->operation = op_code(str);
+ if (log_entry->operation == -1)
+ goto fail;
+ for (i = 0; i < 3; i++) {
+ char *end;
+
+ str = strtok(NULL, " \t\n");
+ if (!str)
+ goto fail;
+ log_entry->args[i] = strtoul(str, &end, 0);
+ if (*end)
+ goto fail;
+ }
+ while ((str = strtok(NULL, " \t\n"))) {
+ if (strcmp(str, "keep_size") == 0)
+ log_entry->flags |= FL_KEEP_SIZE;
+ else if (strcmp(str, "close_open") == 0)
+ log_entry->flags |= FL_CLOSE_OPEN;
+ else if (strcmp(str, "*") == 0)
+ ; /* overlap marker; ignore */
+ else
+ goto fail;
+ }
+ }
+ return 1;
+
+fail:
+ fprintf(stderr, "%s: parse error\n", replayops);
+ fclose(replayopsf);
+ replayopsf = NULL;
+ cleanup(100); /* doesn't return */
+ return 0;
+}
+
+
+int
test(void)
{
unsigned long offset;
- unsigned long size = maxoplen;
- unsigned long rv = random();
+ unsigned long size;
+ unsigned long rv;
unsigned long op;
int keep_size = 0;

@@ -1220,16 +1351,39 @@ test(void)

testcalls++;

- if (closeprob)
- closeopen = (rv >> 3) < (1 << 28) / closeprob;
-
if (debugstart > 0 && testcalls >= debugstart)
debug = 1;

if (!quiet && testcalls < simulatedopcount && testcalls % 100000 == 0)
prt("%lu...\n", testcalls);

+ if (replayopsf) {
+ struct log_entry log_entry;
+
+ while (read_op(&log_entry)) {
+ if (log_entry.flags & FL_SKIPPED) {
+ log4(log_entry.operation,
+ log_entry.args[0], log_entry.args[1],
+ log_entry.flags);
+ continue;
+ }
+
+ op = log_entry.operation;
+ offset = log_entry.args[0];
+ size = log_entry.args[1];
+ closeopen = !!(log_entry.flags & FL_CLOSE_OPEN);
+ keep_size = !!(log_entry.flags & FL_KEEP_SIZE);
+ goto have_op;
+ }
+ return 0;
+ }
+
+ rv = random();
+ if (closeprob)
+ closeopen = (rv >> 3) < (1 << 28) / closeprob;
+
offset = random();
+ size = maxoplen;
if (randomoplen)
size = random() % (maxoplen + 1);

@@ -1240,6 +1394,10 @@ test(void)
op = rv % OP_MAX_FULL;

switch(op) {
+ case OP_TRUNCATE:
+ if (!style)
+ size = random() % maxfilelen;
+ break;
case OP_FALLOCATE:
if (fallocate_calls && size && keep_size_calls)
keep_size = random() % 2;
@@ -1250,6 +1408,8 @@ test(void)
break;
}

+have_op:
+
switch (op) {
case OP_MAPREAD:
if (!mapped_reads)
@@ -1313,8 +1473,6 @@ test(void)
break;

case OP_TRUNCATE:
- if (!style)
- size = random() % maxfilelen;
dotruncate(size);
break;

@@ -1368,6 +1526,7 @@ out:
check_size();
if (closeopen)
docloseopen();
+ return 1;
}

@@ -1594,6 +1753,11 @@ __test_fallocate(int mode, const char *mode_str)
#endif
}

+static struct option longopts[] = {
+ {"replay-ops", required_argument, 0, 256},
+ { }
+};
+
int
main(int argc, char **argv)
{
@@ -1613,8 +1777,9 @@ main(int argc, char **argv)

setvbuf(stdout, (char *)0, _IOLBF, 0); /* line buffered stdout */

- while ((ch = getopt(argc, argv, "b:c:dfl:m:no:p:qr:s:t:w:xyAD:FKHzCILN:OP:RS:WZ"))
- != EOF)
+ while ((ch = getopt_long(argc, argv,
+ "b:c:dfl:m:no:p:qr:s:t:w:xyAD:FKHzCILN:OP:RS:WZ",
+ longopts, NULL)) != EOF)
switch (ch) {
case 'b':
simulatedopcount = getnum(optarg, &endp);
@@ -1762,6 +1927,9 @@ main(int argc, char **argv)
case 'Z':
o_direct = O_DIRECT;
break;
+ case 256: /* --replay-ops */
+ replayops = optarg;
+ break;
default:
usage();
/* NOTREACHED */
@@ -1827,6 +1995,17 @@ main(int argc, char **argv)
prterr(logfile);
exit(93);
}
+ strncat(opsfile, fname, 256);
+ strcat(opsfile, ".fsxops");
+ unlink(opsfile);
+
+ if (replayops) {
+ replayopsf = fopen(replayops, "r");
+ if (!replayopsf) {
+ prterr(replayops);
+ exit(93);
+ }
+ }

#ifdef AIO
if (aio)
@@ -1889,7 +2068,8 @@ main(int argc, char **argv)
insert_range_calls = test_fallocate(FALLOC_FL_INSERT_RANGE);

while (numops == -1 || numops--)
- test();
+ if (!test())
+ break;

if (close(fd)) {
prterr("close");
--
2.4.3