[REVIEW] add logger in cuML C++

CHANGELOG.md

@@ -1,6 +1,7 @@
 # cuML 0.14.0 (Date TBD)
 
 ## New Features
+- PR #1867: C++: add logging interface support in cuML based spdlog
 - PR #1906: UMAP MNMG
 
 ## Improvements

cpp/CMakeLists.txt

@@ -241,6 +241,7 @@ set(CUML_INCLUDE_DIRECTORIES
   ${CMAKE_CUDA_TOOLKIT_INCLUDE_DIRECTORIES}
   ${CUTLASS_DIR}/src/cutlass
   ${CUB_DIR}/src/cub
+  ${SPDLOG_DIR}/src/spdlog/include
   ${TREELITE_DIR}/include
   ${TREELITE_DIR}/include/fmt)
 
@@ -264,6 +265,7 @@ if(BUILD_CUML_CPP_LIBRARY)
     src/common/cumlHandle.cpp
     src/common/cuml_api.cpp
     src/common/cuML_comms_impl.cpp
+    src/common/logger.cpp
     src/common/nvtx.cu
     src/comms/cuML_comms_test.cpp
     src/datasets/make_blobs.cu

cpp/bench/CMakeLists.txt

@@ -52,14 +52,16 @@ if(BUILD_CUML_PRIMS_BENCH)
     prims/distance_l1.cu
     prims/distance_unexp_l2.cu
     prims/fused_l2_nn.cu
+    prims/main.cpp
     prims/map_then_reduce.cu
     prims/matrix_vector_op.cu
     prims/permute.cu
     prims/reduce.cu
     prims/rng.cu
-    prims/main.cpp)
+    ../src/common/logger.cpp  # because prims is header only!
+    )
 
-  add_dependencies(prims_benchmark cutlass)
+  add_dependencies(prims_benchmark spdlog)
 
   target_link_libraries(prims_benchmark benchmarklib)
 

cpp/bench/prims/benchmark.cuh

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2019, NVIDIA CORPORATION.
+ * Copyright (c) 2019-2020, NVIDIA CORPORATION.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -20,6 +20,7 @@
 #include <cuda_runtime.h>
 #include <cuda_utils.h>
 #include <utils.h>
+#include <cuml/common/logger.hpp>
 #include <sstream>
 #include <string>
 #include <vector>
