#2187: trace: fix order of nested trace user events

src/vt/trace/trace.cc

@@ -327,7 +327,8 @@ void Trace::addUserEventBracketedManual(
   );
 
   auto id = user_event_.createEvent(true, false, 0, event);
-  addUserEventBracketed(id, begin, end);
+  addUserEventBracketedBeginTime(id, begin);
+  addUserEventBracketedEndTime(id, end);
 }
 
 void Trace::addMemoryEvent(std::size_t memory, TimeType time) {

src/vt/trace/trace_lite.cc

@@ -248,7 +248,7 @@ bool TraceLite::checkDynamicRuntimeEnabled(bool is_end_event) {
     (trace_enabled_cur_phase_ or is_end_event);
 }
 
-void TraceLite::addUserEventBracketedBegin(
+void TraceLite::addUserEventBracketedBeginTime(
   UserEventIDType event, double begin
 ) {
   if (not checkDynamicRuntimeEnabled()) {
@@ -267,7 +267,7 @@ void TraceLite::addUserEventBracketedBegin(
   logEvent(LogType{begin, type, node, event, true});
 }
 
-void TraceLite::addUserEventBracketedEnd(
+void TraceLite::addUserEventBracketedEndTime(
   UserEventIDType event, double end
 ) {
   if (not checkDynamicRuntimeEnabled()) {
@@ -468,6 +468,10 @@ void TraceLite::flushTracesFile(bool useGlobalSync) {
     // (Consider pushing out: barrier usages are probably domain-specific.)
     theCollective()->barrier();
   }
+  if (incomplete_events_ > 0) {
+    // wait until all incomplete events are patched up before flushing to disk
+    return;
+  }
   if (
     traces_.size() >=
     static_cast<std::size_t>(theConfig()->vt_trace_flush_size)) {

src/vt/trace/trace_lite.h

@@ -171,15 +171,15 @@ struct TraceLite  {
    * \param[in] event the ID for the sts file
    * \param[in] begin the begin time
    */
-  void addUserEventBracketedBegin(UserEventIDType event, double begin);
+  void addUserEventBracketedBeginTime(UserEventIDType event, double begin);
 
   /**
    * \brief Log a bracketed user event with end time
    *
    * \param[in] event the ID for the sts file
    * \param[in] end the end time
    */
-  void addUserEventBracketedEnd(UserEventIDType event, double end);
+  void addUserEventBracketedEndTime(UserEventIDType event, double end);
 
   /**
    * \brief Log a user bracketed event with a note
@@ -273,10 +273,26 @@ struct TraceLite  {
    *
    * @return the last recorded trace event
    */
-  const LogType* getLastTraceEvent() const noexcept {
+  LogType* getLastTraceEvent() noexcept {
     return traces_.empty() ? nullptr : &traces_.back();
   }
 
+  /**
+   * \brief Increment incomplete events (used to inhibit flushing before the
+   * event scope closes, leading to incomplete trace output)
+   */
+  void incrementIncompleteEvents() {
+    incomplete_events_++;
+  }
+
+  /**
+   * \brief Decrement incomplete events (used to inhibit flushing before the
+   * event scope closes, leading to incomplete trace output)
+   */
+  void decrementIncompleteEvents() {
+    incomplete_events_++;
+  }
+
 protected:
   /**
    * \brief Emit a 'stop' trace for previous open event or a '[re]start' trace
@@ -404,6 +420,7 @@ struct TraceLite  {
   bool trace_enabled_cur_phase_ = true;
   bool idle_begun_              = false;
   std::unique_ptr<vt_gzFile> log_file_;
+  std::size_t incomplete_events_ = 0;
 };
 
 }} //end namespace vt::trace

src/vt/trace/trace_user.cc

@@ -83,12 +83,15 @@ void addUserEvent([[maybe_unused]] UserEventIDType event) {
 #endif
 }
 
-void addUserEventBracketed(
-  [[maybe_unused]] UserEventIDType event, [[maybe_unused]] TimeType begin,
-  [[maybe_unused]] TimeType end
-) {
+void addUserEventBracketedBeginTime(UserEventIDType event, double begin) {
+#if vt_check_enabled(trace_enabled)
+  theTrace()->addUserEventBracketedBeginTime(event, begin);
+#endif
+}
+
+void addUserEventBracketedEndTime(UserEventIDType event, double end) {
 #if vt_check_enabled(trace_enabled)
-  theTrace()->addUserEventBracketed(event, begin, end);
+  theTrace()->addUserEventBracketedEndTime(event, end);
 #endif
 }
 

src/vt/trace/trace_user.h

@@ -46,6 +46,7 @@
 
 #include "vt/config.h"
 #include "vt/trace/trace_common.h"
+#include "vt/runtime/runtime.h"
 #include "vt/timing/timing_type.h"
 
 #include <string>
@@ -174,7 +175,7 @@ struct TraceScopedEventHash final {
       str_(in_str)
   {
     event_ = registerEventHashed(str_);
-    theTrace()->addUserEventBracketedBegin(event_, begin_);
+    theTrace()->addUserEventBracketedBeginTime(event_, begin_);
   }
 
   TraceScopedEventHash& operator=(TraceScopedEventHash const&) = delete;
@@ -187,7 +188,7 @@ struct TraceScopedEventHash final {
   void end() {
     if (event_ != no_user_event_id) {
       double end = TraceLite::getCurrentTime();
-      theTrace()->addUserEventBracketedEnd(event_, end);
+      theTrace()->addUserEventBracketedEndTime(event_, end);
       event_ = no_user_event_id;
     }
   }
@@ -218,7 +219,9 @@ struct TraceScopedEvent final {
     : begin_(event != no_user_event_id ? TraceLite::getCurrentTime() : TimeType{0.}),
       event_(event)
   {
-    theTrace()->addUserEventBracketedBegin(event_, begin_);
+    if (event != no_user_event_id) {
+      theTrace()->addUserEventBracketedBeginTime(event_, begin_);
+    }
   }
 
   TraceScopedEvent(TraceScopedEvent const&) = delete;
@@ -244,7 +247,7 @@ struct TraceScopedEvent final {
   void end() {
     if (event_ != no_user_event_id) {
       double end = TraceLite::getCurrentTime();
-      theTrace()->addUserEventBracketedEnd(event_, end);
+      theTrace()->addUserEventBracketedEndTime(event_, end);
       event_ = no_user_event_id;
     }
   }
@@ -276,14 +279,25 @@ struct TraceScopedNote final {
   ) : begin_(in_event != no_trace_event ? TraceLite::getCurrentTime() : TimeType{0.}),
       event_(in_event),
       note_(in_note)
-  { }
+  {
+    if (event_ != no_user_event_id) {
+      // We need to emit this right away so the event is in the proper place wrt
+      // the begin time. We can patch up the end time later
+      theTrace()->incrementIncompleteEvents();
+    }
+    theTrace()->addUserBracketedNote(begin_, begin_, note_, event_);
+    if (event_ != no_user_event_id) {
+      log_ = theTrace()->getLastTraceEvent();
+    }
+  }
 
   TraceScopedNote(TraceScopedNote const&) = delete;
   TraceScopedNote(TraceScopedNote &&other) noexcept
   {
     std::swap(begin_, other.begin_);
     std::swap(event_, other.event_);
     std::swap(note_, other.note_);
+    std::swap(log_, other.log_);
   }
 
   TraceScopedNote& operator=(TraceScopedNote const&) = delete;
@@ -292,6 +306,7 @@ struct TraceScopedNote final {
     std::swap(begin_, other.begin_);
     std::swap(event_, other.event_);
     std::swap(note_, other.note_);
+    std::swap(log_, other.log_);
     return *this;
   }
 
@@ -302,9 +317,9 @@ struct TraceScopedNote final {
    */
   void end() {
     if (event_ != no_user_event_id) {
-      auto end = TraceLite::getCurrentTime();
-      theTrace()->addUserBracketedNote(begin_, end, note_, event_);
-
+      double end = TraceLite::getCurrentTime();
+      log_->end_time = end;
+      theTrace()->decrementIncompleteEvents();
       event_ = no_user_event_id;
     }
   }
@@ -317,6 +332,7 @@ struct TraceScopedNote final {
   TimeType begin_         = TimeType{0.0};
   TraceEventIDType event_ = no_trace_event;
   std::string note_       = "";
+  Log* log_               = nullptr;
 };
 
 #else