diff --git a/src/vt/context/runnable_context/trace.cc b/src/vt/context/runnable_context/trace.cc index 8f0f8c6f34..61773e9db0 100644 --- a/src/vt/context/runnable_context/trace.cc +++ b/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) { diff --git a/src/vt/context/runnable_context/trace.h b/src/vt/context/runnable_context/trace.h index 8e2cb3cea8..e3e2405ecd 100644 --- a/src/vt/context/runnable_context/trace.h +++ b/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 diff --git a/src/vt/objgroup/manager.impl.h b/src/vt/objgroup/manager.impl.h index 26ae714e04..52f6fa63c6 100644 --- a/src/vt/objgroup/manager.impl.h +++ b/src/vt/objgroup/manager.impl.h @@ -220,11 +220,26 @@ ObjGroupManager::invoke(ProxyElmType 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)...); +#else return runnable::makeRunnableVoid(false, uninitialized_handler, this_node) .withObjGroup(get(proxy)) .runLambda(f, get(proxy), std::forward(args)...); +#endif } diff --git a/src/vt/registry/auto/auto_registry_common.h b/src/vt/registry/auto/auto_registry_common.h index 0ae1ed2d39..3caa722eea 100644 --- a/src/vt/registry/auto/auto_registry_common.h +++ b/src/vt/registry/auto/auto_registry_common.h @@ -130,6 +130,8 @@ struct HandlersDispatcher final : BaseHandlersDispatcher { } } else if constexpr (std::is_same_v) { std::apply(fp, msg->getTuple()); + } else if constexpr (std::is_same_v) { + // do nothing } else { if constexpr (IsColTrait::value and IsWrapMsgTrait::value) { auto& m = msg->getMsg(); diff --git a/src/vt/runnable/make_runnable.h b/src/vt/runnable/make_runnable.h index 19ffce1d53..9fdd519124 100644 --- a/src/vt/runnable/make_runnable.h +++ b/src/vt/runnable/make_runnable.h @@ -351,7 +351,8 @@ RunnableMaker 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 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{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 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{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 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{r, nullptr, handler, from}; +} + + }} /* end namespace vt::runnable */ #include "vt/runnable/make_runnable.impl.h" diff --git a/src/vt/scheduler/scheduler.cc b/src/vt/scheduler/scheduler.cc index 2fe896135b..d2c6ba1d3d 100644 --- a/src/vt/scheduler/scheduler.cc +++ b/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 cond) { diff --git a/src/vt/scheduler/scheduler.h b/src/vt/scheduler/scheduler.h index 533faf1623..723829395c 100644 --- a/src/vt/scheduler/scheduler.h +++ b/src/vt/scheduler/scheduler.h @@ -343,6 +343,11 @@ struct Scheduler : runtime::component::Component { */ 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 { | 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 { 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 diff --git a/src/vt/trace/trace.cc b/src/vt/trace/trace.cc index c4d2ed0f1c..e09aacaef6 100644 --- a/src/vt/trace/trace.cc +++ b/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() { diff --git a/src/vt/trace/trace.h b/src/vt/trace/trace.h index 232f36d4e5..0be6770c94 100644 --- a/src/vt/trace/trace.h +++ b/src/vt/trace/trace.h @@ -172,8 +172,10 @@ struct Trace : runtime::component::Component, 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, 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 @@ -385,7 +403,8 @@ struct Trace : runtime::component::Component, 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, 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 diff --git a/src/vt/vrt/collection/balance/lb_invoke/lb_manager.cc b/src/vt/vrt/collection/balance/lb_invoke/lb_manager.cc index 830d1563e6..d54ba31d43 100644 --- a/src/vt/vrt/collection/balance/lb_invoke/lb_manager.cc +++ b/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*/ diff --git a/src/vt/vrt/collection/manager.impl.h b/src/vt/vrt/collection/manager.impl.h index f03d60fa9f..897acd884e 100644 --- a/src/vt/vrt/collection/manager.impl.h +++ b/src/vt/vrt/collection/manager.impl.h @@ -465,10 +465,33 @@ auto CollectionManager::invoke( auto const this_node = theContext()->getNode(); +#if vt_check_enabled(trace_enabled) + auto const han = auto_registry::makeAutoHandlerCollectionMemParam< + ColT, decltype(f), f, void + >(); + auto const trace_event = theMsg()->makeTraceCreationSend(han, 0, false); + +#if vt_check_enabled(trace_enabled) + auto idx = ptr->getIndex(); + uint64_t const idx1 = idx.ndims() > 0 ? idx[0] : 0; + uint64_t const idx2 = idx.ndims() > 1 ? idx[1] : 0; + uint64_t const idx3 = idx.ndims() > 2 ? idx[2] : 0; + uint64_t const idx4 = idx.ndims() > 3 ? idx[3] : 0; +#endif + + return runnable::makeRunnableVoidTraced( + false, han, this_node, trace_event, 0, idx1, idx2, idx3, idx4 + ) + .withCollection(ptr) + .withLBDataVoidMsg(ptr) + .runLambda(f, ptr, std::forward(args)...); + +#else return runnable::makeRunnableVoid(false, uninitialized_handler, this_node) .withCollection(ptr) .withLBDataVoidMsg(ptr) .runLambda(f, ptr, std::forward(args)...); +#endif } template < diff --git a/tests/unit/trace/test_runnable_context_trace.cc b/tests/unit/trace/test_runnable_context_trace.cc index 018aacc0af..3918a5a2ee 100644 --- a/tests/unit/trace/test_runnable_context_trace.cc +++ b/tests/unit/trace/test_runnable_context_trace.cc @@ -68,6 +68,11 @@ TEST_F(TestRunnableContextTrace, runnable_context_trace_test_1) { HandlerManager::setHandlerTrace(handler, true); + // Avoid special case in test, where we tell the trace component that we are + // in a direct invoke context to avoid the scheduler creating + // 'between-scheduler' events + theTrace()->setInInvokeContext(true); + // Give some nonsense parameters but Trace shouldn't touch them auto t = ctx::Trace( msg, /* in_trace_event */ 7, handler, /* in_from_node */ 3,