From 77040fab16266864ebbe4cb0bd66276663bd2bd7 Mon Sep 17 00:00:00 2001 From: Jonathan Lifflander Date: Tue, 5 Sep 2023 13:52:25 -0700 Subject: [PATCH 01/20] #2187: trace: first fix regular user events without a note --- src/vt/trace/trace_lite.cc | 28 ++++++++++++++++++++++++---- src/vt/trace/trace_lite.h | 11 +++++++++-- src/vt/trace/trace_user.h | 15 ++++++++------- 3 files changed, 41 insertions(+), 13 deletions(-) diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index 06d574c782..426e478f2e 100644 --- a/src/vt/trace/trace_lite.cc +++ b/src/vt/trace/trace_lite.cc @@ -248,21 +248,41 @@ bool TraceLite::checkDynamicRuntimeEnabled(bool is_end_event) { (trace_enabled_cur_phase_ or is_end_event); } -void TraceLite::addUserEventBracketed( - UserEventIDType event, TimeType begin, TimeType end) { +void TraceLite::addUserEventBracketedBegin( + UserEventIDType event, double begin +) { if (not checkDynamicRuntimeEnabled()) { return; } vt_debug_print( normal, trace, - "Trace::addUserEventBracketed: event={:x}, begin={}, end={}\n", - event, begin, end); + "Trace::addUserEventBracketedBegin: event={:x}, begin={}\n", + event, begin + ); auto const type = TraceConstantsType::UserEventPair; NodeType const node = theContext()->getNode(); logEvent(LogType{begin, type, node, event, true}); +} + +void TraceLite::addUserEventBracketedEnd( + UserEventIDType event, double end +) { + if (not checkDynamicRuntimeEnabled()) { + return; + } + + vt_debug_print( + normal, trace, + "Trace::addUserEventBracketedEnd: event={:x}, end={}\n", + event, end + ); + + auto const type = TraceConstantsType::UserEventPair; + NodeType const node = theContext()->getNode(); + logEvent(LogType{end, type, node, event, false}); } diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index e1d53a4316..b34ac86959 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -166,13 +166,20 @@ struct TraceLite { void disableTracing(); /** - * \brief Log a bracketed user event with start and end time + * \brief Log a bracketed user event with begin time * * \param[in] event the ID for the sts file * \param[in] begin the begin time + */ + void addUserEventBracketedBegin(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 addUserEventBracketed(UserEventIDType event, TimeType begin, TimeType end); + void addUserEventBracketedEnd(UserEventIDType event, double end); /** * \brief Log a user bracketed event with a note diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index a9aa2a8d3e..dadfd827fd 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -174,6 +174,7 @@ struct TraceScopedEventHash final { str_(in_str) { event_ = registerEventHashed(str_); + theTrace()->addUserEventBracketedBegin(event_, begin_); } TraceScopedEventHash& operator=(TraceScopedEventHash const&) = delete; @@ -185,9 +186,8 @@ struct TraceScopedEventHash final { */ void end() { if (event_ != no_user_event_id) { - auto end = TraceLite::getCurrentTime(); - theTrace()->addUserEventBracketed(event_, begin_, end); - + double end = TraceLite::getCurrentTime(); + theTrace()->addUserEventBracketedEnd(event_, end); event_ = no_user_event_id; } } @@ -217,7 +217,9 @@ struct TraceScopedEvent final { explicit TraceScopedEvent(UserEventIDType event) : begin_(event != no_user_event_id ? TraceLite::getCurrentTime() : TimeType{0.}), event_(event) - { } + { + theTrace()->addUserEventBracketedBegin(event_, begin_); + } TraceScopedEvent(TraceScopedEvent const&) = delete; TraceScopedEvent(TraceScopedEvent &&other) noexcept @@ -241,9 +243,8 @@ struct TraceScopedEvent final { */ void end() { if (event_ != no_user_event_id) { - auto end = TraceLite::getCurrentTime(); - theTrace()->addUserEventBracketed(event_, begin_, end); - + double end = TraceLite::getCurrentTime(); + theTrace()->addUserEventBracketedEnd(event_, end); event_ = no_user_event_id; } } From 925bd43e6a8ebff1ad131f02f1c64a78ed7dbfa5 Mon Sep 17 00:00:00 2001 From: Jonathan Lifflander Date: Thu, 7 Sep 2023 14:34:38 -0700 Subject: [PATCH 02/20] #2187: trace: fix order of nested trace user events --- src/vt/trace/trace.cc | 3 ++- src/vt/trace/trace_lite.cc | 8 ++++++-- src/vt/trace/trace_lite.h | 23 ++++++++++++++++++++--- src/vt/trace/trace_user.cc | 13 ++++++++----- src/vt/trace/trace_user.h | 32 ++++++++++++++++++++++++-------- 5 files changed, 60 insertions(+), 19 deletions(-) diff --git a/src/vt/trace/trace.cc b/src/vt/trace/trace.cc index 83aff586a8..31f6ee58ef 100644 --- a/src/vt/trace/trace.cc +++ b/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) { diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index 426e478f2e..73695bcc16 100644 --- a/src/vt/trace/trace_lite.cc +++ b/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(theConfig()->vt_trace_flush_size)) { diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index b34ac86959..3766d7acd3 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -171,7 +171,7 @@ 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 @@ -179,7 +179,7 @@ struct TraceLite { * \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 log_file_; + std::size_t incomplete_events_ = 0; }; }} //end namespace vt::trace diff --git a/src/vt/trace/trace_user.cc b/src/vt/trace/trace_user.cc index 0733f68c04..c8bff3df2e 100644 --- a/src/vt/trace/trace_user.cc +++ b/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 } diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index dadfd827fd..bd54f2717f 100644 --- a/src/vt/trace/trace_user.h +++ b/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 @@ -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,7 +279,17 @@ 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 @@ -284,6 +297,7 @@ struct TraceScopedNote final { 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 From dde94d3e89d952cf597611d3e193398e7d8f6a37 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Tue, 2 Jul 2024 17:18:39 +0200 Subject: [PATCH 03/20] #2187: Redo some of the changes after resolving conflicts --- src/vt/trace/trace_lite.cc | 4 ++-- src/vt/trace/trace_lite.h | 6 +++--- src/vt/trace/trace_user.cc | 4 ++-- src/vt/trace/trace_user.h | 8 ++++---- 4 files changed, 11 insertions(+), 11 deletions(-) diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index 73695bcc16..a8786752d6 100644 --- a/src/vt/trace/trace_lite.cc +++ b/src/vt/trace/trace_lite.cc @@ -249,7 +249,7 @@ bool TraceLite::checkDynamicRuntimeEnabled(bool is_end_event) { } void TraceLite::addUserEventBracketedBeginTime( - UserEventIDType event, double begin + UserEventIDType event, TimeType begin ) { if (not checkDynamicRuntimeEnabled()) { return; @@ -268,7 +268,7 @@ void TraceLite::addUserEventBracketedBeginTime( } void TraceLite::addUserEventBracketedEndTime( - UserEventIDType event, double end + UserEventIDType event, TimeType end ) { if (not checkDynamicRuntimeEnabled()) { return; diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index 3766d7acd3..1eb8743cf3 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -171,7 +171,7 @@ struct TraceLite { * \param[in] event the ID for the sts file * \param[in] begin the begin time */ - void addUserEventBracketedBeginTime(UserEventIDType event, double begin); + void addUserEventBracketedBeginTime(UserEventIDType event, TimeType begin); /** * \brief Log a bracketed user event with end time @@ -179,7 +179,7 @@ struct TraceLite { * \param[in] event the ID for the sts file * \param[in] end the end time */ - void addUserEventBracketedEndTime(UserEventIDType event, double end); + void addUserEventBracketedEndTime(UserEventIDType event, TimeType end); /** * \brief Log a user bracketed event with a note @@ -251,7 +251,7 @@ struct TraceLite { /** * \brief Convert time in seconds to integer in microseconds * - * \param[in] time the time in seconds as double + * \param[in] time the time in seconds as TimeType * * \return time in microsecond as integer */ diff --git a/src/vt/trace/trace_user.cc b/src/vt/trace/trace_user.cc index c8bff3df2e..ba59e6d302 100644 --- a/src/vt/trace/trace_user.cc +++ b/src/vt/trace/trace_user.cc @@ -83,13 +83,13 @@ void addUserEvent([[maybe_unused]] UserEventIDType event) { #endif } -void addUserEventBracketedBeginTime(UserEventIDType event, double begin) { +void addUserEventBracketedBeginTime(UserEventIDType event, TimeType begin) { #if vt_check_enabled(trace_enabled) theTrace()->addUserEventBracketedBeginTime(event, begin); #endif } -void addUserEventBracketedEndTime(UserEventIDType event, double end) { +void addUserEventBracketedEndTime(UserEventIDType event, TimeType end) { #if vt_check_enabled(trace_enabled) theTrace()->addUserEventBracketedEndTime(event, end); #endif diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index bd54f2717f..893e27b76c 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -101,7 +101,7 @@ void addUserEvent(UserEventIDType event); * \param[in] begin the begin time * \param[in] end the end time */ -void addUserEventBracketed(UserEventIDType event, double begin, double end); +void addUserEventBracketed(UserEventIDType event, TimeType begin, TimeType end); /** * \brief Log a user note @@ -187,7 +187,7 @@ struct TraceScopedEventHash final { */ void end() { if (event_ != no_user_event_id) { - double end = TraceLite::getCurrentTime(); + auto end = TraceLite::getCurrentTime(); theTrace()->addUserEventBracketedEndTime(event_, end); event_ = no_user_event_id; } @@ -246,7 +246,7 @@ struct TraceScopedEvent final { */ void end() { if (event_ != no_user_event_id) { - double end = TraceLite::getCurrentTime(); + auto end = TraceLite::getCurrentTime(); theTrace()->addUserEventBracketedEndTime(event_, end); event_ = no_user_event_id; } @@ -317,7 +317,7 @@ struct TraceScopedNote final { */ void end() { if (event_ != no_user_event_id) { - double end = TraceLite::getCurrentTime(); + auto end = TraceLite::getCurrentTime(); log_->end_time = end; theTrace()->decrementIncompleteEvents(); event_ = no_user_event_id; From 9ce726a7dee47b93a88d288d5285adbc5988c19d Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Wed, 3 Jul 2024 17:18:45 +0200 Subject: [PATCH 04/20] #2187: Use TraceScopedNote instead of addUserBracketedNote(...) --- src/vt/event/event.cc | 9 ++++----- src/vt/messaging/active.cc | 32 +++++++++++++++---------------- src/vt/messaging/request_holder.h | 8 ++++---- src/vt/trace/trace_user.h | 5 +++++ 4 files changed, 29 insertions(+), 25 deletions(-) diff --git a/src/vt/event/event.cc b/src/vt/event/event.cc index c367a6cfcb..c02c4a9a3f 100644 --- a/src/vt/event/event.cc +++ b/src/vt/event/event.cc @@ -304,10 +304,9 @@ AsyncEvent::EventStateType AsyncEvent::testEventComplete(EventType const& event) void AsyncEvent::testEventsTrigger(int const& num_events) { # if vt_check_enabled(trace_enabled) int32_t num_completed = 0; - auto tr_begin = TimeType{0.0}; - + std::unique_ptr trace_note; if (theConfig()->vt_trace_event_polling) { - tr_begin = timing::getCurrentTime(); + trace_note = std::make_unique("", trace_event_polling); } # endif @@ -356,9 +355,9 @@ void AsyncEvent::testEventsTrigger(int const& num_events) { # if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_event_polling) { if (num_completed > 0) { - TimeType tr_end = timing::getCurrentTime(); auto tr_note = fmt::format("completed {} of {}", num_completed, cur); - trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_event_polling); + trace_note->setNote(tr_note); + trace_note->end(); } } else { (void)num_completed; diff --git a/src/vt/messaging/active.cc b/src/vt/messaging/active.cc index 02f3f61753..5d1e69f654 100644 --- a/src/vt/messaging/active.cc +++ b/src/vt/messaging/active.cc @@ -349,9 +349,9 @@ EventType ActiveMessenger::sendMsgMPI( { VT_ALLOW_MPI_CALLS; #if vt_check_enabled(trace_enabled) - auto tr_begin = TimeType{0.}; + std::unique_ptr trace_note; if (theConfig()->vt_trace_mpi) { - tr_begin = vt::timing::getCurrentTime(); + trace_note = std::make_unique("", trace_isend); } #endif int const ret = MPI_Isend( @@ -362,9 +362,9 @@ EventType ActiveMessenger::sendMsgMPI( #if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_mpi) { - auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format("Isend(AM): dest={}, bytes={}", dest, msg_size); - trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_isend); + trace_note->setNote(tr_note); + trace_note->end(); } #endif } @@ -581,9 +581,9 @@ std::tuple ActiveMessenger::sendDataMPI( ); { #if vt_check_enabled(trace_enabled) - auto tr_begin = TimeType{0.}; + std::unique_ptr trace_note; if (theConfig()->vt_trace_mpi) { - tr_begin = vt::timing::getCurrentTime(); + trace_note = std::make_unique("", trace_isend); } #endif @@ -603,9 +603,9 @@ std::tuple ActiveMessenger::sendDataMPI( #if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_mpi) { - auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format("Isend(Data): dest={}, bytes={}", dest, subsize); - trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_isend); + trace_note->setNote(tr_note); + trace_note->end(); } #endif } @@ -771,9 +771,9 @@ void ActiveMessenger::recvDataDirect( ); #if vt_check_enabled(trace_enabled) - auto tr_begin = TimeType{0.}; + std::unique_ptr trace_note; if (theConfig()->vt_trace_mpi) { - tr_begin = vt::timing::getCurrentTime(); + trace_note = std::make_unique("", trace_irecv); } #endif @@ -790,12 +790,12 @@ void ActiveMessenger::recvDataDirect( #if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_mpi) { - auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format( "Irecv(Data): from={}, bytes={}", from, sublen ); - trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_irecv); + trace_note->setNote(tr_note); + trace_note->end(); } #endif @@ -1008,9 +1008,9 @@ bool ActiveMessenger::tryProcessIncomingActiveMsg() { { #if vt_check_enabled(trace_enabled) - auto tr_begin = TimeType{0.}; + std::unique_ptr trace_note; if (theConfig()->vt_trace_mpi) { - tr_begin = vt::timing::getCurrentTime(); + trace_note = std::make_unique("", trace_irecv); } #endif @@ -1024,12 +1024,12 @@ bool ActiveMessenger::tryProcessIncomingActiveMsg() { #if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_mpi) { - auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format( "Irecv(AM): from={}, bytes={}", stat.MPI_SOURCE, num_probe_bytes ); - trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_irecv); + trace_note->setNote(tr_note); + trace_note->end(); } #endif } diff --git a/src/vt/messaging/request_holder.h b/src/vt/messaging/request_holder.h index bf48e5b098..f87c185281 100644 --- a/src/vt/messaging/request_holder.h +++ b/src/vt/messaging/request_holder.h @@ -98,9 +98,9 @@ struct RequestHolder { bool testAll(Callable c, int& num_mpi_tests) { # if vt_check_enabled(trace_enabled) std::size_t const holder_size_start = holder_.size(); - auto tr_begin = TimeType{0.0}; + std::unique_ptr trace_note; if (theConfig()->vt_trace_irecv_polling) { - tr_begin = vt::timing::getCurrentTime(); + trace_note = std::make_unique("", trace_user_event_); } # endif @@ -131,13 +131,13 @@ struct RequestHolder { # if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_irecv_polling) { if (holder_size_start > 0) { - auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format( "completed {} of {}", holder_size_start - holder_.size(), holder_size_start ); - trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_user_event_); + trace_note->setNote(tr_note); + trace_note->end(); } } # endif diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index 893e27b76c..6bdf198ece 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -319,6 +319,7 @@ struct TraceScopedNote final { if (event_ != no_user_event_id) { auto end = TraceLite::getCurrentTime(); log_->end_time = end; + log_->setUserNote(note_); theTrace()->decrementIncompleteEvents(); event_ = no_user_event_id; } @@ -328,6 +329,10 @@ struct TraceScopedNote final { event_ = in_event; } + void setNote(std::string const& in_note) { + note_ = in_note; + } + private: TimeType begin_ = TimeType{0.0}; TraceEventIDType event_ = no_trace_event; From ab03f7c6b7f781c1ab236d381be7913261db3342 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Fri, 5 Jul 2024 15:35:54 +0200 Subject: [PATCH 05/20] #2187: Fix order of traces for addUserNotePre/Epi --- src/vt/trace/trace_user.cc | 31 ++++++++++++++----------------- src/vt/trace/trace_user.h | 6 ++++++ 2 files changed, 20 insertions(+), 17 deletions(-) diff --git a/src/vt/trace/trace_user.cc b/src/vt/trace/trace_user.cc index ba59e6d302..89a5eace7c 100644 --- a/src/vt/trace/trace_user.cc +++ b/src/vt/trace/trace_user.cc @@ -118,39 +118,36 @@ void addUserBracketedNote( } #if vt_check_enabled(trace_enabled) -struct UserSplitHolder final { - static std::unordered_map split_; +struct UserNoteHolder final { + static std::unordered_map notes_; }; -/*static*/ std::unordered_map UserSplitHolder::split_ = {}; +/*static*/ std::unordered_map UserNoteHolder::notes_ = {}; #endif void addUserNotePre( - [[maybe_unused]] std::string const& note, - [[maybe_unused]] TraceEventIDType const + [[maybe_unused]] std::string const& in_note, + [[maybe_unused]] TraceEventIDType const in_event ) { #if vt_check_enabled(trace_enabled) - auto iter = UserSplitHolder::split_.find(note); - vtAssertExpr(iter == UserSplitHolder::split_.end()); - UserSplitHolder::split_.emplace( + auto iter = UserNoteHolder::notes_.find(in_note); + vtAssertExpr(iter == UserNoteHolder::notes_.end()); + UserNoteHolder::notes_.emplace( std::piecewise_construct, - std::forward_as_tuple(note), - std::forward_as_tuple(Trace::getCurrentTime()) + std::forward_as_tuple(in_note), + std::forward_as_tuple(in_note, in_event) ); #endif } void addUserNoteEpi( [[maybe_unused]] std::string const& in_note, - [[maybe_unused]] TraceEventIDType const event + [[maybe_unused]] TraceEventIDType const in_event ) { #if vt_check_enabled(trace_enabled) - auto iter = UserSplitHolder::split_.find(in_note); - vtAssertExpr(iter != UserSplitHolder::split_.end()); - auto begin = iter->second; - auto end = Trace::getCurrentTime(); - theTrace()->addUserBracketedNote(begin, end, in_note, event); - UserSplitHolder::split_.erase(iter); + auto iter = UserNoteHolder::notes_.find(in_note); + vtAssertExpr(iter != UserNoteHolder::notes_.end()); + UserNoteHolder::notes_.erase(iter); #endif } diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index 6bdf198ece..29e70d0f7c 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -135,6 +135,9 @@ void addUserBracketedNote( /** * \brief Log the start for a bracketed user event with a note + * + * \note See \c TraceScopedNote for a safer scope-based logging mechanism for + * bracketed user events with a note. * * \param[in] note the note * \param[in] event the pre-registered user event ID @@ -144,6 +147,9 @@ void addUserNotePre(std::string const& note, TraceEventIDType const event); /** * \brief Log the end for a bracketed user event with a note * + * \note See \c TraceScopedNote for a safer scope-based logging mechanism for + * bracketed user events with a note. + * * \param[in] note the note * \param[in] event the pre-registered user event ID */ From 51d159455bafd0f5f1ba3a39b3e15c22d1f86f27 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Fri, 5 Jul 2024 18:56:24 +0200 Subject: [PATCH 06/20] #2187: Rework the bracketed user note --- src/vt/trace/trace_lite.cc | 48 ++++++++++++++++++++++---- src/vt/trace/trace_lite.h | 42 +++++++++++----------- src/vt/trace/trace_log.h | 1 - src/vt/trace/trace_user.cc | 22 ------------ src/vt/trace/trace_user.h | 71 +++++++++----------------------------- 5 files changed, 78 insertions(+), 106 deletions(-) diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index a8786752d6..996b745914 100644 --- a/src/vt/trace/trace_lite.cc +++ b/src/vt/trace/trace_lite.cc @@ -286,25 +286,59 @@ void TraceLite::addUserEventBracketedEndTime( logEvent(LogType{end, type, node, event, false}); } -void TraceLite::addUserBracketedNote( - TimeType const begin, TimeType const end, std::string const& note, - TraceEventIDType const event +void TraceLite::addUserNoteBracketedBeginTime( + std::string const& note, TraceEventIDType const event ) { if (not checkDynamicRuntimeEnabled()) { return; } + auto begin = getCurrentTime(); vt_debug_print( normal, trace, - "Trace::addUserBracketedNote: begin={}, end={}, note={}, event={}\n", - begin, end, note, event + "Trace::addUserNoteBracketedBeginTime: begin={}, note={}, event={}\n", + begin, note, event ); auto const type = TraceConstantsType::UserSuppliedBracketedNote; + logEvent(LogType{begin, begin, type, note, event}); - logEvent(LogType{begin, end, type, note, event}); + // Save event log for fixing up the end time later + if (event != no_user_event_id) { + auto* last_trace = getLastTraceEvent(); + incomplete_notes_[event].push(last_trace); + } } +void TraceLite::addUserNoteBracketedEndTime( + std::string const& note, TraceEventIDType const event +) { + if (not checkDynamicRuntimeEnabled()) { + return; + } + auto end = getCurrentTime(); + + vt_debug_print( + normal, trace, + "Trace::addUserNoteBracketedEndTime: end={}, note={}, event={}\n", + end, note, event + ); + + // Fixup end time of the note + if (event != no_user_event_id) { + auto iter = incomplete_notes_.find(event); + vtAssertExpr(iter != incomplete_notes_.end()); + // update data in the Log + auto& last_trace = iter->second.top(); + last_trace->end_time = end; + last_trace->setUserNote(note); + // clean up pointers to Log + iter->second.pop(); + if (iter->second.empty()) { + incomplete_notes_.erase(iter); + } + } +} TraceEventIDType TraceLite::logEvent(LogType&& log) { if (not checkDynamicRuntimeEnabled()) { @@ -468,7 +502,7 @@ void TraceLite::flushTracesFile(bool useGlobalSync) { // (Consider pushing out: barrier usages are probably domain-specific.) theCollective()->barrier(); } - if (incomplete_events_ > 0) { + if (incomplete_notes_.size() > 0) { // wait until all incomplete events are patched up before flushing to disk return; } diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index 1eb8743cf3..7952d3f835 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -54,6 +54,7 @@ #include #include #include +#include #include namespace vt { namespace trace { @@ -184,14 +185,27 @@ struct TraceLite { /** * \brief Log a user bracketed event with a note * - * \param[in] begin the begin time - * \param[in] end the end time + * \note See \c TraceScopedNote for a safer scope-based logging mechanism for + * bracketed user events with a note. + * + * \param[in] note the note to log + * \param[in] event the event ID + */ + void addUserNoteBracketedBeginTime( + std::string const& note, TraceEventIDType const event = no_trace_event + ); + + /** + * \brief Log a user bracketed event with a note + * + * \note See \c TraceScopedNote for a safer scope-based logging mechanism for + * bracketed user events with a note. + * * \param[in] note the note to log * \param[in] event the event ID */ - void addUserBracketedNote( - TimeType const begin, TimeType const end, std::string const& note, - TraceEventIDType const event = no_trace_event + void addUserNoteBracketedEndTime( + std::string const& note, TraceEventIDType const event = no_trace_event ); /** @@ -277,22 +291,6 @@ struct TraceLite { 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 @@ -420,7 +418,7 @@ struct TraceLite { bool trace_enabled_cur_phase_ = true; bool idle_begun_ = false; std::unique_ptr log_file_; - std::size_t incomplete_events_ = 0; + std::unordered_map> incomplete_notes_ = {}; }; }} //end namespace vt::trace diff --git a/src/vt/trace/trace_log.h b/src/vt/trace/trace_log.h index 1b8443f700..3dab0be4e3 100644 --- a/src/vt/trace/trace_log.h +++ b/src/vt/trace/trace_log.h @@ -223,7 +223,6 @@ struct Log final { } }; - // [[deprecated]]] - use appropriate ctor void setUserNote(std::string const& note) { if (data.user.data_type == LogDataType::user) { data.user.user_note = note; diff --git a/src/vt/trace/trace_user.cc b/src/vt/trace/trace_user.cc index 89a5eace7c..baf10698fd 100644 --- a/src/vt/trace/trace_user.cc +++ b/src/vt/trace/trace_user.cc @@ -83,18 +83,6 @@ void addUserEvent([[maybe_unused]] UserEventIDType event) { #endif } -void addUserEventBracketedBeginTime(UserEventIDType event, TimeType begin) { -#if vt_check_enabled(trace_enabled) - theTrace()->addUserEventBracketedBeginTime(event, begin); -#endif -} - -void addUserEventBracketedEndTime(UserEventIDType event, TimeType end) { -#if vt_check_enabled(trace_enabled) - theTrace()->addUserEventBracketedEndTime(event, end); -#endif -} - void addUserNote([[maybe_unused]] std::string const& note) { #if vt_check_enabled(trace_enabled) theTrace()->addUserNote(note); @@ -107,16 +95,6 @@ void addUserData([[maybe_unused]] int32_t data) { #endif } -void addUserBracketedNote( - [[maybe_unused]] TimeType const begin, [[maybe_unused]] TimeType const end, - [[maybe_unused]] std::string const& note, - [[maybe_unused]] TraceEventIDType const event -) { -#if vt_check_enabled(trace_enabled) - theTrace()->addUserBracketedNote(begin, end, note, event); -#endif -} - #if vt_check_enabled(trace_enabled) struct UserNoteHolder final { static std::unordered_map notes_; diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index 29e70d0f7c..cb5fb05cec 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -91,18 +91,6 @@ UserEventIDType registerEventHashed(std::string const& name); */ void addUserEvent(UserEventIDType event); -/** - * \brief Log a bracketed user event - * - * \note See \c TraceScopedEvent for a safer scope-based logging mechanism for - * bracketed user events. - * - * \param[in] event the event ID to log - * \param[in] begin the begin time - * \param[in] end the end time - */ -void addUserEventBracketed(UserEventIDType event, TimeType begin, TimeType end); - /** * \brief Log a user note * @@ -117,22 +105,6 @@ void addUserNote(std::string const& note); */ void addUserData(int32_t data); -/** - * \brief Log a bracketed user event with a note - * - * \note See \c TraceScopedNote for a safer scope-based logging mechanism for - * bracketed user events with a note. - * - * \param[in] begin the begin time - * \param[in] end the end time - * \param[in] note the note to log - * \param[in] event the event ID to log - */ -void addUserBracketedNote( - TimeType const begin, TimeType const end, std::string const& note, - TraceEventIDType const event = no_trace_event -); - /** * \brief Log the start for a bracketed user event with a note * @@ -282,37 +254,37 @@ struct TraceScopedNote final { */ TraceScopedNote( std::string const& in_note, TraceEventIDType const in_event = no_trace_event - ) : begin_(in_event != no_trace_event ? TraceLite::getCurrentTime() : TimeType{0.}), - event_(in_event), + ) : 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(); - } + theTrace()->addUserNoteBracketedBeginTime(note_, event_); + } + + /** + * \brief Construct a scoped event with an empty note + * + * \param[in] event the user event to log (e.g., may be obtained from + * \c registerEventCollective ) + */ + TraceScopedNote(TraceEventIDType const in_event = no_trace_event) + : event_(in_event), + note_("") + { + theTrace()->addUserNoteBracketedBeginTime(note_, event_); } 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; TraceScopedNote& operator=(TraceScopedNote &&other) noexcept { - std::swap(begin_, other.begin_); std::swap(event_, other.event_); std::swap(note_, other.note_); - std::swap(log_, other.log_); return *this; } @@ -323,27 +295,18 @@ struct TraceScopedNote final { */ void end() { if (event_ != no_user_event_id) { - auto end = TraceLite::getCurrentTime(); - log_->end_time = end; - log_->setUserNote(note_); - theTrace()->decrementIncompleteEvents(); + theTrace()->addUserNoteBracketedEndTime(note_, event_); event_ = no_user_event_id; } } - void setEvent(TraceEventIDType const in_event) { - event_ = in_event; - } - void setNote(std::string const& in_note) { note_ = in_note; } private: - TimeType begin_ = TimeType{0.0}; TraceEventIDType event_ = no_trace_event; std::string note_ = ""; - Log* log_ = nullptr; }; #else @@ -352,7 +315,7 @@ struct TraceScopedNote final { TraceScopedNote(std::string const&, TraceEventIDType const = no_trace_event) { } void end() { } - void setEvent([[maybe_unused]] TraceEventIDType const in_event) { } + void setNote([[maybe_unused]] std::string const& in_note) { } }; struct TraceScopedEvent final { From ca54c34a7ad4ed1a097fadcc9e3628b85862e2a7 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Fri, 5 Jul 2024 18:57:06 +0200 Subject: [PATCH 07/20] #2187: Use new constructor of TraceScopedNote without an empty note --- src/vt/event/event.cc | 2 +- src/vt/messaging/active.cc | 8 ++++---- src/vt/messaging/request_holder.h | 2 +- src/vt/trace/trace_user.h | 2 +- 4 files changed, 7 insertions(+), 7 deletions(-) diff --git a/src/vt/event/event.cc b/src/vt/event/event.cc index c02c4a9a3f..e721f127f4 100644 --- a/src/vt/event/event.cc +++ b/src/vt/event/event.cc @@ -306,7 +306,7 @@ void AsyncEvent::testEventsTrigger(int const& num_events) { int32_t num_completed = 0; std::unique_ptr trace_note; if (theConfig()->vt_trace_event_polling) { - trace_note = std::make_unique("", trace_event_polling); + trace_note = std::make_unique(trace_event_polling); } # endif diff --git a/src/vt/messaging/active.cc b/src/vt/messaging/active.cc index 5d1e69f654..1c6e1d0aaf 100644 --- a/src/vt/messaging/active.cc +++ b/src/vt/messaging/active.cc @@ -351,7 +351,7 @@ EventType ActiveMessenger::sendMsgMPI( #if vt_check_enabled(trace_enabled) std::unique_ptr trace_note; if (theConfig()->vt_trace_mpi) { - trace_note = std::make_unique("", trace_isend); + trace_note = std::make_unique(trace_isend); } #endif int const ret = MPI_Isend( @@ -583,7 +583,7 @@ std::tuple ActiveMessenger::sendDataMPI( #if vt_check_enabled(trace_enabled) std::unique_ptr trace_note; if (theConfig()->vt_trace_mpi) { - trace_note = std::make_unique("", trace_isend); + trace_note = std::make_unique(trace_isend); } #endif @@ -773,7 +773,7 @@ void ActiveMessenger::recvDataDirect( #if vt_check_enabled(trace_enabled) std::unique_ptr trace_note; if (theConfig()->vt_trace_mpi) { - trace_note = std::make_unique("", trace_irecv); + trace_note = std::make_unique(trace_irecv); } #endif @@ -1010,7 +1010,7 @@ bool ActiveMessenger::tryProcessIncomingActiveMsg() { #if vt_check_enabled(trace_enabled) std::unique_ptr trace_note; if (theConfig()->vt_trace_mpi) { - trace_note = std::make_unique("", trace_irecv); + trace_note = std::make_unique(trace_irecv); } #endif diff --git a/src/vt/messaging/request_holder.h b/src/vt/messaging/request_holder.h index f87c185281..552e0e92c4 100644 --- a/src/vt/messaging/request_holder.h +++ b/src/vt/messaging/request_holder.h @@ -100,7 +100,7 @@ struct RequestHolder { std::size_t const holder_size_start = holder_.size(); std::unique_ptr trace_note; if (theConfig()->vt_trace_irecv_polling) { - trace_note = std::make_unique("", trace_user_event_); + trace_note = std::make_unique(trace_user_event_); } # endif diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index cb5fb05cec..f5ab06ac80 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -107,7 +107,7 @@ void addUserData(int32_t data); /** * \brief Log the start for a bracketed user event with a note - * + * * \note See \c TraceScopedNote for a safer scope-based logging mechanism for * bracketed user events with a note. * From 46b9cc8edb3dbbb87431a38d9bcb4671726f229d Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Mon, 8 Jul 2024 17:51:00 +0200 Subject: [PATCH 08/20] #2187: Update TraceScopedNote to prevent tracing without user event ID --- src/vt/trace/trace_user.h | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index f5ab06ac80..dbfc96e40b 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -257,7 +257,9 @@ struct TraceScopedNote final { ) : event_(in_event), note_(in_note) { - theTrace()->addUserNoteBracketedBeginTime(note_, event_); + if (event_ != no_user_event_id) { + theTrace()->addUserNoteBracketedBeginTime(note_, event_); + } } /** @@ -270,7 +272,9 @@ struct TraceScopedNote final { : event_(in_event), note_("") { - theTrace()->addUserNoteBracketedBeginTime(note_, event_); + if (event_ != no_user_event_id) { + theTrace()->addUserNoteBracketedBeginTime(note_, event_); + } } TraceScopedNote(TraceScopedNote const&) = delete; From 7f653d8d52550d4a8d67714e8d360e6d3d630d5d Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Mon, 8 Jul 2024 17:51:37 +0200 Subject: [PATCH 09/20] #2187: Add tests for user tracing behavior --- tests/unit/trace/test_trace_user.cc | 353 ++++++++++++++++++++++++++++ 1 file changed, 353 insertions(+) create mode 100644 tests/unit/trace/test_trace_user.cc diff --git a/tests/unit/trace/test_trace_user.cc b/tests/unit/trace/test_trace_user.cc new file mode 100644 index 0000000000..1533df5657 --- /dev/null +++ b/tests/unit/trace/test_trace_user.cc @@ -0,0 +1,353 @@ +/* +//@HEADER +// ***************************************************************************** +// +// test_trace_user.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 "test_parallel_harness.h" +#include "test_helpers.h" + +#if vt_check_enabled(trace_enabled) + +#include +#include + +#include +#include + +namespace vt { namespace tests { namespace unit { + +struct TestTraceUser : TestParallelHarness { + // Set dir for tracing to be the same as test name + void addAdditionalArgs() override { + trace_dir = fmt::format( + "--vt_trace_dir={}", + ::testing::UnitTest::GetInstance()->current_test_info()->name()); + addArgs(trace_dir); + addArgs(flush); + } + + virtual void TearDown() override { + TestHarnessAny::TearDown(); + } + + static void stopVt() { + try { + vt::theSched()->runSchedulerWhile([] { return !rt->isTerminated(); }); + } catch (std::exception& e) { + ADD_FAILURE() << fmt::format("Caught an exception: {}\n", e.what()); + } + +#if DEBUG_TEST_HARNESS_PRINT + auto const& my_node = theContext()->getNode(); + fmt::print("my_node={}, tearing down runtime\n", my_node); +#endif + + CollectiveOps::finalize(); + } + +private: + std::string trace_dir; + // must be != 0 for the test to work + std::string flush = "--vt_trace_flush_size=100"; +}; + +void validateLine(const std::string line, int& time) { + using vt::trace::eTraceConstants; + + // skip header (starts with P) + if (line.front() == 80) { + return; + } + // Split to tokens + std::stringstream stream(line); + std::vector tokens; + std::string token; + while (stream >> token) { + tokens.push_back(token); + } + + // validate the start time + int start_time = 0; + bool check_time = true; + eTraceConstants type = static_cast(std::stoi(tokens[0])); + switch(type) { + case eTraceConstants::Creation: // 1 + case eTraceConstants::BeginProcessing: // 2 + case eTraceConstants::EndProcessing: // 3 + start_time = std::stoi(tokens[3]); + break; + case eTraceConstants::UserEvent: // 13 + case eTraceConstants::UserSupplied: // 26 + case eTraceConstants::BeginUserEventPair: // 98 + case eTraceConstants::EndUserEventPair: // 99 + start_time = std::stoi(tokens[2]); + break; + case eTraceConstants::BeginComputation: // 6 + case eTraceConstants::EndComputation: // 7 + case eTraceConstants::BeginIdle: // 14 + case eTraceConstants::EndIdle: // 15 + case eTraceConstants::UserSuppliedNote: // 28 + case eTraceConstants::UserSuppliedBracketedNote: // 29 + start_time = std::stoi(tokens[1]); + break; + default: + check_time = false; + } + + if (check_time) { + EXPECT_GE(start_time, time); + time = start_time; + } +} + +void validateAllTraceFiles() { + std::string test_name = + ::testing::UnitTest::GetInstance()->current_test_info()->name(); + std::filesystem::path path = std::filesystem::current_path() / test_name / ""; + std::string ext = ".gz"; + + // iterate over files in test output directory + for (const auto& file : std::filesystem::directory_iterator(path)) { + if (file.path().extension() == ext) { + auto log_file_ = + std::make_shared(gzopen(file.path().c_str(), "rb")); + EXPECT_TRUE(nullptr != log_file_); + + // should be more than enough + char buffer[4096]; + int bytesRead = gzread(*log_file_, buffer, sizeof(buffer)); + EXPECT_GT(bytesRead, 0); + + std::istringstream stream(std::string(buffer, bytesRead)); + + int lastStartTime = 0; + std::string line; + // read line by line all validate start time + while (std::getline(stream, line)) { + validateLine(line, lastStartTime); + } + } + } +} + +TEST_F(TestTraceUser, trace_user_add_note_pre_epi) { + if (!theTrace()->checkDynamicRuntimeEnabled()) { + TestTraceUser::stopVt(); + GTEST_SKIP() << "trace tests require --vt_trace to be set"; + } + + // Only the begging of the note + { + trace::addUserNotePre("some note", 2); + trace::addUserNoteEpi("some note", 2); // will crash without it + } + // Two opening notes with the same id + { + // trace::addUserNotePre("note 1", 5); // will crash + // trace::addUserNotePre("note 2", 5); // will crash + } + // note with events in between + { + trace::addUserEvent(901); + trace::addUserNotePre("TEST NOTE", 10); + trace::addUserEvent(902); + trace::addUserNoteEpi("TEST NOTE", 10); + trace::addUserEvent(903); + } + + TestTraceUser::stopVt(); + validateAllTraceFiles(); +} + +TEST_F(TestTraceUser, trace_user_scoped_event_hash) { + if (!theTrace()->checkDynamicRuntimeEnabled()) { + TestTraceUser::stopVt(); + GTEST_SKIP() << "trace tests require --vt_trace to be set"; + } + + // single event + { + trace::TraceScopedEventHash("test_event"); + } + // a few events + { + auto ev1 = trace::TraceScopedEventHash("test_event_1"); + auto ev2 = trace::TraceScopedEventHash("test_event_2"); + auto ev3 = trace::TraceScopedEventHash("test_event_3"); + } + // nested events + { + auto ev1 = trace::TraceScopedEventHash("test_event_1"); + { + auto ev2 = trace::TraceScopedEventHash("test_event_2"); + { + auto ev3 = trace::TraceScopedEventHash("test_event_3"); + } + } + } + + TestTraceUser::stopVt(); + validateAllTraceFiles(); +} + +TEST_F(TestTraceUser, trace_user_scoped_event) { + if (!theTrace()->checkDynamicRuntimeEnabled()) { + TestTraceUser::stopVt(); + GTEST_SKIP() << "trace tests require --vt_trace to be set"; + } + + // single event + { + trace::TraceScopedEvent(123); + } + // a few events + { + auto ev1 = trace::TraceScopedEvent(1); + auto ev2 = trace::TraceScopedEvent(2); + auto ev3 = trace::TraceScopedEvent(3); + } + // nested + { + auto ev1 = trace::TraceScopedEvent(123); + { + auto ev2 = trace::TraceScopedEvent(123); + { + auto ev3 = trace::TraceScopedEvent(123); + } + } + } + + TestTraceUser::stopVt(); + validateAllTraceFiles(); +} + +TEST_F(TestTraceUser, trace_user_scoped_note) { + if (!theTrace()->checkDynamicRuntimeEnabled()) { + TestTraceUser::stopVt(); + GTEST_SKIP() << "trace tests require --vt_trace to be set"; + } + + // single note + { + trace::TraceScopedNote(123); + trace::TraceScopedNote("Some note", 456); + + auto note1 = trace::TraceScopedNote(1); + auto note2 = trace::TraceScopedNote("note", 2); + auto note3 = trace::TraceScopedNote(3); + } + // nested + { + auto note11 = trace::TraceScopedNote(123); + auto note12 = trace::TraceScopedNote("test", 456); + { + auto note21 = trace::TraceScopedNote(123); + auto note22 = trace::TraceScopedNote("test 2", 456); + { + auto note31 = trace::TraceScopedNote(123); + auto note32 = trace::TraceScopedNote("test 3", 456); + } + } + } + + TestTraceUser::stopVt(); + validateAllTraceFiles(); +} + +TEST_F(TestTraceUser, trace_user_note_bracketed) { + if (!theTrace()->checkDynamicRuntimeEnabled()) { + TestTraceUser::stopVt(); + GTEST_SKIP() << "trace tests require --vt_trace to be set"; + } + + theTrace()->addUserNoteBracketedBeginTime("", 10); + theTrace()->addUserNoteBracketedBeginTime("", 10); + theTrace()->addUserNoteBracketedBeginTime("", 10); + theTrace()->addUserNoteBracketedBeginTime("", 12); + + theTrace()->addUserEvent(901); + trace::addUserNote("Note 0"); + theTrace()->addUserEvent(902); + + theTrace()->addUserNoteBracketedEndTime("INNER INNER INNER TEST NOTE 10", 12); + trace::addUserNote("Note 1"); + theTrace()->addUserNoteBracketedEndTime("INNER INNER TEST NOTE 10", 10); + trace::addUserNote("Note 2"); + theTrace()->addUserNoteBracketedEndTime("INNER TEST NOTE 10", 10); + trace::addUserNote("Note 3"); + theTrace()->addUserNoteBracketedEndTime("OUTER TEST NOTE 10", 10); + trace::addUserNote("Note 4"); + + TestTraceUser::stopVt(); + validateAllTraceFiles(); +} + +TEST_F(TestTraceUser, trace_user_bracketed_event) { + if (!theTrace()->checkDynamicRuntimeEnabled()) { + TestTraceUser::stopVt(); + GTEST_SKIP() << "trace tests require --vt_trace to be set"; + } + + theTrace()->addUserEvent(124); + theTrace()->addUserNote("Some Note"); + + theTrace()->addUserEventBracketedBegin(1); + theTrace()->addUserEventBracketedBegin(2); + theTrace()->addUserEventBracketedEnd(2); + theTrace()->addUserEventBracketedBegin(3); + + theTrace()->addUserEventManual(123); + theTrace()->addUserData(123456789); + + theTrace()->addUserEventBracketedEnd(1); + theTrace()->addUserEventBracketedEnd(3); + + theTrace()->addUserNote("Some Note 2"); + theTrace()->addUserData(123456); + theTrace()->addUserEvent(124); + + TestTraceUser::stopVt(); + validateAllTraceFiles(); +} + +}}} // end namespace vt::tests::unit + +#endif // vt_check_enabled(trace_enabled) From 38d7ca6e0ba6f9146697e8fdada45aa3d1b83625 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Tue, 9 Jul 2024 15:27:58 +0200 Subject: [PATCH 10/20] #2187: Fix for crash which could occur when stopping the vt --- src/vt/trace/trace_user.cc | 24 ++++++------------------ 1 file changed, 6 insertions(+), 18 deletions(-) diff --git a/src/vt/trace/trace_user.cc b/src/vt/trace/trace_user.cc index baf10698fd..f6e5299568 100644 --- a/src/vt/trace/trace_user.cc +++ b/src/vt/trace/trace_user.cc @@ -95,26 +95,14 @@ void addUserData([[maybe_unused]] int32_t data) { #endif } -#if vt_check_enabled(trace_enabled) -struct UserNoteHolder final { - static std::unordered_map notes_; -}; - -/*static*/ std::unordered_map UserNoteHolder::notes_ = {}; -#endif - void addUserNotePre( [[maybe_unused]] std::string const& in_note, [[maybe_unused]] TraceEventIDType const in_event ) { #if vt_check_enabled(trace_enabled) - auto iter = UserNoteHolder::notes_.find(in_note); - vtAssertExpr(iter == UserNoteHolder::notes_.end()); - UserNoteHolder::notes_.emplace( - std::piecewise_construct, - std::forward_as_tuple(in_note), - std::forward_as_tuple(in_note, in_event) - ); + if (in_event != no_user_event_id) { + theTrace()->addUserNoteBracketedBeginTime(in_note, in_event); + } #endif } @@ -123,9 +111,9 @@ void addUserNoteEpi( [[maybe_unused]] TraceEventIDType const in_event ) { #if vt_check_enabled(trace_enabled) - auto iter = UserNoteHolder::notes_.find(in_note); - vtAssertExpr(iter != UserNoteHolder::notes_.end()); - UserNoteHolder::notes_.erase(iter); + if (in_event != no_user_event_id) { + theTrace()->addUserNoteBracketedEndTime(in_note, in_event); + } #endif } From 58cf5d35ae308550e00479bb1b09d180dbf13957 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Tue, 9 Jul 2024 15:28:34 +0200 Subject: [PATCH 11/20] #2187: Add additional checks in tests for validating the end time --- tests/unit/trace/test_trace_user.cc | 31 +++++++++++++++++------------ 1 file changed, 18 insertions(+), 13 deletions(-) diff --git a/tests/unit/trace/test_trace_user.cc b/tests/unit/trace/test_trace_user.cc index 1533df5657..c16ced42ce 100644 --- a/tests/unit/trace/test_trace_user.cc +++ b/tests/unit/trace/test_trace_user.cc @@ -61,7 +61,6 @@ struct TestTraceUser : TestParallelHarness { "--vt_trace_dir={}", ::testing::UnitTest::GetInstance()->current_test_info()->name()); addArgs(trace_dir); - addArgs(flush); } virtual void TearDown() override { @@ -85,8 +84,6 @@ struct TestTraceUser : TestParallelHarness { private: std::string trace_dir; - // must be != 0 for the test to work - std::string flush = "--vt_trace_flush_size=100"; }; void validateLine(const std::string line, int& time) { @@ -105,13 +102,14 @@ void validateLine(const std::string line, int& time) { } // validate the start time - int start_time = 0; - bool check_time = true; + int start_time = 0, end_time = 0; + bool check_start_time = true, check_end_time = false; eTraceConstants type = static_cast(std::stoi(tokens[0])); switch(type) { case eTraceConstants::Creation: // 1 case eTraceConstants::BeginProcessing: // 2 case eTraceConstants::EndProcessing: // 3 + case eTraceConstants::CreationBcast: // 20 start_time = std::stoi(tokens[3]); break; case eTraceConstants::UserEvent: // 13 @@ -125,17 +123,25 @@ void validateLine(const std::string line, int& time) { case eTraceConstants::BeginIdle: // 14 case eTraceConstants::EndIdle: // 15 case eTraceConstants::UserSuppliedNote: // 28 + start_time = std::stoi(tokens[1]); + break; + // those with end time case eTraceConstants::UserSuppliedBracketedNote: // 29 start_time = std::stoi(tokens[1]); + end_time = std::stoi(tokens[2]); + check_end_time = true; break; default: - check_time = false; + check_start_time = false; } - if (check_time) { + if (check_start_time) { EXPECT_GE(start_time, time); time = start_time; } + if (check_end_time) { + EXPECT_GE(end_time, start_time); + } } void validateAllTraceFiles() { @@ -177,12 +183,11 @@ TEST_F(TestTraceUser, trace_user_add_note_pre_epi) { // Only the begging of the note { trace::addUserNotePre("some note", 2); - trace::addUserNoteEpi("some note", 2); // will crash without it } // Two opening notes with the same id { - // trace::addUserNotePre("note 1", 5); // will crash - // trace::addUserNotePre("note 2", 5); // will crash + trace::addUserNotePre("note 1", 5); + trace::addUserNotePre("note 2", 5); } // note with events in between { @@ -333,13 +338,13 @@ TEST_F(TestTraceUser, trace_user_bracketed_event) { theTrace()->addUserEventBracketedBegin(2); theTrace()->addUserEventBracketedEnd(2); theTrace()->addUserEventBracketedBegin(3); - + theTrace()->addUserEventManual(123); theTrace()->addUserData(123456789); - + theTrace()->addUserEventBracketedEnd(1); theTrace()->addUserEventBracketedEnd(3); - + theTrace()->addUserNote("Some Note 2"); theTrace()->addUserData(123456); theTrace()->addUserEvent(124); From 21edbf4110da2a4779cc5eba85cf2558a3a50a0e Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Mon, 22 Jul 2024 15:43:20 +0200 Subject: [PATCH 12/20] #2187: Add a note to the documentation about incomplete notes --- docs/md/trace.md | 11 ++++++++++- src/vt/trace/trace_lite.h | 3 +++ 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/docs/md/trace.md b/docs/md/trace.md index 0b3e0f0367..d8e3eb363d 100644 --- a/docs/md/trace.md +++ b/docs/md/trace.md @@ -19,4 +19,13 @@ In order to customize when tracing is enabled and disabled, a trace specification file can be passed to \vt via a command-line flag: `--vt_trace_spec --vt_trace_spec_file=filename.spec`. -For details about vt's Specification File see \ref spec-file \ No newline at end of file +For details about vt's Specification File see \ref spec-file + +\section incremental-tracing Incremental Trace Output + +The trace events can be configured to be saved to the file in the incremental matter. +To configure the interval of the flushes use the `--vt_trace_flush_size=X` parameter. +The `X` stands for the number of trace events before the next flush. + +\note The incremental flushing will be blocked in the case of an incomplete user notes. +In that scenario there will be no output to the files. All trace events will be kept in memory and will be tried to be flushed on the next interval if the incomplete notes where closed. diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index 7952d3f835..748a30a2a5 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -236,6 +236,9 @@ struct TraceLite { /** * \brief Flush traces to file * + * \note The flush will be blocked when having an incomplete user notes. + * In that case method will not flush any traces. + * * \param[in] useGlobalSync whether a global sync should be invoked before * flushing output */ From 782a6a7617ca27f23f3bada7d91f361354240a0f Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Mon, 5 Aug 2024 13:19:10 -0400 Subject: [PATCH 13/20] #2187: Fix typos in trace.md --- docs/md/trace.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/md/trace.md b/docs/md/trace.md index d8e3eb363d..e2433676c2 100644 --- a/docs/md/trace.md +++ b/docs/md/trace.md @@ -27,5 +27,5 @@ The trace events can be configured to be saved to the file in the incremental ma To configure the interval of the flushes use the `--vt_trace_flush_size=X` parameter. The `X` stands for the number of trace events before the next flush. -\note The incremental flushing will be blocked in the case of an incomplete user notes. -In that scenario there will be no output to the files. All trace events will be kept in memory and will be tried to be flushed on the next interval if the incomplete notes where closed. +\note The incremental flushing will be blocked in the case of an incomplete user note. +In that scenario there will be no output to the files. All trace events will be kept in memory and will be tried to be flushed on the next interval if the incomplete notes were closed. From 748f7a646d47e7b5e9769ae86c162156f4584c29 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Mon, 5 Aug 2024 14:00:59 -0400 Subject: [PATCH 14/20] #2187: Fix constant being used in TraceScopedNote --- src/vt/trace/trace_user.h | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index dbfc96e40b..e3a6a8ff07 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -257,7 +257,7 @@ struct TraceScopedNote final { ) : event_(in_event), note_(in_note) { - if (event_ != no_user_event_id) { + if (event_ != no_trace_event) { theTrace()->addUserNoteBracketedBeginTime(note_, event_); } } @@ -272,7 +272,7 @@ struct TraceScopedNote final { : event_(in_event), note_("") { - if (event_ != no_user_event_id) { + if (event_ != no_trace_event) { theTrace()->addUserNoteBracketedBeginTime(note_, event_); } } @@ -298,9 +298,9 @@ struct TraceScopedNote final { * \brief Manually end the scoped event early (before it goes out of scope) */ void end() { - if (event_ != no_user_event_id) { + if (event_ != no_trace_event) { theTrace()->addUserNoteBracketedEndTime(note_, event_); - event_ = no_user_event_id; + event_ = no_trace_event; } } From 96d3a3ed7976ea244535a6503890a9f16346710c Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Tue, 6 Aug 2024 13:51:45 -0400 Subject: [PATCH 15/20] #2187: Update interface for adding user note to be more clear with the message overriding behavior --- src/vt/trace/trace_lite.cc | 52 +++++++++++++++++++++-------- src/vt/trace/trace_lite.h | 19 +++++++++-- src/vt/trace/trace_user.cc | 2 +- src/vt/trace/trace_user.h | 2 +- tests/unit/trace/test_trace_user.cc | 42 +++++++++++++++++++---- 5 files changed, 92 insertions(+), 25 deletions(-) diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index 996b745914..1e5915f2dd 100644 --- a/src/vt/trace/trace_lite.cc +++ b/src/vt/trace/trace_lite.cc @@ -310,8 +310,42 @@ void TraceLite::addUserNoteBracketedBeginTime( } } +void TraceLite::fixupNoteEndTime(const TraceEventIDType& event, const TimeType& end, const std::string* new_note) { + auto iter = incomplete_notes_.find(event); + vtAssertExpr(iter != incomplete_notes_.end()); + // update data in the Log + auto& last_trace = iter->second.top(); + last_trace->end_time = end; + if (new_note != nullptr) { + last_trace->setUserNote(*new_note); + } + // clean up pointers to Log + iter->second.pop(); + if (iter->second.empty()) { + incomplete_notes_.erase(iter); + } +} + +void TraceLite::addUserNoteBracketedEndTime(TraceEventIDType const event) { + if (not checkDynamicRuntimeEnabled()) { + return; + } + auto end = getCurrentTime(); + + vt_debug_print( + normal, trace, + "Trace::addUserNoteBracketedEndTime: end={}, event={}\n", + end, event + ); + + // Fixup end time of the note + if (event != no_trace_event) { + fixupNoteEndTime(event, end, nullptr); + } +} + void TraceLite::addUserNoteBracketedEndTime( - std::string const& note, TraceEventIDType const event + TraceEventIDType const event, std::string const& new_note ) { if (not checkDynamicRuntimeEnabled()) { return; @@ -320,23 +354,13 @@ void TraceLite::addUserNoteBracketedEndTime( vt_debug_print( normal, trace, - "Trace::addUserNoteBracketedEndTime: end={}, note={}, event={}\n", - end, note, event + "Trace::addUserNoteBracketedEndTime: end={}, new_note={}, event={}\n", + end, new_note, event ); // Fixup end time of the note if (event != no_user_event_id) { - auto iter = incomplete_notes_.find(event); - vtAssertExpr(iter != incomplete_notes_.end()); - // update data in the Log - auto& last_trace = iter->second.top(); - last_trace->end_time = end; - last_trace->setUserNote(note); - // clean up pointers to Log - iter->second.pop(); - if (iter->second.empty()) { - incomplete_notes_.erase(iter); - } + fixupNoteEndTime(event, end, &new_note); } } diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index 748a30a2a5..58576f9d65 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -201,11 +201,21 @@ struct TraceLite { * \note See \c TraceScopedNote for a safer scope-based logging mechanism for * bracketed user events with a note. * - * \param[in] note the note to log * \param[in] event the event ID */ + void addUserNoteBracketedEndTime(TraceEventIDType const event = no_trace_event); + + /** + * \brief Log a user bracketed event with a note + * + * \note See \c TraceScopedNote for a safer scope-based logging mechanism for + * bracketed user events with a note. + * + * \param[in] event the event ID + * \param[in] new_note the new note which overrides the old one + */ void addUserNoteBracketedEndTime( - std::string const& note, TraceEventIDType const event = no_trace_event + TraceEventIDType const event, std::string const& new_note ); /** @@ -395,6 +405,11 @@ struct TraceLite { return traces_.size() * sizeof(Log); } +private: + void fixupNoteEndTime( + const TraceEventIDType& event, const TimeType& end, + const std::string* new_note); + protected: /* * Incremental flush mode for zlib. Not set here with zlib constants to reduce diff --git a/src/vt/trace/trace_user.cc b/src/vt/trace/trace_user.cc index f6e5299568..2121e2ccf5 100644 --- a/src/vt/trace/trace_user.cc +++ b/src/vt/trace/trace_user.cc @@ -112,7 +112,7 @@ void addUserNoteEpi( ) { #if vt_check_enabled(trace_enabled) if (in_event != no_user_event_id) { - theTrace()->addUserNoteBracketedEndTime(in_note, in_event); + theTrace()->addUserNoteBracketedEndTime(in_event, in_note); } #endif } diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index e3a6a8ff07..ce689a31f2 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -299,7 +299,7 @@ struct TraceScopedNote final { */ void end() { if (event_ != no_trace_event) { - theTrace()->addUserNoteBracketedEndTime(note_, event_); + theTrace()->addUserNoteBracketedEndTime(event_, note_); event_ = no_trace_event; } } diff --git a/tests/unit/trace/test_trace_user.cc b/tests/unit/trace/test_trace_user.cc index c16ced42ce..1225d8aeb3 100644 --- a/tests/unit/trace/test_trace_user.cc +++ b/tests/unit/trace/test_trace_user.cc @@ -303,22 +303,50 @@ TEST_F(TestTraceUser, trace_user_note_bracketed) { GTEST_SKIP() << "trace tests require --vt_trace to be set"; } - theTrace()->addUserNoteBracketedBeginTime("", 10); - theTrace()->addUserNoteBracketedBeginTime("", 10); - theTrace()->addUserNoteBracketedBeginTime("", 10); + theTrace()->addUserNoteBracketedBeginTime("OUTER TEST NOTE 10", 10); + theTrace()->addUserNoteBracketedBeginTime("INNER TEST NOTE 10", 10); + theTrace()->addUserNoteBracketedBeginTime("INNER INNER TEST NOTE 10", 10); + theTrace()->addUserNoteBracketedBeginTime("INNER INNER INNER TEST NOTE 12", 12); + + theTrace()->addUserEvent(901); + trace::addUserNote("Note 0"); + theTrace()->addUserEvent(902); + + theTrace()->addUserNoteBracketedEndTime(12); + trace::addUserNote("Note 1"); + theTrace()->addUserNoteBracketedEndTime(10); + trace::addUserNote("Note 2"); + theTrace()->addUserNoteBracketedEndTime(10); + trace::addUserNote("Note 3"); + theTrace()->addUserNoteBracketedEndTime(10); + trace::addUserNote("Note 4"); + + TestTraceUser::stopVt(); + validateAllTraceFiles(); +} + +TEST_F(TestTraceUser, trace_user_note_bracketed_override_note) { + if (!theTrace()->checkDynamicRuntimeEnabled()) { + TestTraceUser::stopVt(); + GTEST_SKIP() << "trace tests require --vt_trace to be set"; + } + + theTrace()->addUserNoteBracketedBeginTime("ABC", 10); + theTrace()->addUserNoteBracketedBeginTime("123", 10); + theTrace()->addUserNoteBracketedBeginTime("X", 10); theTrace()->addUserNoteBracketedBeginTime("", 12); theTrace()->addUserEvent(901); trace::addUserNote("Note 0"); theTrace()->addUserEvent(902); - theTrace()->addUserNoteBracketedEndTime("INNER INNER INNER TEST NOTE 10", 12); + theTrace()->addUserNoteBracketedEndTime(12, "INNER INNER INNER TEST NOTE 12"); trace::addUserNote("Note 1"); - theTrace()->addUserNoteBracketedEndTime("INNER INNER TEST NOTE 10", 10); + theTrace()->addUserNoteBracketedEndTime(10, "INNER INNER TEST NOTE 10"); trace::addUserNote("Note 2"); - theTrace()->addUserNoteBracketedEndTime("INNER TEST NOTE 10", 10); + theTrace()->addUserNoteBracketedEndTime(10, "INNER TEST NOTE 10"); trace::addUserNote("Note 3"); - theTrace()->addUserNoteBracketedEndTime("OUTER TEST NOTE 10", 10); + theTrace()->addUserNoteBracketedEndTime(10, "OUTER TEST NOTE 10"); trace::addUserNote("Note 4"); TestTraceUser::stopVt(); From ad2136025f21b1d48ff96565fa512a857a2307ff Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Tue, 6 Aug 2024 15:29:23 -0400 Subject: [PATCH 16/20] #2187: Remove default event id from TraceScopedNote --- src/vt/trace/trace_user.h | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index ce689a31f2..a43a9881fe 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -253,7 +253,7 @@ struct TraceScopedNote final { * \c registerEventCollective ) */ TraceScopedNote( - std::string const& in_note, TraceEventIDType const in_event = no_trace_event + std::string const& in_note, TraceEventIDType const in_event ) : event_(in_event), note_(in_note) { @@ -268,7 +268,7 @@ struct TraceScopedNote final { * \param[in] event the user event to log (e.g., may be obtained from * \c registerEventCollective ) */ - TraceScopedNote(TraceEventIDType const in_event = no_trace_event) + TraceScopedNote(TraceEventIDType const in_event) : event_(in_event), note_("") { @@ -316,10 +316,11 @@ struct TraceScopedNote final { #else struct TraceScopedNote final { - TraceScopedNote(std::string const&, TraceEventIDType const = no_trace_event) { } + TraceScopedNote(std::string const&, TraceEventIDType const) { } + TraceScopedNote(TraceEventIDType const) { } void end() { } - void setNote([[maybe_unused]] std::string const& in_note) { } + void setNote(std::string const&) { } }; struct TraceScopedEvent final { From a3a71f6b50cba6a81a7128984aa1a2477135df5d Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Tue, 6 Aug 2024 19:29:15 +0200 Subject: [PATCH 17/20] #2187: Add missing documentation for updateNoteEndTime method --- src/vt/trace/trace_lite.cc | 8 +++++--- src/vt/trace/trace_lite.h | 11 ++++++++++- 2 files changed, 15 insertions(+), 4 deletions(-) diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index 1e5915f2dd..336894bbbe 100644 --- a/src/vt/trace/trace_lite.cc +++ b/src/vt/trace/trace_lite.cc @@ -310,7 +310,9 @@ void TraceLite::addUserNoteBracketedBeginTime( } } -void TraceLite::fixupNoteEndTime(const TraceEventIDType& event, const TimeType& end, const std::string* new_note) { +void TraceLite::updateNoteEndTime( + const TraceEventIDType& event, const TimeType& end, const std::string* new_note +) { auto iter = incomplete_notes_.find(event); vtAssertExpr(iter != incomplete_notes_.end()); // update data in the Log @@ -340,7 +342,7 @@ void TraceLite::addUserNoteBracketedEndTime(TraceEventIDType const event) { // Fixup end time of the note if (event != no_trace_event) { - fixupNoteEndTime(event, end, nullptr); + updateNoteEndTime(event, end, nullptr); } } @@ -360,7 +362,7 @@ void TraceLite::addUserNoteBracketedEndTime( // Fixup end time of the note if (event != no_user_event_id) { - fixupNoteEndTime(event, end, &new_note); + updateNoteEndTime(event, end, &new_note); } } diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index 58576f9d65..003fb10f2b 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -406,7 +406,16 @@ struct TraceLite { } private: - void fixupNoteEndTime( + + /** + * \brief Completes the user note by updating the event end time + * and replacing the message if new one is supplied. + * + * \param[in] event the event to be closed + * \param[in] end the time to be set as event end time + * \param[in] new_note the new note + */ + void updateNoteEndTime( const TraceEventIDType& event, const TimeType& end, const std::string* new_note); From ab32e74d33a9eaae1c2826d70b39771da260778d Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Tue, 13 Aug 2024 12:44:46 +0200 Subject: [PATCH 18/20] #2187: Use proper constant when adding a user note --- src/vt/trace/trace_lite.cc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index 336894bbbe..87f2a7a5ac 100644 --- a/src/vt/trace/trace_lite.cc +++ b/src/vt/trace/trace_lite.cc @@ -304,7 +304,7 @@ void TraceLite::addUserNoteBracketedBeginTime( logEvent(LogType{begin, begin, type, note, event}); // Save event log for fixing up the end time later - if (event != no_user_event_id) { + if (event != no_trace_event) { auto* last_trace = getLastTraceEvent(); incomplete_notes_[event].push(last_trace); } @@ -361,7 +361,7 @@ void TraceLite::addUserNoteBracketedEndTime( ); // Fixup end time of the note - if (event != no_user_event_id) { + if (event != no_trace_event) { updateNoteEndTime(event, end, &new_note); } } From e305ac2c6c8d41a5de3fee588c1a1df86c618551 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Tue, 13 Aug 2024 12:45:58 +0200 Subject: [PATCH 19/20] #2187: Fix order of the parametrs in the method for starting a user note --- src/vt/trace/trace_lite.cc | 2 +- src/vt/trace/trace_lite.h | 6 +++--- src/vt/trace/trace_user.cc | 2 +- src/vt/trace/trace_user.h | 4 ++-- tests/unit/trace/test_trace_user.cc | 16 ++++++++-------- 5 files changed, 15 insertions(+), 15 deletions(-) diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index 87f2a7a5ac..702c484bcf 100644 --- a/src/vt/trace/trace_lite.cc +++ b/src/vt/trace/trace_lite.cc @@ -287,7 +287,7 @@ void TraceLite::addUserEventBracketedEndTime( } void TraceLite::addUserNoteBracketedBeginTime( - std::string const& note, TraceEventIDType const event + TraceEventIDType const event, std::string const& note ) { if (not checkDynamicRuntimeEnabled()) { return; diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index 003fb10f2b..48c9d2683a 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -188,11 +188,11 @@ struct TraceLite { * \note See \c TraceScopedNote for a safer scope-based logging mechanism for * bracketed user events with a note. * - * \param[in] note the note to log * \param[in] event the event ID + * \param[in] note the note to log */ void addUserNoteBracketedBeginTime( - std::string const& note, TraceEventIDType const event = no_trace_event + TraceEventIDType const event, std::string const& note ); /** @@ -203,7 +203,7 @@ struct TraceLite { * * \param[in] event the event ID */ - void addUserNoteBracketedEndTime(TraceEventIDType const event = no_trace_event); + void addUserNoteBracketedEndTime(TraceEventIDType const event); /** * \brief Log a user bracketed event with a note diff --git a/src/vt/trace/trace_user.cc b/src/vt/trace/trace_user.cc index 2121e2ccf5..0cb39fd8d5 100644 --- a/src/vt/trace/trace_user.cc +++ b/src/vt/trace/trace_user.cc @@ -101,7 +101,7 @@ void addUserNotePre( ) { #if vt_check_enabled(trace_enabled) if (in_event != no_user_event_id) { - theTrace()->addUserNoteBracketedBeginTime(in_note, in_event); + theTrace()->addUserNoteBracketedBeginTime(in_event, in_note); } #endif } diff --git a/src/vt/trace/trace_user.h b/src/vt/trace/trace_user.h index a43a9881fe..62e57f60ce 100644 --- a/src/vt/trace/trace_user.h +++ b/src/vt/trace/trace_user.h @@ -258,7 +258,7 @@ struct TraceScopedNote final { note_(in_note) { if (event_ != no_trace_event) { - theTrace()->addUserNoteBracketedBeginTime(note_, event_); + theTrace()->addUserNoteBracketedBeginTime(event_, note_); } } @@ -273,7 +273,7 @@ struct TraceScopedNote final { note_("") { if (event_ != no_trace_event) { - theTrace()->addUserNoteBracketedBeginTime(note_, event_); + theTrace()->addUserNoteBracketedBeginTime(event_, note_); } } diff --git a/tests/unit/trace/test_trace_user.cc b/tests/unit/trace/test_trace_user.cc index 1225d8aeb3..2b068881aa 100644 --- a/tests/unit/trace/test_trace_user.cc +++ b/tests/unit/trace/test_trace_user.cc @@ -303,10 +303,10 @@ TEST_F(TestTraceUser, trace_user_note_bracketed) { GTEST_SKIP() << "trace tests require --vt_trace to be set"; } - theTrace()->addUserNoteBracketedBeginTime("OUTER TEST NOTE 10", 10); - theTrace()->addUserNoteBracketedBeginTime("INNER TEST NOTE 10", 10); - theTrace()->addUserNoteBracketedBeginTime("INNER INNER TEST NOTE 10", 10); - theTrace()->addUserNoteBracketedBeginTime("INNER INNER INNER TEST NOTE 12", 12); + theTrace()->addUserNoteBracketedBeginTime(10, "OUTER TEST NOTE 10"); + theTrace()->addUserNoteBracketedBeginTime(10, "INNER TEST NOTE 10"); + theTrace()->addUserNoteBracketedBeginTime(10, "INNER INNER TEST NOTE 10"); + theTrace()->addUserNoteBracketedBeginTime(12, "INNER INNER INNER TEST NOTE 12"); theTrace()->addUserEvent(901); trace::addUserNote("Note 0"); @@ -331,10 +331,10 @@ TEST_F(TestTraceUser, trace_user_note_bracketed_override_note) { GTEST_SKIP() << "trace tests require --vt_trace to be set"; } - theTrace()->addUserNoteBracketedBeginTime("ABC", 10); - theTrace()->addUserNoteBracketedBeginTime("123", 10); - theTrace()->addUserNoteBracketedBeginTime("X", 10); - theTrace()->addUserNoteBracketedBeginTime("", 12); + theTrace()->addUserNoteBracketedBeginTime(10, "ABC"); + theTrace()->addUserNoteBracketedBeginTime(10, "123"); + theTrace()->addUserNoteBracketedBeginTime(10, "X"); + theTrace()->addUserNoteBracketedBeginTime(12, ""); theTrace()->addUserEvent(901); trace::addUserNote("Note 0"); From b7419f316aa6a203ea1654a4db4a61877ee25848 Mon Sep 17 00:00:00 2001 From: Arkadiusz Szczepkowicz Date: Wed, 4 Sep 2024 12:48:59 +0200 Subject: [PATCH 20/20] #2187: Fix wrong constant being used in addUserNotePre/Epi --- src/vt/trace/trace_lite.cc | 8 +++----- src/vt/trace/trace_lite.h | 10 +++++----- src/vt/trace/trace_user.cc | 4 ++-- 3 files changed, 10 insertions(+), 12 deletions(-) diff --git a/src/vt/trace/trace_lite.cc b/src/vt/trace/trace_lite.cc index 702c484bcf..b6adddfa6a 100644 --- a/src/vt/trace/trace_lite.cc +++ b/src/vt/trace/trace_lite.cc @@ -296,7 +296,7 @@ void TraceLite::addUserNoteBracketedBeginTime( vt_debug_print( normal, trace, - "Trace::addUserNoteBracketedBeginTime: begin={}, note={}, event={}\n", + "Trace::addUserNoteBracketedBegin: begin={}, note={}, event={}\n", begin, note, event ); @@ -336,11 +336,10 @@ void TraceLite::addUserNoteBracketedEndTime(TraceEventIDType const event) { vt_debug_print( normal, trace, - "Trace::addUserNoteBracketedEndTime: end={}, event={}\n", + "Trace::addUserNoteBracketedEnd: end={}, event={}\n", end, event ); - // Fixup end time of the note if (event != no_trace_event) { updateNoteEndTime(event, end, nullptr); } @@ -356,11 +355,10 @@ void TraceLite::addUserNoteBracketedEndTime( vt_debug_print( normal, trace, - "Trace::addUserNoteBracketedEndTime: end={}, new_note={}, event={}\n", + "Trace::addUserNoteBracketedEnd: end={}, new_note={}, event={}\n", end, new_note, event ); - // Fixup end time of the note if (event != no_trace_event) { updateNoteEndTime(event, end, &new_note); } diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index 48c9d2683a..e5b7ff54d9 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -167,7 +167,7 @@ struct TraceLite { void disableTracing(); /** - * \brief Log a bracketed user event with begin time + * \brief Log the start of the bracketed user event * * \param[in] event the ID for the sts file * \param[in] begin the begin time @@ -175,7 +175,7 @@ struct TraceLite { void addUserEventBracketedBeginTime(UserEventIDType event, TimeType begin); /** - * \brief Log a bracketed user event with end time + * \brief Log the end of the bracketed user event * * \param[in] event the ID for the sts file * \param[in] end the end time @@ -183,7 +183,7 @@ struct TraceLite { void addUserEventBracketedEndTime(UserEventIDType event, TimeType end); /** - * \brief Log a user bracketed event with a note + * \brief Log the start of the bracketed user event with a note * * \note See \c TraceScopedNote for a safer scope-based logging mechanism for * bracketed user events with a note. @@ -196,7 +196,7 @@ struct TraceLite { ); /** - * \brief Log a user bracketed event with a note + * \brief Log the end of the bracketed user event with a note * * \note See \c TraceScopedNote for a safer scope-based logging mechanism for * bracketed user events with a note. @@ -206,7 +206,7 @@ struct TraceLite { void addUserNoteBracketedEndTime(TraceEventIDType const event); /** - * \brief Log a user bracketed event with a note + * \brief Log the end of the bracketed user event with a note * * \note See \c TraceScopedNote for a safer scope-based logging mechanism for * bracketed user events with a note. diff --git a/src/vt/trace/trace_user.cc b/src/vt/trace/trace_user.cc index 0cb39fd8d5..325c4784ab 100644 --- a/src/vt/trace/trace_user.cc +++ b/src/vt/trace/trace_user.cc @@ -100,7 +100,7 @@ void addUserNotePre( [[maybe_unused]] TraceEventIDType const in_event ) { #if vt_check_enabled(trace_enabled) - if (in_event != no_user_event_id) { + if (in_event != no_trace_event) { theTrace()->addUserNoteBracketedBeginTime(in_event, in_note); } #endif @@ -111,7 +111,7 @@ void addUserNoteEpi( [[maybe_unused]] TraceEventIDType const in_event ) { #if vt_check_enabled(trace_enabled) - if (in_event != no_user_event_id) { + if (in_event != no_trace_event) { theTrace()->addUserNoteBracketedEndTime(in_event, in_note); } #endif