Add timing info to comm_spawn - timing collected and reported when OMPI_MCA_ompi_timing = 1 (or something other than zero).

This commit was SVN r12381.

ompi/communicator/comm_dyn.c

@@ -26,6 +26,9 @@
 #ifdef HAVE_UNISTD_H
 #include <unistd.h>
 #endif
+#ifdef HAVE_SYS_TIME_H
+#include <sys/time.h>
+#endif  /* HAVE_SYS_TIME_H */
 
 #include "opal/util/printf.h"
 #include "opal/util/convert.h"
@@ -360,6 +363,9 @@ ompi_comm_start_processes(int count, char **array_of_commands,
     opal_list_t attributes;
     opal_list_item_t *item;
 
+    bool timing = false;
+    struct timeval ompistart, ompistop;
+    int param, value;
     
     /* parse the info object */
     /* check potentially for:
@@ -376,6 +382,19 @@ ompi_comm_start_processes(int count, char **array_of_commands,
     /* make sure the progress engine properly trips the event library */
     opal_progress_event_increment();
     
+    /* check to see if we want timing information */
+    param = mca_base_param_reg_int_name("ompi", "timing",
+                                        "Request that critical timing loops be measured",
+                                        false, false, 0, &value);
+    if (value != 0) {
+        timing = true;
+        if (0 != gettimeofday(&ompistart, NULL)) {
+            opal_output(0, "ompi_comm_start_procs: could not obtain start time");
+            ompistart.tv_sec = 0;
+            ompistart.tv_usec = 0;
+        }
+    }
+    
     /* setup to record the attributes */
     OBJ_CONSTRUCT(&attributes, opal_list_t);
     
@@ -568,6 +587,22 @@ ompi_comm_start_processes(int count, char **array_of_commands,
         return MPI_ERR_SPAWN;
     }
 
+    /* check for timing request - get stop time and report elapsed time if so */
+    if (timing) {
+        if (0 != gettimeofday(&ompistop, NULL)) {
+            opal_output(0, "ompi_comm_start_procs: could not obtain stop time");
+        } else {
+            opal_output(0, "ompi_comm_start_procs: time from start to prepare to spawn %ld usec",
+                        (long int)((ompistop.tv_sec - ompistart.tv_sec)*1000000 +
+                                   (ompistop.tv_usec - ompistart.tv_usec)));
+            if (0 != gettimeofday(&ompistart, NULL)) {
+                opal_output(0, "ompi_comm_start_procs: could not obtain new start time");
+                ompistart.tv_sec = ompistop.tv_sec;
+                ompistart.tv_usec = ompistop.tv_usec;
+            }
+        }
+    }
+    
     /* spawn procs */
     if (ORTE_SUCCESS != (rc = orte_rmgr.spawn_job(apps, count, &new_jobid, 0, NULL, NULL, ORTE_PROC_STATE_NONE, &attributes))) {
         ORTE_ERROR_LOG(rc);
@@ -575,6 +610,17 @@ ompi_comm_start_processes(int count, char **array_of_commands,
         return MPI_ERR_SPAWN;
     }
 
+    /* check for timing request - get stop time and report elapsed time if so */
+    if (timing) {
+        if (0 != gettimeofday(&ompistop, NULL)) {
+            opal_output(0, "ompi_comm_start_procs: could not obtain stop time");
+        } else {
+            opal_output(0, "ompi_comm_start_procs: time to spawn %ld usec",
+                        (long int)((ompistop.tv_sec - ompistart.tv_sec)*1000000 +
+                                   (ompistop.tv_usec - ompistart.tv_usec)));
+         }
+    }
+    
     /* clean up */
     opal_progress_event_decrement();
     while (NULL != (item = opal_list_remove_first(&attributes))) OBJ_RELEASE(item);