[PATCH] fio: split up and improve output stats

diff --git a/fio-ini.c b/fio-ini.c
index 748a29cf948d7e8bdc314bebd622d1948d8bf14b..093b9b308d71334b778230c07c0f4d0452b85266 100644 (file)
--- a/fio-ini.c
+++ b/fio-ini.c
@@ -206,9 +206,9 @@ static int add_job(struct thread_data *td, const char *jobname, int prioclass,
 
        sem_init(&td->mutex, 0, 0);
 
-       td->clat_stat.min_val = ULONG_MAX;
-       td->slat_stat.min_val = ULONG_MAX;
-       td->bw_stat.min_val = ULONG_MAX;
+       td->clat_stat[0].min_val = td->clat_stat[1].min_val = ULONG_MAX;
+       td->slat_stat[0].min_val = td->slat_stat[1].min_val = ULONG_MAX;
+       td->bw_stat[0].min_val = td->bw_stat[1].min_val = ULONG_MAX;
 
        if (td->min_bs == -1U)
                td->min_bs = td->bs;

diff --git a/fio.c b/fio.c
index e166f49850e1528c95f58223079c708a6bea6ef5..5f7d53da0ed0e5a38f6305c9e60093ba456ed4ed 100644 (file)
--- a/fio.c
+++ b/fio.c
@@ -253,8 +253,8 @@ static unsigned int get_next_buflen(struct thread_data *td)
                buflen = (buflen + td->min_bs - 1) & ~(td->min_bs - 1);
        }
 
-       if (buflen > td->io_size - td->this_io_bytes)
-               buflen = td->io_size - td->this_io_bytes;
+       if (buflen > td->io_size - td->this_io_bytes[td->ddir])
+               buflen = td->io_size - td->this_io_bytes[td->ddir];
 
        return buflen;
 }
@@ -286,35 +286,35 @@ static void add_log_sample(struct thread_data *td, struct io_log *iolog,
        iolog->nr_samples++;
 }
 
-static void add_clat_sample(struct thread_data *td, unsigned long msec)
+static void add_clat_sample(struct thread_data *td, int ddir,unsigned long msec)
 {
-       add_stat_sample(&td->clat_stat, msec);
+       add_stat_sample(&td->clat_stat[ddir], msec);
 
        if (td->lat_log)
                add_log_sample(td, td->lat_log, msec);
 }
 
-static void add_slat_sample(struct thread_data *td, unsigned long msec)
+static void add_slat_sample(struct thread_data *td, int ddir,unsigned long msec)
 {
-       add_stat_sample(&td->slat_stat, msec);
+       add_stat_sample(&td->slat_stat[ddir], msec);
 }
 
