From 57d753e342441e531626c2e0b50d2eb28f67ada4 Mon Sep 17 00:00:00 2001 From: Jens Axboe Date: Tue, 25 Oct 2005 12:44:35 +0200 Subject: [PATCH] [PATCH] fio: Add submission latency numbers for aio --- fio.c | 158 +++++++++++++++++++++++++++++++++++----------------------- 1 file changed, 95 insertions(+), 63 deletions(-) diff --git a/fio.c b/fio.c index 3d284c5..afb82bf 100644 --- 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; } -- 2.25.1