Merge pull request ESMCI#1498 from NCAR/ejh_mpe_4

Now enable MPE logging in test_async_perf.c

src/clib/pio_internal.h

@@ -97,7 +97,7 @@ void pio_log(int severity, const char *fmt, ...);
 #define START 0
 #define END 1
 
-/* These are the events. */
+/* These are the MPE states (events) we keep track of. */
 #define NUM_EVENTS 7
 #define INIT 0
 #define DECOMP 1
@@ -106,6 +106,11 @@ void pio_log(int severity, const char *fmt, ...);
 #define DARRAY_WRITE 4
 #define DARRAY_READ 6
 #define CLOSE 5
+
+/* The max length of msg added to log with mpe_log_pack(). (NULL
+ * terminator is not required by mpe_log_pack(), so need not be
+ * counted in this total).*/
+#define MPE_MAX_MSG_LEN 32
 #endif /* USE_MPE */
 
 #if defined(__cplusplus)

src/clib/pioc_support.c

@@ -168,17 +168,25 @@ PIOc_set_log_level(int level)
 /* This array holds even numbers for MPE. */
 int event_num[2][NUM_EVENTS];
 
+/* This keeps track of whether MPE has been initialized. */
+int mpe_logging_initialized = 0;
+
 /** This will set up the MPE logging event numbers. The calling
- * program must call MPE_Init_log() before this function is
- * called. MPE must be installed, get it from
- * https://www.mcs.anl.gov/research/projects/perfvis/software/MPE/.
+ * program does not need to call MPE_Init_log(), that is done by the
+ * mpe library in MPI_Init(). MPE must be installed, get it from
+ * https://www.mcs.anl.gov/research/projects/perfvis/software/MPE/. PIO
+ * and the whole I/O stack must be built with MPE.
  *
  * @param my_rank rank of processor in MPI_COMM_WORLD.
  * @author Ed Hartnett
 */
 int
 init_mpe(int my_rank)
 {
+    /* If we've already initialized MPE states, just return. */
+    if (mpe_logging_initialized++)
+        return 0;
+
     /* Get a bunch of event numbers. */
     event_num[START][INIT] = MPE_Log_get_event_number();
     event_num[END][INIT] = MPE_Log_get_event_number();
@@ -195,11 +203,12 @@ init_mpe(int my_rank)
     event_num[START][DARRAY_READ] = MPE_Log_get_event_number();
     event_num[END][DARRAY_READ] = MPE_Log_get_event_number();
 
-    /* Available colors: "white", "black", "red", "yellow", "green",
-       "cyan", "blue", "magenta", "aquamarine", "forestgreen",
-       "orange", "marroon", "brown", "pink", "coral", "gray" */
+    /* On rank 0, set up the info states. */
     if (!my_rank)
     {
+        /* Available colors: "white", "black", "red", "yellow", "green",
+           "cyan", "blue", "magenta", "aquamarine", "forestgreen",
+           "orange", "marroon", "brown", "pink", "coral", "gray" */
         MPE_Describe_info_state(event_num[START][INIT], event_num[END][INIT],
                                 "PIO init", "green", "%s");
         MPE_Describe_info_state(event_num[START][DECOMP],
@@ -238,16 +247,24 @@ pio_start_mpe_log(int state)
 /**
  * End MPE logging.
  *
+ * @param state one of the MPE states defined in pio_internal.h.
+ * @param msg a text message to describe the state. Will be truncated
+ * to MPE_MAX_MSG_LEN.
  * @author Ed Hartnett
  */
 void
 pio_stop_mpe_log(int state, const char *msg)
 {
     MPE_LOG_BYTES bytebuf;
     int pos = 0;
+    int msglen;
     int ret;
 
-    MPE_Log_pack(bytebuf, &pos, 's', strlen(msg), msg);
+    /* Truncate messages longer than MPE_MAX_MSG_LEN. */
+    msglen = strlen(msg) > MPE_MAX_MSG_LEN ? MPE_MAX_MSG_LEN : strlen(msg);
+
+    /* Tell MPE to stop the state, with a message. */
+    MPE_Log_pack(bytebuf, &pos, 's', msglen, msg);
     if ((ret = MPE_Log_event(event_num[END][state], 0, bytebuf)))
         pio_err(NULL, NULL, PIO_EIO, __FILE__, __LINE__);
 }

tests/cunit/pio_tests.h

@@ -20,6 +20,23 @@
 #include <mpe.h>
 #endif /* USE_MPE */
 
+#ifdef USE_MPE
+/* These are for the event numbers array used to log various events in
+ * the program with the MPE library, which produces output for the
+ * Jumpshot program. */
+#define TEST_NUM_EVENTS 6
+#define TEST_INIT 0
+#define TEST_DECOMP 1
+#define TEST_CREATE 2
+#define TEST_DARRAY_WRITE 3
+#define TEST_CLOSE 4
+#define TEST_CALCULATE 5
+
+int init_mpe_test_logging(int my_rank, int test_event[][TEST_NUM_EVENTS]);
+void test_start_mpe_log(int state);
+void test_stop_mpe_log(int state, const char *msg);
+#endif /* USE_MPE */
+
 /** The number of possible output netCDF output flavors available to
  * the ParallelIO library. */
 #define NUM_FLAVORS 4

tests/cunit/test_async_perf.c

@@ -36,9 +36,12 @@
 #define LON_LEN 3
 
 /* The length of our sample data along each dimension. */
-#define X_DIM_LEN 1024
-#define Y_DIM_LEN 1024
-#define Z_DIM_LEN 256
+#define X_DIM_LEN 128
+#define Y_DIM_LEN 128
+#define Z_DIM_LEN 32
+/* #define X_DIM_LEN 1024 */
+/* #define Y_DIM_LEN 1024 */
+/* #define Z_DIM_LEN 256 */
 
 /* The number of timesteps of data to write. */
 #define NUM_TIMESTEPS 3
@@ -58,6 +61,14 @@ char dim_name[NDIM4][PIO_MAX_NAME + 1] = {"unlim", "x", "y", "z"};
 
 #define NUM_VAR_SETS 2
 
+/* How long to sleep for "calculation time". */
+#define SLEEP_SECONDS 1
+
+#ifdef USE_MPE
+/* This array holds even numbers for MPE. */
+int test_event[2][TEST_NUM_EVENTS];
+#endif /* USE_MPE */
+
 /* Create the decomposition to divide the 4-dimensional sample data
  * between the 4 tasks. For the purposes of decomposition we are only
  * concerned with 3 dimensions - we ignore the unlimited dimension.
@@ -70,14 +81,20 @@ char dim_name[NDIM4][PIO_MAX_NAME + 1] = {"unlim", "x", "y", "z"};
  * @param ioid a pointer that gets the ID of this decomposition.
  * @returns 0 for success, error code otherwise.
  **/
-int create_decomposition_3d(int ntasks, int my_rank, int iosysid, int *ioid, PIO_Offset *elements_per_pe)
+int
+create_decomposition_3d(int ntasks, int my_rank, int iosysid, int *ioid,
+                        PIO_Offset *elements_per_pe)
 {
     PIO_Offset my_elem_per_pe;     /* Array elements per processing unit. */
     PIO_Offset *compdof;  /* The decomposition mapping. */
     int dim_len_3d[NDIM3] = {X_DIM_LEN, Y_DIM_LEN, Z_DIM_LEN};
     int my_proc_rank = my_rank - 1;
     int ret;
 
+#ifdef USE_MPE
+    test_start_mpe_log(TEST_DECOMP);
+#endif /* USE_MPE */
+
     /* How many data elements per task? */
     my_elem_per_pe = X_DIM_LEN * Y_DIM_LEN * Z_DIM_LEN / ntasks;
     if (elements_per_pe)
@@ -99,6 +116,14 @@ int create_decomposition_3d(int ntasks, int my_rank, int iosysid, int *ioid, PIO
     /* Free the mapping. */
     free(compdof);
 
+#ifdef USE_MPE
+    {
+        char msg[MPE_MAX_MSG_LEN + 1];
+        sprintf(msg, "elements_per_pe %lld", my_elem_per_pe);
+        test_stop_mpe_log(TEST_DECOMP, msg);
+    }
+#endif /* USE_MPE */
+
     return 0;
 }
 
@@ -135,6 +160,10 @@ run_darray_async_test(int iosysid, int fmt, int my_rank, int ntasks, int niotask
         for (d = 0; d < elements_per_pe2; d++)
             my_data_int[d] = my_rank;
 
+#ifdef USE_MPE
+        test_start_mpe_log(TEST_CREATE);
+#endif /* USE_MPE */
+
         /* Create sample output file. */
         /* sprintf(data_filename, "data_%s_iotype_%d_piotype_%d.nc", TEST_NAME, flavor[fmt], */
         /*         piotype); */
@@ -143,6 +172,14 @@ run_darray_async_test(int iosysid, int fmt, int my_rank, int ntasks, int niotask
                                    NC_CLOBBER)))
             BAIL(ret);
 
+#ifdef USE_MPE
+        {
+            char msg[MPE_MAX_MSG_LEN + 1];
+            sprintf(msg, "iotype %d", flavor[fmt]);
+            test_stop_mpe_log(TEST_CREATE, msg);
+        }
+#endif /* USE_MPE */
+
         /* Find the size of the type. */
         if ((ret = PIOc_inq_type(ncid, piotype, NULL, &type_size)))
             BAIL(ret);
@@ -162,6 +199,10 @@ run_darray_async_test(int iosysid, int fmt, int my_rank, int ntasks, int niotask
 
         for (t = 0; t < NUM_TIMESTEPS; t++)
         {
+#ifdef USE_MPE
+            test_start_mpe_log(TEST_DARRAY_WRITE);
+#endif /* USE_MPE */
+
             /* Set the record number for the record vars. */
             if ((ret = PIOc_setframe(ncid, varid, t)))
                 BAIL(ret);
@@ -171,12 +212,30 @@ run_darray_async_test(int iosysid, int fmt, int my_rank, int ntasks, int niotask
                                          my_data_int, NULL)))
                 BAIL(ret);
 
-            /* Sync the file. */
-            if ((ret = PIOc_sync(ncid)))
-                BAIL(ret);
+#ifdef USE_MPE
+            {
+                char msg[MPE_MAX_MSG_LEN + 1];
+                sprintf(msg, "timestep %d", t);
+                test_stop_mpe_log(TEST_DARRAY_WRITE, msg);
+            }
+#endif /* USE_MPE */
 
-        }
+            /* Now do some calculations. */
+#ifdef USE_MPE
+            test_start_mpe_log(TEST_CALCULATE);
+#endif /* USE_MPE */
+
+            /* Sleep some seconds away. */
+            sleep(SLEEP_SECONDS);
 
+#ifdef USE_MPE
+            {
+                char msg[MPE_MAX_MSG_LEN + 1];
+                sprintf(msg, "timestep %d", t);
+                test_stop_mpe_log(TEST_CALCULATE, msg);
+            }
+#endif /* USE_MPE */
+        }
 
         /* Close the file. */
         if ((ret = PIOc_closefile(ncid)))
@@ -213,6 +272,14 @@ int main(int argc, char **argv)
     /* Initialize test. */
     if ((ret = pio_test_init2(argc, argv, &my_rank, &ntasks, 1, 0, -1, &test_comm)))
         ERR(ERR_INIT);
+
+#ifdef USE_MPE
+    /* If --enable-mpe was specified at configure, start MPE
+     * logging. */
+    if (init_mpe_test_logging(my_rank, test_event))
+        return ERR_AWFUL;
+#endif /* USE_MPE */
+
     if ((ret = PIOc_set_iosystem_error_handling(PIO_DEFAULT, PIO_RETURN_ERROR, NULL)))
         return ret;
 
@@ -248,6 +315,10 @@ int main(int argc, char **argv)
             float delta_in_sec;
             float mb_per_sec;
 
+#ifdef USE_MPE
+            test_start_mpe_log(TEST_INIT);
+#endif /* USE_MPE */
+
             /* Start the clock. */
             if (!my_rank)
             {
@@ -260,6 +331,14 @@ int main(int argc, char **argv)
                                        PIO_REARR_BOX, &iosysid)))
                 ERR(ERR_INIT);
 
