#2389: trace: start tracing invoke calls

src/vt/context/runnable_context/trace.cc

@@ -54,11 +54,46 @@
 
 namespace vt { namespace ctx {
 
+Trace::Trace(
+  trace::TraceEventIDType event, HandlerType const in_handler,
+  NodeType const in_from_node, std::size_t msg_size
+) : is_collection_(false),
+    event_(event),
+    msg_size_(msg_size),
+    is_traced_(HandlerManager::isHandlerTrace(in_handler)),
+    from_node_(in_from_node),
+    handler_(in_handler)
+{ }
+
+Trace::Trace(
+  trace::TraceEventIDType event, HandlerType const in_handler,
+  NodeType const in_from_node, std::size_t msg_size,
+  uint64_t in_idx1, uint64_t in_idx2, uint64_t in_idx3, uint64_t in_idx4
+) : is_collection_(false),
+    event_(event),
+    msg_size_(msg_size),
+    is_traced_(HandlerManager::isHandlerTrace(in_handler)),
+    from_node_(in_from_node),
+    handler_(in_handler),
+    idx1_(in_idx1),
+    idx2_(in_idx2),
+    idx3_(in_idx3),
+    idx4_(in_idx4)
+{ }
+
 void Trace::start(TimeType time) {
   if (not is_traced_) {
     return;
   }
 
+  // If our scheduler depth is zero, we need to end the between scheduler event
+  if (theSched()->getSchedulerDepth() == 0 and not theTrace()->inInvokeContext()) {
+    at_sched_depth_zero_ = true;
+    theTrace()->setInInvokeContext(true);
+    auto const end_between_sched_time = theTrace()->beginSchedulerLoop();
+    time = std::max(time, end_between_sched_time);
+  }
+
   auto const trace_id = auto_registry::handlerTraceID(handler_);
 
   if (is_collection_) {
@@ -82,6 +117,11 @@ void Trace::finish(TimeType time) {
   }
 
   theTrace()->endProcessing(processing_tag_, time);
+
+  if (at_sched_depth_zero_) {
+    theTrace()->endSchedulerLoop();
+    theTrace()->setInInvokeContext(false);
+  }
 }
 
 void Trace::suspend(TimeType time) {

src/vt/context/runnable_context/trace.h

@@ -61,6 +61,40 @@ struct Trace {
 
   Trace() = default;
 
+  /**
+   * \brief Construct a new trace context (basic processing) without a message
+   * directly
+   *
+   * \param[in] event the trace event
+   * \param[in] in_handler the handler
+   * \param[in] in_from_node from node
+   * \param[in] msg_size size of message/payload (zero of not serializable
+   */
+  Trace(
+    trace::TraceEventIDType event, HandlerType const in_handler,
+    NodeType const in_from_node, std::size_t msg_size
+  );
+
+  /**
+   * \brief Construct a new trace context (collection processing) without a
+   * message directly
+   *
+   * \param[in] event the trace event
+   * \param[in] in_handler the handler
+   * \param[in] in_from_node from node
+   * \param[in] msg_size size of message/payload (zero of not serializable
+   * \param[in] in_idx1 1-dimension index
+   * \param[in] in_idx2 2-dimension index
+   * \param[in] in_idx3 3-dimension index
+   * \param[in] in_idx4 4-dimension index
+   */
+  Trace(
+    trace::TraceEventIDType event, HandlerType const in_handler,
+    NodeType const in_from_node, std::size_t msg_size,
+    uint64_t in_idx1, uint64_t in_idx2, uint64_t in_idx3, uint64_t in_idx4
+  );
+
+
   /**
    * \brief Construct a new trace context (basic processing event)
    *
@@ -123,6 +157,8 @@ struct Trace {
   uint64_t idx1_ = 0, idx2_ = 0, idx3_ = 0, idx4_ = 0;
   /// The open processing tag
   trace::TraceProcessingTag processing_tag_;
+  /// At scheduler depth zero
+  bool at_sched_depth_zero_ = false;
 };
 
 #else

src/vt/objgroup/manager.impl.h

@@ -220,11 +220,26 @@ ObjGroupManager::invoke(ProxyElmType<ObjT> proxy, Args&&... args) {
     dest_node == this_node,
     fmt::format(
       "Attempting to invoke handler on node:{} instead of node:{}!\n",
-      this_node, dest_node));
+      this_node, dest_node
+    )
+  );
+
+#if vt_check_enabled(trace_enabled)
+  auto const ctrl = proxy::ObjGroupProxy::getID(proxy.getProxy());
+  auto const han = auto_registry::makeAutoHandlerObjGroupParam<
+    ObjT, decltype(f), f, void
+  >(ctrl);
+  auto const trace_event = theMsg()->makeTraceCreationSend(han, 0, false);
+
+  return runnable::makeRunnableVoidTraced(false, han, this_node, trace_event, 0)
+    .withObjGroup(get(proxy))
+    .runLambda(f, get(proxy), std::forward<Args>(args)...);
 
+#else
   return runnable::makeRunnableVoid(false, uninitialized_handler, this_node)
     .withObjGroup(get(proxy))
     .runLambda(f, get(proxy), std::forward<Args>(args)...);
+#endif
 }
 
 

src/vt/registry/auto/auto_registry_common.h

@@ -130,6 +130,8 @@ struct HandlersDispatcher final : BaseHandlersDispatcher {
       }
     } else if constexpr (std::is_same_v<ObjT, SentinelObject>) {
       std::apply(fp, msg->getTuple());
+    } else if constexpr (std::is_same_v<MsgT, void>) {
+      // do nothing
     } else {
       if constexpr (IsColTrait<ObjT>::value and IsWrapMsgTrait<MsgT>::value) {
         auto& m = msg->getMsg();

src/vt/runnable/make_runnable.h

@@ -351,7 +351,8 @@ RunnableMaker<U> makeRunnable(
 }
 
 /**
- * \brief Make a new runnable without a message (void handler)
+ * \brief Make a new runnable without a message (void handler) -- untraced
+ * variant. Call \c makeRunnableVoidTraced if you want it to show up in tracing
  *
  * \param[in] is_threaded whether it is threaded
  * \param[in] handler the handler bits
@@ -364,11 +365,81 @@ inline RunnableMaker<BaseMsgType> makeRunnableVoid(
 ) {
   // These are currently only types of registry entries that can be void
   auto r = new RunnableNew(is_threaded);
-  // @todo: figure out how to trace this?
   r->addContextSetContext(r, from);
   return RunnableMaker<BaseMsgType>{r, nullptr, handler, from};
 }
 
+/**
+ * \brief Make a new runnable without a message (void handler) with tracing
+ *
+ * \param[in] is_threaded whether it is threaded
+ * \param[in] handler the handler bits
+ * \param[in] from the node that caused this runnable to execute
+ *
+ * \return the maker for further customization
+ */
+inline RunnableMaker<BaseMsgType> makeRunnableVoidTraced(
+  bool is_threaded, HandlerType handler, NodeType from,
+  [[maybe_unused]] trace::TraceEventIDType trace_event,
+  [[maybe_unused]] std::size_t msg_size
+) {
+  // These are currently only types of registry entries that can be void
+  auto r = new RunnableNew(is_threaded);
+  r->addContextSetContext(r, from);
+
+#if vt_check_enabled(trace_enabled)
+  auto const han_type = HandlerManager::getHandlerRegistryType(handler);
+  if (han_type == auto_registry::RegistryTypeEnum::RegVrt or
+      han_type == auto_registry::RegistryTypeEnum::RegGeneral or
+      han_type == auto_registry::RegistryTypeEnum::RegObjGroup) {
+    r->addContextTrace(trace_event, handler, from, msg_size);
+  }
+#endif
+
+  return RunnableMaker<BaseMsgType>{r, nullptr, handler, from};
+}
+
+/**
+ * \brief Make a new runnable without a message (void handler) with tracing for
+ * collections
+ *
+ * \param[in] is_threaded whether it is threaded
+ * \param[in] handler the handler bits
+ * \param[in] from the node that caused this runnable to execute
+ * \param[in] idx1 1-dimension index
+ * \param[in] idx2 2-dimension index
+ * \param[in] idx3 3-dimension index
+ * \param[in] idx4 4-dimension index
+ *
+ * \return the maker for further customization
+ */
+inline RunnableMaker<BaseMsgType> makeRunnableVoidTraced(
+  bool is_threaded, HandlerType handler, NodeType from,
+  [[maybe_unused]] trace::TraceEventIDType trace_event,
+  [[maybe_unused]] std::size_t msg_size,
+  [[maybe_unused]] uint64_t idx1,
+  [[maybe_unused]] uint64_t idx2,
+  [[maybe_unused]] uint64_t idx3,
+  [[maybe_unused]] uint64_t idx4
+) {
+  // These are currently only types of registry entries that can be void
+  auto r = new RunnableNew(is_threaded);
+  r->addContextSetContext(r, from);
+
+#if vt_check_enabled(trace_enabled)
+  auto const han_type = HandlerManager::getHandlerRegistryType(handler);
+  if (han_type == auto_registry::RegistryTypeEnum::RegVrtCollection or
+      han_type == auto_registry::RegistryTypeEnum::RegVrtCollectionMember) {
+    r->addContextTrace(
+      trace_event, handler, from, msg_size, idx1, idx2, idx3, idx4
+    );
+  }
+#endif
+
+  return RunnableMaker<BaseMsgType>{r, nullptr, handler, from};
+}
+
+
 }} /* end namespace vt::runnable */
 
 #include "vt/runnable/make_runnable.impl.h"

src/vt/scheduler/scheduler.cc

@@ -303,11 +303,13 @@ void Scheduler::runSchedulerOnceImpl(bool msg_only) {
 
 Scheduler::SchedulerLoopGuard::SchedulerLoopGuard(Scheduler* scheduler)
   : scheduler_{scheduler} {
+  scheduler_->in_sched_depth_++;
   scheduler_->triggerEvent(SchedulerEventType::BeginSchedulerLoop);
 }
 
 Scheduler::SchedulerLoopGuard::~SchedulerLoopGuard() {
   scheduler_->triggerEvent(SchedulerEventType::EndSchedulerLoop);
+  scheduler_->in_sched_depth_--;
 }
 
 void Scheduler::runSchedulerWhile(std::function<bool()> cond) {

src/vt/scheduler/scheduler.h

@@ -343,6 +343,11 @@ struct Scheduler : runtime::component::Component<Scheduler> {
    */
   void setRecentTimeToStale() { is_recent_time_stale_ = true; }
 
+  /**
+   * \brief Get the current recursive scheduler depth
+   */
+  unsigned int getSchedulerDepth() const { return in_sched_depth_; }
+
 #if vt_check_enabled(fcontext)
   /**
    * \brief Get the thread manager
@@ -363,6 +368,7 @@ struct Scheduler : runtime::component::Component<Scheduler> {
       | is_idle
       | is_idle_minus_term
       | action_depth_
+      | in_sched_depth_
       | num_term_msgs_
       | event_triggers
       | event_triggers_once
@@ -430,6 +436,8 @@ struct Scheduler : runtime::component::Component<Scheduler> {
   bool is_idle_minus_term = true;
   // The depth of work action currently executing.
   unsigned int action_depth_ = 0;
+  /// In-scheduler depth, zero indicates not in a scheduler
+  unsigned int in_sched_depth_ = 0;
 
   // The number of termination messages currently in the queue---they weakly
   // imply idleness for the stake of termination

src/vt/trace/trace.cc

@@ -349,8 +349,9 @@ TraceProcessingTag Trace::beginProcessing(
 
   vt_debug_print(
     normal, trace,
-    "event_start: ep={}, event={}, time={}, from={}, entry chare={}\n",
-    ep, event, time, from_node, TraceRegistry::getEvent(ep).theEventSeq()
+    "event_start: ep={}, event={}, time={}, from={}, entry chare={}, name={}\n",
+    ep, event, time, from_node, TraceRegistry::getEvent(ep).theEventSeq(),
+    TraceRegistry::getEvent(ep).theEventName()
   );
 
   auto const type = TraceConstantsType::BeginProcessing;
@@ -394,9 +395,9 @@ void Trace::endProcessing(
 
   vt_debug_print(
     normal, trace,
-    "event_stop: ep={}, event={}, time={}, from_node={}, entry chare={}\n",
+    "event_stop: ep={}, event={}, time={}, from_node={}, entry chare={}, name={}\n",
     ep, event, time, open_events_.back().node,
-    TraceRegistry::getEvent(ep).theEventSeq()
+    TraceRegistry::getEvent(ep).theEventSeq(), TraceRegistry::getEvent(ep).theEventName()
   );
 
   vtAssert(
@@ -428,13 +429,15 @@ void Trace::pendingSchedulerLoop() {
   between_sched_event_ = TraceProcessingTag{};
 }
 
-void Trace::beginSchedulerLoop() {
+TimeType Trace::beginSchedulerLoop() {
+  auto const cur_time = timing::getCurrentTime();
   // Always end between-loop event. The pending case is not always triggered.
-  endProcessing(between_sched_event_, timing::getCurrentTime());
+  endProcessing(between_sched_event_, cur_time);
   between_sched_event_ = TraceProcessingTag{};
 
   // Capture the current open event depth.
   event_holds_.push_back(open_events_.size());
+  return cur_time;
 }
 
 void Trace::endSchedulerLoop() {

src/vt/trace/trace.h

@@ -172,8 +172,10 @@ struct Trace : runtime::component::Component<Trace>, TraceLite {
 
   /**
    * \brief Scheduler trigger for \c sched::SchedulerEvent::BeginSchedulerLoop
+   *
+   * \return the time the between scheduler event was ended
    */
-  void beginSchedulerLoop();
+  TimeType beginSchedulerLoop();
 
   /**
    * \brief Scheduler trigger for \c sched::SchedulerEvent::EndSchedulerLoop
@@ -361,6 +363,22 @@ struct Trace : runtime::component::Component<Trace>, TraceLite {
    */
   bool inIdleEvent() const;
 
+  /**
+   * \brief Set if we are inside an invoke context
+   *
+   * \param[in] set the variable value to set
+   */
+  void setInInvokeContext(bool set) {
+    inside_invoke_context_ = set;
+  }
+
+  /**
+   * \brief Return if we are inside an invoke context
+   *
+   * \return whether we are inside an invoke context
+   */
+  bool inInvokeContext() const { return inside_invoke_context_; }
+
   friend void insertNewUserEvent(UserEventIDType event, std::string const& name);
 
   template <typename SerializerT>
@@ -385,7 +403,8 @@ struct Trace : runtime::component::Component<Trace>, TraceLite {
       | trace_enabled_cur_phase_
       | flush_event_
       | between_sched_event_type_
-      | between_sched_event_;
+      | between_sched_event_
+      | inside_invoke_context_;
 
     s.skip(log_file_); // definition unavailable
   }
@@ -398,15 +417,12 @@ struct Trace : runtime::component::Component<Trace>, TraceLite {
   int incremental_flush_mode = 0;
 
 private:
-
-
   ObjGroupProxyType spec_proxy_ = vt::no_obj_group;
 
-
-
   // Processing event between top-level loops.
   TraceEntryIDType between_sched_event_type_ = no_trace_entry_id;
   TraceProcessingTag between_sched_event_;
+  bool inside_invoke_context_ = false;
 };
 
 }} //end namespace vt::trace

src/vt/vrt/collection/balance/lb_invoke/lb_manager.cc

@@ -366,7 +366,7 @@ void LBManager::startLB(
     break;
   }
 
-  runLB(phase, cb);
+  proxy_[theContext()->getNode()].template invoke<&LBManager::runLB>(phase, cb);
 }
 
 /*static*/