Merge pull request #7512 from artpol84/topic/master/timings_update

Topic/master/timings update

ompi/util/timings.h

@@ -120,7 +120,7 @@ typedef struct ompi_timing_t {
         }                                                                          \
     } while(0)
 
-#define OMPI_TIMING_APPEND(filename,func,desc,ts)                                  \
+#define OMPI_TIMING_APPEND_PREFIX(filename, _prefix, func,desc,ts)                                  \
     do {                                                                           \
         if (OMPI_TIMING.cur_timing->use >= OMPI_TIMING.size){                      \
             OMPI_TIMING_ITEM_EXTEND;                                               \
@@ -130,7 +130,12 @@ typedef struct ompi_timing_t {
         if (len >= OPAL_TIMING_STR_LEN) {                                          \
             OMPI_TIMING.error = 1;                                                 \
         }                                                                          \
-        OMPI_TIMING.cur_timing->val[OMPI_TIMING.cur_timing->use].prefix = func;    \
+        if( _prefix[0] ) {                                                         \
+            OMPI_TIMING.cur_timing->val[OMPI_TIMING.cur_timing->use].prefix =      \
+                                                              func "/" _prefix;    \
+        } else {                                                                   \
+            OMPI_TIMING.cur_timing->val[OMPI_TIMING.cur_timing->use].prefix = func;\
+        }                                                                          \
         OMPI_TIMING.cur_timing->val[OMPI_TIMING.cur_timing->use].file = filename;  \
         OMPI_TIMING.cur_timing->val[OMPI_TIMING.cur_timing->use++].ts = ts;        \
         OMPI_TIMING.cnt++;                                                         \
@@ -143,14 +148,14 @@ typedef struct ompi_timing_t {
             int i;                                                                 \
             double ts;                                                             \
             OMPI_TIMING.import_cnt++;                                              \
-            OPAL_TIMING_ENV_CNT(func, cnt);                                        \
+            OPAL_TIMING_ENV_CNT_PREFIX(_prefix, func, cnt);                        \
             OPAL_TIMING_ENV_ERROR_PREFIX(_prefix, func, OMPI_TIMING.error);        \
             for(i = 0; i < cnt; i++){                                              \
                 char *desc, *filename;                                             \
                 OMPI_TIMING.cur_timing->val[OMPI_TIMING.cur_timing->use].imported= \
                     OMPI_TIMING.import_cnt;                                        \
                 OPAL_TIMING_ENV_GETDESC_PREFIX(_prefix, &filename, func, i, &desc, ts);  \
-                OMPI_TIMING_APPEND(filename, func, desc, ts);                      \
+                OMPI_TIMING_APPEND_PREFIX(filename, _prefix, func, desc, ts);      \
             }                                                                      \
         }                                                                          \
     } while(0)
@@ -275,6 +280,8 @@ typedef struct ompi_timing_t {
 
 #define OMPI_TIMING_IMPORT_OPAL(func)
 
+#define OMPI_TIMING_IMPORT_OPAL_PREFIX(_prefix, func)
+
 #define OMPI_TIMING_FINALIZE
 
 #define OMPI_TIMING_ENABLED 0

opal/util/timings.h

@@ -49,11 +49,11 @@ opal_timing_ts_func_t opal_timing_ts_func(opal_timer_type_t type);
             _prefix = "";                                                         \
         }                                                                         \
         (_nm)->error = 0;                                                         \
-        n = snprintf((_nm)->id, OPAL_TIMING_STR_LEN, "%s%s", _prefix, func);      \
+        n = snprintf((_nm)->id, OPAL_TIMING_STR_LEN, "%s_%s", _prefix, func);     \
         if( n > OPAL_TIMING_STR_LEN ){                                            \
              (_nm)->error = 1;                                                    \
         }                                                                         \
-        n = sprintf((_nm)->cntr_env,"OMPI_TIMING_%s%s_CNT", prefix, (_nm)->id);   \
+        n = sprintf((_nm)->cntr_env,"OMPI_TIMING_%s_CNT", (_nm)->id);             \
         if( n > OPAL_TIMING_STR_LEN ){                                            \
             (_nm)->error = 1;                                                     \
         }                                                                         \
@@ -77,11 +77,6 @@ opal_timing_ts_func_t opal_timing_ts_func(opal_timer_type_t type);
         }                                                                         \
     } while(0)
 
