Add logging to libcudf (#12637)

Adds a global `spdlog` logger.
Logging should be done through `CUDF_LOG_*` macros declared in detail `namespace`.
Logging level and output file path can be set via environment variables.
Logging can also be configured directly through the singleton object using spdlog APIs (should only be used outside of libcudf).

Added sample (useful) logging to `getenv_or`.
Fixed a bug discovered through the log :) Environment variable was being read in each `hostdevice_vector` constructor call.

Authors:
  - Vukasin Milovanovic (https://github.com/vuule)

Approvers:
  - AJ Schmidt (https://github.com/ajschmidt8)
  - Nghia Truong (https://github.com/ttnghia)
  - Robert Maynard (https://github.com/robertmaynard)
  - Vyas Ramasubramani (https://github.com/vyasr)

URL: #12637

conda/environments/all_cuda-118_arch-x86_64.yaml

@@ -27,6 +27,7 @@ dependencies:
 - dlpack>=0.5,<0.6.0a0
 - doxygen=1.8.20
 - fastavro>=0.22.9
+- fmt>=9.1.0,<10
 - fsspec>=0.6.0
 - gcc_linux-64=11.*
 - hypothesis
@@ -68,6 +69,7 @@ dependencies:
 - s3fs>=2022.3.0
 - scikit-build>=0.13.1
 - scipy
+- spdlog>=1.11.0,<1.12
 - sphinx
 - sphinx-autobuild
 - sphinx-copybutton

conda/recipes/libcudf/conda_build_config.yaml

@@ -24,3 +24,9 @@ dlpack_version:
 
 librdkafka_version:
   - ">=1.7.0,<1.8.0a0"
+
+fmt_version:
+  - ">=9.1.0,<10"
+
+spdlog_version:
+  - ">=1.11.0,<1.12"

conda/recipes/libcudf/meta.yaml

@@ -49,6 +49,8 @@ requirements:
     - libarrow {{ libarrow_version }}
     - dlpack {{ dlpack_version }}
     - librdkafka {{ librdkafka_version }}
+    - fmt {{ fmt_version }}
+    - spdlog {{ spdlog_version }}
 
 outputs:
   - name: libcudf
@@ -128,6 +130,7 @@ outputs:
         - test -f $PREFIX/include/cudf/detail/utilities/int_fastdiv.h
         - test -f $PREFIX/include/cudf/detail/utilities/integer_utils.hpp
         - test -f $PREFIX/include/cudf/detail/utilities/linked_column.hpp
+        - test -f $PREFIX/include/cudf/detail/utilities/logger.hpp
         - test -f $PREFIX/include/cudf/detail/utilities/pinned_allocator.hpp
         - test -f $PREFIX/include/cudf/detail/utilities/vector_factories.hpp
         - test -f $PREFIX/include/cudf/detail/utilities/visitor_overload.hpp
@@ -278,6 +281,7 @@ outputs:
         - test -f $PREFIX/include/cudf/utilities/bit.hpp
         - test -f $PREFIX/include/cudf/utilities/default_stream.hpp
         - test -f $PREFIX/include/cudf/utilities/error.hpp
+        - test -f $PREFIX/include/cudf/utilities/logger.hpp
         - test -f $PREFIX/include/cudf/utilities/span.hpp
         - test -f $PREFIX/include/cudf/utilities/traits.hpp
         - test -f $PREFIX/include/cudf/utilities/type_checks.hpp

cpp/CMakeLists.txt

@@ -120,15 +120,16 @@ set(CUDF_CUDA_FLAGS "")
 set(CUDF_CXX_DEFINITIONS "")
 set(CUDF_CUDA_DEFINITIONS "")
 
-# Set RMM logging level
-set(RMM_LOGGING_LEVEL
+# Set logging level
+set(LIBCUDF_LOGGING_LEVEL
     "INFO"
     CACHE STRING "Choose the logging level."
 )
 set_property(
-  CACHE RMM_LOGGING_LEVEL PROPERTY STRINGS "TRACE" "DEBUG" "INFO" "WARN" "ERROR" "CRITICAL" "OFF"
+  CACHE LIBCUDF_LOGGING_LEVEL PROPERTY STRINGS "TRACE" "DEBUG" "INFO" "WARN" "ERROR" "CRITICAL"
+                                       "OFF"
 )
-message(VERBOSE "CUDF: RMM_LOGGING_LEVEL = '${RMM_LOGGING_LEVEL}'.")
+message(VERBOSE "CUDF: LIBCUDF_LOGGING_LEVEL = '${LIBCUDF_LOGGING_LEVEL}'.")
 
 if(NOT CUDF_GENERATED_INCLUDE_DIR)
   set(CUDF_GENERATED_INCLUDE_DIR ${CUDF_BINARY_DIR})
@@ -191,6 +192,10 @@ include(cmake/Modules/JitifyPreprocessKernels.cmake)
 include(cmake/thirdparty/get_cufile.cmake)
 # find KvikIO
 include(cmake/thirdparty/get_kvikio.cmake)
+# find fmt
+include(cmake/thirdparty/get_fmt.cmake)
+# find spdlog
+include(cmake/thirdparty/get_spdlog.cmake)
 
 # Workaround until https://github.com/rapidsai/rapids-cmake/issues/176 is resolved
 if(NOT BUILD_SHARED_LIBS)
@@ -597,6 +602,7 @@ add_library(
   src/unary/nan_ops.cu
   src/unary/null_ops.cu
   src/utilities/default_stream.cpp
+  src/utilities/logger.cpp
   src/utilities/traits.cpp
   src/utilities/type_checks.cpp
   src/utilities/type_dispatcher.cpp
@@ -677,8 +683,11 @@ if(NOT USE_NVTX)
   target_compile_definitions(cudf PUBLIC NVTX_DISABLE)
 endif()
 
+# Define RMM logging level
+target_compile_definitions(cudf PRIVATE "RMM_LOGGING_LEVEL=LIBCUDF_LOGGING_LEVEL")
+
 # Define spdlog level
-target_compile_definitions(cudf PUBLIC "SPDLOG_ACTIVE_LEVEL=SPDLOG_LEVEL_${RMM_LOGGING_LEVEL}")
+target_compile_definitions(cudf PUBLIC "SPDLOG_ACTIVE_LEVEL=SPDLOG_LEVEL_${LIBCUDF_LOGGING_LEVEL}")
 
 # Compile stringified JIT sources first
 add_dependencies(cudf jitify_preprocess_run)

cpp/cmake/thirdparty/get_fmt.cmake

@@ -0,0 +1,22 @@
+# =============================================================================
+# Copyright (c) 2023, NVIDIA CORPORATION.
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except
+# in compliance with the License. You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software distributed under the License
+# is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express
+# or implied. See the License for the specific language governing permissions and limitations under
+# the License.
+# =============================================================================
+
+# Use CPM to find or clone fmt
+function(find_and_configure_fmt)
+
+  include(${rapids-cmake-dir}/cpm/fmt.cmake)
+  rapids_cpm_fmt(INSTALL_EXPORT_SET cudf-exports BUILD_EXPORT_SET cudf-exports)
+endfunction()
+
+find_and_configure_fmt()

cpp/cmake/thirdparty/get_spdlog.cmake

@@ -0,0 +1,34 @@
+# =============================================================================
+# Copyright (c) 2023, NVIDIA CORPORATION.
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except
+# in compliance with the License. You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software distributed under the License
+# is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express
+# or implied. See the License for the specific language governing permissions and limitations under
+# the License.
+# =============================================================================
+
+# Use CPM to find or clone speedlog
+function(find_and_configure_spdlog)
+
+  include(${rapids-cmake-dir}/cpm/spdlog.cmake)
+  rapids_cpm_spdlog(FMT_OPTION "EXTERNAL_FMT_HO" INSTALL_EXPORT_SET cudf-exports)
+  rapids_export_package(BUILD spdlog cudf-exports)
+
+  if(spdlog_ADDED)
+    rapids_export(
+      BUILD spdlog
+      EXPORT_SET spdlog
+      GLOBAL_TARGETS spdlog spdlog_header_only
+      NAMESPACE spdlog::
+    )
+    include("${rapids-cmake-dir}/export/find_package_root.cmake")
+    rapids_export_find_package_root(BUILD spdlog [=[${CMAKE_CURRENT_LIST_DIR}]=] cudf-exports)
+  endif()
+endfunction()
+
+find_and_configure_spdlog()

cpp/doxygen/developer_guide/DEVELOPER_GUIDE.md

@@ -901,6 +901,46 @@ void trivial_types_only(T t){
 }
 ```
 
+# Logging
+
+libcudf includes logging utilities (built on top of [spdlog](https://github.com/gabime/spdlog)
+library), which should be used to log important events (e.g. user warnings). This utility can also
+be used to log debug information, as long as the correct logging level is used. There are six macros
+that should be used for logging at different levels:
+
+* `CUDF_LOG_TRACE` - verbose debug messages (targeted at developers)
+* `CUDF_LOG_DEBUG` - debug messages (targeted at developers)
+* `CUDF_LOG_INFO` - information about rare events (e.g. once per run) that occur during normal
+execution
+* `CUDF_LOG_WARN` - user warnings about potentially unexpected behavior or deprecations
+* `CUDF_LOG_ERROR` - recoverable errors
+* `CUDF_LOG_CRITICAL` - unrecoverable errors (e.g. memory corruption)
+
+By default, `TRACE`, `DEBUG` and `INFO` messages are excluded from the log. In addition, in public
+builds, the code that logs at `TRACE` and `DEBUG` levels is compiled out. This prevents logging of
+potentially sensitive data that might be done for debug purposes. Also, this allows developers to
+include expensive computation in the trace/debug logs, as the overhead will not be present in the
+public builds.
+The minimum enabled logging level is `WARN`, and it can be modified in multiple ways:
+
+* CMake configuration variable `LIBCUDF_LOGGING_LEVEL` - sets the minimum level of logging that
+will be compiled in the build.
+Available levels are `TRACE`, `DEBUG`, `INFO`, `WARN`, `ERROR`, `CRITICAL`, and `OFF`.
+* Environment variable `LIBCUDF_LOGGING_LEVEL` - sets the minimum logging level during
+initialization. If this setting is higher than the compile-time CMake variable, any logging levels
+in between the two settings will be excluded from the written log. The available levels are the same
+as for the CMake variable.
+* Global logger object exposed via `cudf::logger()` - sets the minimum logging level at runtime.
+For example, calling `cudf::logger().set_level(spdlog::level::err)`, will exclude any messages that
+are not errors or critical errors. This API should not be used within libcudf to manipulate logging,
+its purpose is to allow upstream users to configure libcudf logging to fit their application.
+
+By default, logging messages are output to stderr.
+Setting the environment variable `LIBCUDF_DEBUG_LOG_FILE` redirects the log to a file with the
+specified path (can be relative to the current directory).
+Upstream users can also manipulate `cudf::logger().sinks()` to add sinks or divert the log to
+standard output or even a custom spdlog sink.
+
 # Data Types
 
 Columns may contain data of a number of types (see `enum class type_id` in `include/cudf/types.hpp`)

cpp/include/cudf/detail/utilities/logger.hpp

@@ -0,0 +1,27 @@
+/*
+ * Copyright (c) 2023, NVIDIA CORPORATION.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#pragma once
+
+#include <cudf/utilities/logger.hpp>
+
+// Log messages that require computation should only be used at level TRACE and DEBUG
+#define CUDF_LOG_TRACE(...)    SPDLOG_LOGGER_TRACE(&cudf::logger(), __VA_ARGS__)
+#define CUDF_LOG_DEBUG(...)    SPDLOG_LOGGER_DEBUG(&cudf::logger(), __VA_ARGS__)
+#define CUDF_LOG_INFO(...)     SPDLOG_LOGGER_INFO(&cudf::logger(), __VA_ARGS__)
+#define CUDF_LOG_WARN(...)     SPDLOG_LOGGER_WARN(&cudf::logger(), __VA_ARGS__)
+#define CUDF_LOG_ERROR(...)    SPDLOG_LOGGER_ERROR(&cudf::logger(), __VA_ARGS__)
+#define CUDF_LOG_CRITICAL(...) SPDLOG_LOGGER_CRITICAL(&cudf::logger(), __VA_ARGS__)

cpp/include/cudf/utilities/logger.hpp

@@ -0,0 +1,46 @@
+/*
+ * Copyright (c) 2023, NVIDIA CORPORATION.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#pragma once
+
+#include <spdlog/spdlog.h>
+
+namespace cudf {
+
+/**
+ * @brief Returns the global logger.
+ *
+ * This is a global instance of a spdlog logger. It can be used to configure logging behavior in
+ * libcudf.
+ *
+ * Examples:
+ * @code{.cpp}
+ * // Turn off logging at runtime
+ * cudf::logger().set_level(spdlog::level::off);
+ * // Add a stdout sink to the logger
+ * cudf::logger().sinks().push_back(std::make_shared<spdlog::sinks::stdout_sink_mt>());
+ * // Replace the default sink
+ * cudf::logger().sinks() ={std::make_shared<spdlog::sinks::stderr_sink_mt>()};
+ * @endcode
+ *
+ * Note: Changes to the sinks are not thread safe and should only be done during global
+ * initialization.
+ *
+ * @return spdlog::logger& The logger.
+ */
+spdlog::logger& logger();
+
+}  // namespace cudf

cpp/src/io/utilities/config_utils.cpp

@@ -23,12 +23,6 @@
 
 namespace cudf::io::detail {
 
-std::string getenv_or(std::string const& env_var_name, std::string_view default_val)
-{
-  auto const env_val = std::getenv(env_var_name.c_str());
-  return std::string{(env_val == nullptr) ? default_val : env_val};
-}
-
 namespace cufile_integration {
 
 namespace {

cpp/src/io/utilities/config_utils.hpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2021-2022, NVIDIA CORPORATION.
+ * Copyright (c) 2021-2023, 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,6 +15,8 @@
  */
 #pragma once
 
+#include <cudf/detail/utilities/logger.hpp>
+
 #include <sstream>
 #include <string>
 
@@ -28,6 +30,13 @@ template <typename T>
 T getenv_or(std::string_view env_var_name, T default_val)
 {
   auto const env_val = std::getenv(env_var_name.data());
+  if (env_val != nullptr) {
+    CUDF_LOG_INFO("Environment variable {} read as {}", env_var_name, env_val);
+  } else {
+    CUDF_LOG_INFO(
+      "Environment variable {} is not set, using default value {}", env_var_name, default_val);
+  }
+
   if (env_val == nullptr) { return default_val; }
 
   std::stringstream sstream(env_val);

cpp/src/io/utilities/hostdevice_vector.hpp

@@ -30,6 +30,13 @@
 
 #include <variant>
 
+inline bool hostdevice_vector_uses_pageable_buffer()
+{
+  static bool const use_pageable =
+    cudf::io::detail::getenv_or("LIBCUDF_IO_PREFER_PAGEABLE_TMP_MEMORY", 0);
+  return use_pageable;
+}
+
 /**
  * @brief A helper class that wraps fixed-length device memory for the GPU, and
  * a mirror host pinned memory for the CPU.
@@ -56,9 +63,7 @@ class hostdevice_vector {
   {
     CUDF_EXPECTS(initial_size <= max_size, "initial_size cannot be larger than max_size");
 
-    auto const use_pageable_buffer =
-      cudf::io::detail::getenv_or("LIBCUDF_IO_PREFER_PAGEABLE_TMP_MEMORY", 0);
-    if (use_pageable_buffer) {
+    if (hostdevice_vector_uses_pageable_buffer()) {
       h_data_owner = thrust::host_vector<T>();
     } else {
       h_data_owner = thrust::host_vector<T, cudf::detail::pinned_allocator<T>>();