[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:

1 files changed, 87 insertions, 9 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;