Merge pull request #20 from sandialabs/19-spdlog-support

#19: spdlog support

CMakeLists.txt

@@ -57,6 +57,8 @@ target_include_directories(bvh INTERFACE
         $<INSTALL_INTERFACE:include>
         )
 
+add_subdirectory(tpl)
+
 # Various default compiler options
 
 target_compile_options(bvh PUBLIC $<$<CONFIG:DEBUG>:-O0 -ggdb3 -fno-inline>)
@@ -107,6 +109,9 @@ endif()
 set_property(TARGET bvh PROPERTY CXX_STANDARD ${Kokkos_CXX_STANDARD})
 target_link_libraries(bvh PUBLIC Kokkos::kokkos)
 
+find_package(spdlog 1.13 REQUIRED)
+target_link_libraries(bvh PUBLIC spdlog::spdlog)
+
 option(BVH_ENABLE_TRACING "Enable detailed performance tracing (may have an impact on performance" OFF)
 if (BVH_ENABLE_TRACING)
   find_package(perf REQUIRED)

cmake/bvhConfig.cmake.in

@@ -7,15 +7,14 @@ if (@VTK_FOUND@)
   find_dependency(VTK REQUIRED HINTS @VTK_DIR@)
 endif()
 
-# VT optional dependency
-if (@vt_FOUND@)
-  find_dependency(vt REQUIRED HINTS @vt_DIR@)
-endif()
+# VT
+find_dependency(vt REQUIRED HINTS @vt_DIR@)
 
-# Kokkos optional dependency
-if (@Kokkos_FOUND@)
-    find_dependency(Kokkos REQUIRED NO_CMAKE_PACKAGE_REGISTRY HINTS @Kokkos_DIR@)
-endif()
+# Kokkos
+find_dependency(Kokkos REQUIRED NO_CMAKE_PACKAGE_REGISTRY HINTS @Kokkos_DIR@)
+
+# spdlog
+find_dependency(spdlog REQUIRED)
 
 if (@perf_FOUND@)
   find_dependency(perf REQUIRED HINTS @perf_DIR@)

src/bvh/collision_object.cpp

@@ -77,11 +77,16 @@ namespace bvh
   collision_object::collision_object( collision_world &_world, std::size_t _idx, std::size_t _overdecomposition )
     : m_impl{ std::make_unique< impl >( _world, _idx ) }
   {
-    bvh_splitting_geom_axis_ = ::vt::theTrace()->registerUserEventColl("bvh_splitting_geom_axis_");
-    bvh_splitting_ml_ = ::vt::theTrace()->registerUserEventColl("bvh_splitting_ml_");
-    bvh_set_entity_data_impl_ = ::vt::theTrace()->registerUserEventColl("bvh_set_entity_data_impl_");
-    bvh_clustering_ = ::vt::theTrace()->registerUserEventColl("bvh_clustering_");
-    bvh_build_trees_ = ::vt::theTrace()->registerUserEventColl("bvh_build_trees_");
+    bvh_splitting_geom_axis_ = ::vt::theTrace()->registerUserEventColl( "bvh_splitting_geom_axis_" );
+    m_impl->logger->trace( "obj={} registered user tracing event bvh_splitting_geom_axis_", m_impl->collision_idx );
+    bvh_splitting_ml_ = ::vt::theTrace()->registerUserEventColl( "bvh_splitting_ml_" );
+    m_impl->logger->trace( "obj={} registered user tracing event bvh_splitting_ml_", m_impl->collision_idx );
+    bvh_set_entity_data_impl_ = ::vt::theTrace()->registerUserEventColl( "bvh_set_entity_data_impl_" );
+    m_impl->logger->trace( "obj={} registered user tracing event bvh_set_entity_data_impl_", m_impl->collision_idx );
+    bvh_clustering_ = ::vt::theTrace()->registerUserEventColl( "bvh_clustering_" );
+    m_impl->logger->trace( "obj={} registered user tracing event bvh_clustering_", m_impl->collision_idx );
+    bvh_build_trees_ = ::vt::theTrace()->registerUserEventColl( "bvh_build_trees_" );
+    m_impl->logger->trace( "obj={} registered user tracing event bvh_build_trees_", m_impl->collision_idx );
 
     m_impl->overdecomposition = static_cast< int >( _overdecomposition );
 
@@ -90,15 +95,19 @@ namespace bvh
       m_impl->chainset.addIndex( vt_index{ i } );
     }
 
