X-Git-Url: https://git.kernel.dk/?p=fio.git;a=blobdiff_plain;f=log.c;h=a327f6aa4c0e68f9e822e349984f31c3d509d9e2;hp=790d3a1e32c9d4c046bb17be0f10f44a74f5fef3;hb=df4bf1178ed773986129da6038961388af926971;hpb=748b23a36509240af1debf5f7f3ca8ef153548ea

diff --git a/log.c b/log.c
index 790d3a1e..a327f6aa 100644
--- a/log.c
+++ b/log.c
@@ -1,473 +1,193 @@
-/*
- * Code related to writing an iolog of what a thread is doing, and to
- * later read that back and replay
- */
-#include <stdio.h>
-#include <stdlib.h>
-#include <assert.h>
-#include "list.h"
-#include "fio.h"
-
-static const char iolog_ver2[] = "fio version 2 iolog";
-
-void queue_io_piece(struct thread_data *td, struct io_piece *ipo)
-{
-	list_add_tail(&ipo->list, &td->io_log_list);
-	td->total_io_size += ipo->len;
-}
-
-void log_io_u(struct thread_data *td, struct io_u *io_u)
-{
-	const char *act[] = { "read", "write", "sync" };
-
-	assert(io_u->ddir < 3);
-
-	if (!td->o.write_iolog_file)
-		return;
-
-	fprintf(td->iolog_f, "%s %s %llu %lu\n", io_u->file->file_name,
-						act[io_u->ddir], io_u->offset,
-						io_u->buflen);
-}
-
-void log_file(struct thread_data *td, struct fio_file *f,
-	      enum file_log_act what)
-{
-	const char *act[] = { "add", "open", "close" };
-
-	assert(what < 3);
-
-	if (!td->o.write_iolog_file)
-		return;
+#include <unistd.h>
+#include <fcntl.h>
+#include <string.h>
+#include <stdarg.h>
+#include <syslog.h>
 
-	fprintf(td->iolog_f, "%s %s\n", f->file_name, act[what]);
-}
-
-static void iolog_delay(struct thread_data *td, unsigned long delay)
-{
-	unsigned long usec = utime_since_now(&td->last_issue);
-
-	if (delay < usec)
-		return;
-
-	delay -= usec;
+#include "fio.h"
 
-	/*
-	 * less than 100 usec delay, just regard it as noise
-	 */
-	if (delay < 100)
-		return;
+#define LOG_START_SZ		512
 
-	usec_sleep(td, delay);
-}
-
-static int ipo_special(struct thread_data *td, struct io_piece *ipo)
+size_t log_info_buf(const char *buf, size_t len)
 {
-	struct fio_file *f;
-	int ret;
-
 	/*
-	 * Not a special ipo
+	 * buf could be NULL (not just "").
 	 */
-	if (ipo->ddir != DDIR_INVAL)
+	if (!buf)
 		return 0;
 
-	f = td->files[ipo->fileno];
-
-	switch (ipo->file_action) {
-	case FIO_LOG_OPEN_FILE:
-		ret = td_io_open_file(td, f);
-		if (!ret) {
-			free(ipo);
-			break;
-		}
-		td_verror(td, ret, "iolog open file");
-		return -1;
-	case FIO_LOG_CLOSE_FILE:
-		td_io_close_file(td, f);
-		break;
-	case FIO_LOG_UNLINK_FILE:
-		unlink(f->file_name);
-		break;
-	default:
-		log_err("fio: bad file action %d\n", ipo->file_action);
-		break;
+	if (is_backend) {
+		size_t ret = fio_server_text_output(FIO_LOG_INFO, buf, len);
+		if (ret != -1)
+			return ret;
 	}
 
-	return 1;
+	if (log_syslog) {
+		syslog(LOG_INFO, "%s", buf);
+		return len;
+	} else
+		return fwrite(buf, len, 1, f_out);
 }
 
-int read_iolog_get(struct thread_data *td, struct io_u *io_u)
+static size_t valist_to_buf(char **buffer, const char *fmt, va_list src_args)
 {
-	struct io_piece *ipo;
+	size_t len, cur = LOG_START_SZ;
+	va_list args;
 
-	while (!list_empty(&td->io_log_list)) {
-		int ret;
+	do {
+		*buffer = calloc(1, cur);
+		if (!*buffer)
+			return 0;
 
-		ipo = list_entry(td->io_log_list.next, struct io_piece, list);
-		list_del(&ipo->list);
+		va_copy(args, src_args);
+		len = vsnprintf(*buffer, cur, fmt, args);
+		va_end(args);
 
-		ret = ipo_special(td, ipo);
-		if (ret < 0) {
-			free(ipo);
+		if (len < cur)
 			break;
-		} else if (ret > 0) {
-			free(ipo);
-			continue;
-		}
-
-		io_u->offset = ipo->offset;
-		io_u->buflen = ipo->len;
-		io_u->ddir = ipo->ddir;
-		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);
-
-		free(ipo);
-		return 0;
-	}
-
-	td->done = 1;
-	return 1;
-}
-
-void prune_io_piece_log(struct thread_data *td)
-{
-	struct io_piece *ipo;
-	struct rb_node *n;
-
-	while ((n = rb_first(&td->io_hist_tree)) != NULL) {
-		ipo = rb_entry(n, struct io_piece, rb_node);
-		rb_erase(n, &td->io_hist_tree);
-		free(ipo);
-	}
+		cur = len + 1;
+		free(*buffer);
+	} while (1);
 
-	while (!list_empty(&td->io_hist_list)) {
-		ipo = list_entry(td->io_hist_list.next, struct io_piece, list);
-		list_del(&ipo->list);
-		free(ipo);
-	}
+	return len;
 }
 
