[svn-r5367] Purpose:

    Modification
Description:
    Put some of the variables into the global space so that random
    functions can access them. (The output and timer variables which
    point to the output file and timer resp.)

    Placed the debug level 4 prints into the timer module so that it's
    easier to automatically put timer start/stop printfs for new timers
    which are created.

    Added timers for MPI Time calls (called HDF5_MPI_WRITE and
    HDF5_MPI_READ).
Platforms tested:
    Linux

5 files changed, 141 insertions, 136 deletions

diff --git a/perform/pio_engine.c b/perform/pio_engine.c
index 79f035a..0c5a9f3 100644
--- a/perform/pio_engine.c
+++ b/perform/pio_engine.c
@@ -145,7 +145,7 @@ static void do_cleanupfile(iotype iot, char *fname);
  * Modifications:
  */
 results
-do_pio(FILE *output, parameters param)
+do_pio(parameters param)
 {
     /* return codes */
     herr_t      ret_code = 0;   /*return code                           */
@@ -164,10 +164,6 @@ do_pio(FILE *output, parameters param)
     /* HDF5 variables */
     herr_t          hrc;                /*HDF5 return code              */
 
-    int         myrank;
-
-    MPI_Comm_rank(pio_comm_g, &myrank);
-
     /* Sanity check parameters */
 
     /* IO type */
@@ -256,10 +252,15 @@ buf_size=MIN(1024*1024, buf_size);
         GOTOERROR(FAIL);
     }
 
