diff --git a/src/vt/context/runnable_context/lb_data.cc b/src/vt/context/runnable_context/lb_data.cc index 917f239291..bb0d57105e 100644 --- a/src/vt/context/runnable_context/lb_data.cc +++ b/src/vt/context/runnable_context/lb_data.cc @@ -46,30 +46,32 @@ namespace vt { namespace ctx { -void LBData::start() { +void LBData::start(TimeType time) { // record start time if (should_instrument_) { - lb_data_->startTime(); + lb_data_->start(time); } } -void LBData::finish() { +void LBData::finish(TimeType time) { // record end time if (should_instrument_) { - lb_data_->stopTime(); + lb_data_->stop(time); } } void LBData::send(elm::ElementIDStruct dest, MsgSizeType bytes) { - lb_data_->sendToEntity(dest, cur_elm_id_, bytes); + if (should_instrument_) { + lb_data_->sendToEntity(dest, cur_elm_id_, bytes); + } } -void LBData::suspend() { - finish(); +void LBData::suspend(TimeType time) { + finish(time); } -void LBData::resume() { - start(); +void LBData::resume(TimeType time) { + start(time); } typename LBData::ElementIDStruct const& LBData::getCurrentElementID() const { diff --git a/src/vt/context/runnable_context/lb_data.h b/src/vt/context/runnable_context/lb_data.h index 89dc703025..f211a90839 100644 --- a/src/vt/context/runnable_context/lb_data.h +++ b/src/vt/context/runnable_context/lb_data.h @@ -81,15 +81,20 @@ struct LBData { should_instrument_(true) { } + /** + * \brief Return whether time is required + */ + bool needsTime() const { return should_instrument_; } + /** * \brief Set the context and timing for a collection task */ - void start(); + void start(TimeType time); /** * \brief Remove the context and store timing for a collection task */ - void finish(); + void finish(TimeType time); /** * \brief Record LB data whenever a message is sent and a collection @@ -100,8 +105,8 @@ struct LBData { */ void send(elm::ElementIDStruct dest, MsgSizeType bytes); - void suspend(); - void resume(); + void suspend(TimeType time); + void resume(TimeType time); /** * \brief Get the current element ID struct for the running context diff --git a/src/vt/context/runnable_context/trace.cc b/src/vt/context/runnable_context/trace.cc index 921d6cb43a..bb955a8212 100644 --- a/src/vt/context/runnable_context/trace.cc +++ b/src/vt/context/runnable_context/trace.cc @@ -54,7 +54,7 @@ namespace vt { namespace ctx { -void Trace::start() { +void Trace::start(TimeType time) { if (not is_traced_) { return; } @@ -67,30 +67,30 @@ void Trace::start() { from_node_ != uninitialized_destination ? from_node_ : cur_node; processing_tag_ = theTrace()->beginProcessing( - trace_id, msg_size_, event_, from_node, idx1_, idx2_, idx3_, idx4_ + trace_id, msg_size_, event_, from_node, idx1_, idx2_, idx3_, idx4_, time ); } else { processing_tag_ = theTrace()->beginProcessing( - trace_id, msg_size_, event_, from_node_ + trace_id, msg_size_, event_, from_node_, time ); } } -void Trace::finish() { +void Trace::finish(TimeType time) { if (not is_traced_) { return; } - theTrace()->endProcessing(processing_tag_); + theTrace()->endProcessing(processing_tag_, time); } -void Trace::suspend() { - finish(); +void Trace::suspend(TimeType time) { + finish(time); } -void Trace::resume() { +void Trace::resume(TimeType time) { // @todo: connect up the last event to this new one after suspension - start(); + start(time); } }} /* end namespace vt::ctx */ diff --git a/src/vt/context/runnable_context/trace.h b/src/vt/context/runnable_context/trace.h index d09f35a9cd..aa4577bf28 100644 --- a/src/vt/context/runnable_context/trace.h +++ b/src/vt/context/runnable_context/trace.h @@ -101,10 +101,10 @@ struct Trace { */ trace::TraceEventIDType getEvent() const { return event_; } - void start(); - void finish(); - void suspend(); - void resume(); + void start(TimeType time); + void finish(TimeType time); + void suspend(TimeType time); + void resume(TimeType time); private: /// Whether it's a collection or not diff --git a/src/vt/elm/elm_lb_data.cc b/src/vt/elm/elm_lb_data.cc index d5dc5d5584..ff8f09ebad 100644 --- a/src/vt/elm/elm_lb_data.cc +++ b/src/vt/elm/elm_lb_data.cc @@ -50,8 +50,8 @@ namespace vt { namespace elm { -void ElementLBData::startTime() { - TimeTypeWrapper const start_time = timing::getCurrentTime(); +void ElementLBData::start(TimeType time) { + TimeTypeWrapper const start_time = time; cur_time_ = start_time.seconds(); cur_time_started_ = true; @@ -62,8 +62,8 @@ void ElementLBData::startTime() { ); } -void ElementLBData::stopTime() { - TimeTypeWrapper const stop_time = timing::getCurrentTime(); +void ElementLBData::stop(TimeType time) { + TimeTypeWrapper const stop_time = time; TimeTypeWrapper const total_time = stop_time.seconds() - cur_time_; //vtAssert(cur_time_started_, "Must have started time"); auto const started = cur_time_started_; diff --git a/src/vt/elm/elm_lb_data.h b/src/vt/elm/elm_lb_data.h index 554856f8d1..1ebc07c6c3 100644 --- a/src/vt/elm/elm_lb_data.h +++ b/src/vt/elm/elm_lb_data.h @@ -61,8 +61,8 @@ struct ElementLBData { ElementLBData(ElementLBData const&) = default; ElementLBData(ElementLBData&&) = default; - void startTime(); - void stopTime(); + void start(TimeType time); + void stop(TimeType time); void addTime(TimeTypeWrapper const& time); void sendToEntity(ElementIDStruct to, ElementIDStruct from, double bytes); diff --git a/src/vt/parameterization/parameterization.h b/src/vt/parameterization/parameterization.h index eb0fa73191..5f9c15e8c9 100644 --- a/src/vt/parameterization/parameterization.h +++ b/src/vt/parameterization/parameterization.h @@ -107,7 +107,7 @@ static void dataMessageHandler(DataMsg* msg) { NodeType const& from_node = theContext()->getFromNodeCurrentTask(); processing_tag = - theTrace()->beginProcessing(ep, msg_size, event, from_node); + theTrace()->beginProcessing(ep, msg_size, event, from_node, timing::getCurrentTime()); } #endif @@ -121,7 +121,7 @@ static void dataMessageHandler(DataMsg* msg) { } #if vt_check_enabled(trace_enabled) - theTrace()->endProcessing(processing_tag); + theTrace()->endProcessing(processing_tag, timing::getCurrentTime()); #endif } diff --git a/src/vt/rdma/state/rdma_state.cc b/src/vt/rdma/state/rdma_state.cc index 72f39b226b..bd8190d48b 100644 --- a/src/vt/rdma/state/rdma_state.cc +++ b/src/vt/rdma/state/rdma_state.cc @@ -261,7 +261,7 @@ void State::getData( size_t msg_size = info.num_bytes; processing_tag = - theTrace()->beginProcessing(trace_id, msg_size, event, from_node); + theTrace()->beginProcessing(trace_id, msg_size, event, from_node, timing::getCurrentTime()); } #endif @@ -280,7 +280,7 @@ void State::getData( } #if vt_check_enabled(trace_enabled) - theTrace()->endProcessing(processing_tag); + theTrace()->endProcessing(processing_tag, timing::getCurrentTime()); #endif } else { pending_tag_gets[tag].push_back(info); @@ -328,7 +328,7 @@ void State::putData( size_t msg_size = info.num_bytes; processing_tag = - theTrace()->beginProcessing(trace_id, msg_size, event, from_node); + theTrace()->beginProcessing(trace_id, msg_size, event, from_node, timing::getCurrentTime()); } #endif @@ -346,7 +346,7 @@ void State::putData( } #if vt_check_enabled(trace_enabled) - theTrace()->endProcessing(processing_tag); + theTrace()->endProcessing(processing_tag, timing::getCurrentTime()); #endif } else { pending_tag_puts[tag].push_back(info); diff --git a/src/vt/runnable/invoke.h b/src/vt/runnable/invoke.h index 7e494ab1d5..9c0596699d 100644 --- a/src/vt/runnable/invoke.h +++ b/src/vt/runnable/invoke.h @@ -140,12 +140,12 @@ static trace::TraceProcessingTag BeginProcessingInvokeEvent() { const auto trace_event = theTrace()->messageCreation(trace_id, 0); const auto from_node = theContext()->getNode(); - return theTrace()->beginProcessing(trace_id, 0, trace_event, from_node); + return theTrace()->beginProcessing(trace_id, 0, trace_event, from_node, timing::getCurrentTime()); } template static void EndProcessingInvokeEvent(trace::TraceProcessingTag processing_tag) { - theTrace()->endProcessing(processing_tag); + theTrace()->endProcessing(processing_tag, timing::getCurrentTime()); const auto trace_id = CallableWrapper::GetTraceID(); theTrace()->messageCreation(trace_id, 0); diff --git a/src/vt/runnable/make_runnable.h b/src/vt/runnable/make_runnable.h index 438a0db655..e3b713b83e 100644 --- a/src/vt/runnable/make_runnable.h +++ b/src/vt/runnable/make_runnable.h @@ -287,6 +287,15 @@ struct RunnableMaker { */ void enqueue(); + /** + * \brief Return the underlying \c RunnableNew + * + * \warning This is for testing only + * + * \return the underlying runnable + */ + RunnableNew* getRunnableImpl() { return impl_; } + private: /** * \internal \brief Setup for running or enqueuing diff --git a/src/vt/runnable/runnable.cc b/src/vt/runnable/runnable.cc index 419a6c2840..4beb1dba91 100644 --- a/src/vt/runnable/runnable.cc +++ b/src/vt/runnable/runnable.cc @@ -115,15 +115,25 @@ void RunnableNew::run() { ); #endif + bool needs_time = false; +#if vt_check_enabled(trace_enabled) + if (contexts_.has_trace) needs_time = true; + else +#endif + if (contexts_.has_lb) + { + needs_time = contexts_.lb.needsTime(); + } + TimeType start_time = needs_time ? theSched()->getRecentTime() : NAN; + #if vt_check_enabled(fcontext) if (suspended_) { - resume(); - } else { - start(); - } -#else - start(); + resume(start_time); + } else #endif + { + start(start_time); + } #if vt_check_enabled(fcontext) if (is_threaded_ and not theConfig()->vt_ult_disable) { @@ -164,16 +174,20 @@ void RunnableNew::run() { done_ = true; #endif } + theSched()->setRecentTimeToStale(); + TimeType end_time = needs_time ? theSched()->getRecentTime() : NAN; + + #if vt_check_enabled(fcontext) if (done_) { - finish(); + finish(end_time); } else { suspended_ = true; - suspend(); + suspend(end_time); } #else - finish(); + finish(end_time); #endif #if vt_check_enabled(fcontext) @@ -185,49 +199,49 @@ void RunnableNew::run() { #endif } -void RunnableNew::start() { +void RunnableNew::start(TimeType time) { contexts_.setcontext.start(); if (contexts_.has_td) contexts_.td.start(); if (contexts_.has_col) contexts_.col.start(); - if (contexts_.has_lb) contexts_.lb.start(); + if (contexts_.has_lb) contexts_.lb.start(time); #if vt_check_enabled(trace_enabled) - if (contexts_.has_trace) contexts_.trace.start(); + if (contexts_.has_trace) contexts_.trace.start(time); #endif } -void RunnableNew::finish() { +void RunnableNew::finish(TimeType time) { contexts_.setcontext.finish(); if (contexts_.has_td) contexts_.td.finish(); if (contexts_.has_col) contexts_.col.finish(); if (contexts_.has_cont) contexts_.cont.finish(); - if (contexts_.has_lb) contexts_.lb.finish(); + if (contexts_.has_lb) contexts_.lb.finish(time); #if vt_check_enabled(trace_enabled) - if (contexts_.has_trace) contexts_.trace.finish(); + if (contexts_.has_trace) contexts_.trace.finish(time); #endif } -void RunnableNew::suspend() { +void RunnableNew::suspend(TimeType time) { #if vt_check_enabled(fcontext) contexts_.setcontext.suspend(); if (contexts_.has_td) contexts_.td.suspend(); if (contexts_.has_col) contexts_.col.suspend(); - if (contexts_.has_lb) contexts_.lb.suspend(); + if (contexts_.has_lb) contexts_.lb.suspend(time); # if vt_check_enabled(trace_enabled) - if (contexts_.has_trace) contexts_.trace.suspend(); + if (contexts_.has_trace) contexts_.trace.suspend(time); # endif #endif } -void RunnableNew::resume() { +void RunnableNew::resume(TimeType time) { #if vt_check_enabled(fcontext) contexts_.setcontext.resume(); if (contexts_.has_td) contexts_.td.resume(); if (contexts_.has_col) contexts_.col.resume(); - if (contexts_.has_lb) contexts_.lb.resume(); + if (contexts_.has_lb) contexts_.lb.resume(time); # if vt_check_enabled(trace_enabled) - if (contexts_.has_trace) contexts_.trace.resume(); + if (contexts_.has_trace) contexts_.trace.resume(time); # endif #endif } diff --git a/src/vt/runnable/runnable.h b/src/vt/runnable/runnable.h index 120200cee4..2bfe5425a1 100644 --- a/src/vt/runnable/runnable.h +++ b/src/vt/runnable/runnable.h @@ -233,13 +233,16 @@ struct RunnableNew { */ template decltype(auto) runLambda(Callable&& c, Args&&... args) { - start(); + auto start_time = timing::getCurrentTime(); + start(start_time); if constexpr(std::is_void_v>) { std::invoke(std::forward(c), std::forward(args)...); - finish(); + auto finish_time = timing::getCurrentTime(); + finish(finish_time); } else { decltype(auto) r{std::invoke(std::forward(c), std::forward(args)...)}; - finish(); + auto finish_time = timing::getCurrentTime(); + finish(finish_time); return r; } } @@ -261,25 +264,25 @@ struct RunnableNew { * \internal \brief Loop through all the contexts associated with this * runnable and invoke \c start() on them. */ - void start(); + void start(TimeType time); /** * \internal \brief Loop through all the contexts associated with this * runnable and invoke \c finish() on them. */ - void finish(); + void finish(TimeType time); /** * \internal \brief Loop through all the contexts associated with this * runnable and invoke \c suspend() on them. */ - void suspend(); + void suspend(TimeType time); /** * \internal \brief Loop through all the contexts associated with this * runnable and invoke \c resume() on them. */ - void resume(); + void resume(TimeType time); public: /** diff --git a/src/vt/scheduler/base_unit.cc b/src/vt/scheduler/base_unit.cc index 3a4292d289..85dfdbbea0 100644 --- a/src/vt/scheduler/base_unit.cc +++ b/src/vt/scheduler/base_unit.cc @@ -62,6 +62,7 @@ void BaseUnit::execute() { #endif } else if (work_) { work_(); + theSched()->setRecentTimeToStale(); } } diff --git a/src/vt/scheduler/scheduler.cc b/src/vt/scheduler/scheduler.cc index 34a298cadd..d67a23da11 100644 --- a/src/vt/scheduler/scheduler.cc +++ b/src/vt/scheduler/scheduler.cc @@ -239,24 +239,24 @@ void Scheduler::runProgress(bool msg_only, TimeType current_time) { if (theConfig()->vt_print_memory_at_threshold) { printMemoryUsage(); } - + is_recent_time_stale_ = true; if (special_progress_) { // Reset count of processed handlers since the last time progress was invoked processed_after_last_progress_ = 0; - last_progress_time_ = timing::getCurrentTime(); + last_progress_time_ = getRecentTime(); } } void Scheduler::runSchedulerOnceImpl(bool msg_only) { if (special_progress_) { - auto current_time = timing::getCurrentTime(); + auto current_time = getRecentTime(); auto time_since_last_progress = current_time - last_progress_time_; if (shouldCallProgress(processed_after_last_progress_, time_since_last_progress)) { runProgress(msg_only, current_time); } } else if (work_queue_.empty()) { if (curRT->needsCurrentTime()) { - runProgress(msg_only, timing::getCurrentTime()); + runProgress(msg_only, getRecentTime()); } else { runProgress(msg_only, TimeType{0}); } diff --git a/src/vt/scheduler/scheduler.h b/src/vt/scheduler/scheduler.h index 4cc2e96d95..1f01738c0b 100644 --- a/src/vt/scheduler/scheduler.h +++ b/src/vt/scheduler/scheduler.h @@ -324,6 +324,25 @@ struct Scheduler : runtime::component::Component { */ void resume(ThreadIDType tid); + /** + * \brief Return a valid recent time, after checking whether an update is needed + * + * \return a valid recent time + */ + TimeType getRecentTime() { + if(is_recent_time_stale_) { + recent_time_ = timing::getCurrentTime(); + is_recent_time_stale_ = false; + } + return recent_time_; + } + + /** + * \brief Set the flag so that recent_time_ will be updated at next get request + * + */ + void setRecentTimeToStale() { is_recent_time_stale_ = true; } + #if vt_check_enabled(fcontext) /** * \brief Get the thread manager @@ -353,6 +372,9 @@ struct Scheduler : runtime::component::Component { | last_threshold_memory_usage_ | threshold_memory_usage_ | last_memory_usage_poll_ + | special_progress_ + | recent_time_ + | is_recent_time_stale_ | progressCount | workUnitCount | queueSizeGauge @@ -425,6 +447,8 @@ struct Scheduler : runtime::component::Component { std::size_t last_memory_usage_poll_ = 0; bool special_progress_ = false; /**< time-based/k-handler progress enabled */ + TimeType recent_time_; + bool is_recent_time_stale_ = true; // Access to triggerEvent. template diff --git a/src/vt/trace/trace.cc b/src/vt/trace/trace.cc index dd1f3a7dff..885fc450ca 100644 --- a/src/vt/trace/trace.cc +++ b/src/vt/trace/trace.cc @@ -117,7 +117,7 @@ void Trace::startup() /*override*/ { void Trace::finalize() /*override*/ { // Always end any between-loop event left open. - endProcessing(between_sched_event_); + endProcessing(between_sched_event_, timing::getCurrentTime()); between_sched_event_ = TraceProcessingTag{}; } @@ -335,9 +335,9 @@ void Trace::addMemoryEvent(std::size_t memory, double time) { TraceProcessingTag Trace::beginProcessing( TraceEntryIDType const ep, TraceMsgLenType const len, TraceEventIDType const event, NodeType const from_node, + TimeType const time, uint64_t const idx1, uint64_t const idx2, - uint64_t const idx3, uint64_t const idx4, - double const time + uint64_t const idx3, uint64_t const idx4 ) { if (not checkDynamicRuntimeEnabled()) { return TraceProcessingTag{}; @@ -367,7 +367,7 @@ TraceProcessingTag Trace::beginProcessing( void Trace::endProcessing( TraceProcessingTag const& processing_tag, - double const time + TimeType const time ) { // End event honored even if tracing is disabled in this phase. // This ensures proper stack unwinding in all contexts. @@ -420,13 +420,13 @@ void Trace::endProcessing( void Trace::pendingSchedulerLoop() { // Always end between-loop event. - endProcessing(between_sched_event_); + endProcessing(between_sched_event_, timing::getCurrentTime()); between_sched_event_ = TraceProcessingTag{}; } void Trace::beginSchedulerLoop() { // Always end between-loop event. The pending case is not always triggered. - endProcessing(between_sched_event_); + endProcessing(between_sched_event_, timing::getCurrentTime()); between_sched_event_ = TraceProcessingTag{}; // Capture the current open event depth. @@ -449,7 +449,7 @@ void Trace::endSchedulerLoop() { // Start an event representing time outside of top-level scheduler. if (event_holds_.size() == 1) { between_sched_event_ = beginProcessing( - between_sched_event_type_, 0, trace::no_trace_event, 0 + between_sched_event_type_, 0, trace::no_trace_event, 0, timing::getCurrentTime() ); } } diff --git a/src/vt/trace/trace.h b/src/vt/trace/trace.h index e41fe2050f..31fe8b6c8b 100644 --- a/src/vt/trace/trace.h +++ b/src/vt/trace/trace.h @@ -136,20 +136,20 @@ struct Trace : runtime::component::Component, TraceLite { * \param[in] len size of message in bytes * \param[in] event the associated trace event * \param[in] from_node which node instigated this processing + * \param[in] time the time this occurred * \param[in] idx1 (optional) if collection, dimension 1 * \param[in] idx2 (optional) if collection, dimension 2 * \param[in] idx3 (optional) if collection, dimension 3 * \param[in] idx4 (optional) if collection, dimension 4 - * \param[in] time the time this occurred * * \return a tag to close this processing event */ TraceProcessingTag beginProcessing( TraceEntryIDType const ep, TraceMsgLenType const len, TraceEventIDType const event, NodeType const from_node, + TimeType const time, uint64_t const idx1 = 0, uint64_t const idx2 = 0, - uint64_t const idx3 = 0, uint64_t const idx4 = 0, - double const time = getCurrentTime() + uint64_t const idx3 = 0, uint64_t const idx4 = 0 ); /** @@ -162,7 +162,7 @@ struct Trace : runtime::component::Component, TraceLite { */ void endProcessing( TraceProcessingTag const& processing_tag, - double const time = getCurrentTime() + TimeType const time ); /** diff --git a/tests/unit/scheduler/test_scheduler_timings.cc b/tests/unit/scheduler/test_scheduler_timings.cc new file mode 100644 index 0000000000..3521cd7973 --- /dev/null +++ b/tests/unit/scheduler/test_scheduler_timings.cc @@ -0,0 +1,152 @@ +/* +//@HEADER +// ***************************************************************************** +// +// test_scheduler_timings.cc +// DARMA/vt => Virtual Transport +// +// Copyright 2019-2021 National Technology & Engineering Solutions of Sandia, LLC +// (NTESS). Under the terms of Contract DE-NA0003525 with NTESS, the U.S. +// Government retains certain rights in this software. +// +// Redistribution and use in source and binary forms, with or without +// modification, are permitted provided that the following conditions are met: +// +// * Redistributions of source code must retain the above copyright notice, +// this list of conditions and the following disclaimer. +// +// * Redistributions in binary form must reproduce the above copyright notice, +// this list of conditions and the following disclaimer in the documentation +// and/or other materials provided with the distribution. +// +// * Neither the name of the copyright holder nor the names of its +// contributors may be used to endorse or promote products derived from this +// software without specific prior written permission. +// +// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" +// AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE +// IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE +// ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE +// LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR +// CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF +// SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS +// INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN +// CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) +// ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE +// POSSIBILITY OF SUCH DAMAGE. +// +// Questions? Contact darma@sandia.gov +// +// ***************************************************************************** +//@HEADER +*/ + +#include + +#include "vt/scheduler/scheduler.h" +#include "vt/elm/elm_id_bits.h" + +#include "test_parallel_harness.h" +#include "test_helpers.h" + +#include +#include + +namespace vt { namespace tests { namespace unit { + +struct TestSchedTimings : TestParallelHarness { }; + +struct MyMsg : vt::Message { + int ms = 0; +}; + +int count = 0; + +void myHandler(MyMsg* msg) { + fmt::print("running myHandler: ms={}\n", msg->ms); + std::this_thread::sleep_for(std::chrono::milliseconds{msg->ms}); + count++; +} +#if vt_check_enabled(lblite) + TEST_F(TestSchedTimings, test_sched_lb) { + + auto sched = std::make_unique(); + + auto const this_node = theContext()->getNode(); + + std::vector>> v; + + int const num_iter = 10; + + + for (int i = 0; i < num_iter; i++) { + int time = i*50; + v.emplace_back(time, std::make_unique()); + + auto id = elm::ElmIDBits::createCollection(true, this_node); + auto handler = auto_registry::makeAutoHandler(); + auto msg = vt::makeMessage(); + msg->ms = time; + auto maker = vt::runnable::makeRunnable(msg, false, handler, 0) + .withLBData(std::get<1>(v[i]).get(), id); + auto runnable = maker.getRunnableImpl(); + runnable->setupHandler(handler); + sched->enqueue(false, runnable); + } + + sched->runSchedulerWhile([&]{ return count < num_iter; }); + //To appease CI just ask for more comparisons to be good than bad + int num_pass =0; + for (auto& [time, data] : v) { + auto load = 1000.0* data->getLoad(0); + fmt::print("expected time={}, observed time={}\n", time, load); + double margin = 30+ time*0.20; + if ((time - load)< margin) { num_pass++; } + } + EXPECT_GT (num_pass, num_iter - num_pass); + + } +#endif +TEST_F(TestSchedTimings, test_sched_msg) { + + auto sched = std::make_unique(); + + int const num_iter = 10; + int const ms_delay = 50; + count = 0; + auto start_time = vt::timing::getCurrentTime(); + + for (int i = 0; i < num_iter; i++) { + + auto next_msg = vt::makeMessage(); + next_msg->ms = ms_delay; + + auto handler = auto_registry::makeAutoHandler(); + + auto maker = vt::runnable::makeRunnable(next_msg, false, handler, 0); + + auto runnable = maker.getRunnableImpl(); + runnable->setupHandler(handler); + sched->enqueue(false, runnable); + } + + sched->runSchedulerWhile([&]{ return count < num_iter; }); + double const fudge = 0.8; + auto observed_time = 1000.0 *(vt::timing::getCurrentTime() - start_time); + + // This ought to take close to a second (with ms_delay = 100) + EXPECT_GT( + observed_time, + vt::theConfig()->vt_sched_progress_sec * fudge + ); + + auto sum_time = num_iter *ms_delay; + fmt::print("expected time={}, observed time={}\n", sum_time, observed_time); + //double margin =30+ sum_time*0.2; + //EXPECT_NEAR(sum_time, observed_time, margin ); + EXPECT_GT(observed_time, sum_time); + +} + + +}}} /* vt::tests::unit */