simoop: improve timing printouts

This records the amount of time required to run the filler threads,
adds a signal handler for SIGINT, and reworks the final stats printed on
process exit.

Signed-off-by: Chris Mason <clm@fb.com>

1 files changed, 29 insertions, 4 deletions

diff --git a/simoop.c b/simoop.c
index 0a5dbd9..097271e 100644
--- a/simoop.c
+++ b/simoop.c
@@ -26,6 +26,7 @@
 #include <ctype.h>
 #include <limits.h>
 #include <stdint.h>
+#include <signal.h>
 #include "xxhash.h"
 
 /* these are part of the histogram accounting */
@@ -131,6 +132,7 @@ static unsigned long interval_seconds = 120;
 /* the master thread flips this to true when runtime is up */
 static volatile unsigned long stopping = 0;
 static volatile unsigned long warmup_done = 0;
+static double filler_completion_time = 0;
 
 /*
  * one stat struct per thread data, when the workers sleep this records the
@@ -1524,12 +1526,17 @@ void run_filler_threads(void)
 	int j;
 	pthread_t *tids;
 	pthread_t *this_tid;
+	struct timeval now;
+	struct timeval start;
+	unsigned long long delta;
+	double seconds;
 
 	tids = malloc(sizeof(*tids) * total_paths * FILES_SPLIT);
 	if (!tids) {
 		perror("malloc");
 		exit(1);
 	}
+	gettimeofday(&start, NULL);
 	fprintf(stderr, "Creating working files\n");
 	this_tid = tids;
 	for (i = 0; i < total_paths; i++) {
@@ -1557,7 +1564,13 @@ void run_filler_threads(void)
 			this_tid++;
 		}
 	}
-	fprintf(stderr, "done creating working files\n");
+
+	gettimeofday(&now, NULL);
+	delta = tvdelta(&start, &now);
+	seconds = (double)delta / 1000000;
+	filler_completion_time = seconds;
+
+	fprintf(stderr, "done creating working files %.2f seconds total time\n", seconds);
 	free(tids);
 }
 
@@ -1857,6 +1870,13 @@ static void print_latencies(struct thread_data *worker_threads_mem,
 
 }
 
+void mysigint(int sig)
+{
+	fprintf(stderr, "Stopping due to signal %d...\n", sig);
+	__sync_synchronize();
+	stopping = 1;
+}
+
 /* runtime from the command line is in seconds.  Sleep until its up */
 static void sleep_for_runtime(struct thread_data *worker_threads_mem)
 {
@@ -1886,7 +1906,7 @@ static void sleep_for_runtime(struct thread_data *worker_threads_mem)
 	read_vmstat(&vmstat_info);
 	save_vmstat_rates(&vmstat_info);
 	save_instant_vmstat_rates(&vmstat_info);
-	while(1) {
+	while(!stopping) {
 		gettimeofday(&now, NULL);
 		instant_start = now;
 		delta = tvdelta(&start, &now);
@@ -1930,7 +1950,8 @@ static void sleep_for_runtime(struct thread_data *worker_threads_mem)
 	}
 	__sync_synchronize();
 	stopping = 1;
-	fprintf(stderr, "stopping, runtime_usec %Lu delta %Lu\n", runtime_usec, delta);
+	fprintf(stderr, "\n------\nFinal stats:\n\n");
+	fprintf(stderr, "Initial filler completion time %.2f seconds\n", filler_completion_time);
 
 	for (i = 0; i < cpu_threads + worker_threads; i++) {
 		pthread_join(worker_threads_mem[i].tid, NULL);
@@ -1951,6 +1972,7 @@ static void sleep_for_runtime(struct thread_data *worker_threads_mem)
 			work_done - instant_work_done,
 			rate_delta, instant_delta);
 
+
 }
 
 int main(int ac, char **av)
@@ -1983,6 +2005,10 @@ int main(int ac, char **av)
 	run_filler_threads();
 
 	stopping = 0;
+	if (signal(SIGINT, mysigint) == SIG_ERR) {
+		perror("signal");
+		exit(1);
+	}
 
 	/* worker threads do the IO and the real stuff */
 	for (i = 0; i < worker_threads; i++) {
@@ -2030,6 +2056,5 @@ int main(int ac, char **av)
 	}
 
 	free(worker_threads_mem);
-	fprintf(stderr, "normal exit\n");
 	return 0;
 }