diff --git a/common/CMakeLists.txt b/common/CMakeLists.txt index 69eab22f4..b484af16e 100644 --- a/common/CMakeLists.txt +++ b/common/CMakeLists.txt @@ -43,6 +43,9 @@ ADD_LIBRARY(JFJochLogger STATIC ) TARGET_LINK_LIBRARIES(JFJochLogger PUBLIC spdlog::spdlog JFJochVersion) +IF (JFJOCH_CUDA_AVAILABLE) + TARGET_LINK_LIBRARIES(JFJochLogger PRIVATE CUDA::nvtx3) # header-only NVTX v3 +ENDIF() ADD_LIBRARY(JFJochZMQ STATIC ZMQWrappers.cpp ZMQWrappers.h) diff --git a/common/Logger.cpp b/common/Logger.cpp index de61bedff..f84d357db 100644 --- a/common/Logger.cpp +++ b/common/Logger.cpp @@ -9,6 +9,24 @@ #include "Logger.h" #include "GitInfo.h" +#ifdef JFJOCH_USE_CUDA +#include + +uint64_t NvtxRangeStart(const std::string &name) { + return nvtxRangeStartA(name.c_str()); +} + +void NvtxRangeEnd(uint64_t id) { + nvtxRangeEnd(id); +} +#else +uint64_t NvtxRangeStart(const std::string &) { + return 0; +} + +void NvtxRangeEnd(uint64_t) {} +#endif + namespace { spdlog::sink_ptr routed_sink; // set once, at start-up, before any thread logs } diff --git a/common/Logger.h b/common/Logger.h index 57795ec55..4549aeb4c 100644 --- a/common/Logger.h +++ b/common/Logger.h @@ -70,13 +70,21 @@ public: void ReplayInto(Logger &to) const; }; +// An NVTX range named `name`, so a timed section shows up by name in an Nsight Systems trace. A start/end +// pair, not a push/pop, so a range may end on another thread and ranges on parallel threads may overlap. +// Without a profiler attached both calls return at once; without CUDA they do nothing. +uint64_t NvtxRangeStart(const std::string &name); +void NvtxRangeEnd(uint64_t id); + // Times one section of a run: logs "TIMING
" at debug level when the section ends - // at Stop(), or when the mark goes out of scope, whichever comes first. rugnux keeps debug lines off the -// terminal and in _log.txt; tools/rugnux_timing.py turns them into a table. +// terminal and in _log.txt; tools/rugnux_timing.py turns them into a table. The section is also +// an NVTX range of the same name. class TimingMark { Logger &logger; std::string section; std::chrono::steady_clock::time_point start = std::chrono::steady_clock::now(); + uint64_t nvtx_range = NvtxRangeStart(section); bool stopped = false; public: TimingMark(Logger &in_logger, std::string in_section) @@ -88,6 +96,7 @@ public: if (stopped) return; stopped = true; + NvtxRangeEnd(nvtx_range); logger.Debug("TIMING {} {:.3f}", section, std::chrono::duration(std::chrono::steady_clock::now() - start).count()); } diff --git a/rugnux/RugnuxConsole.cpp b/rugnux/RugnuxConsole.cpp index 0d74e4f35..12c1a0e36 100644 --- a/rugnux/RugnuxConsole.cpp +++ b/rugnux/RugnuxConsole.cpp @@ -204,6 +204,7 @@ void RugnuxConsole::Close(const char *how) { } pending_log_.push_back(std::move(log_text)); pending_timing_.push_back(fmt::format("TIMING step {} {:.3f}", step_title_, total)); + NvtxRangeEnd(step_nvtx_); warnings_held_.clear(); step_ = 0; } @@ -216,6 +217,7 @@ void RugnuxConsole::OnStep(const std::string &title) { step_ = last_step_ = number; step_title_ = title; step_start_ = mark_ = Clock::now(); + step_nvtx_ = NvtxRangeStart(fmt::format("Step {} {}", step_, title)); notes_ = 0; if (!verbose_) Emit(fmt::format("Step {:<2} {}", step_, title)); diff --git a/rugnux/RugnuxConsole.h b/rugnux/RugnuxConsole.h index 5d91e5f81..fb12eb021 100644 --- a/rugnux/RugnuxConsole.h +++ b/rugnux/RugnuxConsole.h @@ -74,6 +74,7 @@ private: int last_step_ = 0; std::string step_title_; Clock::time_point step_start_{}; + uint64_t step_nvtx_ = 0; // the open step's NVTX range Clock::time_point mark_{}; // the last line of the open step int notes_ = 0;