From: Jens Axboe <axboe@suse.de>
Date: Wed, 7 Dec 2005 18:40:29 +0000 (+0100)
Subject: [PATCH] fio: split up and improve output stats
X-Git-Url: https://git.kernel.dk/?a=commitdiff_plain;h=28f0d681668aaccb4f4a937b7771c313662685b0;p=disktools.git

[PATCH] fio: split up and improve output stats
---

diff --git a/fio-ini.c b/fio-ini.c
index 748a29c..093b9b3 100644
--- 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 e166f49..5f7d53d 100644
--- 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 2853c4f..600c3be 100644
--- 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