[PATCH] IO completion time histograms
[fio.git] / fio.c
diff --git a/fio.c b/fio.c
index 8c059df627294f3607e2e1bae00a6f2c571451fb..e8a86585d4bd5d4ee83cff9202eca1ef8a3a58a9 100644 (file)
--- a/fio.c
+++ b/fio.c
 #include <string.h>
 #include <signal.h>
 #include <time.h>
-#include <assert.h>
+#include <locale.h>
 #include <sys/stat.h>
 #include <sys/wait.h>
 #include <sys/ipc.h>
 #include <sys/shm.h>
-#include <sys/ioctl.h>
 #include <sys/mman.h>
 
 #include "fio.h"
 #include "os.h"
 
-#define MASK   (4095)
-
-#define ALIGN(buf)     (char *) (((unsigned long) (buf) + MASK) & ~(MASK))
+static unsigned long page_mask;
+#define ALIGN(buf)     \
+       (char *) (((unsigned long) (buf) + page_mask) & ~page_mask)
 
 int groupid = 0;
 int thread_number = 0;
 int shm_id = 0;
 int temp_stall_ts;
-const char *fio_inst_prefix = _INST_PREFIX;
 
 static volatile int startup_sem;
+static volatile int fio_abort;
+static int exit_value;
+
+struct io_log *agg_io_log[2];
 
 #define TERMINATE_ALL          (-1)
 #define JOB_START_TIMEOUT      (5 * 1000)
 
-static void terminate_threads(int group_id)
+static inline void td_set_runstate(struct thread_data *td, int runstate)
+{
+       td->runstate = runstate;
+}
+
+static void terminate_threads(int group_id, int forced_kill)
 {
        struct thread_data *td;
        int i;
@@ -61,6 +68,8 @@ static void terminate_threads(int group_id)
                if (group_id == TERMINATE_ALL || groupid == td->groupid) {
                        td->terminate = 1;
                        td->start_delay = 0;
+                       if (forced_kill)
+                               td_set_runstate(td, TD_EXITED);
                }
        }
 }
@@ -74,9 +83,9 @@ static void sig_handler(int sig)
                        print_thread_status();
                        break;
                default:
-                       printf("\nfio: terminating on signal\n");
+                       printf("\nfio: terminating on signal %d\n", sig);
                        fflush(stdout);
-                       terminate_threads(TERMINATE_ALL);
+                       terminate_threads(TERMINATE_ALL, 0);
                        break;
        }
 }
@@ -106,7 +115,7 @@ static int check_min_rate(struct thread_data *td, struct timeval *now)
 
                rate = (td->this_io_bytes[ddir] - td->rate_bytes) / spent;
                if (rate < td->ratemin) {
-                       fprintf(f_out, "%s: min rate %d not met, got %ldKiB/sec\n", td->name, td->ratemin, rate);
+                       fprintf(f_out, "%s: min rate %u not met, got %luKiB/sec\n", td->name, td->ratemin, rate);
                        return 1;
                }
        }
@@ -126,11 +135,6 @@ static inline int runtime_exceeded(struct thread_data *td, struct timeval *t)
        return 0;
 }
 
