-/*
- * 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 <libgen.h>
-#include <assert.h>
-#include "flist.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)
-{
- flist_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);
+#include <unistd.h>
+#include <fcntl.h>
+#include <string.h>
+#include <stdarg.h>
+#include <syslog.h>
- if (!td->o.write_iolog_file)
- return;
+#include "fio.h"
- fprintf(td->iolog_f, "%s %s %llu %lu\n", io_u->file->file_name,
- act[io_u->ddir], io_u->offset,
- io_u->buflen);
-}
+#define LOG_START_SZ 512
-void log_file(struct thread_data *td, struct fio_file *f,
- enum file_log_act what)
+size_t log_info_buf(const char *buf, size_t len)
{
- const char *act[] = { "add", "open", "close" };
-
- assert(what < 3);
-
- if (!td->o.write_iolog_file)
- return;
-
-
/*
- * this happens on the pre-open/close done before the job starts
+ * buf could be NULL (not just "").
*/
- if (!td->iolog_f)
- return;
-
- 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;
+ if (!buf)
+ return 0;
- /*
- * less than 100 usec delay, just regard it as noise
- */
- if (delay < 100)
- return;
+ if (is_backend) {
+ size_t ret = fio_server_text_output(FIO_LOG_INFO, buf, len);
+ if (ret != -1)
+ return ret;
+ }
- usec_sleep(td, delay);
+ if (log_syslog) {
+ syslog(LOG_INFO, "%s", buf);
+ return len;
+ } else
+ return fwrite(buf, len, 1, f_out);
}
-static int ipo_special(struct thread_data *td, struct io_piece *ipo)
+static size_t valist_to_buf(char **buffer, const char *fmt, va_list src_args)
{
- struct fio_file *f;
- int ret;
+ size_t len, cur = LOG_START_SZ;
+ va_list args;
- /*
- * Not a special ipo
- */
- if (ipo->ddir != DDIR_INVAL)
- return 0;
+ do {
+ *buffer = calloc(1, cur);
+ if (!*buffer)
+ return 0;
- f = td->files[ipo->fileno];
+ va_copy(args, src_args);
+ len = vsnprintf(*buffer, cur, fmt, args);
+ va_end(args);
- switch (ipo->file_action) {
- case FIO_LOG_OPEN_FILE:
- ret = td_io_open_file(td, f);
- if (!ret) {
- free(ipo);
+ if (len < cur)
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;
- }
- return 1;
+ cur = len + 1;
+ free(*buffer);
+ } while (1);
+
+ return len;
}
-int read_iolog_get(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 io_piece *ipo;
+ size_t len, cur = LOG_START_SZ;
+ va_list args;
- while (!flist_empty(&td->io_log_list)) {
- int ret;
+ do {
+ *buffer = calloc(1, cur);
+ if (!*buffer)
+ return 0;
- ipo = flist_entry(td->io_log_list.next, struct io_piece, list);
- flist_del(&ipo->list);
+ va_copy(args, src_args);
+ memcpy(*buffer, pre, prelen);
+ len = prelen + vsnprintf(*buffer + prelen, cur - prelen, 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);
+ cur = len + 1;
+ free(*buffer);
+ } while (1);
- 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;
+ return len;
}
-void prune_io_piece_log(struct thread_data *td)
+size_t log_valist(const char *fmt, va_list args)
{
- struct io_piece *ipo;
- struct rb_node *n;
+ char *buffer;
+ size_t len;
- 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);
- }
+ len = valist_to_buf(&buffer, fmt, args);
+ len = log_info_buf(buffer, len);
+ free(buffer);
- while (!flist_empty(&td->io_hist_list)) {
- ipo = flist_entry(td->io_hist_list.next, struct io_piece, list);
- flist_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)
+/* add prefix for the specified type in front of the valist */
+void log_prevalist(int type, const char *fmt, va_list args)
{
- struct rb_node **p, *parent;
- struct io_piece *ipo, *__ipo;
-
- ipo = malloc(sizeof(struct io_piece));
- ipo->file = io_u->file;
- ipo->offset = io_u->offset;
- ipo->len = io_u->buflen;
+ char pre[32];
+ char *buffer;
+ size_t len;
+ int prelen;
+ pid_t pid;
- /*
- * 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_FLIST_HEAD(&ipo->list);
- flist_add_tail(&ipo->list, &td->io_hist_list);
+ pid = gettid();
+ if (fio_debug_jobp && *fio_debug_jobp != -1U
+ && pid != *fio_debug_jobp)
return;
- }
- RB_CLEAR_NODE(&ipo->rb_node);
- p = &td->io_hist_tree.rb_node;
- parent = NULL;
-
- /*
- * 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;
- }
-
- rb_link_node(&ipo->rb_node, parent, p);
- rb_insert_color(&ipo->rb_node, &td->io_hist_tree);
-}
-
-void write_iolog_close(struct thread_data *td)
-{
- fflush(td->iolog_f);
- fclose(td->iolog_f);
- free(td->iolog_buf);
- td->iolog_f = NULL;
- td->iolog_buf = NULL;
-}
-
-/*
- * 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;
-
- free_release_files(td);
-
- /*
- * 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_FLIST_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);
+ 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);
}
-
- free(str);
- free(act);
- free(fname);
-
- if (writes && read_only) {
- log_err("fio: <%s> skips replay of %d writes due to"
- " read-only\n", td->o.name, writes);
- writes = 0;
- }
-
- 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;
- }
-
- 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_list args;
+ size_t ret;
- /*
- * 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;
- }
+ va_start(args, format);
+ ret = log_valist(format, args);
+ va_end(args);
- 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));
+ size_t ret, len;
+ char *buffer;
+ va_list args;
- l->nr_samples = 0;
- l->max_samples = 1024;
- l->log = malloc(l->max_samples * sizeof(struct io_sample));
- *log = l;
-}
+ va_start(args, format);
+ len = valist_to_buf(&buffer, format, args);
+ va_end(args);
-void __finish_log(struct io_log *log, const char *name)
-{
- unsigned int i;
- FILE *f;
-
- 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];
}
projects / fio.git / blobdiff