-    if (pio_debug_level >= 4)
+    if (pio_debug_level >= 4) {
+        int myrank;
+
+        MPI_Comm_rank(pio_comm_g, &myrank);
+
         /* output all of the times for all iterations */
         if (myrank == 0)
             fprintf(output, "Timer details:\n");
+    }
 
     for (nf = 1; nf <= nfiles; nf++) {
 	/*
@@ -277,43 +278,20 @@ fprintf(stderr, "filename=%s\n", fname);
 #endif
 
         set_time(res.timers, HDF5_GROSS_WRITE_FIXED_DIMS, START);
-
-        if (pio_debug_level >= 4)
-            /* output all of the times for all iterations */
-            fprintf(output, "    Proc %d: Gross Write Start: %.2f\n",
-                    myrank, get_time(res.timers, HDF5_GROSS_WRITE_FIXED_DIMS));
-
         hrc = do_fopen(iot, fname, &fd, PIO_CREATE | PIO_WRITE);
 
         VRFY((hrc == SUCCESS), "do_fopen failed");
 
         set_time(res.timers, HDF5_FINE_WRITE_FIXED_DIMS, START);
-
-        if (pio_debug_level >= 4)
-            /* output all of the times for all iterations */
-            fprintf(output, "    Proc %d: Fine Write Start: %.2f\n",
-                    myrank, get_time(res.timers, HDF5_FINE_WRITE_FIXED_DIMS));
-
         hrc = do_write(&fd, iot, ndsets, nelmts, buf_size, buffer);
         set_time(res.timers, HDF5_FINE_WRITE_FIXED_DIMS, STOP);
 
-        if (pio_debug_level >= 4)
-            /* output all of the times for all iterations */
-            fprintf(output, "    Proc %d: Fine Write Stop: %.2f\n",
-                    myrank, get_time(res.timers, HDF5_FINE_WRITE_FIXED_DIMS));
-
         VRFY((hrc == SUCCESS), "do_write failed");
 
         /* Close file for write */
         hrc = do_fclose(iot, &fd);
 
         set_time(res.timers, HDF5_GROSS_WRITE_FIXED_DIMS, STOP);
-
-        if (pio_debug_level >= 4)
-            /* output all of the times for all iterations */
-            fprintf(output, "    Proc %d: Gross Write Stop: %.2f\n",
-                    myrank, get_time(res.timers, HDF5_GROSS_WRITE_FIXED_DIMS));
-
         VRFY((hrc == SUCCESS), "do_fclose failed");
 
         MPI_Barrier(pio_comm_g);
@@ -323,43 +301,19 @@ fprintf(stderr, "filename=%s\n", fname);
 	 */
         /* Open file for read */
         set_time(res.timers, HDF5_GROSS_READ_FIXED_DIMS, START);
-
-        if (pio_debug_level >= 4)
-            /* output all of the times for all iterations */
-            fprintf(output, "    Proc %d: Gross Read Start: %.2f\n",
-                    myrank, get_time(res.timers, HDF5_GROSS_READ_FIXED_DIMS));
-
         hrc = do_fopen(iot, fname, &fd, PIO_READ);
 
         VRFY((hrc == SUCCESS), "do_fopen failed");
 
         set_time(res.timers, HDF5_FINE_READ_FIXED_DIMS, START);
-
-        if (pio_debug_level >= 4)
-            /* output all of the times for all iterations */
-            fprintf(output, "    Proc %d: Fine Read Start: %.2f\n",
-                    myrank, get_time(res.timers, HDF5_FINE_READ_FIXED_DIMS));
-
         hrc = do_read(&fd, iot, ndsets, nelmts, buf_size, buffer);
         set_time(res.timers, HDF5_FINE_READ_FIXED_DIMS, STOP);
-
-        if (pio_debug_level >= 4)
-            /* output all of the times for all iterations */
-            fprintf(output, "    Proc %d: Fine Read Stop: %.2f\n",
-                    myrank, get_time(res.timers, HDF5_FINE_READ_FIXED_DIMS));
-
         VRFY((hrc == SUCCESS), "do_read failed");
 
         /* Close file for read */
         hrc = do_fclose(iot, &fd);
 
         set_time(res.timers, HDF5_GROSS_READ_FIXED_DIMS, STOP);
-
-        if (pio_debug_level >= 4)
-            /* output all of the times for all iterations */
-            fprintf(output, "    Proc %d: Gross Read Stop: %.2f\n",
-                    myrank, get_time(res.timers, HDF5_GROSS_READ_FIXED_DIMS));
-
         VRFY((hrc == SUCCESS), "do_fclose failed");
 
         MPI_Barrier(pio_comm_g);
diff --git a/perform/pio_perf.c b/perform/pio_perf.c
index db6ccc0..7dca0e4 100644
--- a/perform/pio_perf.c
+++ b/perform/pio_perf.c
@@ -79,8 +79,10 @@
 #define MB_PER_SEC(bytes,t) (((bytes) / ONE_MB) / t)
 
 /* global variables */
-int         comm_world_rank_g;  /* my rank in MPI_COMM_RANK */
-int         comm_world_nprocs_g;/* num. of processes of MPI_COMM_WORLD */
+FILE       *output;             /* output file                          */
+pio_time   *timer;              /* timer: global for stub functions     */
+int         comm_world_rank_g;  /* my rank in MPI_COMM_RANK             */
+int         comm_world_nprocs_g;/* num. of processes of MPI_COMM_WORLD  */
 MPI_Comm    pio_comm_g;         /* Communicator to run the PIO          */
 int         pio_mpi_rank_g;     /* MPI rank of pio_comm_g               */
 int         pio_mpi_nprocs_g;   /* Number of processes of pio_comm_g    */
@@ -222,15 +224,15 @@ typedef struct _minmax {
 /* local functions */
 static long parse_size_directive(const char *size);
 static struct options *parse_command_line(int argc, char *argv[]);
-static void run_test_loop(FILE *output, struct options *options);
-static int run_test(FILE *output, iotype iot, parameters parms);
-static void output_all_info(FILE *output, minmax *mm, int count, int indent_level);
+static void run_test_loop(struct options *options);
+static int run_test(iotype iot, parameters parms);
+static void output_all_info(minmax *mm, int count, int indent_level);
 static void get_minmax(minmax *mm, double val);
 static minmax accumulate_minmax_stuff(minmax *mm, long raw_size, int count);
 static int create_comm_world(int num_procs, int *doing_pio);
 static int destroy_comm_world(void);
-static void output_report(FILE *output, const char *fmt, ...);
-static void print_indent(register FILE *output, register int indent);
+static void output_report(const char *fmt, ...);
+static void print_indent(register int indent);
 static void usage(const char *prog);
 
 /*
@@ -246,9 +248,10 @@ main(int argc, char **argv)
 {
     int ret;
     int exit_value = EXIT_SUCCESS;
-    FILE *output = stdout;
     struct options *opts = NULL;
 
+    output = stdout;
+
     /* initialize MPI and get the maximum num of processors we started with */
     MPI_Init(&argc, &argv);
     ret = MPI_Comm_size(MPI_COMM_WORLD, &comm_world_nprocs_g);
@@ -295,7 +298,7 @@ main(int argc, char **argv)
         }
     }
 
