[PATCH] fio: Add submission latency numbers for aio

diff --git a/fio.c b/fio.c
index 3d284c5372aeea7fbf6b006da681bd8ab1b09953..afb82bfb3b23df0771b6f23a0554c9b48a9a474a 100644 (file)
--- a/fio.c
+++ b/fio.c
@@ -159,6 +159,7 @@ enum {
  */
 struct io_u {
        struct iocb iocb;
+       struct timeval start_time;
        struct timeval issue_time;
 
        void *mem;
@@ -169,6 +170,14 @@ struct io_u {
        struct list_head list;
 };
 
+struct io_stat {
+       unsigned long val;
+       unsigned long val_sq;
+       unsigned long max_val;
+       unsigned long min_val;
+       unsigned long samples;
+};
+
 #define td_read(td)            ((td)->ddir == DDIR_READ)
 #define should_fsync(td)       (!td_read(td) && !(td)->odirect)
 
@@ -215,8 +224,6 @@ struct thread_data {
        unsigned long rate_blocks;
        struct timeval lastrate;
 
-       unsigned long max_latency;      /* msec */
-       unsigned long min_latency;      /* msec */
        unsigned long runtime;          /* sec */
        unsigned long blocks;
        unsigned long io_blocks;
@@ -227,13 +234,11 @@ struct thread_data {
        /*
         * bandwidth and latency stats
         */
-       unsigned long stat_time;
-       unsigned long stat_time_sq;
-       unsigned long stat_time_samples;
+       struct io_stat clat_stat;               /* completion latency */
+       struct io_stat slat_stat;               /* submission latency */
+
+       struct io_stat bw_stat;                 /* bandwidth stats */
        unsigned long stat_io_blocks;
-       unsigned long stat_bw;
-       unsigned long stat_bw_sq;
-       unsigned long stat_bw_samples;
        struct timeval stat_sample_time;
 
        struct timeval start;
@@ -346,24 +351,42 @@ static unsigned long get_next_offset(struct thread_data *td)
        return b * td->bs + td->file_offset;
 }
 
-static void add_stat_sample(struct thread_data *td, unsigned long msec)
+static inline void add_stat_sample(struct thread_data *td, struct io_stat *is,
+                                  unsigned long val)
 {
-       unsigned long spent;
+       if (val > is->max_val)
+               is->max_val = val;
+       if (val < is->min_val)
+               is->min_val = val;
+
+       is->val += val;
+       is->val_sq += val * val;
+       is->samples++;
+}
 
-       td->stat_time += msec;
-       td->stat_time_sq += msec * msec;
-       td->stat_time_samples++;
+static void add_clat_sample(struct thread_data *td, unsigned long msec)
+{
+       add_stat_sample(td, &td->clat_stat, msec);
+}
 
-       spent = mtime_since_now(&td->stat_sample_time);
-       if (spent >= 500) {
-               unsigned long rate = ((td->io_blocks - td->stat_io_blocks) * td->bs) / spent;
+static void add_slat_sample(struct thread_data *td, unsigned long msec)
+{
+       add_stat_sample(td, &td->slat_stat, msec);
+}
 
-               td->stat_bw += rate;
-               td->stat_bw_sq += rate * rate;
-               gettimeofday(&td->stat_sample_time, NULL);
-               td->stat_io_blocks = td->io_blocks;
-               td->stat_bw_samples++;
-       }
+static void add_bw_sample(struct thread_data *td, unsigned long msec)
+{
+       unsigned long spent = mtime_since_now(&td->stat_sample_time);
+       unsigned long rate;
+
+       if (spent < 500)
+               return;
+
+       rate = ((td->io_blocks - td->stat_io_blocks) * td->bs) / spent;
+       add_stat_sample(td, &td->bw_stat, rate);
+
+       gettimeofday(&td->stat_sample_time, NULL);
+       td->stat_io_blocks = td->io_blocks;
 }
 
 static void usec_sleep(int usec)
@@ -469,7 +492,7 @@ static struct io_u *get_io_u(struct thread_data *td)
                        io_prep_pwrite(&io_u->iocb, td->fd, io_u->buf, io_u->buflen, io_u->offset);
        }
 
-       gettimeofday(&io_u->issue_time, NULL);
+       gettimeofday(&io_u->start_time, NULL);
        td->cur_depth++;
        return io_u;
 }
@@ -520,7 +543,7 @@ static void do_sync_io(struct thread_data *td)
 
                gettimeofday(&e, NULL);
 
-               usec = utime_since(&io_u->issue_time, &e);
+               usec = utime_since(&io_u->start_time, &e);
 
                rate_throttle(td, usec);
 
@@ -530,12 +553,8 @@ static void do_sync_io(struct thread_data *td)
                }
 
                msec = usec / 1000;
