Add --debug for enabling internal dumps on various actions
authorJens Axboe <jens.axboe@oracle.com>
Fri, 1 Feb 2008 09:30:20 +0000 (10:30 +0100)
committerJens Axboe <jens.axboe@oracle.com>
Fri, 1 Feb 2008 09:30:20 +0000 (10:30 +0100)
A little weak currently, when it's fully integrated everywhere in
fio it'll help find fio problems that I can't trigger.

Signed-off-by: Jens Axboe <jens.axboe@oracle.com>
README
filesetup.c
fio.c
fio.h
init.c
ioengines.c
log.c
memory.c

diff --git a/README b/README
index 3ef13ea..a13151c 100644 (file)
--- a/README
+++ b/README
@@ -62,6 +62,7 @@ Command line
 ------------
 
 $ fio
+        --debug         Enable some debugging options (see below)
         --output        Write output to file
         --runtime       Runtime in seconds
         --latency-log   Generate per-job latency logs
@@ -87,6 +88,18 @@ if rw=write/randwrite/rw/randrw is given, but this extra safety net can
 be used as an extra precaution. It will also enable a write check in the
 io engine core to prevent an accidental write due to a fio bug.
 
+The debug switch allows adding options that trigger certain logging
+options in fio. Currently the options are:
+
+       process         Dump info related to processes
+       file            Dump info related to file actions
+       io              Dump info related to IO queuing
+       mem             Dump info related to memory allocations
+
+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.
+
 
 Job file
 --------
index f509220..20ef3f8 100644 (file)
@@ -44,6 +44,7 @@ static int extend_file(struct thread_data *td, struct fio_file *f)
        if (new_layout)
                flags |= O_TRUNC;
 
