[svn-r11894] Purpose:

Feature, address bug #426

Description:
The h5perf test now also keeps track of the time it takes to:

open a file: Time between start of open and start first read/write
close a file: Time between end of last read/write and end of close.

This information is only displayed if debug output printing is enabled (level 3 or higher)

Solution:
The test actually has all of the data necessary to compute the time it takes to open
and close a file; it just wasn't recording it.  Added 4 new timers:

HDF5_FILE_READ_OPEN
HDF5_FILE_READ_CLOSE
HDF5_FILE_WRITE_OPEN
HDF5_FILE_WRITE_CLOSE

that keep track of the time to open/close a file opened for reading/writing.

Platforms tested:
heping and mir

Misc. update:

3 files changed, 137 insertions, 12 deletions

diff --git a/perform/pio_perf.c b/perform/pio_perf.c
index d436e5c..f19afa7 100644
--- a/perform/pio_perf.c
+++ b/perform/pio_perf.c
@@ -532,6 +532,10 @@ run_test(iotype iot, parameters parms, struct options *opts)
     minmax         *read_mm_table=NULL;
     minmax         *read_gross_mm_table=NULL;
     minmax         *read_raw_mm_table=NULL;
+    minmax	   *read_open_mm_table=NULL;
+    minmax	   *read_close_mm_table=NULL;
+    minmax	   *write_open_mm_table=NULL;
+    minmax	   *write_close_mm_table=NULL;
     minmax          write_mpi_mm = {0.0, 0.0, 0.0, 0};
     minmax          write_mm = {0.0, 0.0, 0.0, 0};
     minmax          write_gross_mm = {0.0, 0.0, 0.0, 0};
@@ -540,6 +544,10 @@ run_test(iotype iot, parameters parms, struct options *opts)
     minmax          read_mm = {0.0, 0.0, 0.0, 0};
     minmax          read_gross_mm = {0.0, 0.0, 0.0, 0};
     minmax          read_raw_mm = {0.0, 0.0, 0.0, 0};
+    minmax	    read_open_mm = {0.0, 0.0, 0.0, 0};
+    minmax	    read_close_mm = {0.0, 0.0, 0.0, 0};
+    minmax	    write_open_mm = {0.0, 0.0, 0.0, 0};
+    minmax	    write_close_mm = {0.0, 0.0, 0.0, 0};
 
     raw_size = (off_t)parms.num_dsets * (off_t)parms.num_bytes;
     parms.io_type = iot;
