From bd6f78b2f0b6375383948f126368804612ec0035 Mon Sep 17 00:00:00 2001 From: Jens Axboe Date: Fri, 1 Feb 2008 20:27:52 +0100 Subject: [PATCH] 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 --- README | 7 +++++-- blktrace.c | 10 +++++++++- fio.c | 4 ++-- fio.h | 29 ++++++++++++++++++++--------- init.c | 23 +++++++++++------------ verify.c | 46 +++++++++++++++++++++++++++++++++++++++++++++- 6 files changed, 92 insertions(+), 27 deletions(-) diff --git a/README b/README index a13151ce..4c58d376 100644 --- 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 64e49f5e..538bcd71 100644 --- 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 841b59a5..04a06bac 100644 --- 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 b21ec18d..c86e4629 100644 --- 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 3c0af71d..7fd38ad8 100644 --- 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 3cda3267..c9f23743 100644 --- 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; } -- 2.25.1