+       dprint(FD_FILE, "open file %s, flags %x\n", f->file_name, flags);
        f->fd = open(f->file_name, flags, 0644);
        if (f->fd < 0) {
                td_verror(td, errno, "open");
@@ -53,11 +54,15 @@ static int extend_file(struct thread_data *td, struct fio_file *f)
        if (!new_layout)
                goto done;
 
+       dprint(FD_FILE, "truncate file %s, size %llu\n", f->file_name,
+                                                       f->real_file_size);
        if (ftruncate(f->fd, f->real_file_size) == -1) {
                td_verror(td, errno, "ftruncate");
                goto err;
        }
 
+       dprint(FD_FILE, "fallocate file %s, size %llu\n", f->file_name,
+                                                       f->real_file_size);
        if (posix_fallocate(f->fd, 0, f->real_file_size) < 0) {
                td_verror(td, errno, "posix_fallocate");
                goto err;
@@ -172,6 +177,8 @@ int file_invalidate_cache(struct thread_data *td, struct fio_file *f)
 {
        int ret = 0;
 
+       dprint(FD_IO, "invalidate cache (%d)\n", td->o.odirect);
+
        if (td->o.odirect)
                return 0;
 
@@ -204,6 +211,7 @@ int file_invalidate_cache(struct thread_data *td, struct fio_file *f)
 
 void generic_close_file(struct thread_data fio_unused *td, struct fio_file *f)
 {
+       dprint(FD_FILE, "fd close %s\n", f->file_name);
        close(f->fd);
        f->fd = -1;
 }
@@ -213,6 +221,8 @@ int generic_open_file(struct thread_data *td, struct fio_file *f)
        int is_std = 0;
        int flags = 0;
 
+       dprint(FD_FILE, "fd open %s\n", f->file_name);
+
        if (!strcmp(f->file_name, "-")) {
                if (td_rw(td)) {
                        log_err("fio: can't read/write to stdin/out\n");
@@ -288,6 +298,8 @@ int open_files(struct thread_data *td)
        unsigned int i;
        int err = 0;
 
+       dprint(FD_FILE, "open files\n");
+
        for_each_file(td, f, i) {
                err = td_io_open_file(td, f);
                if (err) {
@@ -351,6 +363,8 @@ int setup_files(struct thread_data *td)
        unsigned int i;
        int err = 0, need_extend;
 
+       dprint(FD_FILE, "setup files\n");
+
        /*
         * if ioengine defines a setup() method, it's responsible for
         * opening the files and setting f->real_file_size to indicate
@@ -506,6 +520,8 @@ void close_files(struct thread_data *td)
        struct fio_file *f;
        unsigned int i;
 
+       dprint(FD_FILE, "close files\n");
+
        for_each_file(td, f, i) {
                if (td->o.unlink && f->filetype == FIO_TYPE_FILE)
                        unlink(f->file_name);
@@ -553,6 +569,8 @@ int add_file(struct thread_data *td, const char *fname)
        struct fio_file *f;
        int len = 0;
 
+       dprint(FD_FILE, "add file %s\n", fname);
+
        td->files = realloc(td->files, (cur_files + 1) * sizeof(*f));
 
        f = &td->files[cur_files];
@@ -582,12 +600,15 @@ int add_file(struct thread_data *td, const char *fname)
 
 void get_file(struct fio_file *f)
 {
+       dprint(FD_FILE, "get file %s/%d\n", f->file_name, f->references);
        assert(f->flags & FIO_FILE_OPEN);
        f->references++;
 }
 
 void put_file(struct thread_data *td, struct fio_file *f)
 {
+       dprint(FD_FILE, "get put %s/%d\n", f->file_name, f->references);
+
        if (!(f->flags & FIO_FILE_OPEN))
                return;
 
diff --git a/fio.c b/fio.c
index 5a3fddf..2ee7dca 100644 (file)
--- a/fio.c
+++ b/fio.c
@@ -60,6 +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);
        td->runstate = runstate;
 }
 
@@ -70,6 +72,7 @@ static void terminate_threads(int group_id)
 
        for_each_td(td, i) {
                if (group_id == TERMINATE_ALL || groupid == td->groupid) {
+                       dprint(FD_PROCESS, "setting terminate on %d\n",td->pid);
                        /*
                         * if the thread is running, just let it exit
                         */
@@ -806,6 +809,8 @@ static void *thread_main(void *data)
 
        td->pid = getpid();
 
+       dprint(FD_PROCESS, "jobs pid=%d started\n", td->pid);
+
        INIT_LIST_HEAD(&td->io_u_freelist);
        INIT_LIST_HEAD(&td->io_u_busylist);
        INIT_LIST_HEAD(&td->io_u_requeues);
@@ -1068,8 +1073,11 @@ reaped:
                if (td->o.use_thread) {
                        long ret;
 
-                       if (pthread_join(td->thread, (void *) &ret))
+                       dprint(FD_PROCESS, "joining tread %d\n", td->pid);
+                       if (pthread_join(td->thread, (void *) &ret)) {
+                               dprint(FD_PROCESS, "join failed %ld\n", ret);
                                perror("pthread_join");
+                       }
                }
 
                (*nr_running)--;
@@ -1184,12 +1192,14 @@ static void run_threads(void)
                        nr_started++;
 
                        if (td->o.use_thread) {
+                               dprint(FD_PROCESS, "will pthread_create\n");
                                if (pthread_create(&td->thread, NULL, thread_main, td)) {
                                        perror("thread_create");
                                        nr_started--;
                                        break;
                                }
                        } else {
+                               dprint(FD_PROCESS, "will fork\n");
                                if (!fork()) {
                                        int ret = fork_main(shm_id, i);
 
diff --git a/fio.h b/fio.h
index 09bf6a2..2daeb2a 100644 (file)
--- a/fio.h
+++ b/fio.h
@@ -972,4 +972,19 @@ static inline void clear_error(struct thread_data *td)
        td->verror[0] = '\0';
 }
 
+enum {
+       FD_PROCESS      = 1 << 0,
+       FD_FILE         = 1 << 1,
+       FD_IO           = 1 << 2,
+       FD_MEM          = 1 << 3,
+};
+
+extern unsigned long fio_debug;
+#define dprint(type, str, args...)             \
+       do {                                    \
+               if (((type) & fio_debug) == 0)  \
+                       break;                  \
+               printf(str, ##args);            \
+       } while (0)
+
 #endif
diff --git a/init.c b/init.c
index 4762a81..dcad1b3 100644 (file)
--- a/init.c
+++ b/init.c
@@ -43,6 +43,8 @@ static int write_lat_log = 0;
 
 static int prev_group_jobs;
 
+unsigned long fio_debug = 0;
+
 /*
  * Command line options. These will contain the above, plus a few
  * extra that only pertain to fio itself and not jobs.
@@ -103,6 +105,11 @@ static struct option long_options[FIO_NR_OPTIONS] = {
                .has_arg        = required_argument,
                .val            = 'e',
        },
+       {
+               .name           = "debug",
+               .has_arg        = required_argument,
+               .val            = 'd',
+       },
        {
                .name           = NULL,
        },
@@ -758,6 +765,7 @@ static void usage(const char *name)
 {
        printf("%s\n", fio_version_string);
        printf("%s [options] [job options] <job file(s)>\n", name);
+       printf("\t--debug=options\tEnable debug logging\n");
        printf("\t--output\tWrite output to file\n");
        printf("\t--timeout\tRuntime in seconds\n");
        printf("\t--latency-log\tGenerate per-job latency logs\n");
@@ -771,6 +779,56 @@ 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_PROCESS, },
+       { .name = "io", .mask = FD_IO, },
+       { .name = "mem", .mask = FD_MEM, },
+       { },
+};
+
+static void set_debug(const char *string)
+{
+       struct debug_level *dl;
+       char *p = (char *) string;
+       char *opt;
+       int i;
+
+       if (!strcmp(string, "?") || !strcmp(string, "help")) {
+               int i;
+
+               log_info("fio: dumping debug options:");
+               for (i = 0; debug_levels[i].name; i++) {
+                       dl = &debug_levels[i];
+                       log_info("%s,", dl->name);
+               }
+               log_info("\n");
+               return;
+       }
+
+       while ((opt = strsep(&p, ",")) != NULL) {
+               int found = 0;
+
+               for (i = 0; debug_levels[i].name; i++) {
+                       dl = &debug_levels[i];
+                       if (!strncmp(opt, dl->name, strlen(opt))) {
+                               log_info("fio: set debug option %s\n", opt);
+                               found = 1;
+                               fio_debug |= dl->mask;
+                               break;
+                       }
+               }
+
+               if (!found)
+                       log_err("fio: debug mask %s not found\n", opt);
+       }
+}
+
 static int parse_cmd_line(int argc, char *argv[])
 {
        struct thread_data *td = NULL;
@@ -818,6 +876,9 @@ static int parse_cmd_line(int argc, char *argv[])
                        else if (!strcmp("never", optarg))
                                eta_print = FIO_ETA_NEVER;
                        break;
+               case 'd':
+                       set_debug(optarg);
+                       break;
                case FIO_GETOPT_JOB: {
                        const char *opt = long_options[lidx].name;
                        char *val = optarg;
index 9aacc33..c0e30c9 100644 (file)
@@ -56,12 +56,14 @@ static int check_engine_ops(struct ioengine_ops *ops)
 
 void unregister_ioengine(struct ioengine_ops *ops)
 {
+       dprint(FD_IO, "ioengine %s unregistered\n", ops->name);
        list_del(&ops->list);
        INIT_LIST_HEAD(&ops->list);
 }
 
 void register_ioengine(struct ioengine_ops *ops)
 {
+       dprint(FD_IO, "ioengine %s registered\n", ops->name);
        INIT_LIST_HEAD(&ops->list);
        list_add_tail(&ops->list, &engine_list);
 }
@@ -86,6 +88,8 @@ static struct ioengine_ops *dlopen_ioengine(struct thread_data *td,
        struct ioengine_ops *ops;
        void *dlhandle;
 
+       dprint(FD_IO, "dload engine %s\n", engine_lib);
+
        dlerror();
        dlhandle = dlopen(engine_lib, RTLD_LAZY);
        if (!dlhandle) {
@@ -113,6 +117,8 @@ struct ioengine_ops *load_ioengine(struct thread_data *td, const char *name)
        struct ioengine_ops *ops, *ret;
        char engine[16];
 
+       dprint(FD_IO, "load ioengine %s\n", name);
+
        strncpy(engine, name, sizeof(engine) - 1);
 
        /*
@@ -145,6 +151,8 @@ struct ioengine_ops *load_ioengine(struct thread_data *td, const char *name)
 
 void close_ioengine(struct thread_data *td)
 {
+       dprint(FD_IO, "close ioengine %s\n", td->io_ops->name);
+
        if (td->io_ops->cleanup)
                td->io_ops->cleanup(td);
 
@@ -155,8 +163,20 @@ void close_ioengine(struct thread_data *td)
        td->io_ops = NULL;
 }
 
+static void dprint_io_u(struct io_u *io_u, const char *p)
+{
+       struct fio_file *f = io_u->file;
+
+       dprint(FD_IO, "%s: off=%llu/len=%lu/ddir=%d", p, io_u->offset,
+                                       io_u->buflen, io_u->ddir);
+       if (f)
+               dprint(FD_IO, "/%s", f->file_name);
+       dprint(FD_IO, "\n");
+}
+
 int td_io_prep(struct thread_data *td, struct io_u *io_u)
 {
+       dprint_io_u(io_u, "prep");
        fio_ro_check(td, io_u);
 
        if (td->io_ops->prep)
@@ -168,22 +188,27 @@ int td_io_prep(struct thread_data *td, struct io_u *io_u)
 int td_io_getevents(struct thread_data *td, unsigned int min, unsigned int max,
                    struct timespec *t)
 {
-       if (min > 0 && td->io_ops->commit) {
-               int r = td->io_ops->commit(td);
+       int r = 0;
 
+       if (min > 0 && td->io_ops->commit) {
+               r = td->io_ops->commit(td);
                if (r < 0)
-                       return r;
+                       goto out;
        }
-       if (td->io_ops->getevents)
-               return td->io_ops->getevents(td, min, max, t);
 
-       return 0;
+       r = 0;
+       if (td->io_ops->getevents)
+               r = td->io_ops->getevents(td, min, max, t);
+out:
+       dprint(FD_IO, "getevents: %d\n", r);
+       return r;
 }
 
 int td_io_queue(struct thread_data *td, struct io_u *io_u)
 {
        int ret;
 
+       dprint_io_u(io_u, "queue");
        fio_ro_check(td, io_u);
 
        assert((io_u->flags & IO_U_F_FLIGHT) == 0);
@@ -253,6 +278,8 @@ int td_io_init(struct thread_data *td)
 
 int td_io_commit(struct thread_data *td)
 {
+       dprint(FD_IO, "calling ->commit(), depth %d\n", td->cur_depth);
+
        if (!td->cur_depth)
                return 0;
 
diff --git a/log.c b/log.c
index 039e74b..5b21ee2 100644 (file)
--- a/log.c
+++ b/log.c
@@ -84,6 +84,9 @@ int read_iolog_get(struct thread_data *td, struct io_u *io_u)
                io_u->file = &td->files[ipo->fileno];
                get_file(io_u->file);
 
+               dprint(FD_IO, "iolog: get %llu/%lu/%s\n", io_u->offset,
+                                       io_u->buflen, io_u->file->file_name);
+
                if (ipo->delay)
                        iolog_delay(td, ipo->delay);
 
index 5678350..be1fd24 100644 (file)
--- a/memory.c
+++ b/memory.c
@@ -12,6 +12,7 @@ static void *pinned_mem;
 void fio_unpin_memory(void)
 {
        if (pinned_mem) {
+               dprint(FD_MEM, "unpinning %llu bytes\n", mlock_size);
                if (munlock(pinned_mem, mlock_size) < 0)
                        perror("munlock");
                munmap(pinned_mem, mlock_size);
@@ -26,6 +27,8 @@ int fio_pin_memory(void)
        if (!mlock_size)
                return 0;
 
+       dprint(FD_MEM, "pinning %llu bytes\n", mlock_size);
+
        /*
         * Don't allow mlock of more than real_mem-128MB
         */
@@ -61,6 +64,7 @@ static int alloc_mem_shm(struct thread_data *td)
                flags |= SHM_HUGETLB;
 
        td->shm_id = shmget(IPC_PRIVATE, td->orig_buffer_size, flags);
+       dprint(FD_MEM, "shmget %zu, %d\n", td->orig_buffer_size, td->shm_id);
        if (td->shm_id < 0) {
                td_verror(td, errno, "shmget");
                if (geteuid() != 0 && errno == ENOMEM)
@@ -78,6 +82,7 @@ static int alloc_mem_shm(struct thread_data *td)
        }
 
        td->orig_buffer = shmat(td->shm_id, NULL, 0);
+       dprint(FD_MEM, "shmat %d, %p\n", td->shm_id, td->orig_buffer);
        if (td->orig_buffer == (void *) -1) {
                td_verror(td, errno, "shmat");
                td->orig_buffer = NULL;
@@ -110,6 +115,8 @@ static int alloc_mem_mmap(struct thread_data *td)
                flags |= OS_MAP_ANON;
 
        td->orig_buffer = mmap(NULL, td->orig_buffer_size, PROT_READ | PROT_WRITE, flags, td->mmapfd, 0);
+       dprint(FD_MEM, "mmap %zu/%d %p\n", td->orig_buffer_size, td->mmapfd,
+                                                       td->orig_buffer);
        if (td->orig_buffer == MAP_FAILED) {
                td_verror(td, errno, "mmap");
                td->orig_buffer = NULL;
@@ -132,6 +139,7 @@ static int alloc_mem_malloc(struct thread_data *td)
                bsize += page_mask;
                
        td->orig_buffer = malloc(bsize);
+       dprint(FD_MEM, "malloc %u %p\n", bsize, td->orig_buffer);
        if (td->orig_buffer)
                return 0;
 
@@ -167,15 +175,19 @@ int allocate_io_mem(struct thread_data *td)
 
 void free_io_mem(struct thread_data *td)
 {
-       if (td->o.mem_type == MEM_MALLOC)
+       if (td->o.mem_type == MEM_MALLOC) {
+               dprint(FD_MEM, "free mem %p\n", td->orig_buffer);
                free(td->orig_buffer);
-       else if (td->o.mem_type == MEM_SHM || td->o.mem_type == MEM_SHMHUGE) {
+       else if (td->o.mem_type == MEM_SHM || td->o.mem_type == MEM_SHMHUGE) {
                struct shmid_ds sbuf;
 
+               dprint(FD_MEM, "shmdt/ctl %d %p\n", td->shm_id,td->orig_buffer);
                shmdt(td->orig_buffer);
                shmctl(td->shm_id, IPC_RMID, &sbuf);
        } else if (td->o.mem_type == MEM_MMAP ||
                   td->o.mem_type == MEM_MMAPHUGE) {
+               dprint(FD_MEM, "munmap %zu %p\n", td->orig_buffer_size,
+                                                       td->orig_buffer);
                munmap(td->orig_buffer, td->orig_buffer_size);
                if (td->mmapfile) {
                        close(td->mmapfd);