-static void add_bw_sample(struct thread_data *td)
+static void add_bw_sample(struct thread_data *td, int ddir)
 {
-       unsigned long spent = mtime_since_now(&td->stat_sample_time);
+       unsigned long spent = mtime_since_now(&td->stat_sample_time[ddir]);
        unsigned long rate;
 
        if (spent < td->bw_avg_time)
                return;
 
-       rate = (td->this_io_bytes - td->stat_io_bytes) / spent;
-       add_stat_sample(&td->bw_stat, rate);
+       rate = (td->this_io_bytes[ddir] - td->stat_io_bytes[ddir]) / spent;
+       add_stat_sample(&td->bw_stat[ddir], rate);
 
        if (td->bw_log)
                add_log_sample(td, td->bw_log, rate);
 
-       gettimeofday(&td->stat_sample_time, NULL);
-       td->stat_io_bytes = td->this_io_bytes;
+       gettimeofday(&td->stat_sample_time[ddir], NULL);
+       td->stat_io_bytes[ddir] = td->this_io_bytes[ddir];
 }
 
 /*
@@ -385,6 +385,7 @@ static int check_min_rate(struct thread_data *td, struct timeval *now)
 {
        unsigned long spent;
        unsigned long rate;
+       int ddir = td->ddir;
 
        /*
         * allow a 2 second settle period in the beginning
@@ -400,7 +401,7 @@ static int check_min_rate(struct thread_data *td, struct timeval *now)
                if (spent < td->ratecycle)
                        return 0;
 
-               rate = (td->this_io_bytes - td->rate_bytes) / spent;
+               rate = (td->this_io_bytes[ddir] - td->rate_bytes) / spent;
                if (rate < td->ratemin) {
                        printf("Client%d: min rate %d not met, got %ldKiB/sec\n", td->thread_number, td->ratemin, rate);
                        if (rate_quit)
@@ -409,7 +410,7 @@ static int check_min_rate(struct thread_data *td, struct timeval *now)
                }
        }
 
-       td->rate_bytes = td->this_io_bytes;
+       td->rate_bytes = td->this_io_bytes[ddir];
        memcpy(&td->lastrate, now, sizeof(*now));
        return 0;
 }
@@ -729,48 +730,55 @@ static int io_u_queue(struct thread_data *td, struct io_u *io_u)
 
 #define iocb_time(iocb)        ((unsigned long) (iocb)->data)
 
-static int ios_completed(struct thread_data *td, int nr, int *err)
+static void io_completed(struct thread_data *td, struct io_u *io_u,
+                        struct io_completion_data *icd)
 {
-       unsigned long msec;
-       struct io_u *io_u;
        struct timeval e;
-       int i, bytes_done;
-
-       if (err)
-               *err = 0;
+       unsigned long msec;
 
        gettimeofday(&e, NULL);
 
-       for (i = 0, bytes_done = 0; i < nr; i++) {
-               io_u = td->io_event(td, i);
+       if (!io_u->error) {
+               int idx = io_u->ddir;
 
-               if (!io_u->error) {
-                       td->io_blocks++;
-                       td->io_bytes += (io_u->buflen - io_u->resid);
-                       td->this_io_bytes += (io_u->buflen - io_u->resid);
+               td->io_blocks[idx]++;
+               td->io_bytes[idx] += (io_u->buflen - io_u->resid);
+               td->this_io_bytes[idx] += (io_u->buflen - io_u->resid);
 
-                       msec = mtime_since(&io_u->issue_time, &e);
+               msec = mtime_since(&io_u->issue_time, &e);
+
+               add_clat_sample(td, io_u->ddir, msec);
+               add_bw_sample(td, io_u->ddir);
+
+               if (td_write(td) && io_u->ddir == DDIR_WRITE)
+                       log_io_piece(td, io_u);
+
+               icd->bytes_done[idx] += (io_u->buflen - io_u->resid);
+       } else
+               icd->error = io_u->error;
+}
 
-                       add_clat_sample(td, msec);
-                       add_bw_sample(td);
+static void ios_completed(struct thread_data *td,struct io_completion_data *icd)
+{
+       struct io_u *io_u;
+       int i;
 
-                       if (td_write(td))
-                               log_io_piece(td, io_u);
+       icd->error = 0;
+       icd->bytes_done[0] = icd->bytes_done[1] = 0;
 
-                       bytes_done += (io_u->buflen - io_u->resid);
-               } else if (err)
-                       *err = io_u->error;
+       for (i = 0; i < icd->nr; i++) {
+               io_u = td->io_event(td, i);
 
+               io_completed(td, io_u, icd);
                put_io_u(td, io_u);
        }
-
-       return bytes_done;
 }
 
 static void cleanup_pending_aio(struct thread_data *td)
 {
        struct timespec ts = { .tv_sec = 0, .tv_nsec = 0};
        struct list_head *entry, *n;
+       struct io_completion_data icd;
        struct io_u *io_u;
        int r;
 
@@ -778,8 +786,10 @@ static void cleanup_pending_aio(struct thread_data *td)
         * get immediately available events, if any
         */
        r = io_u_getevents(td, 0, td->cur_depth, &ts);
-       if (r > 0)
-               ios_completed(td, r, NULL);
+       if (r > 0) {
+               icd.nr = r;
+               ios_completed(td, &icd);
+       }
 
        /*
         * now cancel remaining active events
@@ -796,8 +806,10 @@ static void cleanup_pending_aio(struct thread_data *td)
 
        if (td->cur_depth) {
                r = io_u_getevents(td, td->cur_depth, td->cur_depth, NULL);
-               if (r > 0)
-                       ios_completed(td, r, NULL);
+               if (r > 0) {
+                       icd.nr = r;
+                       ios_completed(td, &icd);
+               }
        }
 }
 
@@ -819,6 +831,7 @@ 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;
        int ret;
 
        td_set_runstate(td, TD_VERIFYING);
@@ -853,7 +866,7 @@ static void do_verify(struct thread_data *td)
                }
 
                /*
-                * we have one pending to verify, do that while the next
+                * we have one pending to verify, do that while
                 * we are doing io on the next one
                 */
                if (do_io_u_verify(td, &v_io_u))
@@ -867,8 +880,12 @@ static void do_verify(struct thread_data *td)
                }
 
                v_io_u = td->io_event(td, 0);