@@ -123,13 +124,13 @@ struct CudaEventTimer {
    *       value given by `cudaEventElapsedTime()`.
    */
   ~CudaEventTimer() {
-    CUDA_CHECK(cudaEventRecord(stop, stream));
-    CUDA_CHECK(cudaEventSynchronize(stop));
+    CUDA_CHECK_NO_THROW(cudaEventRecord(stop, stream));
+    CUDA_CHECK_NO_THROW(cudaEventSynchronize(stop));
     float milliseconds = 0.0f;
-    CUDA_CHECK(cudaEventElapsedTime(&milliseconds, start, stop));
+    CUDA_CHECK_NO_THROW(cudaEventElapsedTime(&milliseconds, start, stop));
     state->SetIterationTime(milliseconds / 1000.f);
-    CUDA_CHECK(cudaEventDestroy(start));
-    CUDA_CHECK(cudaEventDestroy(stop));
+    CUDA_CHECK_NO_THROW(cudaEventDestroy(start));
+    CUDA_CHECK_NO_THROW(cudaEventDestroy(stop));
   }
 
  private:

cpp/bench/sg/benchmark.cuh

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2019, NVIDIA CORPORATION.
+ * Copyright (c) 2019-2020, NVIDIA CORPORATION.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -19,6 +19,7 @@
 #include <benchmark/benchmark.h>
 #include <cuda_runtime.h>
 #include <utils.h>
+#include <cuml/common/logger.hpp>
 #include <cuml/cuml.hpp>
 #include <sstream>
 #include <vector>
@@ -207,13 +208,13 @@ struct CudaEventTimer {
    *       value given by `cudaEventElapsedTime()`.
    */
   ~CudaEventTimer() {
-    CUDA_CHECK(cudaEventRecord(stop, stream));
-    CUDA_CHECK(cudaEventSynchronize(stop));
+    CUDA_CHECK_NO_THROW(cudaEventRecord(stop, stream));
+    CUDA_CHECK_NO_THROW(cudaEventSynchronize(stop));
     float milliseconds = 0.0f;
-    CUDA_CHECK(cudaEventElapsedTime(&milliseconds, start, stop));
+    CUDA_CHECK_NO_THROW(cudaEventElapsedTime(&milliseconds, start, stop));
     state->SetIterationTime(milliseconds / 1000.f);
-    CUDA_CHECK(cudaEventDestroy(start));
-    CUDA_CHECK(cudaEventDestroy(stop));
+    CUDA_CHECK_NO_THROW(cudaEventDestroy(start));
+    CUDA_CHECK_NO_THROW(cudaEventDestroy(stop));
   }
 
  private:

cpp/cmake/Dependencies.cmake

@@ -41,6 +41,19 @@ ExternalProject_Add(cutlass
   BUILD_COMMAND     ""
   INSTALL_COMMAND   "")
 
+##############################################################################
+# - spdlog -------------------------------------------------------------------
+
+set(SPDLOG_DIR ${CMAKE_CURRENT_BINARY_DIR}/spdlog CACHE STRING
+  "Path to spdlog install directory")
+ExternalProject_Add(spdlog
+  GIT_REPOSITORY    https://github.com/gabime/spdlog.git
+  GIT_TAG           v1.x
+  PREFIX            ${SPDLOG_DIR}
+  CONFIGURE_COMMAND ""
+  BUILD_COMMAND     ""
+  INSTALL_COMMAND   "")
+
 ##############################################################################
 # - faiss --------------------------------------------------------------------
 
@@ -155,7 +168,8 @@ set_property(TARGET benchmarklib PROPERTY
 # This allows the cloning to happen sequentially, enhancing the printing at
 # compile time, helping significantly to troubleshoot build issues.
 add_dependencies(cutlass cub)
-add_dependencies(faiss cutlass)
+add_dependencies(spdlog cutlass)
+add_dependencies(faiss spdlog)
 add_dependencies(faisslib faiss)
 add_dependencies(treelite faiss)
 add_dependencies(googletest treelite)

cpp/comms/mpi/src/cuML_comms_mpi_impl.cpp

@@ -21,6 +21,7 @@
 
 #include <common/cumlHandle.hpp>
 #include <cuML_comms.hpp>
+#include <cuml/common/logger.hpp>
 
 #include <utils.h>
 
@@ -36,19 +37,16 @@
     }                                                                       \
   } while (0)
 
-//@todo adapt logging infrastructure for MPI_CHECK_NO_THROW once available:
-//https://github.com/rapidsai/cuml/issues/100
-#define MPI_CHECK_NO_THROW(call)                                              \
-  do {                                                                        \
-    int status = call;                                                        \
-    if (MPI_SUCCESS != status) {                                              \
-      int mpi_error_string_lenght = 0;                                        \
-      char mpi_error_string[MPI_MAX_ERROR_STRING];                            \
-      MPI_Error_string(status, mpi_error_string, &mpi_error_string_lenght);   \
-      std::fprintf(stderr,                                                    \
-                   "ERROR: MPI call='%s' at file=%s line=%d failed with %s ", \
-                   #call, __FILE__, __LINE__, mpi_error_string);              \
-    }                                                                         \
+#define MPI_CHECK_NO_THROW(call)                                            \
+  do {                                                                      \
+    int status = call;                                                      \
+    if (MPI_SUCCESS != status) {                                            \
+      int mpi_error_string_lenght = 0;                                      \
+      char mpi_error_string[MPI_MAX_ERROR_STRING];                          \
+      MPI_Error_string(status, mpi_error_string, &mpi_error_string_lenght); \
+      CUML_LOG_ERROR("MPI call='%s' at file=%s line=%d failed with %s ",    \
+                     #call, __FILE__, __LINE__, mpi_error_string);          \
+    }                                                                       \
   } while (0)
 
 #define NCCL_CHECK(call)                                                       \
@@ -58,16 +56,13 @@
            ncclGetErrorString(status));                                        \
   } while (0)
 
-//@todo adapt logging infrastructure for NCCL_CHECK_NO_THROW once available:
-//https://github.com/rapidsai/cuml/issues/100
-#define NCCL_CHECK_NO_THROW(call)                                              \
-  do {                                                                         \
-    ncclResult_t status = call;                                                \
-    if (ncclSuccess != status) {                                               \
-      std::fprintf(stderr,                                                     \
-                   "ERROR: NCCL call='%s' at file=%s line=%d failed with %s ", \
-                   #call, __FILE__, __LINE__, ncclGetErrorString(status));     \
-    }                                                                          \
+#define NCCL_CHECK_NO_THROW(call)                                 \
+  do {                                                            \
+    ncclResult_t status = call;                                   \
+    if (status != ncclSuccess) {                                  \
+      CUML_LOG_ERROR("NCCL call='%s' failed. Reason:%s\n", #call, \
+                     ncclGetErrorString(status));                 \
+    }                                                             \
   } while (0)
 
 namespace ML {

cpp/comms/std/src/cuML_std_comms_impl.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2019, NVIDIA CORPORATION.
+ * Copyright (c) 2019-2020, NVIDIA CORPORATION.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -39,6 +39,9 @@ constexpr bool UCX_ENABLED = false;
 #include <cuML_comms.hpp>
 #include <exception>
 #include <memory>
+
+#include <cuml/common/logger.hpp>
+
 #include <thread>
 
 #include <cuda_runtime.h>
@@ -52,16 +55,13 @@ constexpr bool UCX_ENABLED = false;
            ncclGetErrorString(status));                                        \
   } while (0)
 
-//@todo adapt logging infrastructure for NCCL_CHECK_NO_THROW once available:
-//https://github.com/rapidsai/cuml/issues/100
-#define NCCL_CHECK_NO_THROW(call)                                              \
-  do {                                                                         \
-    ncclResult_t status = call;                                                \
-    if (ncclSuccess != status) {                                               \
-      std::fprintf(stderr,                                                     \
-                   "ERROR: NCCL call='%s' at file=%s line=%d failed with %s ", \
-                   #call, __FILE__, __LINE__, ncclGetErrorString(status));     \
-    }                                                                          \
+#define NCCL_CHECK_NO_THROW(call)                                 \
+  do {                                                            \
+    ncclResult_t status = call;                                   \
+    if (status != ncclSuccess) {                                  \
+      CUML_LOG_ERROR("NCCL call='%s' failed. Reason:%s\n", #call, \
+                     ncclGetErrorString(status));                 \
+    }                                                             \
   } while (0)
 
 namespace ML {
@@ -296,11 +296,10 @@ void cumlStdCommunicator_impl::isend(const void *buf, int size, int dest,
     ucp_isend((struct comms_ucp_handle *)_ucp_handle, ep_ptr, buf, size, tag,
               default_tag_mask, getRank(), _verbose);
 
-  if (_verbose) {
-    std::cout << getRank() << ": Created send request [id=" << *request
-              << ", ptr= " << ucp_req->req << ", to=" << dest
-              << ", ep=" << ep_ptr << "]" << std::endl;
-  }
+  CUML_LOG_DEBUG(
+    "%d: Created send request [id=%llu], ptr=%llu, to=%llu, ep=%llu", getRank(),
+    (unsigned long long)*request, (unsigned long long)ucp_req->req,
+    (unsigned long long)dest, (unsigned long long)ep_ptr);
 
   _requests_in_flight.insert(std::make_pair(*request, ucp_req));
 #endif
@@ -328,11 +327,10 @@ void cumlStdCommunicator_impl::irecv(void *buf, int size, int source, int tag,
     ucp_irecv((struct comms_ucp_handle *)_ucp_handle, _ucp_worker, ep_ptr, buf,
               size, tag, tag_mask, source, _verbose);
 
-  if (_verbose) {
-    std::cout << getRank() << ": Created receive request [id=" << *request
-              << ", ptr=" << ucp_req->req << ", from=" << source
-              << "ep=" << ep_ptr << "]" << std::endl;
-  }
+  CUML_LOG_DEBUG(
+    "%d: Created receive request [id=%llu], ptr=%llu, from=%llu, ep=%llu",
+    getRank(), (unsigned long long)*request, (unsigned long long)ucp_req->req,
+    (unsigned long long)source, (unsigned long long)ep_ptr);
 
   _requests_in_flight.insert(std::make_pair(*request, ucp_req));
 #endif
@@ -396,14 +394,11 @@ void cumlStdCommunicator_impl::waitall(int count,
       // is complete, we can go ahead and clean it up.
       if (!req->needs_release || req->req->completed == 1) {
         restart = true;
-        if (_verbose) {
-          std::cout << getRank() << ": request completed. [ptr=" << req->req
-                    << ", num_left= " << requests.size() - 1
-                    << ", other_rank=" << req->other_rank
-                    << ", is_send=" << req->is_send_request
-                    << ", completed_immediately=" << !req->needs_release << "]"
-                    << std::endl;
-        }
+        CUML_LOG_DEBUG(
+          "%d: request completed. [ptr=%llu, num_left=%lu,"
+          " other_rank=%d, is_send=%d, completed_immediately=%d]",
+          getRank(), (unsigned long long)req->req, requests.size() - 1,
+          req->other_rank, req->is_send_request, !req->needs_release);
 
         // perform cleanup
         free_ucp_request((struct comms_ucp_handle *)_ucp_handle, req);

cpp/comms/std/src/ucp_helper.h

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2019, NVIDIA CORPORATION.
+ * Copyright (c) 2019-2020, NVIDIA CORPORATION.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -15,12 +15,12 @@
  */
 
 #include <dlfcn.h>
+#include <stdio.h>
 #include <ucp/api/ucp.h>
 #include <ucp/api/ucp_def.h>
-
-#include <stdio.h>
-
 #include <utils.h>
+#include <cuml/common/logger.hpp>
+#include <cuml/common/utils.hpp>
 
 /**
  * An opaque handle for managing `dlopen` state within
@@ -72,10 +72,7 @@ void load_ucp_handle(struct comms_ucp_handle *ucp_handle) {
     dlopen("libucp.so", RTLD_LAZY | RTLD_NOLOAD | RTLD_NODELETE);
   if (!ucp_handle->ucp_handle) {
     ucp_handle->ucp_handle = dlopen("libucp.so", RTLD_LAZY | RTLD_NODELETE);
-    if (!ucp_handle->ucp_handle) {
-      printf("Cannot open UCX library: %s\n", dlerror());
-      exit(1);
-    }
+    ASSERT(ucp_handle->ucp_handle, "Cannot open UCX library: %s\n", dlerror());
   }
   dlerror();
 }
@@ -161,7 +158,7 @@ struct ucp_request *ucp_isend(struct comms_ucp_handle *ucp_handle,
                               bool verbose) {
   ucp_tag_t ucp_tag = build_message_tag(rank, tag);
 
-  if (verbose) printf("Sending tag: %ld\n", ucp_tag);
+  CUML_LOG_DEBUG("Sending tag: %ld", ucp_tag);
 
   ucs_status_ptr_t send_result = (*(ucp_handle->send_func))(
     ep_ptr, buf, size, ucp_dt_make_contig(1), ucp_tag, send_handle);
@@ -201,7 +198,7 @@ struct ucp_request *ucp_irecv(struct comms_ucp_handle *ucp_handle,
                               int sender_rank, bool verbose) {
   ucp_tag_t ucp_tag = build_message_tag(sender_rank, tag);
 
-  if (verbose) printf("%d: Receiving tag: %ld\n", ucp_tag);
+  CUML_LOG_DEBUG("%d: Receiving tag: %ld", ucp_tag);
 
   ucs_status_ptr_t recv_result = (*(ucp_handle->recv_func))(
     worker, buf, size, ucp_dt_make_contig(1), ucp_tag, tag_mask, recv_handle);