From ee56ad500f6692381e131cc37299d23fa910a24a Mon Sep 17 00:00:00 2001
From: Jens Axboe <jens.axboe@oracle.com>
Date: Fri, 1 Feb 2008 10:30:20 +0100
Subject: [PATCH] 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>
---
 README      | 13 ++++++++++++
 filesetup.c | 21 ++++++++++++++++++
 fio.c       | 12 ++++++++++-
 fio.h       | 15 +++++++++++++
 init.c      | 61 +++++++++++++++++++++++++++++++++++++++++++++++++++++
 ioengines.c | 39 ++++++++++++++++++++++++++++------
 log.c       |  3 +++
 memory.c    | 16 ++++++++++++--
 8 files changed, 171 insertions(+), 9 deletions(-)

diff --git a/README b/README
index 3ef13eaa..a13151ce 100644
--- 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
 --------
diff --git a/filesetup.c b/filesetup.c
index f5092202..20ef3f8f 100644
--- a/filesetup.c
+++ b/filesetup.c
@@ -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 5a3fddf0..2ee7dcaf 100644
--- 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 09bf6a20..2daeb2a6 100644
--- 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 4762a815..dcad1b39 100644
--- 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;
diff --git a/ioengines.c b/ioengines.c
index 9aacc335..c0e30c9b 100644
--- a/ioengines.c
+++ b/ioengines.c
@@ -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 039e74b2..5b21ee22 100644
--- 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);
 
diff --git a/memory.c b/memory.c
index 5678350f..be1fd24c 100644
--- 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);
-- 
2.25.1