-               add_stat_sample(td, msec);
-
-               if (msec < td->min_latency)
-                       td->min_latency = msec;
-               if (msec > td->max_latency)
-                       td->max_latency = msec;
+               add_clat_sample(td, msec);
+               add_bw_sample(td, msec);
 
                if (runtime_exceeded(td, &e))
                        break;
@@ -586,12 +605,8 @@ static void ios_completed(struct thread_data *td, int nr)
 
                msec = mtime_since(&io_u->issue_time, &e);
 
-               add_stat_sample(td, msec);
-
-               if (msec < td->min_latency)
-                       td->min_latency = msec;
-               if (msec > td->max_latency)
-                       td->max_latency = msec;
+               add_clat_sample(td, msec);
+               add_bw_sample(td, msec);
 
                put_io_u(td, io_u);
        }
@@ -648,7 +663,7 @@ static void do_async_io(struct thread_data *td)
 
                io_u = get_io_u(td);
 
-               memcpy(&s, &io_u->issue_time, sizeof(s));
+               memcpy(&s, &io_u->start_time, sizeof(s));
 
                ret = io_u_queue(td, io_u);
                if (ret) {
@@ -657,6 +672,9 @@ static void do_async_io(struct thread_data *td)
                        break;
                }
 
+               gettimeofday(&io_u->issue_time, NULL);
+               add_slat_sample(td, mtime_since(&io_u->start_time, &io_u->issue_time));
+
                if (td->cur_depth < td->aio_depth) {
                        timeout = &ts;
                        min_evts = 0;
@@ -761,18 +779,18 @@ static int create_file(struct thread_data *td)
        unsigned int i;
        char *b;
 
-       if (!td->file_size) {
-               fprintf(stderr, "Need size for create\n");
-               td->error = EINVAL;
-               return 1;
-       }
-
        /*
         * unless specifically asked for overwrite, let normal io extend it
         */
        if (!td_read(td) && !td->overwrite)
                return 0;
 
+       if (!td->file_size) {
+               fprintf(stderr, "Need size for create\n");
+               td->error = EINVAL;
+               return 1;
+       }
+
        td->fd = open(td->file_name, O_WRONLY | O_CREAT | O_TRUNC, 0644);
        if (td->fd < 0) {
                td->error = errno;
@@ -956,11 +974,28 @@ static void free_shm(void)
        shmdt(threads);
 }
 
+static int calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max,
+                   double *mean, double *dev)
+{
+       double n;
+
+       if (is->samples == 0)
+               return 0;
+
+       *min = is->min_val;
+       *max = is->max_val;
+
+       n = (double) is->samples;
+       *mean = (double) is->val / n;
+       *dev = sqrt(((double) is->val_sq - (*mean * *mean) / n) / (n - 1));
+       return 1;
+}
+
 static void show_thread_status(struct thread_data *td)
 {
        int prio, prio_class;
-       unsigned long bw = 0;
-       double n_lat, n_bw, m_lat, m_bw, dev_lat, dev_bw;
+       unsigned long min, max, bw = 0;
+       double mean, dev;
 
        if (!td->io_blocks && !td->error)
                return;
@@ -971,15 +1006,14 @@ static void show_thread_status(struct thread_data *td)
        prio = td->ioprio & 0xff;
        prio_class = td->ioprio >> IOPRIO_CLASS_SHIFT;
 
-       n_lat = (double) td->stat_time_samples;
-       n_bw = (double) td->stat_bw_samples;
+       printf("Client%d: err=%2d, io=%6luMiB, bw=%6luKiB/s\n", td->thread_number, td->error, td->io_blocks * td->bs >> 20, bw);
 
-       m_lat = (double) td->stat_time / n_lat;
-       dev_lat = sqrt(((double) td->stat_time_sq - (m_lat * m_lat) / n_lat) / (n_lat - 1));
-       m_bw = (double) td->stat_bw / n_bw;
-       dev_bw = sqrt(((double) td->stat_bw_sq - (m_bw * m_bw) / n_bw) / (n_bw - 1));
-
-       printf("Client%d: err=%2d, io=%6luMiB, bw=%6luKiB/sec, latmax=%5lumsec, latavg=%5.02fmsec, latdev=%5.02fmsec, bwavg=%5.02fKiB/sec, bwdev=%5.02fKiB/sec\n", td->thread_number, td->error, td->io_blocks * td->bs >> 20, bw, td->max_latency, m_lat, dev_lat, m_bw, dev_bw);
+       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))
+               printf("  bw (KiB/s) : min=%5lu, max=%5lu, avg=%5.02f, dev=%5.02f\n", min, max, mean, dev);
 }
 
 static int setup_rate(struct thread_data *td)
