Add --debug for enabling internal dumps on various actions
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>
diff --git a/README b/README
index 3ef13ea..a13151c 100644
--- a/README
+++ b/README
@@ -62,6 +62,7 @@
------------
$ 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 @@
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
--------
diff --git a/filesetup.c b/filesetup.c
index f509220..20ef3f8 100644
--- a/filesetup.c
+++ b/filesetup.c
@@ -44,6 +44,7 @@
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 @@
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 ret = 0;
+ dprint(FD_IO, "invalidate cache (%d)\n", td->o.odirect);
+
if (td->o.odirect)
return 0;
@@ -204,6 +211,7 @@
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 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 @@
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 @@
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 @@
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 @@
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 @@
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
--- a/fio.c
+++ b/fio.c
@@ -60,6 +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);
td->runstate = runstate;
}
@@ -70,6 +72,7 @@
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 @@
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 @@
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 @@
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
--- a/fio.h
+++ b/fio.h
@@ -972,4 +972,19 @@
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
--- a/init.c
+++ b/init.c
@@ -43,6 +43,8 @@
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.
@@ -104,6 +106,11 @@
.val = 'e',
},
{
+ .name = "debug",
+ .has_arg = required_argument,
+ .val = 'd',
+ },
+ {
.name = NULL,
},
};
@@ -758,6 +765,7 @@
{
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 @@
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 @@
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;
diff --git a/ioengines.c b/ioengines.c
index 9aacc33..c0e30c9 100644
--- a/ioengines.c
+++ b/ioengines.c
@@ -56,12 +56,14 @@
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 @@
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 *ops, *ret;
char engine[16];
+ dprint(FD_IO, "load ioengine %s\n", name);
+
strncpy(engine, name, sizeof(engine) - 1);
/*
@@ -145,6 +151,8 @@
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 @@
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_getevents(struct thread_data *td, unsigned int min, unsigned int max,
struct timespec *t)
{
+ int r = 0;
+
if (min > 0 && td->io_ops->commit) {
- int r = td->io_ops->commit(td);
-
+ 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_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
--- a/log.c
+++ b/log.c
@@ -84,6 +84,9 @@
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);
diff --git a/memory.c b/memory.c
index 5678350..be1fd24 100644
--- a/memory.c
+++ b/memory.c
@@ -12,6 +12,7 @@
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 @@
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 @@
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 @@
}
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 @@
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 @@
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 @@
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);