Add blktrace and verify debug tracing
Also add "all" as a keyword for setting all values, and pretty up
the output a bit by justifying and aligning the output.
Signed-off-by: Jens Axboe <jens.axboe@oracle.com>
diff --git a/README b/README
index a13151c..4c58d37 100644
--- a/README
+++ b/README
@@ -95,10 +95,13 @@
file Dump info related to file actions
io Dump info related to IO queuing
mem Dump info related to memory allocations
+ blktrace Dump info related to blktrace setup
+ verify Dump info related to IO verification
+ all Enable all debug options
+ ? or help Show available debug options.
You can specify as many as you want, eg --debug=file,mem will enable
-file and memory debugging. Specifying --debug=help or --debug=? will
-dump the current modifier list.
+file and memory debugging.
Job file
diff --git a/blktrace.c b/blktrace.c
index 64e49f5..538bcd7 100644
--- a/blktrace.c
+++ b/blktrace.c
@@ -34,6 +34,7 @@
if (ret > 0)
ret = fifo_put(fifo, buf, ret);
+ dprint(FD_BLKTRACE, "refill: filled %d bytes\n", ret);
return ret;
}
@@ -62,6 +63,7 @@
if (t->pdu_len == 0)
return 0;
+ dprint(FD_BLKTRACE, "discard pdu len %u\n", t->pdu_len);
return trace_fifo_get(td, fifo, fd, NULL, t->pdu_len);
}
@@ -130,6 +132,7 @@
continue;
if (maj == major(st.st_rdev) && min == minor(st.st_rdev)) {
+ dprint(FD_BLKTRACE, "device lookup: %d/%d\n", maj,min);
strcpy(path, full_path);
found = 1;
break;
@@ -168,8 +171,10 @@
return;
strcpy(dev, "/dev");
- if (lookup_device(dev, maj, min))
+ if (lookup_device(dev, maj, min)) {
+ dprint(FD_BLKTRACE, "add devices %s\n", dev);
add_file(td, dev);
+ }
}
/*
@@ -193,6 +198,9 @@
else
ipo->ddir = DDIR_READ;
+ dprint(FD_BLKTRACE, "store ddir=%d, off=%llu, len=%lu, delay=%lu\n",
+ ipo->ddir, ipo->offset,
+ ipo->len, ipo->delay);
list_add_tail(&ipo->list, &td->io_log_list);
}
diff --git a/fio.c b/fio.c
index 841b59a..04a06ba 100644
--- a/fio.c
+++ b/fio.c
@@ -60,8 +60,8 @@
static inline void td_set_runstate(struct thread_data *td, int runstate)
{
- dprint(FD_PROCESS, "%d: runstate %d -> %d\n", td->pid, td->runstate,
- runstate);
+ dprint(FD_PROCESS, "pid=%d: runstate %d -> %d\n", td->pid, td->runstate,
+ runstate);
td->runstate = runstate;
}
diff --git a/fio.h b/fio.h
index b21ec18..c86e462 100644
--- a/fio.h
+++ b/fio.h
@@ -973,18 +973,29 @@
}
enum {
- FD_PROCESS = 1 << 0,
- FD_FILE = 1 << 1,
- FD_IO = 1 << 2,
- FD_MEM = 1 << 3,
+ FD_PROCESS = 0,
+ FD_FILE,
+ FD_IO,
+ FD_MEM,
+ FD_BLKTRACE,
+ FD_VERIFY,
+ FD_DEBUG_MAX,
};
+struct debug_level {
+ const char *name;
+ unsigned long shift;
+};
+extern struct debug_level debug_levels[];
+
extern unsigned long fio_debug;
-#define dprint(type, str, args...) \
- do { \
- if (((type) & fio_debug) == 0) \
- break; \
- log_info(str, ##args); \
+#define dprint(type, str, args...) \
+ do { \
+ assert(type < FD_DEBUG_MAX); \
+ if ((((1 << type)) & fio_debug) == 0) \
+ break; \
+ log_info("%-8s ", debug_levels[(type)].name); \
+ log_info(str, ##args); \
} while (0)
static inline void dprint_io_u(struct io_u *io_u, const char *p)
diff --git a/init.c b/init.c
index 3c0af71..7fd38ad 100644
--- a/init.c
+++ b/init.c
@@ -779,16 +779,13 @@
printf("\t \tMay be \"always\", \"never\" or \"auto\"\n");
}
-struct debug_level {
- const char *name;
- unsigned long mask;
-};
-
struct debug_level debug_levels[] = {
- { .name = "process", .mask = FD_PROCESS, },
- { .name = "file", .mask = FD_FILE, },
- { .name = "io", .mask = FD_IO, },
- { .name = "mem", .mask = FD_MEM, },
+ { .name = "process", .shift = FD_PROCESS, },
+ { .name = "file", .shift = FD_FILE, },
+ { .name = "io", .shift = FD_IO, },
+ { .name = "mem", .shift = FD_MEM, },
+ { .name = "blktrace", .shift = FD_BLKTRACE },
+ { .name = "verify", .shift = FD_VERIFY },
{ },
};
@@ -807,7 +804,10 @@
dl = &debug_levels[i];
log_info("%s,", dl->name);
}
- log_info("\n");
+ log_info("all\n");
+ return;
+ } else if (!strcmp(string, "all")) {
+ fio_debug = ~0UL;
return;
}
@@ -819,7 +819,7 @@
if (!strncmp(opt, dl->name, strlen(opt))) {
log_info("fio: set debug option %s\n", opt);
found = 1;
- fio_debug |= dl->mask;
+ fio_debug |= (1UL << dl->shift);
break;
}
}
@@ -933,7 +933,6 @@
return ini_idx;
}
-
int parse_options(int argc, char *argv[])
{
int job_files, i;
diff --git a/verify.c b/verify.c
index 3cda326..c9f2374 100644
--- a/verify.c
+++ b/verify.c
@@ -43,9 +43,11 @@
{
switch (td->o.verify_pattern_bytes) {
case 0:
+ dprint(FD_VERIFY, "fill random bytes len=%u\n", len);
fill_random_bytes(td, p, len);
break;
case 1:
+ dprint(FD_VERIFY, "fill verify pattern b=0 len=%u\n", len);
memset(p, td->o.verify_pattern, len);
break;
case 2:
@@ -56,6 +58,9 @@
unsigned char c1, c2, c3, c4;
unsigned char *b = p;
+ dprint(FD_VERIFY, "fill verify pattern b=%d len=%u\n",
+ td->o.verify_pattern_bytes, len);
+
c1 = pattern & 0xff;
pattern >>= 8;
c2 = pattern & 0xff;
@@ -173,6 +178,8 @@
{
struct vhdr_meta *vh = hdr_priv(hdr);
+ dprint(FD_VERIFY, "meta verify io_u %p, len %u\n", io_u, hdr->len);
+
if (vh->offset != io_u->offset + header_num * td->o.verify_interval) {
log_err("meta: verify failed at %llu/%u\n",
io_u->offset + header_num * hdr->len,
@@ -193,6 +200,8 @@
.buf = sha512,
};
+ dprint(FD_VERIFY, "sha512 verify io_u %p, len %u\n", io_u, hdr->len);
+
sha512_init(&sha512_ctx);
sha512_update(&sha512_ctx, p, hdr->len - hdr_size(hdr));
@@ -218,6 +227,8 @@
.buf = sha256,
};
+ dprint(FD_VERIFY, "sha256 verify io_u %p, len %u\n", io_u, hdr->len);
+
sha256_init(&sha256_ctx);
sha256_update(&sha256_ctx, p, hdr->len - hdr_size(hdr));
@@ -240,6 +251,8 @@
struct vhdr_crc7 *vh = hdr_priv(hdr);
unsigned char c;
+ dprint(FD_VERIFY, "crc7 verify io_u %p, len %u\n", io_u, hdr->len);
+
c = crc7(p, hdr->len - hdr_size(hdr));
if (c != vh->crc7) {
@@ -260,6 +273,8 @@
struct vhdr_crc16 *vh = hdr_priv(hdr);
unsigned short c;
+ dprint(FD_VERIFY, "crc16 verify io_u %p, len %u\n", io_u, hdr->len);
+
c = crc16(p, hdr->len - hdr_size(hdr));
if (c != vh->crc16) {
@@ -280,6 +295,8 @@
struct vhdr_crc64 *vh = hdr_priv(hdr);
unsigned long long c;
+ dprint(FD_VERIFY, "crc64 verify io_u %p, len %u\n", io_u, hdr->len);
+
c = crc64(p, hdr->len - hdr_size(hdr));
if (c != vh->crc64) {
@@ -300,6 +317,8 @@
struct vhdr_crc32 *vh = hdr_priv(hdr);
uint32_t c;
+ dprint(FD_VERIFY, "crc32 verify io_u %p, len %u\n", io_u, hdr->len);
+
c = crc32(p, hdr->len - hdr_size(hdr));
if (c != vh->crc32) {
@@ -323,6 +342,8 @@
.hash = hash,
};
+ dprint(FD_VERIFY, "md5 verify io_u %p, len %u\n", io_u, hdr->len);
+
md5_init(&md5_ctx);
md5_update(&md5_ctx, p, hdr->len - hdr_size(hdr));
@@ -406,6 +427,8 @@
}
if (td->o.verify_pattern_bytes) {
+ dprint(FD_VERIFY, "pattern verify io_u %p, len %u\n",
+ io_u, hdr->len);
ret = verify_io_u_pattern(td->o.verify_pattern,
td->o.verify_pattern_bytes,
p + hdr_size,
@@ -558,27 +581,43 @@
data = p + hdr_size(hdr);
switch (td->o.verify) {
case VERIFY_MD5:
+ dprint(FD_VERIFY, "fill md5 io_u %p, len %u\n",
+ io_u, hdr->len);
fill_md5(hdr, data, data_len);
break;
case VERIFY_CRC64:
+ dprint(FD_VERIFY, "fill crc64 io_u %p, len %u\n",
+ io_u, hdr->len);
fill_crc64(hdr, data, data_len);
break;
case VERIFY_CRC32:
+ dprint(FD_VERIFY, "fill crc32 io_u %p, len %u\n",
+ io_u, hdr->len);
fill_crc32(hdr, data, data_len);
break;
case VERIFY_CRC16:
+ dprint(FD_VERIFY, "fill crc16 io_u %p, len %u\n",
+ io_u, hdr->len);
fill_crc16(hdr, data, data_len);
break;
case VERIFY_CRC7:
+ dprint(FD_VERIFY, "fill crc7 io_u %p, len %u\n",
+ io_u, hdr->len);
fill_crc7(hdr, data, data_len);
break;
case VERIFY_SHA256:
+ dprint(FD_VERIFY, "fill sha256 io_u %p, len %u\n",
+ io_u, hdr->len);
fill_sha256(hdr, data, data_len);
break;
case VERIFY_SHA512:
+ dprint(FD_VERIFY, "fill sha512 io_u %p, len %u\n",
+ io_u, hdr->len);
fill_sha512(hdr, data, data_len);
break;
case VERIFY_META:
+ dprint(FD_VERIFY, "fill meta io_u %p, len %u\n",
+ io_u, hdr->len);
fill_meta(hdr, td, io_u, header_num);
break;
default:
@@ -619,8 +658,11 @@
if ((io_u->file->flags & FIO_FILE_OPEN) == 0) {
int r = td_io_open_file(td, io_u->file);
- if (r)
+ if (r) {
+ dprint(FD_VERIFY, "failed file %s open\n",
+ io_u->file->file_name);
return 1;
+ }
}
get_file(ipo->file);
@@ -629,8 +671,10 @@
io_u->xfer_buf = io_u->buf;
io_u->xfer_buflen = io_u->buflen;
free(ipo);
+ dprint(FD_VERIFY, "get_next_verify: ret io_u %p\n", io_u);
return 0;
}
+ dprint(FD_VERIFY, "get_next_verify: empty\n");
return 1;
}