timings: Update/extend OSHMEM timings

Signed-off-by: Artem Polyakov <artpol84@gmail.com>
(cherry picked from commit 0f51ea3fe5)

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

@@ -24,7 +24,7 @@
 #include "orte/mca/errmgr/errmgr.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
@@ -57,6 +57,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,
@@ -65,11 +67,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",
@@ -78,6 +84,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,
@@ -90,6 +98,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;
 }
 
@@ -104,43 +113,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;
@@ -152,6 +178,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

@@ -148,7 +148,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);
@@ -165,9 +165,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;
@@ -183,6 +188,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");
@@ -259,6 +265,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";
@@ -271,43 +279,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())) {
@@ -315,11 +338,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) {
@@ -327,6 +354,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) {
@@ -334,46 +363,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);
         orte_show_help("help-shmem-runtime.txt",
@@ -386,7 +433,7 @@ static int _shmem_init(int argc, char **argv, int requested, int *provided)
                        ret);
         return ret;
     }
+    OPAL_TIMING_ENV_NEXT(timing, "DONE");
 
     return ret;
 }
-