@@ -569,13 +577,18 @@ run_test(iotype iot, parameters parms, struct options *opts)
     write_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
     write_gross_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
     write_raw_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+    write_open_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+    write_close_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
 
     if (!parms.h5_write_only) {
-        read_mpi_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
-        read_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
-        read_gross_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
-        read_raw_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
-    }
+	read_mpi_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+	read_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+	read_gross_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+	read_raw_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+	read_open_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+	read_close_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+
+   }
 
     /* Do IO iteration times, collecting statistics each time */
     for (i = 0; i < parms.num_iters; ++i) {
@@ -603,10 +616,22 @@ run_test(iotype iot, parameters parms, struct options *opts)
         write_gross_mm_table[i] = write_gross_mm;
 
         /* gather all of the raw "write" times */
-        t = get_time(res.timers, HDF5_RAW_WRITE_FIXED_DIMS);
+	t = get_time(res.timers, HDF5_RAW_WRITE_FIXED_DIMS);
 	get_minmax(&write_raw_mm, t);
 
-        write_raw_mm_table[i] = write_raw_mm;
+	write_raw_mm_table[i] = write_raw_mm;
+
+	/* gather all of the file open times (time from open to first write) */
+	t = get_time(res.timers, HDF5_FILE_WRITE_OPEN);
+	get_minmax(&write_open_mm, t);
+
+	write_open_mm_table[i] = write_open_mm;
+
+	/* gather all of the file close times (time from last write to close) */
+	t = get_time(res.timers, HDF5_FILE_WRITE_CLOSE);
+	get_minmax(&write_close_mm, t);
+
+        write_close_mm_table[i] = write_close_mm;
 
         if (!parms.h5_write_only) {
             /* gather all of the "mpi read" times */
@@ -632,6 +657,19 @@ run_test(iotype iot, parameters parms, struct options *opts)
             get_minmax(&read_raw_mm, t);
 
             read_raw_mm_table[i] = read_raw_mm;
+
+	    /* gather all of the file open times (time from open to first read) */
+	    t = get_time(res.timers, HDF5_FILE_READ_OPEN);
+	    get_minmax(&read_open_mm, t);
+
+	    read_open_mm_table[i] = read_open_mm;
+
+	    /* gather all of the file close times (time from last read to close) */
+	    t = get_time(res.timers, HDF5_FILE_READ_CLOSE);
+	    get_minmax(&read_close_mm, t);
+
+	    read_close_mm_table[i] = read_close_mm;
+	    
         }
 
         pio_time_destroy(res.timers);
@@ -684,6 +722,24 @@ run_test(iotype iot, parameters parms, struct options *opts)
 
     output_results(opts,"Write Open-Close",write_gross_mm_table,parms.num_iters,raw_size);
 
+    /* Print out time from open to first write */
+    if (pio_debug_level >= 3) {
+	/* output all of the times for all iterations */
+	print_indent(3);
+	output_report("Write file open details:\n");
+	output_all_info(write_open_mm_table, parms.num_iters, 4);
+    }
+
+    /* Print out time from last write to close */
+    if (pio_debug_level >= 3) {
+	/* output all of the times for all iterations */
+	print_indent(3);
+	output_report("Write file close details:\n");
+	output_all_info(write_close_mm_table, parms.num_iters, 4);
+    }
+
+
+    
     if (!parms.h5_write_only) {
         /* Read statistics	*/
         /* Print the raw data throughput if desired */
@@ -728,8 +784,26 @@ run_test(iotype iot, parameters parms, struct options *opts)
             output_all_info(read_gross_mm_table, parms.num_iters, 4);
         }
 
-        output_results(opts, "Read Open-Close", read_gross_mm_table,
-                       parms.num_iters, raw_size);
+	output_results(opts, "Read Open-Close", read_gross_mm_table,
+		parms.num_iters, raw_size);
+
+
+	/* Print out time from open to first read */
+	if (pio_debug_level >= 3) {
+	    /* output all of the times for all iterations */
+	    print_indent(3);
+	    output_report("Read file open details:\n");
+	    output_all_info(read_open_mm_table, parms.num_iters, 4);
+	}
+
+	/* Print out time from last read to close */
+	if (pio_debug_level >= 3) {
+	    /* output all of the times for all iterations */
+	    print_indent(3);
+	    output_report("Read file close details:\n");
+	    output_all_info(read_close_mm_table, parms.num_iters, 4);
+	}
+
     }
 
     /* clean up our mess */
@@ -737,12 +811,16 @@ run_test(iotype iot, parameters parms, struct options *opts)
     free(write_mm_table);
     free(write_gross_mm_table);
     free(write_raw_mm_table);
+    free(write_open_mm_table);
+    free(write_close_mm_table);
 
     if (!parms.h5_write_only) {
         free(read_mpi_mm_table);
         free(read_mm_table);
         free(read_gross_mm_table);
         free(read_raw_mm_table);
+	free(read_open_mm_table);
+	free(read_close_mm_table);
     }
 
     return ret_value;