-#define OPAL_TIMING_ENV_INIT(name)                                                \
-    opal_timing_env_t name ## _val, *name = &(name ## _val);                      \
-    OPAL_TIMING_ENV_START_TYPE(__func__, name, OPAL_TIMING_AUTOMATIC_TIMER, "");
-
-
 /* We use function names for identification
  * however this might be a problem for the private
  * functions declared as static as their names may
@@ -89,10 +84,10 @@ opal_timing_ts_func_t opal_timing_ts_func(opal_timer_type_t type);
  * Use prefix to do a finer-grained identification if needed
  */
 #define OPAL_TIMING_ENV_INIT_PREFIX(prefix, name)                                 \
-    do {                                                                          \
+    opal_timing_env_t name ## _val, *name = &(name ## _val);                      \
-        opal_timing_env_t name ## _val, *name = &(name ## _val);                  \
+    OPAL_TIMING_ENV_START_TYPE(__func__, name, OPAL_TIMING_AUTOMATIC_TIMER, prefix);
-        *name = OPAL_TIMING_ENV_START_TYPE(__func__, name, OPAL_TIMING_AUTOMATIC_TIMER, prefix); \
+
-    } while(0)
+#define OPAL_TIMING_ENV_INIT(name) OPAL_TIMING_ENV_INIT_PREFIX("", name)
 
 #define OPAL_TIMING_ENV_NEXT(h, ...)                                              \
     do {                                                                          \
@@ -161,7 +156,7 @@ opal_timing_ts_func_t opal_timing_ts_func(opal_timer_type_t type);
     do {                                                                          \
         char ename[OPAL_TIMING_STR_LEN];                                          \
         char *ptr = NULL;                                                         \
-        int n = snprintf(ename, OPAL_TIMING_STR_LEN, "OMPI_TIMING_%s%s_CNT", prefix, func);    \
+        int n = snprintf(ename, OPAL_TIMING_STR_LEN, "OMPI_TIMING_%s_%s_CNT", prefix, func);    \
         (_cnt) = 0;                                                               \
         if ( n <= OPAL_TIMING_STR_LEN ){                                          \
             ptr = getenv(ename);                                                  \
@@ -181,18 +176,15 @@ opal_timing_ts_func_t opal_timing_ts_func(opal_timer_type_t type);
         }                                                                         \
     } while(0)
 
-#define OPAL_TIMING_ENV_CNT(func, _cnt)                                           \
-    OPAL_TIMING_ENV_CNT_PREFIX("", func, _cnt)
-
 #define OPAL_TIMING_ENV_GETDESC_PREFIX(prefix, filename, func, i, desc, _t)       \
     do {                                                                          \
         char vname[OPAL_TIMING_STR_LEN];                                          \
         (_t) = 0.0;                                                               \
-        sprintf(vname, "OMPI_TIMING_%s%s_FILE_%d", prefix, func, i);              \
+        sprintf(vname, "OMPI_TIMING_%s_%s_FILE_%d", prefix, func, i);              \
         *filename = getenv(vname);                                                \
-        sprintf(vname, "OMPI_TIMING_%s%s_DESC_%d", prefix, func, i);              \
+        sprintf(vname, "OMPI_TIMING_%s_%s_DESC_%d", prefix, func, i);              \
         *desc = getenv(vname);                                                    \
-        sprintf(vname, "OMPI_TIMING_%s%s_VAL_%d", prefix, func, i);               \
+        sprintf(vname, "OMPI_TIMING_%s_%s_VAL_%d", prefix, func, i);               \
         char *ptr = getenv(vname);                                                \
         if ( NULL != ptr ) {                                                      \
             sscanf(ptr,"%lf", &(_t));                                             \

oshmem/mca/memheap/base/base.h

@@ -62,7 +62,7 @@ typedef struct mca_memheap_map {
 extern mca_memheap_map_t mca_memheap_base_map;
 extern mca_memheap_base_config_t mca_memheap_base_config;
 
-int mca_memheap_base_alloc_init(mca_memheap_map_t *, size_t, long);
+int mca_memheap_base_alloc_init(mca_memheap_map_t *, size_t, long, char *);
 void mca_memheap_base_alloc_exit(mca_memheap_map_t *);
 int mca_memheap_base_static_init(mca_memheap_map_t *);
 void mca_memheap_base_static_exit(mca_memheap_map_t *);

oshmem/mca/memheap/base/memheap_base_alloc.c

@@ -17,13 +17,17 @@
 #include "oshmem/mca/sshmem/base/base.h"
 #include "oshmem/mca/memheap/memheap.h"
 #include "oshmem/mca/memheap/base/base.h"
+#include "ompi/util/timings.h"
 
 
-int mca_memheap_base_alloc_init(mca_memheap_map_t *map, size_t size, long hint)
+int mca_memheap_base_alloc_init(mca_memheap_map_t *map, size_t size, long hint,
+                                char *timing_prefix)
 {
     int ret = OSHMEM_SUCCESS;
     char * seg_filename = NULL;
 
+    OPAL_TIMING_ENV_INIT_PREFIX(timing_prefix, timing);
+
     assert(map);
     if (hint == 0) {
         assert(HEAP_SEG_INDEX == map->n_segments);
@@ -33,8 +37,13 @@ int mca_memheap_base_alloc_init(mca_memheap_map_t *map, size_t size, long hint)
 
     map_segment_t *s = &map->mem_segs[map->n_segments];
     seg_filename = oshmem_get_unique_file_name(oshmem_my_proc_id());
+
+    OPAL_TIMING_ENV_NEXT(timing, "oshmem_get_unique_file_name()");
+
     ret = mca_sshmem_segment_create(s, seg_filename, size, hint);
 
+    OPAL_TIMING_ENV_NEXT(timing, "mca_sshmem_segment_create()");
+
     if (OSHMEM_SUCCESS == ret) {
         map->n_segments++;
         MEMHEAP_VERBOSE(1,
@@ -43,6 +52,7 @@ int mca_memheap_base_alloc_init(mca_memheap_map_t *map, size_t size, long hint)
     }
 
     free(seg_filename);
+    OPAL_TIMING_ENV_NEXT(timing, "DONE");
 
     return ret;
 }

oshmem/mca/memheap/base/memheap_base_mkey.c

@@ -27,6 +27,7 @@
 #include "oshmem/mca/memheap/memheap.h"
 #include "oshmem/mca/memheap/base/base.h"
 #include "oshmem/mca/spml/spml.h"
+#include "opal/util/timings.h"
 
 /* Turn ON/OFF debug output from build (default 0) */
 #ifndef MEMHEAP_BASE_DEBUG
@@ -529,14 +530,16 @@ void mca_memheap_modex_recv_all(void)
     int rc = OSHMEM_SUCCESS;
     size_t buffer_size;
 
+    OPAL_TIMING_ENV_INIT(recv_all);
+
     if (!mca_memheap_base_key_exchange) {
         oshmem_shmem_barrier();
         return;
     }
-
+    OPAL_TIMING_ENV_NEXT(recv_all, "barrier");
     nprocs = oshmem_num_procs();
     my_pe = oshmem_my_proc_id();
-
+    OPAL_TIMING_ENV_NEXT(recv_all, "proc position");
     /* buffer allocation for num_transports
      * message sizes and offsets */
 
@@ -560,6 +563,7 @@ void mca_memheap_modex_recv_all(void)
         rc = OSHMEM_ERR_OUT_OF_RESOURCE;
         goto exit_fatal;
     }
+    OPAL_TIMING_ENV_NEXT(recv_all, "alloc bufs");
 
     /* serialize our own mkeys */
     msg = OBJ_NEW(opal_buffer_t);
@@ -582,6 +586,9 @@ void mca_memheap_modex_recv_all(void)
     opal_dss.unload(msg, &send_buffer, &size);
     MEMHEAP_VERBOSE(1, "local keys packed into %d bytes, %d segments", size, memheap_map->n_segments);
 
+    OPAL_TIMING_ENV_NEXT(recv_all, "serialize data");
+
+
     /* we need to send num_transports and message sizes separately
      * since message sizes depend on types of btl used */
 
@@ -591,12 +598,17 @@ void mca_memheap_modex_recv_all(void)
         goto exit_fatal;
     }
 
+    OPAL_TIMING_ENV_NEXT(recv_all, "allgather: transport cnt");
+
+
     rc = oshmem_shmem_allgather(&size, rcv_size, sizeof(int));
     if (MPI_SUCCESS != rc) {
         MEMHEAP_ERROR("allgather failed");
         goto exit_fatal;
     }
 
+    OPAL_TIMING_ENV_NEXT(recv_all, "allgather: size info");
+
     /* calculating offsets (displacements) for allgatherv */
 
     rcv_offsets[0] = 0;
@@ -613,6 +625,8 @@ void mca_memheap_modex_recv_all(void)
         goto exit_fatal;
     }
 
+    OPAL_TIMING_ENV_NEXT(recv_all, "alloc data buf");
+
     rc = oshmem_shmem_allgatherv(send_buffer, rcv_buffer, size, rcv_size, rcv_offsets);
     if (MPI_SUCCESS != rc) {
         free (rcv_buffer);
@@ -620,6 +634,8 @@ void mca_memheap_modex_recv_all(void)
         goto exit_fatal;
     }
 
+    OPAL_TIMING_ENV_NEXT(recv_all, "Perform mkey exchange");
+
     opal_dss.load(msg, rcv_buffer, buffer_size);
 
     /* deserialize mkeys */
@@ -651,6 +667,8 @@ void mca_memheap_modex_recv_all(void)
         }
     }
 
+    OPAL_TIMING_ENV_NEXT(recv_all, "Unpack data");
+
     OPAL_THREAD_UNLOCK(&memheap_oob.lck);
 
 exit_fatal:
@@ -670,6 +688,7 @@ exit_fatal:
         OBJ_RELEASE(msg);
     }
 