+    m_impl->logger->trace( "obj={} adding {} local indices", m_impl->collision_idx, m_impl->overdecomposition );
+
     // Initialize objgroup for per-node data
     ::vt::runInEpochCollective( "collision_object.make_objgroup", [&](){
-      m_impl->objgroup = ::vt::theObjGroup()->makeCollective<collision_object_holder>( fmt::vt::format( "collision_object {}", _idx ) );
+      m_impl->objgroup = ::vt::theObjGroup()->makeCollective<collision_object_holder>( fmt::format( "collision_object {}", _idx ) );
       m_impl->objgroup.get()->self = this;
 
-      vt::debug( "objgroup make_collective {:x}\n", m_impl->objgroup.getProxy() );
+      m_impl->logger->debug( "obj={} objgroup make_collective {:x}", m_impl->collision_idx, m_impl->objgroup.getProxy() );
     });
 
     m_impl->local_patches.resize( m_impl->overdecomposition );
+
+    m_impl->logger->info( "initialized collision object {}", m_impl->collision_idx );
   }
 
   collision_object::collision_object( collision_object && ) noexcept = default;
@@ -119,7 +128,10 @@ namespace bvh
     m_impl->local_patches.clear();
     m_impl->local_patches.resize( od_factor );
 
-    always_assert( m_impl->num_splits + 1 == od_factor, "error during splitting process, splits {} do not match od factor {}\n", m_impl->num_splits + 1, od_factor );
+    BVH_ASSERT_ALWAYS( m_impl->num_splits + 1 == od_factor,
+                       logger(),
+                       "error during splitting process, splits {} do not match od factor {}\n", m_impl->num_splits + 1,
+                       od_factor );
 
     // Preallocate local data buffers. Do this lazily
     m_impl->narrowphase_patch_messages.resize( od_factor, nullptr );
@@ -135,12 +147,14 @@ namespace bvh
       const auto sbeg = ( i == 0 ) ? 0 : m_impl->splits_h( i - 1 );
       const auto send = ( i == m_impl->num_splits ) ? m_impl->split_indices_h.extent( 0 ) : m_impl->splits_h( i );
       const std::size_t nelements = send - sbeg;
-      ::bvh::vt::debug( "{}: creating broadphase patch for body {} size {} from offset {}\n", ::vt::theContext()->getNode(), m_impl->collision_idx, nelements, sbeg );
+      logger().debug( "creating broadphase patch for body {} size {} from offset {}", m_impl->collision_idx, nelements, sbeg );
       m_impl->local_patches[i] = broadphase_patch_type(
         i + rank * od_factor, span< const entity_snapshot >( m_impl->snapshots.data() + sbeg, nelements ) );
     }
 
-    always_assert( m_impl->local_patches.size() == od_factor, "wrong number of patches\n" );
+    BVH_ASSERT_ALWAYS( m_impl->local_patches.size() == od_factor,
+                       logger(),
+                       "wrong number of patches\n" );
   }
 
   void collision_object::init_broadphase() const
@@ -157,8 +171,13 @@ namespace bvh
     auto coll_size = vt_index{ static_cast< std::size_t >( od_factor * ::vt::theContext()->getNumNodes() ) };
     if ( m_impl->broadphase_patch_collection_proxy.getProxy() == ::vt::no_vrt_proxy )
     {
+      logger().info( "lazily constructing broadphase patch collection with {} elements", coll_size );
       m_impl->broadphase_patch_collection_proxy = ::vt::makeCollection< broadphase_patch_collection_type >().bounds( coll_size ).bulkInsert().wait();
-      m_impl->narrowphase_patch_collection_proxy = ::vt::makeCollection< narrowphase_patch_collection_type >().bounds( coll_size ).bulkInsert().wait();
+      logger().info( "lazily constructing narrophase patch collection with {} elements", coll_size );
+      m_impl->narrowphase_patch_collection_proxy = ::vt::makeCollection< narrowphase_patch_collection_type >()
+        .elementConstructor( [this]( narrowphase_patch_collection_type::IndexType ){ return std::make_unique< narrowphase_patch_collection_type >( m_impl->objgroup ); } )
+        .bounds( coll_size ).bulkInsert().wait();
+      logger().info( "lazily constructing narrowphase collection with dynamic membership" );
       m_impl->narrowphase_collection_proxy = ::vt::makeCollection< narrowphase_collection_type >().dynamicMembership( true ).wait();
     }
 
