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 a13151ce5ce0720715bbc27926cde4eb135ea79e..4c58d376a5e7c8b6caa7a91a589f3d9b20bef5a3 100644 (file)
--- a/README
+++ b/README
@@ -95,10 +95,13 @@ options in fio. Currently the options are:
        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 64e49f5e4b552d3d4e67dea8ca7eed5dcf6e589e..538bcd71b9091b02b558d362fafabc6b15b630c2 100644 (file)
--- a/blktrace.c
+++ b/blktrace.c
@@ -34,6 +34,7 @@ static int refill_fifo(struct thread_data *td, struct fifo *fifo, int fd)
        if (ret > 0)
                ret = fifo_put(fifo, buf, ret);
 
+       dprint(FD_BLKTRACE, "refill: filled %d bytes\n", ret);
        return ret;
 }
 
@@ -62,6 +63,7 @@ static int discard_pdu(struct thread_data *td, struct fifo *fifo, int fd,
        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 @@ static int lookup_device(char *path, unsigned int maj, unsigned int min)
                        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 @@ static void trace_add_file(struct thread_data *td, __u32 device)
                        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 @@ static void store_ipo(struct thread_data *td, unsigned long long offset,
        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 841b59a5ae3111c588338b10ef9c2477d6f5740e..04a06bac1bee010b82866de1ade9ffd5178f3d7f 100644 (file)
--- a/fio.c
+++ b/fio.c
@@ -60,8 +60,8 @@ struct io_log *agg_io_log[2];
 
 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 b21ec18d787821dbefb4c2b9987b1de9bf236c93..c86e4629afef3116dd32cabf123a6d4bf3e94837 100644 (file)
--- a/fio.h
+++ b/fio.h
@@ -973,18 +973,29 @@ static inline void clear_error(struct thread_data *td)
 }
 
 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 3c0af71da10d9639ec864f4296db4f30aa8974d9..7fd38ad8e0c433491b9dcffb79376bc931f66471 100644 (file)
--- a/init.c
+++ b/init.c
@@ -779,16 +779,13 @@ static void usage(const char *name)
        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 @@ static void set_debug(const char *string)
                        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 @@ static void set_debug(const char *string)
                        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 @@ static int parse_cmd_line(int argc, char *argv[])
        return ini_idx;
 }
 
-
 int parse_options(int argc, char *argv[])
 {
        int job_files, i;

diff --git a/verify.c b/verify.c
index 3cda3267c9f7262f88aa59f71dfb33614d0fcdf6..c9f2374391d6c74eb6278406bc50e63270149c67 100644 (file)
--- a/verify.c
+++ b/verify.c
@@ -43,9 +43,11 @@ static void fill_pattern(struct thread_data *td, void *p, unsigned int len)
 {
        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 @@ static void fill_pattern(struct thread_data *td, void *p, unsigned int len)
                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 @@ static int verify_io_u_meta(struct verify_header *hdr, struct thread_data *td,
 {
        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 @@ static int verify_io_u_sha512(struct verify_header *hdr, struct io_u *io_u,
                .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 @@ static int verify_io_u_sha256(struct verify_header *hdr, struct io_u *io_u,
                .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 @@ static int verify_io_u_crc7(struct verify_header *hdr, struct io_u *io_u,
        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 @@ static int verify_io_u_crc16(struct verify_header *hdr, struct io_u *io_u,
        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 @@ static int verify_io_u_crc64(struct verify_header *hdr, struct io_u *io_u,
        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 @@ static int verify_io_u_crc32(struct verify_header *hdr, struct io_u *io_u,
        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 @@ static int verify_io_u_md5(struct verify_header *hdr, struct io_u *io_u,
                .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 @@ int verify_io_u(struct thread_data *td, struct io_u *io_u)
                }
 
                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 @@ void populate_verify_io_u(struct thread_data *td, struct io_u *io_u)
                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 @@ int get_next_verify(struct thread_data *td, struct io_u *io_u)
                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 @@ int get_next_verify(struct thread_data *td, struct io_u *io_u)
                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;
 }