-/*
- * log a successful write, so we can unwind the log for verify
- */
-void log_io_piece(struct thread_data *td, struct io_u *io_u)
+/* allocate buffer, fill with prefix string followed by vararg string */
+static size_t prevalist_to_buf(char **buffer, const char *pre, int prelen,
+		const char *fmt, va_list src_args)
 {
-	struct rb_node **p, *parent;
-	struct io_piece *ipo, *__ipo;
+	size_t len, cur = LOG_START_SZ;
+	va_list args;
 
-	ipo = malloc(sizeof(struct io_piece));
-	ipo->file = io_u->file;
-	ipo->offset = io_u->offset;
-	ipo->len = io_u->buflen;
+	do {
+		*buffer = calloc(1, cur);
+		if (!*buffer)
+			return 0;
 
-	/*
-	 * We don't need to sort the entries, if:
-	 *
-	 *	Sequential writes, or
-	 *	Random writes that lay out the file as it goes along
-	 *
-	 * For both these cases, just reading back data in the order we
-	 * wrote it out is the fastest.
-	 */
-	if (!td_random(td) || !td->o.overwrite) {
-		INIT_LIST_HEAD(&ipo->list);
-		list_add_tail(&ipo->list, &td->io_hist_list);
-		return;
-	}
+		va_copy(args, src_args);
+		memcpy(*buffer, pre, prelen);
+		len = prelen + vsnprintf(*buffer + prelen, cur - prelen, fmt, args);
+		va_end(args);
 
-	RB_CLEAR_NODE(&ipo->rb_node);
-	p = &td->io_hist_tree.rb_node;
-	parent = NULL;
+		if (len < cur)
+			break;
 
-	/*
-	 * Sort the entry into the verification list
-	 */
-	while (*p) {
-		parent = *p;
-
-		__ipo = rb_entry(parent, struct io_piece, rb_node);
-		if (ipo->offset <= __ipo->offset)
-			p = &(*p)->rb_left;
-		else
-			p = &(*p)->rb_right;
-	}
+		cur = len + 1;
+		free(*buffer);
+	} while (1);
 
-	rb_link_node(&ipo->rb_node, parent, p);
-	rb_insert_color(&ipo->rb_node, &td->io_hist_tree);
+	return len;
 }
 
-void write_iolog_close(struct thread_data *td)
+size_t log_valist(const char *fmt, va_list args)
 {
-	fflush(td->iolog_f);
-	fclose(td->iolog_f);
-	free(td->iolog_buf);
-	td->iolog_f = NULL;
-	td->iolog_buf = NULL;
-}
+	char *buffer;
+	size_t len;
 
-/*
- * Read version 2 iolog data. It is enhanced to include per-file logging,
- * syncs, etc.
- */
-static int read_iolog2(struct thread_data *td, FILE *f)
-{
-	unsigned long long offset;
-	unsigned int bytes;
-	int reads, writes, fileno = 0, file_action = 0; /* stupid gcc */
-	char *fname, *act;
-	char *str, *p;
-	enum fio_ddir rw;
+	len = valist_to_buf(&buffer, fmt, args);
+	len = log_info_buf(buffer, len);
+	free(buffer);
 
-	free_release_files(td);
+	return len;
+}
 
