[svn-r5377] Purpose:

    Update
Description:
    Synched the 1.4 branch's performance tests with the 1.5 branch's
    performance tests...
Platforms tested:
    Linux

5 files changed, 251 insertions, 144 deletions

diff --git a/perform/pio_engine.c b/perform/pio_engine.c
index 2da4781..e48129a 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 */
@@ -180,11 +176,11 @@ do_pio(FILE *output, parameters param)
         break;
     case RAWIO:
         fd.rawfd = -1;
-        res.timers = pio_time_new(SYS_TIMER);
+        res.timers = pio_time_new(MPI_TIMER);
         break;
     case PHDF5:
         fd.h5fd = -1;
-        res.timers = pio_time_new(SYS_TIMER);
+        res.timers = pio_time_new(MPI_TIMER);
         break;
     default:
         /* unknown request */
@@ -232,8 +228,8 @@ do_pio(FILE *output, parameters param)
         GOTOERROR(FAIL);
     }
 
-#if AKCDEBUG
-/* DEBUG*/
+#if akcdebug
+/* debug*/
 fprintf(stderr, "nfiles=%d\n", nfiles);
 fprintf(stderr, "ndsets=%ld\n", ndsets);
 fprintf(stderr, "nelmts=%ld\n", nelmts);
@@ -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);
@@ -1147,4 +1101,55 @@ do_cleanupfile(iotype iot, char *fname)
         }
     }
 }
+
+
+#ifndef TIME_MPI
+#define TIME_MPI
+#endif
+#ifdef TIME_MPI
+/* instrument the MPI_File_wrirte_xxx and read_xxx calls to measure
+ * pure time spent in MPI_File code.
+ */
+int MPI_File_read_at(MPI_File fh, MPI_Offset offset, void *buf,
+	  int count, MPI_Datatype datatype, MPI_Status *status)
+{
+    int err;
+    set_time(timer_g, HDF5_MPI_READ, START);
+    err=PMPI_File_read_at(fh, offset, buf, count, datatype, status);
+    set_time(timer_g, HDF5_MPI_READ, STOP);
+    return err;
+}
+
+
+int MPI_File_read_at_all(MPI_File fh, MPI_Offset offset, void *buf,
+	int count, MPI_Datatype datatype, MPI_Status *status)
+{
+    int err;
+    set_time(timer_g, HDF5_MPI_READ, START);
+    err=PMPI_File_read_at_all(fh, offset, buf, count, datatype, status);
+    set_time(timer_g, HDF5_MPI_READ, STOP);
+    return err;
+}
+
+int MPI_File_write_at(MPI_File fh, MPI_Offset offset, void *buf,
+      int count, MPI_Datatype datatype, MPI_Status *status)
+{
+    int err;
+    set_time(timer_g, HDF5_MPI_WRITE, START);
+    err=PMPI_File_write_at(fh, offset, buf, count, datatype, status);
+    set_time(timer_g, HDF5_MPI_WRITE, STOP);
+    return err;
+}
+
+int MPI_File_write_at_all(MPI_File fh, MPI_Offset offset, void *buf,
+    int count, MPI_Datatype datatype, MPI_Status *status)
+{
+    int err;
+    set_time(timer_g, HDF5_MPI_WRITE, START);
+    err=PMPI_File_write_at_all(fh, offset, buf, count, datatype, status);
+    set_time(timer_g, HDF5_MPI_WRITE, STOP);
+    return err;
+}
+
+#endif	/* TIME_MPI */
 #endif /* H5_HAVE_PARALLEL */
diff --git a/perform/pio_perf.c b/perform/pio_perf.c
index db6ccc0..3afc58d 100644
--- a/perform/pio_perf.c
+++ b/perform/pio_perf.c
@@ -79,8 +79,9 @@
 #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                          */
+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 +223,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 +247,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 +297,7 @@ main(int argc, char **argv)
         }
     }
 
-    run_test_loop(output, opts);
+    run_test_loop(opts);
 
 finish:
     MPI_Finalize();
@@ -324,7 +326,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 +365,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 +373,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,47 +406,58 @@ 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;
     int             comm_size;
     long            raw_size;
     minmax          total_mm;
+    minmax         *write_mpi_mm_table;
     minmax         *write_mm_table;
     minmax         *write_gross_mm_table;
+    minmax         *read_mpi_mm_table;
     minmax         *read_mm_table;
     minmax         *read_gross_mm_table;
+    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};
+    minmax          read_mpi_mm = {0.0, 0.0, 0.0, 0};
     minmax          read_mm = {0.0, 0.0, 0.0, 0};
     minmax          read_gross_mm = {0.0, 0.0, 0.0, 0};
 
     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;
     }
 
     MPI_Comm_size(pio_comm_g, &comm_size);
 
+    write_mpi_mm_table = malloc(parms.num_iters * sizeof(minmax));
     write_mm_table = malloc(parms.num_iters * sizeof(minmax));
     write_gross_mm_table = malloc(parms.num_iters * sizeof(minmax));
