feat: Add multilevel host/device logging to propagation (#1071)

Fixes the logging and adds logging output to the propagation (stepper, navigator and actors). The detector building logging is cleaned up a bit and new logging features are introduced:

- Different log levels: NONE, WARN, INFO, VERBOSE and DEBUG, which can be set in the cmake configuration via the DETRAY_SET_LOGGING flag
- Logging is done via clog and stderr, so that it can easily be piped into a file (except device logging, which has to go to stdout)
- Introduced logging for device: HOST logging uses streaming operators to print detailed object information, HOST_DEVICE logging appears in both compilations and uses printf and DEVICE logging only appears in device code and prints the respective backend (CUDA, HIP, SYCL) that issued the message. Any of the HOST, HOST_DEVICE or DEVICE logging macros can be used anywhere in the code, but will only print messages when appropriate.

The default level is INFO, with VERBOSE adding some messages from inside the propagation loop. DEBUG output is for expert level of information.

The DEBUG logging is turned on in the build-only parts of the CI to make sure it continues to compile.

Author: niermann999

.github/workflows/builds.yml

@@ -40,6 +40,7 @@ jobs:
       run: cmake --preset full-fp64
                  -DCMAKE_BUILD_TYPE=${{ matrix.BUILD_TYPE }}
                  -DDETRAY_FAIL_ON_WARNINGS=ON
+                 -DDETRAY_SET_LOGGING=DEBUG
                  -S ${{ github.workspace }} -B build
                  -G "${{ matrix.PLATFORM.GENERATOR }}"
     # Perform the build.
@@ -125,19 +126,19 @@ jobs:
           - NAME: "CUDA"
             CXX_STANDARD: "20"
             CONTAINER: "ghcr.io/acts-project/ubuntu2404_cuda:67"
-            OPTIONS: -DDETRAY_BUILD_CUDA=ON -DDETRAY_EIGEN_PLUGIN=ON -DDETRAY_SMATRIX_PLUGIN=OFF -DDETRAY_VC_AOS_PLUGIN=OFF -DDETRAY_VC_SOA_PLUGIN=OFF
+            OPTIONS: -DDETRAY_BUILD_CUDA=ON -DDETRAY_SET_LOGGING=DEBUG -DDETRAY_EIGEN_PLUGIN=ON -DDETRAY_SMATRIX_PLUGIN=OFF -DDETRAY_VC_AOS_PLUGIN=OFF -DDETRAY_VC_SOA_PLUGIN=OFF
           - NAME: "HIP-AMD"
             CXX_STANDARD: "20"
             CONTAINER: "ghcr.io/acts-project/ubuntu2404_rocm_oneapi:69"
-            OPTIONS: -DCMAKE_PREFIX_PATH=/opt/rocm/lib/cmake/ -DCMAKE_HIP_PLATFORM=amd -DDETRAY_BUILD_HIP=ON -DDETRAY_EIGEN_PLUGIN=ON -DDETRAY_SMATRIX_PLUGIN=OFF -DDETRAY_VC_AOS_PLUGIN=OFF -DDETRAY_VC_SOA_PLUGIN=OFF
+            OPTIONS: -DCMAKE_PREFIX_PATH=/opt/rocm/lib/cmake/ -DCMAKE_HIP_PLATFORM=amd -DDETRAY_BUILD_HIP=ON -DDETRAY_SET_LOGGING=DEBUG -DDETRAY_EIGEN_PLUGIN=ON -DDETRAY_SMATRIX_PLUGIN=OFF -DDETRAY_VC_AOS_PLUGIN=OFF -DDETRAY_VC_SOA_PLUGIN=OFF
           #- NAME: "HIP-NVIDIA"
           #  CXX_STANDARD: "20"
           #  CONTAINER:
           #  OPTIONS: -DCMAKE_HIP_PLATFORM=nvidia -DDETRAY_BUILD_HIP=ON -DDETRAY_EIGEN_PLUGIN=ON -DDETRAY_SMATRIX_PLUGIN=OFF -DDETRAY_VC_AOS_PLUGIN=OFF -DDETRAY_VC_SOA_PLUGIN=OFF
           - NAME: "SYCL"
             CXX_STANDARD: "20"
             CONTAINER: "ghcr.io/acts-project/ubuntu2404_oneapi:56"
-            OPTIONS: -DDETRAY_BUILD_CUDA=OFF -DDETRAY_BUILD_SYCL=ON -DDETRAY_EIGEN_PLUGIN=ON -DDETRAY_SMATRIX_PLUGIN=OFF -DDETRAY_VC_AOS_PLUGIN=OFF -DDETRAY_VC_SOA_PLUGIN=OFF
+            OPTIONS: -DDETRAY_BUILD_CUDA=OFF -DDETRAY_BUILD_SYCL=ON -DDETRAY_SET_LOGGING=DEBUG -DDETRAY_EIGEN_PLUGIN=ON -DDETRAY_SMATRIX_PLUGIN=OFF -DDETRAY_VC_AOS_PLUGIN=OFF -DDETRAY_VC_SOA_PLUGIN=OFF
 
     # The system to run on.
     runs-on: ubuntu-latest

CMakeLists.txt

@@ -89,6 +89,11 @@ cmake_dependent_option(
     "DETRAY_BUILD_CUDA OR DETRAY_BUILD_SYCL OR DETRAY_BUILD_HIP"
     ON
 )
+set(DETRAY_SET_LOGGING "INFO" CACHE STRING "Set the log level")
+set_property(
+    CACHE DETRAY_SET_LOGGING
+    PROPERTY STRINGS "NONE" "WARNING" "INFO" "VERBOSE" "DEBUG"
+)
 option(DETRAY_BUILD_TEST_UTILS "Build the test utility library of Detray" OFF)
 option(DETRAY_BUILD_VALIDATION_TOOLS "Build the validation tools of Detray" OFF)
 option(DETRAY_BUILD_UNITTESTS "Build the unit tests of Detray" OFF)
@@ -301,11 +306,18 @@ if(DETRAY_SETUP_COVFIE)
         add_subdirectory(extern/covfie)
     endif()
 endif()
-option(
-    DETRAY_ENABLE_LOGGING
-    "Enable logging output to stdout. Useful for debugging"
-    OFF
-)
+
+# Resolve the internal log level from user input
+set(DETRAY_LOG_LVL -1 CACHE INTERNAL "Disable logging")
+if(DETRAY_SET_LOGGING STREQUAL "WARN")
+    set(DETRAY_LOG_LVL 0 CACHE INTERNAL "Print warnings and errors" FORCE)
+elseif(DETRAY_SET_LOGGING STREQUAL "INFO")
+    set(DETRAY_LOG_LVL 1 CACHE INTERNAL "Print general information" FORCE)
+elseif(DETRAY_SET_LOGGING STREQUAL "VERBOSE")
+    set(DETRAY_LOG_LVL 2 CACHE INTERNAL "Print detailed information" FORCE)
+elseif(DETRAY_SET_LOGGING STREQUAL "DEBUG")
+    set(DETRAY_LOG_LVL 3 CACHE INTERNAL "Print expert information" FORCE)
+endif()
 
 # Set up all of the libraries of the project.
 add_subdirectory(core)

README.md

@@ -59,6 +59,7 @@ The following cmake options are available and can also be specified explicitly f
 
 | Option | Description | Default |
 | --- | --- | --- |
+| DETRAY_SET_LOGGING  | Set log level (NONE, WARN, INFO, VERBOSE, DEBUG) | INFO |
 | DETRAY_BUILD_CUDA  | Build the CUDA sources included in detray | ON (if available) |
 | DETRAY_BUILD_SYCL  | Build the SYCL sources included in detray | OFF |
 | DETRAY_BUILD_TEST_UTILS  | Build the detray test utilities library (contains e.g. test detectors) | OFF |

core/CMakeLists.txt

@@ -41,10 +41,11 @@ detray_add_library( detray_core core
 )
 target_link_libraries(detray_core INTERFACE vecmem::core)
 
-if(DETRAY_ENABLE_LOGGING)
-    message(STATUS "Enabling debug logging output")
-    target_compile_definitions(detray_core INTERFACE DETRAY_ENABLE_LOGGING)
-endif()
+message(STATUS "Setting detray log level: ${DETRAY_SET_LOGGING}")
+target_compile_definitions(
+    detray_core
+    INTERFACE DETRAY_LOG_LVL=${DETRAY_LOG_LVL}
+)
 
 # Generate a version header for the project.
 configure_file(

core/include/detray/builders/cuboid_portal_generator.hpp

@@ -16,6 +16,7 @@
 #include "detray/definitions/math.hpp"
 #include "detray/geometry/shapes/cuboid3D.hpp"
 #include "detray/utils/bounding_volume.hpp"
+#include "detray/utils/log.hpp"
 #include "detray/utils/ranges.hpp"
 
 // System include(s)
@@ -91,6 +92,8 @@ class cuboid_portal_generator final
                     typename detector_t::geometry_context ctx = {})
         -> dindex_range override {
 
+        DETRAY_VERBOSE_HOST("Generate cuboid portals...");
+
         using point3_t = dpoint3D<algebra_type>;
         using vector3_t = dvector3D<algebra_type>;
 

core/include/detray/builders/cylinder_portal_generator.hpp

@@ -17,6 +17,7 @@
 #include "detray/definitions/indexing.hpp"
 #include "detray/geometry/shapes/cuboid3D.hpp"
 #include "detray/utils/bounding_volume.hpp"
+#include "detray/utils/log.hpp"
 
 // System include(s)
 #include <cassert>
@@ -193,6 +194,8 @@ class cylinder_portal_generator final
                     typename detector_t::geometry_context ctx = {})
         -> dindex_range override {
 
+        DETRAY_VERBOSE_HOST("Generate cylinder portals...");
+
         using aabb_t = axis_aligned_bounding_volume<cuboid3D, algebra_t>;
 
         // Only build portals for cylinder volumes

core/include/detray/builders/detector_builder.hpp

@@ -14,10 +14,10 @@
 #include "detray/core/detector.hpp"
 #include "detray/definitions/geometry.hpp"
 #include "detray/utils/grid/detail/concepts.hpp"
+#include "detray/utils/log.hpp"
 #include "detray/utils/type_traits.hpp"
 
 // Vecmem include(s)
-#include <detray/utils/log.hpp>
 #include <vecmem/memory/memory_resource.hpp>
 
 // System include(s)
@@ -44,9 +44,14 @@ class detector_builder {
     using algebra_type = typename detector_type::algebra_type;
     using scalar_type = dscalar<algebra_type>;
 
+    DETRAY_HOST detector_builder() {
+        DETRAY_VERBOSE_HOST("New builder created");
+    }
+
     /// Set the name of the detector under construction to @param det_name
     DETRAY_HOST void set_name(std::string det_name) {
         m_detector_name = std::move(det_name);
+        DETRAY_VERBOSE_HOST("Set detector name: " << m_detector_name);
     }
 
     /// @returns the name of the detector under construction
@@ -58,6 +63,8 @@ class detector_builder {
     DETRAY_HOST auto new_volume(const volume_id id, Args&&... args)
         -> volume_builder_interface<detector_type>* {
 
+        DETRAY_VERBOSE_HOST("Adding new volume: " << m_volumes.size());
+
         m_volumes.push_back(std::make_unique<volume_builder_t<detector_type>>(
             id, static_cast<dindex>(m_volumes.size()),
             std::forward<Args>(args)...));
@@ -110,23 +117,25 @@ class detector_builder {
     DETRAY_HOST
     auto build(vecmem::memory_resource& resource) -> detector_type {
 
-        DETRAY_DEBUG("detray: building detector " << name());
+        DETRAY_INFO_HOST("Building detector: " << name() << "... ");
 
         detector_type det{resource};
 
-        DETRAY_DEBUG("Have " << m_volumes.size()
-                             << " configured volume builders");
+        DETRAY_INFO_HOST("Have " << m_volumes.size()
+                                 << " configured volume builders");
+        DETRAY_VERBOSE_HOST("Start building the volumes...");
         for (auto& vol_builder : m_volumes) {
 
-            DETRAY_DEBUG("- builder: " << vol_builder->name());
+            DETRAY_VERBOSE_HOST("-> Build: " << vol_builder->name());
             vol_builder->build(det);
         }
 
         det.set_volume_finder(std::move(m_vol_finder));
 
         // TODO: Add sorting, data deduplication etc. here later...
 
-        DETRAY_DEBUG("detray: detector building complete");
+        DETRAY_INFO_HOST("Detector building complete: " << name());
+
         return det;
     }
 
@@ -136,7 +145,7 @@ class detector_builder {
     auto build(vecmem::memory_resource& resource,
                typename detector_type::name_map& name_map) -> detector_type {
 
-        DETRAY_DEBUG("detray: filling names for detector " << name());
+        DETRAY_VERBOSE_HOST("detray: filling names for detector " << name());
 
         assert(name_map.empty());
 
@@ -154,7 +163,7 @@ class detector_builder {
     /// Put the volumes into a search data structure
     template <typename... Args>
     DETRAY_HOST void set_volume_finder([[maybe_unused]] Args&&... args) {
-        DETRAY_DEBUG("Setting volume finder for detector " << name());
+        DETRAY_VERBOSE_HOST("Setting volume finder for detector " << name());
 
         using vol_finder_t = typename detector_type::volume_finder;
 

core/include/detray/builders/grid_builder.hpp

@@ -46,7 +46,9 @@ class grid_builder : public volume_decorator<detector_t> {
     explicit grid_builder(
         std::unique_ptr<volume_builder_interface<detector_t>> vol_builder)
         : volume_decorator<detector_t>(std::move(vol_builder)) {
-        DETRAY_DEBUG("Grid builder created");
+
+        DETRAY_VERBOSE_HOST("Add grid builder to volume: " << this->name());
+
         // The grid builder provides an acceleration structure to the
         // volume, so don't add sensitive surfaces to the brute force method
         if (this->get_builder()) {
@@ -55,8 +57,12 @@ class grid_builder : public volume_decorator<detector_t> {
     }
 
     /// Should the passive surfaces be added to the grid ?
-    void set_add_passives(bool is_add_passive = true) {
+    void set_add_passives(bool is_add_passive = false) {
         m_add_passives = is_add_passive;
+
+        DETRAY_VERBOSE_HOST("Add passive surfaces to grid: "
+                            << std::boolalpha << m_add_passives
+                            << std::noboolalpha);
     }
 
     /// Set the surface category this grid should contain (type id in the
@@ -86,6 +92,8 @@ class grid_builder : public volume_decorator<detector_t> {
         const darray<std::vector<scalar_type>, grid_t::dim> &ax_bin_edges =
             darray<std::vector<scalar_type>, grid_t::dim>()) {
 
+        DETRAY_VERBOSE_HOST("Intialize surface grid...");
+
         static_assert(
             std::is_same_v<typename grid_shape_t::template local_frame_type<
                                typename detector_t::algebra_type>,
@@ -94,6 +102,10 @@ class grid_builder : public volume_decorator<detector_t> {
 
         m_grid = m_factory.template new_grid<grid_t>(m, n_bins, bin_capacities,
                                                      ax_bin_edges);
+
+        DETRAY_VERBOSE_HOST("Created empty grid:\n"
+                            << DETRAY_TYPENAME(grid_t) << "\n"
+                            << m_grid.axes());
     }
 
     /// Build the empty grid from axis parameters
@@ -105,8 +117,14 @@ class grid_builder : public volume_decorator<detector_t> {
         const std::vector<std::vector<scalar_type>> &ax_bin_edges =
             std::vector<std::vector<scalar_type>>()) {
 
+        DETRAY_VERBOSE_HOST("Intialize surface grid...");
+
         m_grid = m_factory.template new_grid<grid_t>(
             spans, n_bins, bin_capacities, ax_bin_edges);
+
+        DETRAY_VERBOSE_HOST("Created empty grid:\n"
+                            << DETRAY_TYPENAME(grid_t) << "\n"
+                            << m_grid.axes());
     }
 
     /// Fill grid from existing volume using a bin filling strategy
@@ -140,7 +158,7 @@ class grid_builder : public volume_decorator<detector_t> {
                typename detector_t::geometry_context ctx = {}) ->
         typename detector_t::volume_type * override {
 
-        DETRAY_DEBUG("grid_builder::build called");
+        DETRAY_VERBOSE_HOST("Build surface grid...");
 
         using surface_desc_t = typename detector_t::surface_type;
 
@@ -153,7 +171,7 @@ class grid_builder : public volume_decorator<detector_t> {
 
         // Grid has not been filled previously, fill it automatically
         if (m_grid.size() == 0u) {
-            DETRAY_DEBUG("-> Filling grid automatically");
+            DETRAY_DEBUG_HOST("-> Filling grid automatically...");
 
             std::vector<surface_desc_t> surfaces{};
             for (auto &sf_desc : vol.surfaces()) {
@@ -169,7 +187,7 @@ class grid_builder : public volume_decorator<detector_t> {
                                 volume_decorator<detector_t>::operator()()},
                 surfaces, det.transform_store(), det.mask_store(), ctx);
         } else {
-            DETRAY_DEBUG("-> Grid is prefilled");
+            DETRAY_DEBUG_HOST("-> Grid is prefilled...");
 
             // The grid is prefilled with surface descriptors that contain the
             // correct LOCAL surface indices per bin (e.g. from file IO).
@@ -185,22 +203,23 @@ class grid_builder : public volume_decorator<detector_t> {
                 assert(new_sf_desc.index() == glob_idx);
                 assert(!new_sf_desc.barcode().is_invalid());
 
-                DETRAY_DEBUG("--> resetting sf_desc \n  old: "
-                             << sf_desc << "\n->\n  new: " << new_sf_desc
-                             << "");
                 sf_desc = new_sf_desc;
             }
         }
 
         // Add the grid to the detector and link it to its volume
         constexpr auto gid{detector_t::accel::template get_id<grid_t>()};
-        DETRAY_DEBUG("Adding grid to volume in detector. m_id="
-                     << m_id << ", gid=" << gid);
+        DETRAY_DEBUG_HOST("Grid indices: m_id=" << m_id << ", gid=" << gid);
+
         det._accelerators.template push_back<gid>(m_grid);
         vol_ptr->set_link(m_id, gid,
                           det.accelerator_store().template size<gid>() - 1);
 
-        DETRAY_DEBUG("Accelerator link: " << vol_ptr->accel_link());
+        DETRAY_DEBUG_HOST("Accelerator link: " << vol_ptr->accel_link());
+        DETRAY_DEBUG_HOST("Finished grid building: " << m_grid);
+
+        DETRAY_VERBOSE_HOST("Successfully built "
+                            << gid << " for volume: " << this->name());
 
         return vol_ptr;
     }