+    OPAL_TIMING_ENV_NEXT(recv_all, "Cleanup");
     /* This function requires abort in any error case */
     if (OSHMEM_SUCCESS != rc) {
         oshmem_shmem_abort(rc);

oshmem/mca/memheap/base/memheap_base_select.c

@@ -23,7 +23,7 @@
 #include "oshmem/mca/memheap/base/base.h"
 #include "oshmem/include/shmemx.h"
 #include "oshmem/mca/sshmem/base/base.h"
-
+#include "ompi/util/timings.h"
 
 mca_memheap_base_config_t mca_memheap_base_config = {
     .device_nic_mem_seg_size = 0
@@ -56,6 +56,8 @@ int mca_memheap_base_select()
     mca_memheap_base_component_t *best_component = NULL;
     mca_memheap_base_module_t *best_module = NULL;
 
+    OPAL_TIMING_ENV_INIT(timing);
+
     if( OPAL_SUCCESS != mca_base_select("memheap", oshmem_memheap_base_framework.framework_output,
                                         &oshmem_memheap_base_framework.framework_components,
                                         (mca_base_module_t **) &best_module,
@@ -64,11 +66,15 @@ int mca_memheap_base_select()
         return OSHMEM_ERROR;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "env");
+
     context = _memheap_create();
     if (NULL == context) {
         return OSHMEM_ERROR;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "_memheap_create()");
+
     if (OSHMEM_SUCCESS != best_component->memheap_init(context)) {
         opal_show_help("help-oshmem-memheap.txt",
                        "find-available:none-found",
@@ -77,6 +83,8 @@ int mca_memheap_base_select()
         return OSHMEM_ERROR;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "best_component->memheap_init()");
+
     /* Calculate memheap size in case it was not set during component initialization */
     best_module->memheap_size = context->user_size;
     setenv(SHMEM_HEAP_TYPE,
@@ -89,6 +97,7 @@ int mca_memheap_base_select()
                     best_component->memheap_version.mca_type_name, 
                     best_component->memheap_version.mca_component_name);
 
+    OPAL_TIMING_ENV_NEXT(timing, "DONE");
     return OSHMEM_SUCCESS;
 }
 
@@ -103,43 +112,60 @@ static memheap_context_t* _memheap_create(void)
     static memheap_context_t context;
     size_t user_size, size;
 
+    OPAL_TIMING_ENV_INIT(timing);
+
     user_size = _memheap_size();
     if (user_size < MEMHEAP_BASE_MIN_SIZE) {
         MEMHEAP_ERROR("Requested memheap size is less than minimal meamheap size (%llu < %llu)",
                       (unsigned long long)user_size, MEMHEAP_BASE_MIN_SIZE);
         return NULL ;
     }
+
+    OPAL_TIMING_ENV_NEXT(timing, "_memheap_size()");
+
     /* Inititialize symmetric area */
     if (OSHMEM_SUCCESS == rc) {
         rc = mca_memheap_base_alloc_init(&mca_memheap_base_map,
-                                         user_size + MEMHEAP_BASE_PRIVATE_SIZE, 0);
+                                         user_size + MEMHEAP_BASE_PRIVATE_SIZE, 0,
+                                         "regular_mem");
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "mca_memheap_base_alloc_init()");
+
     /* Initialize atomic symmetric area */
     size = mca_memheap_base_config.device_nic_mem_seg_size;
     if ((OSHMEM_SUCCESS == rc) && (size > 0)) {
         rc = mca_memheap_base_alloc_init(&mca_memheap_base_map, size,
-                                         SHMEM_HINT_DEVICE_NIC_MEM);
+                                         SHMEM_HINT_DEVICE_NIC_MEM,
+                                         "device_mem");
         if (rc == OSHMEM_ERR_NOT_IMPLEMENTED) {
             /* do not treat NOT_IMPLEMENTED as error */
             rc = OSHMEM_SUCCESS;
         }
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "mca_memheap_base_alloc_init(DEVICE_MEM)");
+
+
     /* Inititialize static/global variables area */
     if (OSHMEM_SUCCESS == rc) {
         rc = mca_memheap_base_static_init(&mca_memheap_base_map);
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "mca_memheap_base_static_init()");
+
     /* Memory Registration */
     if (OSHMEM_SUCCESS == rc) {
         rc = mca_memheap_base_reg(&mca_memheap_base_map);
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "mca_memheap_base_reg()");
+
     /* Init OOB channel */
     if (OSHMEM_SUCCESS == rc) {
         rc = memheap_oob_init(&mca_memheap_base_map);
     }
+    OPAL_TIMING_ENV_NEXT(timing, "memheap_oob_init()");
 
     if (OSHMEM_SUCCESS == rc) {
         context.user_size = user_size;
@@ -151,6 +177,7 @@ static memheap_context_t* _memheap_create(void)
                 (void*) ((unsigned char*) mca_memheap_base_map.mem_segs[HEAP_SEG_INDEX].super.va_base
                         + context.user_size);
     }
+    OPAL_TIMING_ENV_NEXT(timing, "DONE");
 
     return ((OSHMEM_SUCCESS == rc) ? &context : NULL );
 }