+    read_mpi_mm_table = malloc(parms.num_iters * sizeof(minmax));
     read_mm_table = malloc(parms.num_iters * sizeof(minmax));
     read_gross_mm_table = malloc(parms.num_iters * sizeof(minmax));
 
     for (i = 0; i < parms.num_iters; ++i) {
+        write_mpi_mm_table[i].min = 0.0;
+        write_mpi_mm_table[i].max = 0.0;
+        write_mpi_mm_table[i].sum = 0.0;
+        write_mpi_mm_table[i].num = 0;
+
         write_mm_table[i].min = 0.0;
         write_mm_table[i].max = 0.0;
         write_mm_table[i].sum = 0.0;
@@ -456,6 +468,11 @@ run_test(FILE *output, iotype iot, parameters parms)
         write_gross_mm_table[i].sum = 0.0;
         write_gross_mm_table[i].num = 0;
 
+        read_mpi_mm_table[i].min = 0.0;
+        read_mpi_mm_table[i].max = 0.0;
+        read_mpi_mm_table[i].sum = 0.0;
+        read_mpi_mm_table[i].num = 0;
+
         read_mm_table[i].min = 0.0;
         read_mm_table[i].max = 0.0;
         read_mm_table[i].sum = 0.0;
@@ -472,7 +489,13 @@ run_test(FILE *output, iotype iot, parameters parms)
         double t;
 
         MPI_Barrier(pio_comm_g);
-        res = do_pio(output, parms);
+        res = do_pio(parms);
+
+        /* gather all of the "mpi write" times */
+        t = get_time(res.timers, HDF5_MPI_WRITE);
+	get_minmax(&write_mpi_mm, t);
+
+        write_mpi_mm_table[i] = write_mpi_mm;
 
         /* gather all of the "write" times */
         t = get_time(res.timers, HDF5_FINE_WRITE_FIXED_DIMS);
@@ -486,6 +509,12 @@ run_test(FILE *output, iotype iot, parameters parms)
 
         write_gross_mm_table[i] = write_gross_mm;
 
+        /* gather all of the "mpi read" times */
+        t = get_time(res.timers, HDF5_MPI_READ);
+	get_minmax(&read_mpi_mm, t);
+
+        read_mpi_mm_table[i] = read_mpi_mm;
+
         /* gather all of the "read" times */
         t = get_time(res.timers, HDF5_FINE_READ_FIXED_DIMS);
 	get_minmax(&read_mm, t);
@@ -497,98 +526,116 @@ 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);
+    }
+
+    /* show mpi write statics */
+    if (pio_debug_level >= 3) {
+        /* output all of the times for all iterations */
+        print_indent(3);
+        output_report("MPI Write details:\n");
+        output_all_info(write_mpi_mm_table, parms.num_iters, 4);
     }
 
     /* 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);
 
+    /* show mpi read statics */
+    if (pio_debug_level >= 3) {
+        /* output all of the times for all iterations */
+        print_indent(3);
+        output_report("MPI Read details:\n");
+        output_all_info(read_mpi_mm_table, parms.num_iters, 4);
+    }
+
     /* 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 */
+    free(write_mpi_mm_table);
+    free(read_mpi_mm_table);
     free(write_mm_table);
     free(read_mm_table);
     free(write_gross_mm_table);
     free(read_gross_mm_table);
-    pio_time_destroy(res.timers);
     return ret_value;
 }
 
@@ -600,17 +647,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 +803,7 @@ destroy_comm_world(void)
  * Modifications:
  */
 static void
-output_report(FILE *output, const char *fmt, ...)
+output_report(const char *fmt, ...)
 {
     int myrank;
 
@@ -780,7 +827,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..12811e3 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_g;           /* 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..d053e10 100644
--- a/perform/pio_timer.c
+++ b/perform/pio_timer.c
@@ -19,11 +19,16 @@
 
 #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.
  */
-#define MILLISECOND     1000000.0
+#define MICROSECOND     1000000.0
+
+/* global variables */
+pio_time   *timer_g;            /* timer: global for stub functions     */
 
 /*
  * Function:    pio_time_new
@@ -41,6 +46,8 @@ pio_time_new(unsigned int type)
     pio_time *pt = (pio_time *)calloc(1, sizeof(struct pio_time_));
     register int i;
 
+    /* set global timer variable */
+    timer_g = pt;
     for (i = 0; i < NUM_TIMERS; ++i)
         pt->total_time[i] = 0.0;
 
@@ -61,6 +68,8 @@ void
 pio_time_destroy(pio_time *pt)
 {
     free(pt);
+    /* reset the global timer pointer too. */
+    timer_g = NULL;
 }
 
 /*
@@ -115,15 +124,56 @@ set_time(pio_time *pt, timer_type t, int start_stop)
                 struct timeval sys_t;
 
                 gettimeofday(&sys_t, NULL);
-                pt->total_time[t] =
+                pt->total_time[t] +=
                     ((double)sys_t.tv_sec +
-                                ((double)sys_t.tv_usec) / MILLISECOND) -
+                                ((double)sys_t.tv_usec) / MICROSECOND) -
                     ((double)pt->sys_timer[t].tv_sec +
-                            ((double)pt->sys_timer[t].tv_usec) / MILLISECOND);
+                            ((double)pt->sys_timer[t].tv_usec) / MICROSECOND);
             }
         }
     }
 
+    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,