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
        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
 
 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
 
 
 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);
 
        if (ret > 0)
                ret = fifo_put(fifo, buf, ret);
 

+       dprint(FD_BLKTRACE, "refill: filled %d bytes\n", ret);

        return 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;
 
        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);
 }
 
        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)) {
                        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;
                        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");
                        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);
                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;
 
        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);
 }
 
        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)
 {
 
 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;
 }
 
        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 {
 }
 
 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;
 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)
        } 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");
 }
 
        printf("\t          \tMay be \"always\", \"never\" or \"auto\"\n");
 }
 

-struct debug_level {
-       const char *name;
-       unsigned long mask;
-};
-

 struct debug_level debug_levels[] = {
 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);
                }
                        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;
        }
 
                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;
                        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;
                        }
                }
                                break;
                        }
                }


@@ -933,7 +933,6 @@ static int parse_cmd_line(int argc, char *argv[])
        return ini_idx;
 }
 
        return ini_idx;
 }
 

-

 int parse_options(int argc, char *argv[])
 {
        int job_files, i;
 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:
 {
        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:
                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:
                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;
 
                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;
                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);
 
 {
        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,
        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,
        };
 
                .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));
 
        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,
        };
 
                .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));
 
        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;
 
        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) {
        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;
 
        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) {
        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;
 
        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) {
        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;
 
        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) {
        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,
        };
 
                .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));
 
        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) {
                }
 
                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,
                        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:
                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:
                        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:
                        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:
                        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:
                        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:
                        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:
                        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:
                        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:
                        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 ((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;
                                return 1;

+                       }

                }
 
                get_file(ipo->file);
                }
 
                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);
                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;
        }
 
                return 0;
        }
 

+       dprint(FD_VERIFY, "get_next_verify: empty\n");

        return 1;
 }
        return 1;
 }