Add support for write_iops_log

Signed-off-by: Jens Axboe <axboe@kernel.dk>
diff --git a/HOWTO b/HOWTO
index cc2df9b..24a0f3b 100644
--- a/HOWTO
+++ b/HOWTO
@@ -864,6 +864,9 @@
 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 @@
 		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 dc10b40..0baa429 100644
--- a/fio.1
+++ b/fio.1
@@ -673,6 +673,10 @@
 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 @@
 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 61ef88b..d6802e0 100644
--- a/fio.c
+++ b/fio.c
@@ -217,7 +217,7 @@
 	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 @@
 {
 	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 @@
 	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 @@
 		} 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 ab0d6a4..65f79e0 100644
--- a/fio.h
+++ b/fio.h
@@ -139,6 +139,7 @@
 	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 @@
 	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 @@
 	char *write_iolog_file;
 	char *bw_log_file;
 	char *lat_log_file;
+	char *iops_log_file;
 	char *replay_redirect;
 
 	/*
@@ -265,9 +268,13 @@
 	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 @@
 
 	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 21d7c6a..4285415 100755
--- a/fio_generate_plots
+++ b/fio_generate_plots
@@ -43,6 +43,24 @@
 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
 		continue
diff --git a/init.c b/init.c
index fcee02b..94b417e 100644
--- a/init.c
+++ b/init.c
@@ -768,6 +768,8 @@
 	}
 	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 77069c5..9488ade 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 @@
 		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 @@
 		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 @@
 			}
 		}
 
-		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 @@
 		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 @@
 
 		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 dd4d647..d8140f2 100644
--- a/iolog.h
+++ b/iolog.h
@@ -93,6 +93,7 @@
 				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 1914037..f07cc7c 100644
--- a/options.c
+++ b/options.c
@@ -749,6 +749,17 @@
 	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 @@
 		.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",
@@ -1939,6 +1959,13 @@
 		.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,
 		.off1	= td_var_offset(hugepage_size),
diff --git a/stat.c b/stat.c
index 7bcae31..6c652d6 100644
--- a/stat.c
+++ b/stat.c
@@ -372,7 +372,7 @@
 		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 @@
 	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 @@
 	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 89766fc..68bc970 100644
--- a/stat.h
+++ b/stat.h
@@ -128,6 +128,7 @@
 	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