[DRBD-cvs] svn commit by phil - r2531 - branches/drbd-0.7/benchmark - More improvements to the io-latency-test program

[drbd-cvs at lists.linbit.com]

Author: phil
Date: 2006-10-13 16:46:58 +0200 (Fri, 13 Oct 2006)
New Revision: 2531

Modified:
   branches/drbd-0.7/benchmark/io-latency-test.c
Log:
More improvements to the io-latency-test program


Modified: branches/drbd-0.7/benchmark/io-latency-test.c
===================================================================
--- branches/drbd-0.7/benchmark/io-latency-test.c	2006-10-13 14:38:08 UTC (rev 2530)
+++ branches/drbd-0.7/benchmark/io-latency-test.c	2006-10-13 14:46:58 UTC (rev 2531)
@@ -34,6 +34,9 @@
 #include <time.h>
 #include <pthread.h>
 #include <stdio.h>
+#include <stdlib.h>
+#define _GNU_SOURCE
+#include <getopt.h>
 
 #define MONITOR_TIME 300000
 // Check every 300 milliseconds. (3.33 times per second)
@@ -41,22 +44,29 @@
 #define RECORD_TIME 20000
 // Try to write a record every 20 milliseconds (50 per second)
 
+unsigned int monitor_time=MONITOR_TIME;
+unsigned int record_time=RECORD_TIME;
+unsigned long records=0;
+
 struct shared_data {
 	pthread_mutex_t mutex;
 	unsigned long record_nr;
 	unsigned int write_duration_us;
 	unsigned int write_duration_records;
+	double avg_write_duration;
 };
 
 void* wd_thread(void *arg)
 {
 	struct shared_data *data = (struct shared_data*) arg;
-	unsigned long last_record_nr=-1, current_record_nr;
+	unsigned long last_record_nr=-1, current_record_nr=0;
 	unsigned int avg_write,wd,wr;
+	double avg_write_duration;
+
 	enum { IO_RUNNING, IO_BLOCKED } io_state = IO_RUNNING;
 	
 	while(1) {
-		usleep(MONITOR_TIME); // sleep some milliseconds
+		usleep(monitor_time); // sleep some milliseconds
 
 		pthread_mutex_lock(&data->mutex);
 		current_record_nr = data->record_nr;
@@ -64,8 +74,11 @@
 		wr = data->write_duration_records;
 		data->write_duration_us = 0;
 		data->write_duration_records = 0;
+		avg_write_duration = data->avg_write_duration;
 		pthread_mutex_unlock(&data->mutex);
 
+		if( records && current_record_nr == records) break;
+
 		switch(io_state) {
 		case IO_RUNNING:
 			if(current_record_nr == last_record_nr) {
@@ -78,9 +91,11 @@
 				avg_write = wd/wr;
 
 				printf("Current record: %lu "
-				       "( AVG write duration %d.%02dms )\r",
+				       "( cur. write duration %d.%02dms; "
+				       "avg. wd. %.2fms)\r",
 				       current_record_nr,
-				       avg_write/1000,(avg_write%1000)/10);
+				       avg_write/1000,(avg_write%1000)/10,
+				       avg_write_duration/1000);
 				fflush(stdout);
 			}
 			last_record_nr = current_record_nr;
@@ -91,8 +106,20 @@
 			}
 		}
 	}
+	if(io_state == IO_RUNNING) printf("\n");
 }
 