@@ -1042,9 +1076,12 @@ static int add_job(struct thread_data *td, const char *filename, int prioclass,
 
        strcpy(td->file_name, filename);
        sem_init(&td->mutex, 1, 0);
-       td->min_latency = 10000000;
        td->ioprio = (prioclass << IOPRIO_CLASS_SHIFT) | prio;
 
+       td->clat_stat.min_val = ULONG_MAX;
+       td->slat_stat.min_val = ULONG_MAX;
+       td->bw_stat.min_val = ULONG_MAX;
+
        if (td->use_aio) {
                if (!td->aio_depth)
                        td->aio_depth = 1;
@@ -1723,7 +1760,7 @@ int setup_thread_area(void)
 int main(int argc, char *argv[])
 {
        static unsigned long max_run[2], min_run[2], total_blocks[2];
-       static unsigned long max_bw[2], min_bw[2], maxl[2], minl[2];
+       static unsigned long max_bw[2], min_bw[2];
        static unsigned long read_mb, write_mb, read_agg, write_agg;
        int i;
 
@@ -1765,7 +1802,6 @@ int main(int argc, char *argv[])
 
        min_bw[0] = min_run[0] = ~0UL;
        min_bw[1] = min_run[1] = ~0UL;
-       minl[0] = minl[1] = ~0UL;
        for (i = 0; i < thread_number; i++) {
                struct thread_data *td = &threads[i];
                unsigned long bw = 0;
@@ -1784,10 +1820,6 @@ int main(int argc, char *argv[])
                        min_bw[td->ddir] = bw;
                if (bw > max_bw[td->ddir])
                        max_bw[td->ddir] = bw;
-               if (td->max_latency < minl[td->ddir])
-                       minl[td->ddir] = td->max_latency;
-               if (td->max_latency > maxl[td->ddir])
-                       maxl[td->ddir] = td->max_latency;
 
                total_blocks[td->ddir] += td->io_blocks;
 
@@ -1805,11 +1837,11 @@ show_stat:
                show_thread_status(td);
        }
 
-       printf("Run status:\n");
+       printf("\nRun status:\n");
        if (max_run[DDIR_READ])
-               printf("   READ: io=%luMiB, aggrb=%lu, minl=%lu, maxl=%lu, minb=%lu, maxb=%lu, mint=%lumsec, maxt=%lumsec\n", read_mb, read_agg, minl[0], maxl[0], min_bw[0], max_bw[0], min_run[0], max_run[0]);
+               printf("   READ: io=%luMiB, aggrb=%lu, minb=%lu, maxb=%lu, mint=%lumsec, maxt=%lumsec\n", read_mb, read_agg, min_bw[0], max_bw[0], min_run[0], max_run[0]);
        if (max_run[DDIR_WRITE])
-               printf("  WRITE: io=%luMiB, aggrb=%lu, minl=%lu, maxl=%lu, minb=%lu, maxb=%lu, mint=%lumsec, maxt=%lumsec\n", write_mb, write_agg, minl[1], maxl[1], min_bw[1], max_bw[1], min_run[1], max_run[1]);
+               printf("  WRITE: io=%luMiB, aggrb=%lu, minb=%lu, maxb=%lu, mint=%lumsec, maxt=%lumsec\n", write_mb, write_agg, min_bw[1], max_bw[1], min_run[1], max_run[1]);
 
        return 0;
 }