-static inline void td_set_runstate(struct thread_data *td, int runstate)
-{
-       td->runstate = runstate;
-}
-
 static struct fio_file *get_next_file(struct thread_data *td)
 {
        unsigned int old_next_file = td->next_file;
@@ -243,9 +247,8 @@ static int fio_io_sync(struct thread_data *td, struct fio_file *f)
  * The main verify engine. Runs over the writes we previusly submitted,
  * reads the blocks back in, and checks the crc/md5 of the data.
  */
-void do_verify(struct thread_data *td)
+static void do_verify(struct thread_data *td)
 {
-       struct timeval t;
        struct io_u *io_u, *v_io_u = NULL;
        struct io_completion_data icd;
        struct fio_file *f;
@@ -266,14 +269,15 @@ void do_verify(struct thread_data *td)
                if (td->terminate)
                        break;
 
-               gettimeofday(&t, NULL);
-               if (runtime_exceeded(td, &t))
-                       break;
-
                io_u = __get_io_u(td);
                if (!io_u)
                        break;
 
+               if (runtime_exceeded(td, &io_u->start_time)) {
+                       put_io_u(td, io_u);
+                       break;
+               }
+
                if (get_next_verify(td, io_u)) {
                        put_io_u(td, io_u);
                        break;
@@ -314,6 +318,7 @@ void do_verify(struct thread_data *td)
                v_io_u = td->io_ops->event(td, 0);
                icd.nr = 1;
                icd.error = 0;
+               fio_gettime(&icd.time, NULL);
                io_completed(td, v_io_u, &icd);
 
                if (icd.error) {
@@ -350,7 +355,7 @@ static void do_cpuio(struct thread_data *td)
        int i = 0;
 
        while (!td->terminate) {
-               gettimeofday(&e, NULL);
+               fio_gettime(&e, NULL);
 
                if (runtime_exceeded(td, &e))
                        break;
@@ -371,15 +376,14 @@ static void do_cpuio(struct thread_data *td)
 static void do_io(struct thread_data *td)
 {
        struct io_completion_data icd;
-       struct timeval s, e;
+       struct timeval s;
        unsigned long usec;
        struct fio_file *f;
        int i, ret = 0;
 
        td_set_runstate(td, TD_RUNNING);
 
-       while (td->this_io_bytes[td->ddir] < td->io_size) {
-               struct timespec ts = { .tv_sec = 0, .tv_nsec = 0};
+       while ((td->this_io_bytes[0] + td->this_io_bytes[1]) < td->io_size) {
                struct timespec *timeout;
                int min_evts = 0;
                struct io_u *io_u;
@@ -396,17 +400,28 @@ static void do_io(struct thread_data *td)
                        break;
 
                memcpy(&s, &io_u->start_time, sizeof(s));
-
+requeue:
                ret = td_io_queue(td, io_u);
                if (ret) {
-                       td_verror(td, io_u->error);
-                       put_io_u(td, io_u);
-                       break;
+                       if (ret > 0 && (io_u->xfer_buflen != io_u->resid) &&
+                           io_u->resid) {
+                               /*
+                                * short read/write. requeue.
+                                */
+                               io_u->xfer_buflen = io_u->resid;
+                               io_u->xfer_buf += ret;
+                               goto requeue;
+                       } else {
+                               put_io_u(td, io_u);
+                               break;
+                       }
                }
 
                add_slat_sample(td, io_u->ddir, mtime_since(&io_u->start_time, &io_u->issue_time));
 
                if (td->cur_depth < td->iodepth) {
+                       struct timespec ts = { .tv_sec = 0, .tv_nsec = 0};
+
                        timeout = &ts;
                        min_evts = 0;
                } else {
@@ -433,26 +448,30 @@ static void do_io(struct thread_data *td)
                 * of completions except the very first one which may look
                 * a little bursty
                 */
-               gettimeofday(&e, NULL);
-               usec = utime_since(&s, &e);
+               usec = utime_since(&s, &icd.time);
 
                rate_throttle(td, usec, icd.bytes_done[td->ddir], td->ddir);
 
-               if (check_min_rate(td, &e)) {
-                       if (rate_quit)
-                               terminate_threads(td->groupid);
-                       td_verror(td, ENOMEM);
+               if (check_min_rate(td, &icd.time)) {
+                       if (exitall_on_terminate)
+                               terminate_threads(td->groupid, 0);
+                       td_verror(td, ENODATA);
                        break;
                }
 
-               if (runtime_exceeded(td, &e))
+               if (runtime_exceeded(td, &icd.time))
                        break;
 
-               if (td->thinktime)
-                       usec_sleep(td, td->thinktime);
+               if (td->thinktime) {
+                       unsigned long long b;
+
+                       b = td->io_blocks[0] + td->io_blocks[1];
+                       if (!(b % td->thinktime_blocks))
+                               usec_sleep(td, td->thinktime);
+               }
        }
 
-       if (!ret) {
+       if (!td->error) {
                if (td->cur_depth)
                        cleanup_pending_aio(td);
 
@@ -508,7 +527,12 @@ static int init_io_u(struct thread_data *td)
                max_units = td->iodepth;
 
        max_bs = max(td->max_bs[DDIR_READ], td->max_bs[DDIR_WRITE]);
-       td->orig_buffer_size = max_bs * max_units + MASK;
+       td->orig_buffer_size = max_bs * max_units;
+
+       if (td->mem_type == MEM_SHMHUGE || td->mem_type == MEM_MMAPHUGE)
+               td->orig_buffer_size = (td->orig_buffer_size + td->hugepage_size - 1) & ~(td->hugepage_size - 1);
+       else
+               td->orig_buffer_size += page_mask;
 
        if (allocate_io_mem(td))
                return 1;
@@ -606,6 +630,7 @@ static void clear_io_state(struct thread_data *td)
  */
 static void *thread_main(void *data)
 {
+       unsigned long long runtime[2];
        struct thread_data *td = data;
 
        if (!td->use_thread)
@@ -626,9 +651,6 @@ static void *thread_main(void *data)
                goto err;
        }
 
-       if (td_io_init(td))
-               goto err;
-
        if (init_iolog(td))
                goto err;
 
@@ -656,15 +678,27 @@ static void *thread_main(void *data)
 
        if (!td->create_serialize && setup_files(td))
                goto err;
+       if (open_files(td))
+               goto err;
 
-       gettimeofday(&td->epoch, NULL);
+       /*
+        * Do this late, as some IO engines would like to have the
+        * files setup prior to initializing structures.
+        */
+       if (td_io_init(td))
+               goto err;
 
-       if (td->exec_prerun)
-               system(td->exec_prerun);
+       if (td->exec_prerun) {
+               if (system(td->exec_prerun) < 0)
+                       goto err;
+       }
 
+       fio_gettime(&td->epoch, NULL);
+       getrusage(RUSAGE_SELF, &td->ru_start);
+
+       runtime[0] = runtime[1] = 0;
        while (td->loops--) {
-               getrusage(RUSAGE_SELF, &td->ru_start);
-               gettimeofday(&td->start, NULL);
+               fio_gettime(&td->start, NULL);
                memcpy(&td->stat_sample_time, &td->start, sizeof(td->start));
 
                if (td->ratemin)
@@ -678,11 +712,9 @@ static void *thread_main(void *data)
                else
                        do_io(td);
 
-               td->runtime[td->ddir] += mtime_since_now(&td->start);
+               runtime[td->ddir] += utime_since_now(&td->start);
                if (td_rw(td) && td->io_bytes[td->ddir ^ 1])
-                       td->runtime[td->ddir ^ 1] = td->runtime[td->ddir];
-
-               update_rusage_stat(td);
+                       runtime[td->ddir ^ 1] = runtime[td->ddir];
 
                if (td->error || td->terminate)
                        break;
@@ -691,16 +723,21 @@ static void *thread_main(void *data)
                        continue;
 
                clear_io_state(td);
-               gettimeofday(&td->start, NULL);
+               fio_gettime(&td->start, NULL);
 
                do_verify(td);
 
-               td->runtime[DDIR_READ] += mtime_since_now(&td->start);
+               runtime[DDIR_READ] += utime_since_now(&td->start);
 
                if (td->error || td->terminate)
                        break;
        }
 
+       update_rusage_stat(td);
+       fio_gettime(&td->end_time, NULL);
+       td->runtime[0] = runtime[0] / 1000;
+       td->runtime[1] = runtime[1] / 1000;
+
        if (td->bw_log)
                finish_log(td, td->bw_log, "bw");
        if (td->slat_log)
@@ -709,19 +746,22 @@ static void *thread_main(void *data)
                finish_log(td, td->clat_log, "clat");
        if (td->write_iolog_file)
                write_iolog_close(td);
-       if (td->exec_postrun)
-               system(td->exec_postrun);
+       if (td->exec_postrun) {
+               if (system(td->exec_postrun) < 0)
+                       log_err("fio: postrun %s failed\n", td->exec_postrun);
+       }
 
        if (exitall_on_terminate)
-               terminate_threads(td->groupid);
+               terminate_threads(td->groupid, 0);
 
 err:
+       if (td->error)
+               printf("fio: pid=%d, err=%d/%s\n", td->pid, td->error, td->verror);
        close_files(td);
        close_ioengine(td);
        cleanup_io_u(td);
        td_set_runstate(td, TD_EXITED);
        return NULL;
-
 }
 
 /*
@@ -751,12 +791,12 @@ static void *fork_main(int shmid, int offset)
 static void reap_threads(int *nr_running, int *t_rate, int *m_rate)
 {
        struct thread_data *td;
-       int i, cputhreads;
+       int i, cputhreads, pending;
 
        /*
         * reap exited threads (TD_EXITED -> TD_REAPED)
         */
-       cputhreads = 0;
+       pending = cputhreads = 0;
        for_each_td(td, i) {
                /*
                 * ->io_ops is NULL for a thread that has closed its
@@ -765,8 +805,15 @@ static void reap_threads(int *nr_running, int *t_rate, int *m_rate)
                if (td->io_ops && td->io_ops->flags & FIO_CPUIO)
                        cputhreads++;
 
-               if (td->runstate != TD_EXITED)
+               if (td->runstate != TD_EXITED) {
+                       if (td->runstate < TD_RUNNING)
+                               pending++;
+
                        continue;
+               }
+
+               if (td->error)
+                       exit_value++;
 
                td_set_runstate(td, TD_REAPED);
 
@@ -783,8 +830,8 @@ static void reap_threads(int *nr_running, int *t_rate, int *m_rate)
                (*t_rate) -= td->rate;
        }
 
-       if (*nr_running == cputhreads)
-               terminate_threads(TERMINATE_ALL);
+       if (*nr_running == cputhreads && !pending)
+               terminate_threads(TERMINATE_ALL, 0);
 }
 
 /*
@@ -815,10 +862,10 @@ static void run_threads(void)
        for_each_td(td, i) {
                print_status_init(td->thread_number - 1);
 
-               init_disk_util(td);
-
-               if (!td->create_serialize)
+               if (!td->create_serialize) {
+                       init_disk_util(td);
                        continue;
+               }
 
                /*
                 * do file setup here so it happens sequentially,
@@ -826,12 +873,15 @@ static void run_threads(void)
                 * client data interspersed on disk
                 */
                if (setup_files(td)) {
+                       exit_value++;
+                       if (td->error)
+                               log_err("fio: pid=%d, err=%d/%s\n", td->pid, td->error, td->verror);
                        td_set_runstate(td, TD_REAPED);
                        todo--;
                }
-       }
 
-       time_init();
+               init_disk_util(td);
+       }
 
        while (todo) {
                struct thread_data *map[MAX_JOBS];
@@ -892,9 +942,9 @@ static void run_threads(void)
                 * Wait for the started threads to transition to
                 * TD_INITIALIZED.
                 */
-               gettimeofday(&this_start, NULL);
+               fio_gettime(&this_start, NULL);
                left = this_jobs;
-               while (left) {
+               while (left && !fio_abort) {
                        if (mtime_since_now(&this_start) > JOB_START_TIMEOUT)
                                break;
 
@@ -960,6 +1010,15 @@ static void run_threads(void)
 
 int main(int argc, char *argv[])
 {
+       long ps;
+
+       /*
+        * We need locale for number printing, if it isn't set then just
+        * go with the US format.
+        */
+       if (!getenv("LC_NUMERIC"))
+               setlocale(LC_NUMERIC, "en_US");
+
        if (parse_options(argc, argv))
                return 1;
 
@@ -968,10 +1027,30 @@ int main(int argc, char *argv[])
                return 1;
        }
 
+       ps = sysconf(_SC_PAGESIZE);
+       if (ps < 0) {
+               log_err("Failed to get page size\n");
+               return 1;
+       }
+
+       page_mask = ps - 1;
+
+       if (write_bw_log) {
+               setup_log(&agg_io_log[DDIR_READ]);
+               setup_log(&agg_io_log[DDIR_WRITE]);
+       }
+
        disk_util_timer_arm();
 
        run_threads();
-       show_run_stats();
 
-       return 0;
+       if (!fio_abort) {
+               show_run_stats();
+               if (write_bw_log) {
+                       __finish_log(agg_io_log[DDIR_READ],"agg-read_bw.log");
+                       __finish_log(agg_io_log[DDIR_WRITE],"agg-write_bw.log");
+               }
+       }
+
+       return exit_value;
 }