-    run_test_loop(output, opts);
+    run_test_loop(opts);
 
 finish:
     MPI_Finalize();
@@ -324,7 +327,7 @@ finish:
  * Modifications:
  */
 static void
-run_test_loop(FILE *output, struct options *opts)
+run_test_loop(struct options *opts)
 {
     parameters parms;
     long num_procs;
@@ -363,7 +366,7 @@ run_test_loop(FILE *output, struct options *opts)
 
 	/* only processes doing PIO will run the tests */
 	if (doing_pio){
-            output_report(output, "Number of processors = %ld\n", parms.num_procs);
+            output_report("Number of processors = %ld\n", parms.num_procs);
 
             /* multiply the xfer buffer size by 2 for each loop iteration */
             for (buf_size = opts->min_xfer_size;
@@ -371,23 +374,22 @@ run_test_loop(FILE *output, struct options *opts)
                 parms.buf_size = buf_size;
                 parms.num_elmts = opts->file_size / (parms.num_dsets * sizeof(int));
 
-                print_indent(output, 1);
-                output_report(output, "Transfer Buffer Size: %ld bytes, File size: %.2f MBs\n",
+                print_indent(1);
+                output_report("Transfer Buffer Size: %ld bytes, File size: %.2f MBs\n",
                               buf_size,
                               ((double)parms.num_dsets * parms.num_elmts * sizeof(int)) / ONE_MB);
-                print_indent(output, 1);
-                output_report(output,
-                              "  # of files: %ld, # of dsets: %ld, # of elmts per dset: %ld\n",
+                print_indent(1);
+                output_report("  # of files: %ld, # of dsets: %ld, # of elmts per dset: %ld\n",
                               parms.num_files, parms.num_dsets, parms.num_elmts);
 
                 if (io_runs & PIO_RAW)
-                    run_test(output, RAWIO, parms);
+                    run_test(RAWIO, parms);
 
                 if (io_runs & PIO_MPI)
-                    run_test(output, MPIO, parms);
+                    run_test(MPIO, parms);
 
                 if (io_runs & PIO_HDF5)
-                    run_test(output, PHDF5, parms);
+                    run_test(PHDF5, parms);
             }
 
             if (destroy_comm_world() != SUCCESS) {
@@ -405,7 +407,7 @@ run_test_loop(FILE *output, struct options *opts)
  * Modifications:
  */
 static int
-run_test(FILE *output, iotype iot, parameters parms)
+run_test(iotype iot, parameters parms)
 {
     results         res;
     register int    i, ret_value = SUCCESS;
@@ -423,18 +425,18 @@ run_test(FILE *output, iotype iot, parameters parms)
 
     raw_size = parms.num_dsets * parms.num_elmts * sizeof(int);
     parms.io_type = iot;
-    print_indent(output, 2);
-    output_report(output, "Type of IO = ");
+    print_indent(2);
+    output_report("Type of IO = ");
 
     switch (iot) {
     case RAWIO:
-        output_report(output, "Raw\n");
+        output_report("Raw\n");
         break;
     case MPIO:
-        output_report(output, "MPIO\n");
+        output_report("MPIO\n");
         break;
     case PHDF5:
-        output_report(output, "PHDF5\n");
+        output_report("PHDF5\n");
         break;
     }
 
@@ -472,7 +474,8 @@ run_test(FILE *output, iotype iot, parameters parms)
         double t;
 
         MPI_Barrier(pio_comm_g);
-        res = do_pio(output, parms);
+        res = do_pio(parms);
+        timer = res.timers;
 
         /* gather all of the "write" times */
         t = get_time(res.timers, HDF5_FINE_WRITE_FIXED_DIMS);
@@ -497,90 +500,91 @@ run_test(FILE *output, iotype iot, parameters parms)
 	get_minmax(&read_gross_mm, t);
 
         read_gross_mm_table[i] = read_gross_mm;
+        pio_time_destroy(res.timers);
     }
 
     /* accumulate and output the max, min, and average "write" times */
     if (pio_debug_level >= 3) {
         /* output all of the times for all iterations */
-        print_indent(output, 3);
-        output_report(output, "Write details:\n");
-        output_all_info(output, write_mm_table, parms.num_iters, 4);
+        print_indent(3);
+        output_report("Write details:\n");
+        output_all_info(write_mm_table, parms.num_iters, 4);
     }
 
     total_mm = accumulate_minmax_stuff(write_mm_table, raw_size, parms.num_iters);
 
-    print_indent(output, 3);
-    output_report(output, "Write (%d iteration(s)):\n", parms.num_iters);
+    print_indent(3);
+    output_report("Write (%d iteration(s)):\n", parms.num_iters);
 
-    print_indent(output, 4);
-    output_report(output, "Minimum Throughput: %.2f MB/s\n", total_mm.min);
-    print_indent(output, 4);
-    output_report(output, "Maximum Throughput: %.2f MB/s\n", total_mm.max);
-    print_indent(output, 4);
-    output_report(output, "Average Throughput: %.2f MB/s\n",
+    print_indent(4);
+    output_report("Minimum Throughput: %.2f MB/s\n", total_mm.min);
+    print_indent(4);
+    output_report("Maximum Throughput: %.2f MB/s\n", total_mm.max);
+    print_indent(4);
+    output_report("Average Throughput: %.2f MB/s\n",
                   total_mm.sum / total_mm.num);
 
     /* accumulate and output the max, min, and average "gross write" times */
     if (pio_debug_level >= 3) {
         /* output all of the times for all iterations */
-        print_indent(output, 3);
-        output_report(output, "Write Open-Close details:\n");
-        output_all_info(output, write_gross_mm_table, parms.num_iters, 4);
+        print_indent(3);
+        output_report("Write Open-Close details:\n");
+        output_all_info(write_gross_mm_table, parms.num_iters, 4);
     }
 
     total_mm = accumulate_minmax_stuff(write_gross_mm_table, raw_size, parms.num_iters);
 
-    print_indent(output, 3);
-    output_report(output, "Write Open-Close (%d iteration(s)):\n", parms.num_iters);
+    print_indent(3);
+    output_report("Write Open-Close (%d iteration(s)):\n", parms.num_iters);
 
-    print_indent(output, 4);
-    output_report(output, "Minimum Throughput: %.2f MB/s\n", total_mm.min);
-    print_indent(output, 4);
-    output_report(output, "Maximum Throughput: %.2f MB/s\n", total_mm.max);
-    print_indent(output, 4);
-    output_report(output, "Average Throughput: %.2f MB/s\n",
+    print_indent(4);
+    output_report("Minimum Throughput: %.2f MB/s\n", total_mm.min);
+    print_indent(4);
+    output_report("Maximum Throughput: %.2f MB/s\n", total_mm.max);
+    print_indent(4);
+    output_report("Average Throughput: %.2f MB/s\n",
                   total_mm.sum / total_mm.num);
 
     /* accumulate and output the max, min, and average "read" times */
     if (pio_debug_level >= 3) {
         /* output all of the times for all iterations */
-        print_indent(output, 3);
-        output_report(output, "Read details:\n");
-        output_all_info(output, read_mm_table, parms.num_iters, 4);
+        print_indent(3);
+        output_report("Read details:\n");
+        output_all_info(read_mm_table, parms.num_iters, 4);
     }
 
     total_mm = accumulate_minmax_stuff(read_mm_table, raw_size, parms.num_iters);
 
-    print_indent(output, 3);
-    output_report(output, "Read (%d iteration(s)):\n", parms.num_iters);
+    print_indent(3);
+    output_report("Read (%d iteration(s)):\n", parms.num_iters);
 
-    print_indent(output, 4);
-    output_report(output, "Minimum Throughput: %.2f MB/s\n", total_mm.min);
-    print_indent(output, 4);
-    output_report(output, "Maximum Throughput: %.2f MB/s\n", total_mm.max);
-    print_indent(output, 4);
-    output_report(output, "Average Throughput: %.2f MB/s\n",
+    print_indent(4);
+    output_report("Minimum Throughput: %.2f MB/s\n", total_mm.min);
+    print_indent(4);
+    output_report("Maximum Throughput: %.2f MB/s\n", total_mm.max);
+    print_indent(4);
+    output_report("Average Throughput: %.2f MB/s\n",
                   total_mm.sum / total_mm.num);
 
     /* accumulate and output the max, min, and average "gross read" times */
     if (pio_debug_level >= 3) {
         /* output all of the times for all iterations */
-        print_indent(output, 3);
-        output_report(output, "Read Open-Close details:\n");
-        output_all_info(output, read_gross_mm_table, parms.num_iters, 4);
+        print_indent(3);
+        output_report("Read Open-Close details:\n");
+        output_all_info(read_gross_mm_table, parms.num_iters, 4);
     }
 
     total_mm = accumulate_minmax_stuff(read_gross_mm_table, raw_size, parms.num_iters);
 
-    print_indent(output, 3);
-    output_report(output, "Read Open-Close (%d iteration(s)):\n", parms.num_iters);
+    print_indent(3);
+    output_report("Read Open-Close (%d iteration(s)):\n", parms.num_iters);
 
-    print_indent(output, 4);
-    output_report(output, "Minimum Throughput: %.2f MB/s\n", total_mm.min);
-    print_indent(output, 4);
-    output_report(output, "Maximum Throughput: %.2f MB/s\n", total_mm.max);
-    print_indent(output, 4);
-    output_report(output, "Average Throughput: %.2f MB/s\n",
+    print_indent(4);
+    output_report("Minimum Throughput: %.2f MB/s\n", total_mm.min);
+    print_indent(4);
+    output_report("Maximum Throughput: %.2f MB/s\n", total_mm.max);
+    print_indent(4);
+    output_report("Average Throughput: %.2f MB/s\n",
                   total_mm.sum / total_mm.num);
 
     /* clean up our mess */
@@ -588,7 +592,6 @@ run_test(FILE *output, iotype iot, parameters parms)
     free(read_mm_table);
     free(write_gross_mm_table);
     free(read_gross_mm_table);
-    pio_time_destroy(res.timers);
     return ret_value;
 }
 
@@ -600,17 +603,17 @@ run_test(FILE *output, iotype iot, parameters parms)
  * Modifications:
  */
 static void
-output_all_info(FILE *output, minmax *mm, int count, int indent_level)
+output_all_info(minmax *mm, int count, int indent_level)
 {
     register int i;
 
     for (i = 0; i < count; ++i) {
-        print_indent(output, indent_level);
-        output_report(output, "Iteration %d:\n", i + 1);
-        print_indent(output, indent_level + 1);
-        output_report(output, "Minimum Time: %.2fs\n", mm[i].min);
-        print_indent(output, indent_level + 1);
-        output_report(output, "Maximum Time: %.2fs\n", mm[i].max);
+        print_indent(indent_level);
+        output_report("Iteration %d:\n", i + 1);
+        print_indent(indent_level + 1);
+        output_report("Minimum Time: %.2fs\n", mm[i].min);
+        print_indent(indent_level + 1);
+        output_report("Maximum Time: %.2fs\n", mm[i].max);
     }
 }
 
@@ -756,7 +759,7 @@ destroy_comm_world(void)
  * Modifications:
  */
 static void
-output_report(FILE *output, const char *fmt, ...)
+output_report(const char *fmt, ...)
 {
     int myrank;
 
@@ -780,7 +783,7 @@ output_report(FILE *output, const char *fmt, ...)
  * Modifications:
  */
 static void
-print_indent(register FILE *output, register int indent)
+print_indent(register int indent)
 {
     int myrank;
 
diff --git a/perform/pio_perf.h b/perform/pio_perf.h
index 67beb3c..89cba72 100644
--- a/perform/pio_perf.h
+++ b/perform/pio_perf.h
@@ -40,8 +40,10 @@ typedef struct results_ {
 #define FAIL        -1
 #endif  /* !FAIL */
 
-extern int      comm_world_rank_g;  /* my rank in MPI_COMM_RANK */
-extern int      comm_world_nprocs_g;/* num. of processes of MPI_COMM_WORLD */
+extern FILE     *output;            /* output file                          */
+extern pio_time *timer;             /* timer: global for stub functions     */
+extern int      comm_world_rank_g;  /* my rank in MPI_COMM_RANK             */
+extern int      comm_world_nprocs_g;/* num. of processes of MPI_COMM_WORLD  */
 extern MPI_Comm pio_comm_g;         /* Communicator to run the PIO          */
 extern int      pio_mpi_rank_g;     /* MPI rank of pio_comm_g               */
 extern int      pio_mpi_nprocs_g;   /* number of processes of pio_comm_g    */
@@ -50,13 +52,14 @@ extern int      pio_debug_level;    /* The debug level:
                                      *   1 - Minimal
                                      *   2 - Some more
                                      *   3 - Maximal
+                                     *   4 - Even More Debugging (timer stuff)
                                      */
 
 #ifdef __cplusplus
 extern "C" {
 #endif  /* __cplusplus */
 
-extern results do_pio(FILE * output, parameters param);
+extern results do_pio(parameters param);
 
 #ifdef __cplusplus
 }
diff --git a/perform/pio_timer.c b/perform/pio_timer.c
index 2ebdbce..1bf1b0c 100644
--- a/perform/pio_timer.c
+++ b/perform/pio_timer.c
@@ -19,6 +19,8 @@
 
 #include <mpi.h>
 
+#include "pio_perf.h"
+
 /*
  * The number to divide the tv_usec field with to get a nice decimal to add to
  * the number of seconds.
@@ -124,6 +126,47 @@ set_time(pio_time *pt, timer_type t, int start_stop)
         }
     }
 
+    if (pio_debug_level >= 4) {
+        char *msg;
+        int myrank;
+
+        MPI_Comm_rank(pio_comm_g, &myrank);
+
+        switch (t) {
+        case HDF5_FILE_OPENCLOSE:
+            msg = "File Open/Close";
+            break;
+        case HDF5_DATASET_CREATE:
+            msg = "Dataset Create";
+            break;
+        case HDF5_MPI_WRITE:
+            msg = "MPI Write";
+            break;
+        case HDF5_MPI_READ:
+            msg = "MPI Read";
+            break;
+        case HDF5_FINE_WRITE_FIXED_DIMS:
+            msg = "Fine Write";
+            break;
+        case HDF5_FINE_READ_FIXED_DIMS:
+            msg = "Fine Read";
+            break;
+        case HDF5_GROSS_WRITE_FIXED_DIMS:
+            msg = "Gross Write";
+            break;
+        case HDF5_GROSS_READ_FIXED_DIMS:
+            msg = "Gross Read";
+            break;
+        default:
+            msg = "Unknown Timer";
+            break;
+        }
+
+        fprintf(output, "    Proc %d: %s %s: %.2f\n", myrank, msg,
+                (start_stop == START ? "Start" : "Stop"),
+                pt->total_time[t]);
+    }
+
     return pt;
 }
 
diff --git a/perform/pio_timer.h b/perform/pio_timer.h
index dc723a0..4144825 100644
--- a/perform/pio_timer.h
+++ b/perform/pio_timer.h
@@ -22,6 +22,8 @@
 typedef enum timer_type_ {
     HDF5_FILE_OPENCLOSE,
     HDF5_DATASET_CREATE,
+    HDF5_MPI_WRITE,
+    HDF5_MPI_READ,
     HDF5_FINE_WRITE_FIXED_DIMS,
     HDF5_FINE_READ_FIXED_DIMS,
     HDF5_GROSS_WRITE_FIXED_DIMS,