+#ifdef USE_MPE
+            {
+                char msg[MPE_MAX_MSG_LEN + 1];
+                sprintf(msg, "num IO procs %d", num_io_procs[niotest]);
+                test_stop_mpe_log(TEST_INIT, msg);
+            }
+#endif /* USE_MPE */
+
             /* This code runs only on computation components. */
             if (my_rank >= num_io_procs[niotest])
             {
@@ -292,7 +371,7 @@ int main(int argc, char **argv)
                 endt = (1000000 * endtime.tv_sec) + endtime.tv_usec;
                 delta = (endt - startt)/NUM_TIMESTEPS;
                 delta_in_sec = (float)delta / 1000000;
-                num_megabytes = (X_DIM_LEN * Y_DIM_LEN * Z_DIM_LEN * NUM_TIMESTEPS *
+                num_megabytes = (X_DIM_LEN * Y_DIM_LEN * Z_DIM_LEN * (long long int)  NUM_TIMESTEPS *
                                  sizeof(int))/(1024*1024);
                 mb_per_sec = num_megabytes / delta_in_sec;
                 printf("%d\t%d\t%d\t%d\t%d\t%8.3f\t%8.1f\t%8.3f\n", ntasks, num_io_procs[niotest],

tests/cunit/test_common.c

@@ -283,6 +283,81 @@ int pio_test_finalize2(MPI_Comm *test_comm, const char *test_name)
     return pio_test_finalize(test_comm);
 }
 
+#ifdef USE_MPE
+/* This array holds even numbers for MPE. */
+int test_event[2][TEST_NUM_EVENTS];
+
+/* This will set up the MPE logging event numbers. */
+int
+init_mpe_test_logging(int my_rank, int test_event[][TEST_NUM_EVENTS])
+{
+   /* Get a bunch of event numbers. */
+   test_event[START][TEST_INIT] = MPE_Log_get_event_number();
+   test_event[END][TEST_INIT] = MPE_Log_get_event_number();
+   test_event[START][TEST_DECOMP] = MPE_Log_get_event_number();
+   test_event[END][TEST_DECOMP] = MPE_Log_get_event_number();
+   test_event[START][TEST_CREATE] = MPE_Log_get_event_number();
+   test_event[END][TEST_CREATE] = MPE_Log_get_event_number();
+   test_event[START][TEST_DARRAY_WRITE] = MPE_Log_get_event_number();
+   test_event[END][TEST_DARRAY_WRITE] = MPE_Log_get_event_number();
+   test_event[START][TEST_CLOSE] = MPE_Log_get_event_number();
+   test_event[END][TEST_CLOSE] = MPE_Log_get_event_number();
+   test_event[START][TEST_CALCULATE] = MPE_Log_get_event_number();
+   test_event[END][TEST_CALCULATE] = MPE_Log_get_event_number();
+
+   /* Set up MPE states. This only happens on rank 0. */
+   if (!my_rank)
+   {
+        MPE_Describe_info_state(test_event[START][TEST_INIT], test_event[END][TEST_INIT],
+                                "test init", "forestgreen", "%s");
+        MPE_Describe_info_state(test_event[START][TEST_DECOMP],
+                                test_event[END][TEST_DECOMP], "test decomposition",
+                                "blue", "%s");
+        MPE_Describe_info_state(test_event[START][TEST_CREATE], test_event[END][TEST_CREATE],
+                                "test create file", "marroon", "%s");
+        /* MPE_Describe_info_state(test_event[START][TEST_OPEN], test_event[END][TEST_OPEN], */
+        /*                         "test open file", "orange", "%s"); */
+        MPE_Describe_info_state(test_event[START][TEST_DARRAY_WRITE],
+                                test_event[END][TEST_DARRAY_WRITE], "test darray write",
+                                "coral", "%s");
+        MPE_Describe_info_state(test_event[START][TEST_CLOSE],
+                                test_event[END][TEST_CLOSE], "test close",
+                                "gray", "%s");
+        MPE_Describe_info_state(test_event[START][TEST_CALCULATE],
+                                test_event[END][TEST_CALCULATE], "test calculate",
+                                "aquamarine", "%s");
+   }
+   return 0;
+}
+
+/**
+ * Start MPE logging.
+ *
+ * @param state_num the MPE event state number to START (ex. INIT).
+ * @author Ed Hartnett
+ */
+void
+test_start_mpe_log(int state)
+{
+    MPE_Log_event(test_event[START][state], 0, NULL);
+}
+
+/**
+ * End MPE logging.
+ *
+ * @author Ed Hartnett
+ */
+void
+test_stop_mpe_log(int state, const char *msg)
+{
+    MPE_LOG_BYTES bytebuf;
+    int pos = 0;
+
+    MPE_Log_pack(bytebuf, &pos, 's', strlen(msg), msg);
+    MPE_Log_event(test_event[END][state], 0, bytebuf);
+}
+#endif /* USE_MPE */
+
 /* Finalize a PIO C test.
  *
  * @param test_comm pointer to the test communicator.