@@ -178,8 +197,11 @@ namespace bvh
         msg->patch = local_patch;
         msg->origin_node = rank;
         msg->local_idx = _local;
-        ::bvh::vt::debug( "{}: sending broadphase patch {} for body {} size {}\n", ::vt::theContext()->getNode(),
-                          vt_index{ _local.x() + offset }, m_impl->collision_idx, msg->patch.size() );
+        logger().debug( "<send={}> obj={} initialize broadphase patch {} size {}",
+                        vt_index{ _local.x() + offset },
+                         m_impl->collision_idx,
+                        _local.x() + offset,
+                        msg->patch.size() );
         return m_impl->broadphase_patch_collection_proxy[vt_index{ _local.x() + offset }]
           .sendMsg< broadphase_patch_msg, &details::set_broadphase_patches >( msg.get() );
       } else {
@@ -194,8 +216,10 @@ namespace bvh
       ::vt::trace::TraceScopedEvent scope(bvh_build_trees_);
       // Tree build needs to be done collectively, everyone needs to finish before the next step
       m_impl->chainset.nextStepCollective( "build_tree_step", [this, offset]( vt_index _idx ) {
-        ::bvh::vt::debug( "{}: building tree reduction for patch {} for body {}\n", ::vt::theContext()->getNode(),
-                          vt_index{ _idx.x() + offset }, m_impl->collision_idx );
+        logger().debug( "<send={}> obj={} building tree reduction for patch {}",
+                          vt_index{ _idx.x() + offset },
+                          m_impl->collision_idx,
+                          _idx.x() + offset );
         return collision_object_impl::build_trees_top_down( vt_index{ _idx.x() + offset },
             m_impl->objgroup, m_impl->broadphase_patch_collection_proxy );
       } );
@@ -243,9 +267,11 @@ namespace bvh
     m_impl->chainset.nextStepCollective( "start broadphase insertion", [this, &_other]( vt_index _local_idx) {
       if ( _local_idx.x() == 0 )
       {
-        ::bvh::vt::debug( "{}: starting broadphase between body {} and {}\n",
-                          ::vt::theContext()->getNode(), m_impl->collision_idx, _other.m_impl->collision_idx );
+        broadphase_logger().info( "starting broadphase between body {} and {}",
+                                  m_impl->collision_idx, _other.m_impl->collision_idx );
         auto msg = ::vt::makeMessage< collision_object_impl::messages::modify_msg >();
+        broadphase_logger().trace( "<send=objgroup({})> obj={} begin_narrowphase_modification",
+                                   ::vt::theContext()->getNode(), id() );
         return m_impl->objgroup[::vt::theContext()->getNode()].sendMsg< collision_object_impl::messages::modify_msg, &collision_object_impl::collision_object_holder::begin_narrowphase_modification >( msg );
       } else
         return pending_send{ nullptr };
@@ -254,14 +280,19 @@ namespace bvh
     using chainset_type = ::vt::messaging::CollectionChainSet< vt_index >;
     chainset_type::mergeStepCollective( "broadphase_step",m_impl->chainset, _other.m_impl->chainset,
                                        [this, rank, offset, &_other]( vt_index _idx ) {
-                                         return collision_object_impl::broadphase(
-                                           vt_index{ _idx.x() + offset }, vt_index{ _idx.x() }, rank,
-                                           m_impl->broadphase_patch_collection_proxy, m_impl->objgroup,
-                                           _other.m_impl->objgroup );
+      broadphase_logger().trace( "<send={}> obj={} target_obj={} start broadphase",
+                                 vt_index{ _idx.x() + offset }, id(), _other.id() );
+      return collision_object_impl::broadphase(
+        vt_index{ _idx.x() + offset }, vt_index{ _idx.x() }, rank,
+        m_impl->broadphase_patch_collection_proxy, m_impl->objgroup,
+        _other.m_impl->objgroup );
     } );
 
     m_impl->chainset.nextStepCollective( "finalize broadphase insertion", [this]( vt_index _local_idx) {
-      if ( _local_idx.x() == 0 ) {
+      if ( _local_idx.x() == 0 )
+      {
+        broadphase_logger().trace( "<send=objgroup({})> obj={} finish_narrowphase_modification",
+                                   ::vt::theContext()->getNode(), id() );
         auto msg = ::vt::makeMessage< collision_object_impl::messages::modify_msg >();
         return m_impl->objgroup[::vt::theContext()->getNode()].sendMsg< collision_object_impl::messages::modify_msg, &collision_object_impl::collision_object_holder::finish_narrowphase_modification >( msg );
       } else
@@ -448,4 +479,22 @@ namespace bvh
     Kokkos::deep_copy( m_impl->split_indices_h, indices_view );
   }
 
+  spdlog::logger &
+  collision_object::logger() const noexcept
+  {
+    return *m_impl->logger;
+  }
+
+  spdlog::logger &
+  collision_object::broadphase_logger() const noexcept
+  {
+    return *m_impl->broadphase_logger;
+  }
+
+  spdlog::logger &
+  collision_object::narrowphase_logger() const noexcept
+  {
+    return *m_impl->narrowphase_logger;
+  }
+
 } // namespace bvh

src/bvh/collision_object.hpp

@@ -38,6 +38,7 @@
 #include <functional>
 #include <optional>
 #include <vt/context/context.h>
+#include <spdlog/spdlog.h>
 
 #include "snapshot.hpp"
 #include "split/split.hpp"
@@ -98,7 +99,7 @@ namespace bvh
         const auto od_factor = this->overdecomposition_factor();
         const auto num_splits = od_factor - 1;
 
-        ::bvh::vt::debug( "{}: clustering {} elements\n", ::vt::theContext()->getNode(), n  );
+        logger().debug( "obj={} clustering {} elements\n", id(), n  );
         if ( n != m_clusterer.size() )
         {
           m_clusterer.resize( n );
@@ -189,6 +190,10 @@ namespace bvh
 
     span< const patch<> > local_patches() const noexcept;
 
+    spdlog::logger &logger() const noexcept;
+    spdlog::logger &broadphase_logger() const noexcept;
+    spdlog::logger &narrowphase_logger() const noexcept;
+
   private:
 
     friend class collision_world;

src/bvh/collision_object/broadphase.cpp

@@ -86,22 +86,34 @@ namespace bvh
         //
         tmp_idx[1] = static_cast<int>( tree_obj->get_impl().collision_idx );
         //
-        query_tree( tree, patch, [&_msg, local_idx, origin_node, &patch_obj, &tree_obj, &tok]( std::size_t _p, std::size_t _q ){
+
+        auto &logger = patch_obj->broadphase_logger();
+        logger.debug( "(objp={}, size={}) (objq={}, count={}) starting broadphase", patch_obj->id(), patch.size(), tree_obj->id(), tree.count() );
+
+        query_tree( tree, patch, [&_msg, &logger, local_idx, origin_node, &patch_obj, &tree_obj, &tok]( std::size_t _p, std::size_t _q ){
           collision_object_impl::narrowphase_index idx( static_cast< int >( _p ),
                                                         static_cast<int>( tree_obj->get_impl().collision_idx ),
                                                         static_cast< int >( _q ) );
+          logger.trace( "found broadphase contact <{}, {}, {}, {}>",
+                        patch_obj->id(), _p, tree_obj->id(), _q );
+          logger.trace( "obj={} inserting {} into narrowphase collection", patch_obj->id(), idx );
           patch_obj->get_impl().narrowphase_collection_proxy[idx].insert( tok );
+          logger.trace( "obj={} adding {} to active narrowphase indices", patch_obj->id(), idx );
           patch_obj->get_impl().active_narrowphase_indices.emplace_back( idx );
           //
           auto activate_narrowphase_index_msg = ::vt::makeMessage< active_narrowphase_local_index_msg  >();
           activate_narrowphase_index_msg->idx = local_idx;
+          logger.trace( "<send=objgroup({})> obj={} insert_active_narrow_local_index local_idx={}",
+                        origin_node, patch_obj->id(), local_idx );
           patch_obj->get_impl().objgroup[origin_node].sendMsg< active_narrowphase_local_index_msg, &collision_object_impl::collision_object_holder::insert_active_narrow_local_index >( activate_narrowphase_index_msg );
           //
           // Note that the global index `_q` may not be managed by VT on this rank
           // So we need to send a message to the rank that VT is using to manage `_q`.
           //
           auto tree_msg = ::vt::makeMessage< flag_active_narrowpatch_msg  >();
           tree_msg->patch_obj = _msg->tree_obj;
+          logger.trace( "<send={}> obj={} flag_active_narrowpatch",
+                        _q, patch_obj->id() );
           tree_obj->get_impl().broadphase_patch_collection_proxy[_q].sendMsg< flag_active_narrowpatch_msg, &flag_active_narrowpatch >( tree_msg );
         } );
       }