From c8eeb9df1f52f28567a5937e141decc6a26ec30b Mon Sep 17 00:00:00 2001 From: Jens Axboe Date: Wed, 5 Oct 2011 14:02:22 +0200 Subject: [PATCH] Add support for write_iops_log Signed-off-by: Jens Axboe --- HOWTO | 6 +++++ fio.1 | 9 ++++++++ fio.c | 18 +++++++++++---- fio.h | 10 ++++++++- fio_generate_plots | 18 +++++++++++++++ init.c | 2 ++ io_u.c | 55 +++++++++++++++++++++++++++++++--------------- iolog.h | 1 + options.c | 27 +++++++++++++++++++++++ stat.c | 32 ++++++++++++++++++++++++--- stat.h | 1 + 11 files changed, 153 insertions(+), 26 deletions(-) diff --git a/HOWTO b/HOWTO index cc2df9b7..24a0f3b0 100644 --- a/HOWTO +++ b/HOWTO @@ -864,6 +864,9 @@ exitall When one job finishes, terminate the rest. The default is bwavgtime=int Average the calculated bandwidth over the given time. Value is specified in milliseconds. +iopsavgtime=int Average the calculated IOPS over the given time. Value + is specified in milliseconds. + create_serialize=bool If true, serialize the file creating for the jobs. This may be handy to avoid interleaving of data files, which may greatly depend on the filesystem @@ -1104,6 +1107,9 @@ write_lat_log=str Same as write_bw_log, except that this option stores io and foo_lat.log. This helps fio_generate_plot fine the logs automatically. +write_bw_log=str If given, write an IOPS log of the jobs in this job + file. See write_bw_log. + lockmem=int Pin down the specified amount of memory with mlock(2). Can potentially be used instead of removing memory or booting with less memory to simulate a smaller amount of memory. diff --git a/fio.1 b/fio.1 index dc10b403..0baa4295 100644 --- a/fio.1 +++ b/fio.1 @@ -673,6 +673,10 @@ Terminate all jobs when one finishes. Default: wait for each job to finish. Average bandwidth calculations over the given time in milliseconds. Default: 500ms. .TP +.BI iopsavgtime \fR=\fPint +Average IOPS calculations over the given time in milliseconds. Default: +500ms. +.TP .BI create_serialize \fR=\fPbool If true, serialize file creation for the jobs. Default: true. .TP @@ -845,6 +849,11 @@ Same as \fBwrite_bw_log\fR, but writes I/O completion latencies. If no filename is given with this option, the default filename of "jobname_type.log" is used. Even if the filename is given, fio will still append the type of log. .TP +.BI write_iops_log \fR=\fPstr +Same as \fBwrite_bw_log\fR, but writes IOPS. If no filename is given with this +option, the default filename of "jobname_type.log" is used. Even if the +filename is given, fio will still append the type of log. +.TP .BI disable_lat \fR=\fPbool Disable measurements of total latency numbers. Useful only for cutting back the number of calls to gettimeofday, as that does impact performance at diff --git a/fio.c b/fio.c index 61ef88b3..d6802e0a 100644 --- a/fio.c +++ b/fio.c @@ -217,7 +217,7 @@ static int __check_min_rate(struct thread_data *td, struct timeval *now, if (mtime_since(&td->start, now) < 2000) return 0; - iops += td->io_blocks[ddir]; + iops += td->this_io_blocks[ddir]; bytes += td->this_io_bytes[ddir]; ratemin += td->o.ratemin[ddir]; rate_iops += td->o.rate_iops[ddir]; @@ -986,6 +986,8 @@ static void reset_io_counters(struct thread_data *td) { td->stat_io_bytes[0] = td->stat_io_bytes[1] = 0; td->this_io_bytes[0] = td->this_io_bytes[1] = 0; + td->stat_io_blocks[0] = td->stat_io_blocks[1] = 0; + td->this_io_blocks[0] = td->this_io_blocks[1] = 0; td->zone_bytes = 0; td->rate_bytes[0] = td->rate_bytes[1] = 0; td->rate_blocks[0] = td->rate_blocks[1] = 0; @@ -1184,12 +1186,12 @@ static void *thread_main(void *data) clear_state = 0; while (keep_running(td)) { fio_gettime(&td->start, NULL); - memcpy(&td->stat_sample_time[0], &td->start, sizeof(td->start)); - memcpy(&td->stat_sample_time[1], &td->start, sizeof(td->start)); + memcpy(&td->bw_sample_time, &td->start, sizeof(td->start)); + memcpy(&td->iops_sample_time, &td->start, sizeof(td->start)); memcpy(&td->tv_cache, &td->start, sizeof(td->start)); if (td->o.ratemin[0] || td->o.ratemin[1]) - memcpy(&td->lastrate, &td->stat_sample_time, + memcpy(&td->lastrate, &td->bw_sample_time, sizeof(td->lastrate)); if (clear_state) @@ -1266,6 +1268,14 @@ static void *thread_main(void *data) } else finish_log(td, td->clat_log, "clat"); } + if (td->iops_log) { + if (td->o.iops_log_file) { + finish_log_named(td, td->iops_log, + td->o.iops_log_file, "iops"); + } else + finish_log(td, td->iops_log, "iops"); + } + fio_mutex_up(writeout_mutex); if (td->o.exec_postrun) exec_string(td->o.exec_postrun); diff --git a/fio.h b/fio.h index ab0d6a49..65f79e03 100644 --- a/fio.h +++ b/fio.h @@ -139,6 +139,7 @@ struct thread_options { unsigned int use_os_rand; unsigned int write_lat_log; unsigned int write_bw_log; + unsigned int write_iops_log; unsigned int norandommap; unsigned int softrandommap; unsigned int bs_unaligned; @@ -157,6 +158,7 @@ struct thread_options { unsigned long long ramp_time; unsigned int overwrite; unsigned int bw_avg_time; + unsigned int iops_avg_time; unsigned int loops; unsigned long long zone_size; unsigned long long zone_skip; @@ -203,6 +205,7 @@ struct thread_options { char *write_iolog_file; char *bw_log_file; char *lat_log_file; + char *iops_log_file; char *replay_redirect; /* @@ -265,9 +268,13 @@ struct thread_data { struct io_log *clat_log; struct io_log *lat_log; struct io_log *bw_log; + struct io_log *iops_log; uint64_t stat_io_bytes[2]; - struct timeval stat_sample_time[2]; + struct timeval bw_sample_time; + + uint64_t stat_io_blocks[2]; + struct timeval iops_sample_time; struct rusage ru_start; struct rusage ru_end; @@ -365,6 +372,7 @@ struct thread_data { unsigned long io_issues[2]; unsigned long long io_blocks[2]; + unsigned long long this_io_blocks[2]; unsigned long long io_bytes[2]; unsigned long long io_skip_bytes; unsigned long long this_io_bytes[2]; diff --git a/fio_generate_plots b/fio_generate_plots index 21d7c6a9..4285415e 100755 --- a/fio_generate_plots +++ b/fio_generate_plots @@ -42,6 +42,24 @@ if [ "$PLOT_LINE"x != "x" ]; then echo "set title 'Bandwidth - $TITLE'; set xlabel 'time (msec)'; set ylabel 'KB/sec'; set terminal png size $XRES,$YRES; set output '$TITLE-bw.png'; plot " $PLOT_LINE | $GNUPLOT - fi +PLOT_LINE="" +for i in *iops.log; do + if [ ! -r $i ]; then + continue + fi + PT=$(echo $i | sed s/_iops.log//g) + if [ "$PLOT_LINE"x != "x" ]; then + PLOT_LINE=$PLOT_LINE", " + fi + + PLOT_LINE=$PLOT_LINE"'$i' title '$PT' with lines" +done + +if [ "$PLOT_LINE"x != "x" ]; then + echo Making bw logs + echo "set title 'IOPS - $TITLE'; set xlabel 'time (msec)'; set ylabel 'IOPS'; set terminal png size $XRES,$YRES; set output '$TITLE-IOPS.png'; plot " $PLOT_LINE | $GNUPLOT - +fi + PLOT_LINE="" for i in *slat.log; do if [ ! -r $i ]; then diff --git a/init.c b/init.c index fcee02bb..94b417e4 100644 --- a/init.c +++ b/init.c @@ -768,6 +768,8 @@ static int add_job(struct thread_data *td, const char *jobname, int job_add_num) } if (td->o.write_bw_log) setup_log(&td->bw_log); + if (td->o.write_iops_log) + setup_log(&td->iops_log); if (!td->o.name) td->o.name = strdup(jobname); diff --git a/io_u.c b/io_u.c index 77069c55..9488adee 100644 --- a/io_u.c +++ b/io_u.c @@ -13,6 +13,7 @@ struct io_completion_data { int nr; /* input */ + int account; /* input */ int error; /* output */ unsigned long bytes_done[2]; /* output */ @@ -1266,6 +1267,36 @@ void io_u_log_error(struct thread_data *td, struct io_u *io_u) td_verror(td, io_u->error, "io_u error"); } +static void account_io_completion(struct thread_data *td, struct io_u *io_u, + struct io_completion_data *icd, + const enum fio_ddir idx, unsigned int bytes) +{ + unsigned long uninitialized_var(lusec); + + if (!icd->account) + return; + + if (!td->o.disable_clat || !td->o.disable_bw) + lusec = utime_since(&io_u->issue_time, &icd->time); + + if (!td->o.disable_lat) { + unsigned long tusec; + + tusec = utime_since(&io_u->start_time, &icd->time); + add_lat_sample(td, idx, tusec, bytes); + } + + if (!td->o.disable_clat) { + add_clat_sample(td, idx, lusec, bytes); + io_u_mark_latency(td, lusec); + } + + if (!td->o.disable_bw) + add_bw_sample(td, idx, bytes, &icd->time); + + add_iops_sample(td, idx, &icd->time); +} + static void io_completed(struct thread_data *td, struct io_u *io_u, struct io_completion_data *icd) { @@ -1303,6 +1334,7 @@ static void io_completed(struct thread_data *td, struct io_u *io_u, int ret; td->io_blocks[idx]++; + td->this_io_blocks[idx]++; td->io_bytes[idx] += bytes; td->this_io_bytes[idx] += bytes; @@ -1318,25 +1350,9 @@ static void io_completed(struct thread_data *td, struct io_u *io_u, } } - if (ramp_time_over(td)) { - unsigned long uninitialized_var(lusec); + if (ramp_time_over(td) && td->runstate == TD_RUNNING) { + account_io_completion(td, io_u, icd, idx, bytes); - if (!td->o.disable_clat || !td->o.disable_bw) - lusec = utime_since(&io_u->issue_time, - &icd->time); - if (!td->o.disable_lat) { - unsigned long tusec; - - tusec = utime_since(&io_u->start_time, - &icd->time); - add_lat_sample(td, idx, tusec, bytes); - } - if (!td->o.disable_clat) { - add_clat_sample(td, idx, lusec, bytes); - io_u_mark_latency(td, lusec); - } - if (!td->o.disable_bw) - add_bw_sample(td, idx, bytes, &icd->time); if (__should_check_rate(td, idx)) { td->rate_pending_usleep[idx] = ((td->this_io_bytes[idx] * @@ -1386,6 +1402,7 @@ static void init_icd(struct thread_data *td, struct io_completion_data *icd, fio_gettime(&icd->time, NULL); icd->nr = nr; + icd->account = 1; icd->error = 0; icd->bytes_done[0] = icd->bytes_done[1] = 0; @@ -1404,6 +1421,8 @@ static void ios_completed(struct thread_data *td, if (!(io_u->flags & IO_U_F_FREE_DEF)) put_io_u(td, io_u); + + icd->account = 0; } } diff --git a/iolog.h b/iolog.h index dd4d6470..d8140f28 100644 --- a/iolog.h +++ b/iolog.h @@ -93,6 +93,7 @@ extern void add_slat_sample(struct thread_data *, enum fio_ddir, unsigned long, unsigned int); extern void add_bw_sample(struct thread_data *, enum fio_ddir, unsigned int, struct timeval *); +extern void add_iops_sample(struct thread_data *, enum fio_ddir, struct timeval *); extern void show_run_stats(void); extern void init_disk_util(struct thread_data *); extern void update_rusage_stat(struct thread_data *); diff --git a/options.c b/options.c index 19140375..f07cc7c4 100644 --- a/options.c +++ b/options.c @@ -749,6 +749,17 @@ static int str_write_lat_log_cb(void *data, const char *str) return 0; } +static int str_write_iops_log_cb(void *data, const char *str) +{ + struct thread_data *td = data; + + if (str) + td->o.iops_log_file = strdup(str); + + td->o.write_iops_log = 1; + return 0; +} + static int str_gtod_reduce_cb(void *data, int *il) { struct thread_data *td = data; @@ -1821,6 +1832,15 @@ static struct fio_option options[FIO_MAX_OPTS] = { .help = "Time window over which to calculate bandwidth" " (msec)", .def = "500", + .parent = "write_bw_log", + }, + { + .name = "iopsavgtime", + .type = FIO_OPT_INT, + .off1 = td_var_offset(iops_avg_time), + .help = "Time window over which to calculate IOPS (msec)", + .def = "500", + .parent = "write_iops_log", }, { .name = "create_serialize", @@ -1938,6 +1958,13 @@ static struct fio_option options[FIO_MAX_OPTS] = { .cb = str_write_lat_log_cb, .help = "Write log of latency during run", }, + { + .name = "write_iops_log", + .type = FIO_OPT_STR, + .off1 = td_var_offset(write_iops_log), + .cb = str_write_iops_log_cb, + .help = "Write log of IOPS during run", + }, { .name = "hugepage-size", .type = FIO_OPT_INT, diff --git a/stat.c b/stat.c index 7bcae310..6c652d6e 100644 --- a/stat.c +++ b/stat.c @@ -372,7 +372,7 @@ static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts, double p_of_agg; p_of_agg = mean * 100 / (double) rs->agg[ddir]; - log_info(" bw (KB/s) : min=%5lu, max=%5lu, per=%3.2f%%," + log_info(" bw (KB/s) : min=%5lu, max=%5lu, per=%3.2f%%," " avg=%5.02f, stdev=%5.02f\n", min, max, p_of_agg, mean, dev); } @@ -1004,7 +1004,7 @@ void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs, if (!ddir_rw(ddir)) return; - spent = mtime_since(&td->stat_sample_time[ddir], t); + spent = mtime_since(&td->bw_sample_time, t); if (spent < td->o.bw_avg_time) return; @@ -1015,6 +1015,32 @@ void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs, if (td->bw_log) add_log_sample(td, td->bw_log, rate, ddir, bs); - fio_gettime(&td->stat_sample_time[ddir], NULL); + fio_gettime(&td->bw_sample_time, NULL); td->stat_io_bytes[ddir] = td->this_io_bytes[ddir]; } + +void add_iops_sample(struct thread_data *td, enum fio_ddir ddir, + struct timeval *t) +{ + struct thread_stat *ts = &td->ts; + unsigned long spent, iops; + + if (!ddir_rw(ddir)) + return; + + spent = mtime_since(&td->iops_sample_time, t); + if (spent < td->o.iops_avg_time) + return; + + iops = ((td->this_io_blocks[ddir] - td->stat_io_blocks[ddir]) * 1000) / spent; + + add_stat_sample(&ts->iops_stat[ddir], iops); + + if (td->iops_log) { + assert(iops); + add_log_sample(td, td->iops_log, iops, ddir, 0); + } + + fio_gettime(&td->iops_sample_time, NULL); + td->stat_io_blocks[ddir] = td->this_io_blocks[ddir]; +} diff --git a/stat.h b/stat.h index 89766fc0..68bc9702 100644 --- a/stat.h +++ b/stat.h @@ -128,6 +128,7 @@ struct thread_stat { struct io_stat slat_stat[2]; /* submission latency */ struct io_stat lat_stat[2]; /* total latency */ struct io_stat bw_stat[2]; /* bandwidth stats */ + struct io_stat iops_stat[2]; /* IOPS stats */ /* * fio system usage accounting -- 2.25.1