+void usage(char *prgname)
+{
+	fprintf(stderr, "USAGE: %s [options] recordfile\n"
+		"  Available options:\n"
+		"   --records val         -n val\n"
+		"   --record-interval-ms  -r val\n"
+		"   --monitor-interval-ms -m val\n",
+		prgname);
+	exit(20);
+}
+
 int main(int argc, char** argv)
 {
 	pthread_t watch_dog;
@@ -102,17 +129,46 @@
 	struct timeval now_tv, then_tv;
 	struct tm now_tm;
 	int write_duration_us=0;
+	int min_wd=(1<<30), max_wd=0;
+	double avg_write_duration;
+	int avg_wd_nr=0,c;
 
 	struct shared_data data;
 
-	if(argc != 2) {
-		fprintf(stderr,"USAGE: %s recordfile\n",argv[0]);
-		return 10;
+	static struct option options[] = {
+		{"records", required_argument, 0, 'n'},
+		{"record-interval-ms", required_argument, 0, 'r'},
+		{"monitor-interval-ms", required_argument, 0, 'm'},
+		{0, 0, 0, 0 }
+	};
+
+	while (1) {
+		c = getopt_long(argc, argv, "n:r:m:", options, 0);
+		if (c == -1)
+			break;
+		switch (c) {
+		case 'n':
+			records = atol(optarg);
+			break;
+		case 'r':
+			record_time = atoi(optarg) * 1000;
+			break;
+		case 'm':
+			monitor_time = atoi(optarg) * 1000;
+			break;
+		default:
+			usage(argv[0]);
+		}
 	}
 
-	if(!(record_f = fopen(argv[1],"w"))) {
+	if(optind != argc-1) {
+		usage(argv[0]);
+	}
+
+	if(!(record_f = fopen(argv[optind],"w"))) {
 		perror("fopen:");
-		fprintf(stderr,"Failed to open '%s' for writing\n",argv[1]);
+		fprintf(stderr,"Failed to open '%s' for writing\n",
+			argv[optind]);
 		return 10;
 	}
 
@@ -136,7 +192,7 @@
 	data.write_duration_records = 1;
 	pthread_create(&watch_dog,NULL,wd_thread,&data);
 
-	for(;;record_nr++) {
+	for( ; !records || record_nr < records ; record_nr++) {
 		gettimeofday(&now_tv, NULL);
 		localtime_r(&now_tv.tv_sec,&now_tm);
 
@@ -158,20 +214,46 @@
 		fflush(record_f); // flush it from glibc to the kernel.
 		fdatasync(fileno(record_f)); // from buffer cache to disk.
 
-		// eventually wait for full RECORD_TIME
+		// eventually wait for full record_time
 		gettimeofday(&then_tv, NULL);
 		write_duration_us =
 			( (then_tv.tv_sec  - now_tv.tv_sec ) * 1000000 +
 			  (then_tv.tv_usec - now_tv.tv_usec) );
 
+		if(write_duration_us < monitor_time) {
+			if(write_duration_us < min_wd) min_wd = write_duration_us;
+			if(write_duration_us > max_wd) max_wd = write_duration_us;
+
+			avg_write_duration = 
+				(avg_write_duration * avg_wd_nr + 
+				 write_duration_us) / (++avg_wd_nr);
+		}
+
 		pthread_mutex_lock(&data.mutex);
 		data.record_nr = record_nr;
 		data.write_duration_us += write_duration_us;
 		data.write_duration_records++;
+		data.avg_write_duration = avg_write_duration;
 		pthread_mutex_unlock(&data.mutex);
 
-		if(write_duration_us < RECORD_TIME ) {
-			usleep(RECORD_TIME - write_duration_us);
+		if(write_duration_us < record_time ) {
+			usleep(record_time - write_duration_us);
 		}
 	}
+
+	pthread_mutex_lock(&data.mutex);
+	data.record_nr = record_nr;
+	pthread_mutex_unlock(&data.mutex);
+
+	pthread_join(watch_dog,NULL);
+
+	printf( "STATS:\n"
+		"  Records written: %lu\n"
+		"  Average write duration: %.2fms\n"
+		"  Longest write duration (<%dms): %.2fms\n"
+		"  Shortest write duration: %.2fms\n",
+		records,
+		avg_write_duration/1000,
+		monitor_time/1000,(double)max_wd/1000,
+		(double)min_wd/1000);
 }