-               if (v_io_u->error) {
-                       td_verror(td, v_io_u->error);
+               icd.nr = 1;
+               icd.error = 0;
+               io_completed(td, v_io_u, &icd);
+
+               if (icd.error) {
+                       td_verror(td, icd.error);
                        put_io_u(td, v_io_u);
                        v_io_u = NULL;
                        break;
@@ -894,15 +911,15 @@ static void do_verify(struct thread_data *td)
 
 static void do_io(struct thread_data *td)
 {
+       struct io_completion_data icd;
        struct timeval s, e;
        unsigned long usec;
 
-       while (td->this_io_bytes < td->io_size) {
+       while (td->this_io_bytes[td->ddir] < td->io_size) {
                struct timespec ts = { .tv_sec = 0, .tv_nsec = 0};
                struct timespec *timeout;
-               int ret, min_evts = 0, err;
+               int ret, min_evts = 0;
                struct io_u *io_u;
-               unsigned int bytes_done;
 
                if (td->terminate)
                        break;
@@ -921,7 +938,7 @@ static void do_io(struct thread_data *td)
                }
 
                gettimeofday(&io_u->issue_time, NULL);
-               add_slat_sample(td, mtime_since(&io_u->start_time, &io_u->issue_time));
+               add_slat_sample(td, io_u->ddir, mtime_since(&io_u->start_time, &io_u->issue_time));
                if (td->cur_depth < td->iodepth) {
                        timeout = &ts;
                        min_evts = 0;
@@ -937,9 +954,10 @@ static void do_io(struct thread_data *td)
                } else if (!ret)
                        continue;
 
-               bytes_done = ios_completed(td, ret, &err);
-               if (err) {
-                       td_verror(td, err);
+               icd.nr = ret;
+               ios_completed(td, &icd);
+               if (icd.error) {
+                       td_verror(td, icd.error);
                        break;
                }
 
@@ -951,7 +969,7 @@ static void do_io(struct thread_data *td)
                gettimeofday(&e, NULL);
                usec = utime_since(&s, &e);
 
-               rate_throttle(td, usec, bytes_done);
+               rate_throttle(td, usec, icd.bytes_done[td->ddir]);
 
                if (check_min_rate(td, &e)) {
                        td_verror(td, ENOMEM);
@@ -965,7 +983,7 @@ static void do_io(struct thread_data *td)
                        usec_sleep(td, td->thinktime);
 
                if (should_fsync(td) && td->fsync_blocks &&
-                   (td->io_blocks % td->fsync_blocks) == 0)
+                   (td->io_blocks[DDIR_WRITE] % td->fsync_blocks) == 0)
                        sync_td(td);
        }
 
@@ -1585,8 +1603,8 @@ static void clear_io_state(struct thread_data *td)
 
        td->cur_off = 0;
        td->last_bytes = 0;
-       td->stat_io_bytes = 0;
-       td->this_io_bytes = 0;
+       td->stat_io_bytes[0] = td->stat_io_bytes[1] = 0;
+       td->this_io_bytes[0] = td->this_io_bytes[1] = 0;
 
        if (td->file_map)
                memset(td->file_map, 0, td->num_maps * sizeof(long));
@@ -1594,7 +1612,7 @@ static void clear_io_state(struct thread_data *td)
 
 static void update_rusage_stat(struct thread_data *td)
 {
-       if (!td->runtime)
+       if (!(td->runtime[0] + td->runtime[1]))
                return;
 
        getrusage(RUSAGE_SELF, &td->ru_end);
@@ -1659,7 +1677,7 @@ static void *thread_main(void *data)
 
                do_io(td);
 
-               td->runtime += mtime_since_now(&td->start);
+               td->runtime[td->ddir] += mtime_since_now(&td->start);
                update_rusage_stat(td);
 
                if (td->error || td->terminate)
@@ -1669,9 +1687,12 @@ static void *thread_main(void *data)
                        continue;
 
                clear_io_state(td);
+               gettimeofday(&td->start, NULL);
 
                do_verify(td);
 
+               td->runtime[DDIR_READ] += mtime_since_now(&td->start);
+
                if (td->error || td->terminate)
                        break;
        }
@@ -1735,37 +1756,57 @@ static int calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max,
        n = (double) is->samples;
        *mean = (double) is->val / n;
        *dev = sqrt(((double) is->val_sq - (*mean * *mean) / n) / (n - 1));
+       if (!(*min + *max) && !(*mean + *dev))
+               return 0;
+
        return 1;
 }
 
-static void show_thread_status(struct thread_data *td,
-                              struct group_run_stats *rs)
+static void show_ddir_status(struct thread_data *td, struct group_run_stats *rs,
+                            int ddir)
 {
-       unsigned long min, max, bw = 0;
-       double mean, dev, usr_cpu, sys_cpu;
+       char *ddir_str[] = { "read ", "write" };
+       unsigned long min, max, bw;
+       double mean, dev;
 
-       if (!td->io_bytes && !td->error)
+       if (!td->runtime[ddir])
                return;
 
-       if (td->runtime)
-               bw = td->io_bytes / td->runtime;
+       bw = td->io_bytes[ddir] / td->runtime[ddir];
+       printf("  %s: io=%6luMiB, bw=%6luKiB/s, runt=%6lumsec\n", ddir_str[ddir], td->io_bytes[ddir] >> 20, bw, td->runtime[ddir]);
+
+       if (calc_lat(&td->slat_stat[ddir], &min, &max, &mean, &dev))
+               printf("    slat (msec): min=%5lu, max=%5lu, avg=%5.02f, dev=%5.02f\n", min, max, mean, dev);
 
-       printf("Client%d (g=%d): err=%2d, io=%6luMiB, bw=%6luKiB/s, runt=%6lumsec\n", td->thread_number, td->groupid, td->error, td->io_bytes >> 20, bw, td->runtime);
+       if (calc_lat(&td->clat_stat[ddir], &min, &max, &mean, &dev))
+               printf("    clat (msec): min=%5lu, max=%5lu, avg=%5.02f, dev=%5.02f\n", min, max, mean, dev);
 
-       if (calc_lat(&td->slat_stat, &min, &max, &mean, &dev))
-               printf("  slat (msec): min=%5lu, max=%5lu, avg=%5.02f, dev=%5.02f\n", min, max, mean, dev);
-       if (calc_lat(&td->clat_stat, &min, &max, &mean, &dev))
-               printf("  clat (msec): min=%5lu, max=%5lu, avg=%5.02f, dev=%5.02f\n", min, max, mean, dev);
-       if (calc_lat(&td->bw_stat, &min, &max, &mean, &dev)) {
+       if (calc_lat(&td->bw_stat[ddir], &min, &max, &mean, &dev)) {
                double p_of_agg;
 
-               p_of_agg = mean * 100 / (double) rs->agg[td->ddir];
-               printf("  bw (KiB/s) : min=%5lu, max=%5lu, per=%3.2f%%, avg=%5.02f, dev=%5.02f\n", min, max, p_of_agg, mean, dev);
+               p_of_agg = mean * 100 / (double) rs->agg[ddir];
+               printf("    bw (KiB/s) : min=%5lu, max=%5lu, per=%3.2f%%, avg=%5.02f, dev=%5.02f\n", min, max, p_of_agg, mean, dev);
        }
+}
+
+static void show_thread_status(struct thread_data *td,
+                              struct group_run_stats *rs)
+{
+       double usr_cpu, sys_cpu;
 
-       if (td->runtime) {
-               usr_cpu = (double) td->usr_time * 100 / (double) td->runtime;
-               sys_cpu = (double) td->sys_time * 100 / (double) td->runtime;
+       if (!(td->io_bytes[0] + td->io_bytes[1]) && !td->error)
+               return;
+
+       printf("Client%d (g=%d): err=%2d:\n", td->thread_number, td->groupid, td->error);
+
+       show_ddir_status(td, rs, td->ddir);
+       show_ddir_status(td, rs, td->ddir ^ 1);
+
+       if (td->runtime[0] + td->runtime[1]) {
+               double runt = td->runtime[0] + td->runtime[1];
+
+               usr_cpu = (double) td->usr_time * 100 / runt;
+               sys_cpu = (double) td->sys_time * 100 / runt;
        } else {
                usr_cpu = 0;
                sys_cpu = 0;
@@ -1835,12 +1876,11 @@ static void print_thread_status(void)
                        m_rate += td->ratemin;
                }
 
-               /*
-                * doesn't quite work for verify, as it doesn't bump the
-                * io counters. will fix that later.
-                */
                bytes_total += td->total_io_size;
-               bytes_done += td->io_bytes;
+               if (td->verify)
+                       bytes_total += td->total_io_size;
+
+               bytes_done += td->io_bytes[DDIR_READ] +td->io_bytes[DDIR_WRITE];
 
                check_str_update(td);
        }
@@ -2011,7 +2051,7 @@ static void run_threads(void)
 
 static void show_group_stats(struct group_run_stats *rs, int id)
 {
-       printf("\nRun status group %d:\n", id);
+       printf("\nRun status group %d (all jobs):\n", id);
 
        if (rs->max_run[DDIR_READ])
                printf("   READ: io=%luMiB, aggrb=%lu, minb=%lu, maxb=%lu, mint=%lumsec, maxt=%lumsec\n", rs->io_mb[0], rs->agg[0], rs->min_bw[0], rs->max_bw[0], rs->min_run[0], rs->max_run[0]);
@@ -2057,7 +2097,7 @@ static void show_run_stats(void)
        }
 
        for (i = 0; i < thread_number; i++) {
-               unsigned long bw = 0;
+               unsigned long rbw, wbw;
 
                td = &threads[i];
 
@@ -2068,19 +2108,32 @@ static void show_run_stats(void)
 
                rs = &runstats[td->groupid];
 
-               if (td->runtime < rs->min_run[td->ddir])
-                       rs->min_run[td->ddir] = td->runtime;
-               if (td->runtime > rs->max_run[td->ddir])
-                       rs->max_run[td->ddir] = td->runtime;
-
-               if (td->runtime)
-                       bw = td->io_bytes / td->runtime;
-               if (bw < rs->min_bw[td->ddir])
-                       rs->min_bw[td->ddir] = bw;
-               if (bw > rs->max_bw[td->ddir])
-                       rs->max_bw[td->ddir] = bw;
-
-               rs->io_mb[td->ddir] += td->io_bytes >> 20;
+               if (td->runtime[0] < rs->min_run[0] || !rs->min_run[0])
+                       rs->min_run[0] = td->runtime[0];
+               if (td->runtime[0] > rs->max_run[0])
+                       rs->max_run[0] = td->runtime[0];
+               if (td->runtime[1] < rs->min_run[1] || !rs->min_run[1])
+                       rs->min_run[1] = td->runtime[1];
+               if (td->runtime[1] > rs->max_run[1])
+                       rs->max_run[1] = td->runtime[1];
+
+               rbw = wbw = 0;
+               if (td->runtime[0])
+                       rbw = td->io_bytes[0] / td->runtime[0];
+               if (td->runtime[1])
+                       wbw = td->io_bytes[1] / td->runtime[1];
+
+               if (rbw < rs->min_bw[0])
+                       rs->min_bw[0] = rbw;
+               if (wbw < rs->min_bw[1])
+                       rs->min_bw[1] = wbw;
+               if (rbw > rs->max_bw[0])
+                       rs->max_bw[0] = rbw;
+               if (wbw > rs->max_bw[1])
+                       rs->max_bw[1] = wbw;
+
+               rs->io_mb[0] += td->io_bytes[0] >> 20;
+               rs->io_mb[1] += td->io_bytes[1] >> 20;
        }
 
        for (i = 0; i < groupid + 1; i++) {

diff --git a/fio.h b/fio.h
index 2853c4fcd2d26959b906809ba865c9a44f6c784e..600c3be25c5539d3cac3e5cadcc3531924538e73 100644 (file)
--- a/fio.h
+++ b/fio.h
@@ -168,13 +168,13 @@ struct thread_data {
        unsigned long rate_bytes;
        struct timeval lastrate;
 
-       unsigned long runtime;          /* sec */
+       unsigned long runtime[2];               /* msec */
        unsigned long long io_size;
        unsigned long long total_io_size;
 
-       unsigned long io_blocks;
-       unsigned long io_bytes;
-       unsigned long this_io_bytes;
+       unsigned long io_blocks[2];
+       unsigned long io_bytes[2];
+       unsigned long this_io_bytes[2];
        unsigned long last_bytes;
        sem_t mutex;
 
@@ -185,12 +185,12 @@ struct thread_data {
        /*
         * bandwidth and latency stats
         */
-       struct io_stat clat_stat;               /* completion latency */
-       struct io_stat slat_stat;               /* submission latency */
+       struct io_stat clat_stat[2];            /* completion latency */
+       struct io_stat slat_stat[2];            /* submission latency */
+       struct io_stat bw_stat[2];              /* bandwidth stats */
 
-       struct io_stat bw_stat;                 /* bandwidth stats */
-       unsigned long stat_io_bytes;
-       struct timeval stat_sample_time;
+       unsigned long stat_io_bytes[2];
+       struct timeval stat_sample_time[2];
 
        struct io_log *lat_log;
        struct io_log *bw_log;
@@ -293,6 +293,13 @@ struct disk_util {
        struct timeval time;
 };
 
+struct io_completion_data {
+       int nr;                         /* input */
+
+       int error;                      /* output */
+       unsigned long bytes_done[2];    /* output */
+};
+
 #define DISK_UTIL_MSEC (250)
 
 #endif