diff --git a/perform/pio_timer.c b/perform/pio_timer.c
index 10e0ff4..027b536 100644
--- a/perform/pio_timer.c
+++ b/perform/pio_timer.c
@@ -119,21 +119,55 @@ set_time(pio_time *pt, timer_type t, int start_stop)
         if (pt->type == MPI_TIMER) {
             if (start_stop == START) {
                 pt->mpi_timer[t] = MPI_Wtime();
+
+		/* When we start the timer for HDF5_FINE_WRITE_FIXED_DIMS or HDF5_FINE_READ_FIXED_DIMS
+		 * we compute the time it took to only open the file */
+		if(t == HDF5_FINE_WRITE_FIXED_DIMS)
+		    pt->total_time[HDF5_FILE_WRITE_OPEN] += pt->mpi_timer[t] - pt->mpi_timer[HDF5_GROSS_WRITE_FIXED_DIMS];
+		else if(t == HDF5_FINE_READ_FIXED_DIMS)
+		    pt->total_time[HDF5_FILE_READ_OPEN] += pt->mpi_timer[t] - pt->mpi_timer[HDF5_GROSS_READ_FIXED_DIMS];
+
             } else {
                 pt->total_time[t] += MPI_Wtime() - pt->mpi_timer[t];
+		pt->mpi_timer[t] = MPI_Wtime(); 
+
+		/* When we stop the timer for HDF5_GROSS_WRITE_FIXED_DIMS or HDF5_GROSS_READ_FIXED_DIMS
+		 * we compute the time it took to close the file after the last read/write finished */
+		if(t == HDF5_GROSS_WRITE_FIXED_DIMS)
+		    pt->total_time[HDF5_FILE_WRITE_CLOSE] += pt->mpi_timer[t] - pt->mpi_timer[HDF5_FINE_WRITE_FIXED_DIMS];
+		else if(t == HDF5_GROSS_READ_FIXED_DIMS)
+		    pt->total_time[HDF5_FILE_READ_CLOSE] += pt->mpi_timer[t] - pt->mpi_timer[HDF5_FINE_READ_FIXED_DIMS];
             }
         } else {
             if (start_stop == START) {
                 gettimeofday(&pt->sys_timer[t], NULL);
+
+		/* When we start the timer for HDF5_FINE_WRITE_FIXED_DIMS or HDF5_FINE_READ_FIXED_DIMS
+		 * we compute the time it took to only open the file */
+		if(t == HDF5_FINE_WRITE_FIXED_DIMS)
+		    pt->total_time[HDF5_FILE_WRITE_OPEN] += sub_time(&(pt->sys_timer[t]), &(pt->sys_timer[HDF5_GROSS_WRITE_FIXED_DIMS]));
+		else if(t == HDF5_FINE_READ_FIXED_DIMS)
+		    pt->total_time[HDF5_FILE_READ_OPEN] += sub_time(&(pt->sys_timer[t]), &(pt->sys_timer[HDF5_GROSS_READ_FIXED_DIMS]));
+
+		
             } else {
                 struct timeval sys_t;
 
                 gettimeofday(&sys_t, NULL);
-                pt->total_time[t] +=
-                    ((double)sys_t.tv_sec +
+                pt->total_time[t] += sub_time(&sys_t, &(pt->sys_timer[t]));
+
+/*                    ((double)sys_t.tv_sec +
                                 ((double)sys_t.tv_usec) / MICROSECOND) -
                     ((double)pt->sys_timer[t].tv_sec +
-                            ((double)pt->sys_timer[t].tv_usec) / MICROSECOND);
+                            ((double)pt->sys_timer[t].tv_usec) / MICROSECOND);*/
+
+		/* When we stop the timer for HDF5_GROSS_WRITE_FIXED_DIMS or HDF5_GROSS_READ_FIXED_DIMS
+		 * we compute the time it took to close the file after the last read/write finished */
+		if(t == HDF5_GROSS_WRITE_FIXED_DIMS)
+		    pt->total_time[HDF5_FILE_WRITE_CLOSE] += sub_time(&(pt->sys_timer[t]), &(pt->sys_timer[HDF5_FINE_WRITE_FIXED_DIMS]));
+		else if(t == HDF5_GROSS_READ_FIXED_DIMS)
+		    pt->total_time[HDF5_FILE_READ_CLOSE] += sub_time(&(pt->sys_timer[t]), &(pt->sys_timer[HDF5_FINE_READ_FIXED_DIMS]));
+	
             }
         }
 
@@ -201,6 +235,15 @@ get_time(pio_time *pt, timer_type t)
     return pt->total_time[t];
 }
 
+/* Assumes that a > b */
+static inline double sub_time(struct timeval* a, struct timeval* b)
+{
+    ((double)a->tv_sec +
+     ((double)a->tv_usec) / MICROSECOND) -
+	((double)b->tv_sec +
+	 ((double)b->tv_usec) / MICROSECOND);
+}
+
 #endif /* H5_HAVE_PARALLEL */
 #ifdef STANDALONE
 #include "pio_standalone.c"
diff --git a/perform/pio_timer.h b/perform/pio_timer.h
index 3094997..ca942a3 100644
--- a/perform/pio_timer.h
+++ b/perform/pio_timer.h
@@ -32,6 +32,10 @@ typedef enum timer_type_ {
     HDF5_DATASET_CREATE,
     HDF5_MPI_WRITE,
     HDF5_MPI_READ,
+    HDF5_FILE_READ_OPEN,
+    HDF5_FILE_READ_CLOSE,
+    HDF5_FILE_WRITE_OPEN,
+    HDF5_FILE_WRITE_CLOSE,
     HDF5_FINE_WRITE_FIXED_DIMS,
     HDF5_FINE_READ_FIXED_DIMS,
     HDF5_GROSS_WRITE_FIXED_DIMS,