oshmem/runtime/oshmem_shmem_init.c

@@ -138,7 +138,7 @@ int oshmem_shmem_init(int argc, char **argv, int requested, int *provided)
 {
     int ret = OSHMEM_SUCCESS;
 
-    OMPI_TIMING_INIT(32);
+    OMPI_TIMING_INIT(128);
 
     if (!oshmem_shmem_initialized) {
         ret = ompi_mpi_init(argc, argv, requested, provided, true);
@@ -155,9 +155,14 @@ int oshmem_shmem_init(int argc, char **argv, int requested, int *provided)
 
         ret = _shmem_init(argc, argv, requested, provided);
         OMPI_TIMING_NEXT("_shmem_init");
+        OMPI_TIMING_IMPORT_OPAL("_shmem_init");
         OMPI_TIMING_IMPORT_OPAL("mca_scoll_mpi_comm_query");
         OMPI_TIMING_IMPORT_OPAL("mca_scoll_enable");
         OMPI_TIMING_IMPORT_OPAL("mca_scoll_base_select");
+        OMPI_TIMING_IMPORT_OPAL("mca_memheap_base_select");
+        OMPI_TIMING_IMPORT_OPAL("_memheap_create");
+        OMPI_TIMING_IMPORT_OPAL_PREFIX("regular_mem", "mca_memheap_base_alloc_init");
+        OMPI_TIMING_IMPORT_OPAL_PREFIX("device_mem", "mca_memheap_base_alloc_init");
 
         if (OSHMEM_SUCCESS != ret) {
             return ret;
@@ -173,6 +178,7 @@ int oshmem_shmem_init(int argc, char **argv, int requested, int *provided)
         /* this is a collective op, implies barrier */
         MCA_MEMHEAP_CALL(get_all_mkeys());
         OMPI_TIMING_NEXT("get_all_mkeys()");
+        OMPI_TIMING_IMPORT_OPAL("mca_memheap_modex_recv_all");
 
         oshmem_shmem_preconnect_all();
         OMPI_TIMING_NEXT("shmem_preconnect_all");
@@ -249,6 +255,8 @@ static int _shmem_init(int argc, char **argv, int requested, int *provided)
     oshmem_mpi_thread_requested = requested;
     oshmem_mpi_thread_provided = requested;
 
+    OPAL_TIMING_ENV_INIT(timing);
+
     /* Register the OSHMEM layer's MCA parameters */
     if (OSHMEM_SUCCESS != (ret = oshmem_shmem_register_params())) {
         error = "oshmem_info_register: oshmem_register_params failed";
@@ -261,43 +269,58 @@ static int _shmem_init(int argc, char **argv, int requested, int *provided)
     opal_output_set_verbosity(shmem_api_logger_output,
                               oshmem_shmem_api_verbose);
 
+    OPAL_TIMING_ENV_NEXT(timing, "shmem_params");
     /* initialize info */
     if (OSHMEM_SUCCESS != (ret = oshmem_info_init())) {
         error = "oshmem_info_init() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "oshmem_info_init()");
+
     /* initialize proc */
     if (OSHMEM_SUCCESS != (ret = oshmem_proc_init())) {
         error = "oshmem_proc_init() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "oshmem_proc_init()");
+
     if (OSHMEM_SUCCESS != (ret = oshmem_op_init())) {
         error = "oshmem_op_init() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "oshmem_op_init()");
+
     if (OSHMEM_SUCCESS != (ret = mca_base_framework_open(&oshmem_spml_base_framework, MCA_BASE_OPEN_DEFAULT))) {
         error = "mca_spml_base_open() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "open SPML framework");
+
     if (OSHMEM_SUCCESS != (ret = mca_base_framework_open(&oshmem_scoll_base_framework, MCA_BASE_OPEN_DEFAULT))) {
         error = "mca_scoll_base_open() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "open SCOLL framework");
+
     if (OSHMEM_SUCCESS != (ret = mca_spml_base_select(OPAL_ENABLE_PROGRESS_THREADS, 1))) {
         error = "mca_spml_base_select() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "select SPML framework");
+
     if (OSHMEM_SUCCESS != (ret = mca_scoll_base_find_available(OPAL_ENABLE_PROGRESS_THREADS, 1))) {
         error = "mca_scoll_base_find_available() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "find SCOLL components");
+
     /* Initialize each SHMEM handle subsystem */
     /* Initialize requests */
     if (OSHMEM_SUCCESS != (ret = oshmem_request_init())) {
@@ -305,11 +328,15 @@ static int _shmem_init(int argc, char **argv, int requested, int *provided)
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "oshmem_request_init()");
+
     if (OSHMEM_SUCCESS != (ret = oshmem_proc_group_init())) {
         error = "oshmem_proc_group_init() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "oshmem_proc_group_init()");
+
     /* start SPML/BTL's */
     ret = MCA_SPML_CALL(enable(true));
     if (OSHMEM_SUCCESS != ret) {
@@ -317,6 +344,8 @@ static int _shmem_init(int argc, char **argv, int requested, int *provided)
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "MCA_SPML_CALL(enable())");
+
     ret =
             MCA_SPML_CALL(add_procs(oshmem_group_all->proc_array, oshmem_group_all->proc_count));
     if (OSHMEM_SUCCESS != ret) {
@@ -324,46 +353,64 @@ static int _shmem_init(int argc, char **argv, int requested, int *provided)
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "MCA_SPML_CALL(add_procs())");
+
     if (OSHMEM_SUCCESS != (ret = mca_base_framework_open(&oshmem_sshmem_base_framework, MCA_BASE_OPEN_DEFAULT))) {
         error = "mca_sshmem_base_open() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "open SSHMEM framework");
+
     if (OSHMEM_SUCCESS != (ret = mca_sshmem_base_select())) {
         error = "mca_sshmem_base_select() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "select SSHMEM framework");
+
     if (OSHMEM_SUCCESS != (ret = mca_base_framework_open(&oshmem_memheap_base_framework, MCA_BASE_OPEN_DEFAULT))) {
         error = "mca_memheap_base_open() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "open MEMHEAP framework");
+
+
     if (OSHMEM_SUCCESS != (ret = mca_memheap_base_select())) {
         error = "mca_memheap_base_select() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "select MEMHEAP framework");
+
     if (OSHMEM_SUCCESS != (ret = mca_base_framework_open(&oshmem_atomic_base_framework, MCA_BASE_OPEN_DEFAULT))) {
         error = "mca_atomic_base_open() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "open ATOMIC framework");
+
     if (OSHMEM_SUCCESS != (ret = mca_atomic_base_find_available(OPAL_ENABLE_PROGRESS_THREADS, 1))) {
         error = "mca_atomic_base_find_available() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "find avail ATOMIC framework");
+
     /* This call should be done after memheap initialization */
     if (OSHMEM_SUCCESS != (ret = mca_scoll_enable())) {
         error = "mca_scoll_enable() failed";
         goto error;
     }
 
+    OPAL_TIMING_ENV_NEXT(timing, "mca_scoll_enable()");
+
     (*provided) = oshmem_mpi_thread_provided;
 
     oshmem_mpi_thread_multiple = (oshmem_mpi_thread_provided == SHMEM_THREAD_MULTIPLE) ? true : false;
 
+
     error: if (ret != OSHMEM_SUCCESS) {
         const char *err_msg = opal_strerror(ret);
         opal_show_help("help-shmem-runtime.txt",
@@ -376,7 +423,7 @@ static int _shmem_init(int argc, char **argv, int requested, int *provided)
                        ret);
         return ret;
     }
+    OPAL_TIMING_ENV_NEXT(timing, "DONE");
 
     return ret;
 }
-