-	/*
-	 * Read in the read iolog and store it, reuse the infrastructure
-	 * for doing verifications.
-	 */
-	str = malloc(4096);
-	fname = malloc(256+16);
-	act = malloc(256+16);
-
-	reads = writes = 0;
-	while ((p = fgets(str, 4096, f)) != NULL) {
-		struct io_piece *ipo;
-		int r;
-
-		r = sscanf(p, "%256s %256s %llu %u", fname, act, &offset,
-									&bytes);
-		if (r == 4) {
-			/*
-			 * Check action first
-			 */
-			if (!strcmp(act, "read"))
-				rw = DDIR_READ;
-			else if (!strcmp(act, "write"))
-				rw = DDIR_WRITE;
-			else if (!strcmp(act, "sync"))
-				rw = DDIR_SYNC;
-			else {
-				log_err("fio: bad iolog file action: %s\n",
-									act);
-				continue;
-			}
-		} else if (r == 2) {
-			rw = DDIR_INVAL;
-			if (!strcmp(act, "add")) {
-				td->o.nr_files++;
-				fileno = add_file(td, fname);
-				file_action = FIO_LOG_ADD_FILE;
-				continue;
-			} else if (!strcmp(act, "open")) {
-				fileno = get_fileno(td, fname);
-				file_action = FIO_LOG_OPEN_FILE;
-			} else if (!strcmp(act, "close")) {
-				fileno = get_fileno(td, fname);
-				file_action = FIO_LOG_CLOSE_FILE;
-			} else {
-				log_err("fio: bad iolog file action: %s\n",
-									act);
-				continue;
-			}
-		} else {
-			log_err("bad iolog2: %s", p);
-			continue;
-		}
-
-		if (rw == DDIR_READ)
-			reads++;
-		else if (rw == DDIR_WRITE) {
-			/*
-			 * Don't add a write for ro mode
-			 */
-			if (read_only)
-				continue;
-			writes++;
-		} else if (rw != DDIR_SYNC && rw != DDIR_INVAL) {
-			log_err("bad ddir: %d\n", rw);
-			continue;
-		}
-
-		/*
-		 * Make note of file
-		 */
-		ipo = malloc(sizeof(*ipo));
-		memset(ipo, 0, sizeof(*ipo));
-		INIT_LIST_HEAD(&ipo->list);
-		ipo->offset = offset;
-		ipo->len = bytes;
-		ipo->ddir = rw;
-		if (bytes > td->o.max_bs[rw])
-			td->o.max_bs[rw] = bytes;
-		if (rw == DDIR_INVAL) {
-			ipo->fileno = fileno;
-			ipo->file_action = file_action;
-		}
-		queue_io_piece(td, ipo);
-	}
+/* add prefix for the specified type in front of the valist */
+void log_prevalist(int type, const char *fmt, va_list args)
+{
+	char pre[32];
+	char *buffer;
+	size_t len;
+	int prelen;
+	pid_t pid;
 
-	free(str);
-	free(act);
-	free(fname);
+	pid = gettid();
+	if (fio_debug_jobp && *fio_debug_jobp != -1U
+	    && pid != *fio_debug_jobp)
+		return;
 
-	if (writes && read_only) {
-		log_err("fio: <%s> skips replay of %d writes due to"
-			" read-only\n", td->o.name, writes);
-		writes = 0;
+	prelen = snprintf(pre, sizeof pre, "%-8s %-5u ", debug_levels[type].name, (int) pid);
+	if (prelen > 0) {
+		len = prevalist_to_buf(&buffer, pre, prelen, fmt, args);
+		len = log_info_buf(buffer, len);
+		free(buffer);
 	}
-
-	if (!reads && !writes)
-		return 1;
-	else if (reads && !writes)
-		td->o.td_ddir = TD_DDIR_READ;
-	else if (!reads && writes)
-		td->o.td_ddir = TD_DDIR_WRITE;
-	else
-		td->o.td_ddir = TD_DDIR_RW;
-
-	return 0;
 }
 
-/*
- * open iolog, check version, and call appropriate parser
- */
-static int init_iolog_read(struct thread_data *td)
+size_t log_info(const char *format, ...)
 {
-	char buffer[256], *p;
-	FILE *f;
-	int ret;
-
-	f = fopen(td->o.read_iolog_file, "r");
-	if (!f) {
-		perror("fopen read iolog");
-		return 1;
-	}
+	va_list args;
+	size_t ret;
 
-	p = fgets(buffer, sizeof(buffer), f);
-	if (!p) {
-		td_verror(td, errno, "iolog read");
-		log_err("fio: unable to read iolog\n");
-		return 1;
-	}
+	va_start(args, format);
+	ret = log_valist(format, args);
+	va_end(args);
 
-	/*
-	 * version 2 of the iolog stores a specific string as the
-	 * first line, check for that
-	 */
-	if (!strncmp(iolog_ver2, buffer, strlen(iolog_ver2)))
-		ret = read_iolog2(td, f);
-	else {
-		log_err("fio: iolog version 1 is no longer supported\n");
-		ret = 1;
-	}
-
-	fclose(f);
 	return ret;
 }
 
-/*
- * Setup a log for storing io patterns.
- */
-static int init_iolog_write(struct thread_data *td)
+size_t __log_buf(struct buf_output *buf, const char *format, ...)
 {
-	struct fio_file *ff;
-	FILE *f;
-	unsigned int i;
-
-	f = fopen(td->o.write_iolog_file, "w+");
-	if (!f) {
-		perror("fopen write iolog");
-		return 1;
-	}
+	char *buffer;
+	va_list args;
+	size_t len;
 
-	/*
-	 * That's it for writing, setup a log buffer and we're done.
-	  */
-	td->iolog_f = f;
-	td->iolog_buf = malloc(8192);
-	setvbuf(f, td->iolog_buf, _IOFBF, 8192);
+	va_start(args, format);
+	len = valist_to_buf(&buffer, format, args);
+	va_end(args);
 
-	/*
-	 * write our version line
-	 */
-	if (fprintf(f, "%s\n", iolog_ver2) < 0) {
-		perror("iolog init\n");
-		return 1;
-	}
-
-	/*
-	 * add all known files
-	 */
-	for_each_file(td, ff, i)
-		log_file(td, ff, FIO_LOG_ADD_FILE);
+	len = buf_output_add(buf, buffer, len);
+	free(buffer);
 
-	return 0;
+	return len;
 }
 
-int init_iolog(struct thread_data *td)
+int log_info_flush(void)
 {
-	int ret = 0;
-
-	if (td->io_ops->flags & FIO_DISKLESSIO)
+	if (is_backend || log_syslog)
 		return 0;
 
-	if (td->o.read_iolog_file) {
-		/*
-		 * Check if it's a blktrace file and load that if possible.
-		 * Otherwise assume it's a normal log file and load that.
-		 */
-		if (is_blktrace(td->o.read_iolog_file))
-			ret = load_blktrace(td, td->o.read_iolog_file);
-		else
-			ret = init_iolog_read(td);
-	} else if (td->o.write_iolog_file)
-		ret = init_iolog_write(td);
-
-	return ret;
+	return fflush(f_out);
 }
 
-void setup_log(struct io_log **log)
+size_t log_err(const char *format, ...)
 {
-	struct io_log *l = malloc(sizeof(*l));
-
-	l->nr_samples = 0;
-	l->max_samples = 1024;
-	l->log = malloc(l->max_samples * sizeof(struct io_sample));
-	*log = l;
-}
+	size_t ret, len;
+	char *buffer;
+	va_list args;
 
-void __finish_log(struct io_log *log, const char *name)
-{
-	unsigned int i;
-	FILE *f;
+	va_start(args, format);
+	len = valist_to_buf(&buffer, format, args);
+	va_end(args);
 
-	f = fopen(name, "w");
-	if (!f) {
-		perror("fopen log");
-		return;
+	if (is_backend) {
+		ret = fio_server_text_output(FIO_LOG_ERR, buffer, len);
+		if (ret != -1)
+			goto done;
 	}
 
-	for (i = 0; i < log->nr_samples; i++) {
-		fprintf(f, "%lu, %lu, %u\n", log->log[i].time, log->log[i].val,
-						log->log[i].ddir);
+	if (log_syslog) {
+		syslog(LOG_INFO, "%s", buffer);
+		ret = len;
+	} else {
+		if (f_err != stderr)
+			ret = fwrite(buffer, len, 1, stderr);
+
+		ret = fwrite(buffer, len, 1, f_err);
 	}
 
-	fclose(f);
-	free(log->log);
-	free(log);
+done:
+	free(buffer);
+	return ret;
 }
 
-void finish_log(struct thread_data *td, struct io_log *log, const char *name)
+const char *log_get_level(int level)
 {
-	char file_name[256], *p;
+	static const char *levels[] = { "Unknown", "Debug", "Info", "Error",
+						"Unknown" };
+
+	if (level >= FIO_LOG_NR)
+		level = FIO_LOG_NR;
 
-	snprintf(file_name, 200, "%s_%s.log", td->o.name, name);
-	p = basename(file_name);
-	__finish_log(log, p);
+	return levels[level];
 }