Merge pull request #1998 from DARMA-tasking/1938-remove-unneeded-call…

…s-to-mpi_wtime-in-trace-and-lb

1938 remove unneeded calls to mpi wtime in trace and lb

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 {

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

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 */

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

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_;

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);

src/vt/parameterization/parameterization.h

@@ -107,7 +107,7 @@ static void dataMessageHandler(DataMsg<Tuple>* 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<Tuple>* msg) {
   }
 
 #if vt_check_enabled(trace_enabled)
-  theTrace()->endProcessing(processing_tag);
+  theTrace()->endProcessing(processing_tag, timing::getCurrentTime());
 #endif
 }
 

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);

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 <typename Callable, Callable f, typename... Args>
 static void EndProcessingInvokeEvent(trace::TraceProcessingTag processing_tag) {
-  theTrace()->endProcessing(processing_tag);
+  theTrace()->endProcessing(processing_tag, timing::getCurrentTime());
 
   const auto trace_id = CallableWrapper<Callable, f>::GetTraceID();
   theTrace()->messageCreation(trace_id, 0);

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

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
 }