diff --git a/docs/web/profiling.md b/docs/web/profiling.md new file mode 100644 index 000000000..885016931 --- /dev/null +++ b/docs/web/profiling.md @@ -0,0 +1,112 @@ +--- +title: Profiling system in `MGIS` +author: Julien Rigal, Thomas Helfer +date: 2026 +lang: en-EN +numbersections: true +documentclass: article +from: markdown+tex_math_single_backslash +geometry: + - margin=2cm +papersize: a4 +link-citations: true +colorlinks: true +figPrefixTemplate: "$$i$$" +tabPrefixTemplate: "$$i$$" +secPrefixTemplate: "$$i$$" +eqnPrefixTemplate: "($$i$$)" +bibliography: bibliography.bib +--- + +This section describes the profiling system introduced in `MGIS`, which is meant to: + +1. provide a hierarchical and precise measurement of execution times across the library. +2. ensure minimal to zero overhead when disabled, preserving the high-performance computing requirements of the code. + +By tying the profiling system directly to the `Context` object, `MGIS` avoids the need to pass an additional profiler object through the call stack. A function using this profiling strategy is recognizable by the presence of a `Context` object and the use of dedicated profiling macros. + +# The `ProfilingData` structure + +The result of the profiling is not a flat list of timers, but a hierarchical tree. Each node in this tree is represented by the `ProfilingData` structure, which stores: + +- `name`: A `std::string` representing the name of the profiled section. +- `time_in_seconds`: A `double` accumulating the total time spent in this section. +- `calls`: An `unsigned int` counting the number of times this section was executed. +- `children`: A `std::vector` of `std::shared_ptr`, representing the nested profiled sections called within the current one. + +# Managing the Profiling State + +The profiling system is disabled by default to guarantee zero overhead in production runs. It can be dynamically controlled through the `Context` object using the following methods: + +- `enableProfiling(bool)`: Turns the global profiling on or off for the given context. +- `isProfilingEnabled()`: Returns a boolean indicating the current state of the profiler. +- `getProfilingResultTree()`: Retrieves the root node of the profiling tree (`ProfilingData`) containing all the collected metrics. + +# Instrumenting the code + +The profiling relies on the **RAII** (Resource Acquisition Is Initialization) idiom. Instead of manually starting and stopping timers, the developer creates a scoped object that starts a timer upon construction and stops it, while updating the tree, upon destruction. + +To ensure high readability and ease of use, this mechanism is wrapped in macros. + +## The `CatchTimeSection` macro + +The `CatchTimeSection` macro is the standard way to profile a block of code. It takes two arguments: +1. The `Context` object. +2. A string literal representing the name of the section. + +If profiling is enabled in the provided `Context`, the macro will automatically find its place in the hierarchical tree, start the timer, and record the elapsed time at the end of the current scope. If profiling is disabled, the macro does nothing. + +## The `CatchLocalTimeSection` macro + +In some specific debugging scenarios, a developer might want to force the profiling of a specific section even if the global profiling state is disabled. The `CatchLocalTimeSection` macro takes a third boolean argument: + +~~~~{.cxx} +// The third argument 'true' forces the profiling of this specific scope +CatchLocalTimeSection(ctx, "ForcedSection", true); +~~~~ + +# Aggregation and Loops + +To prevent the profiling tree from growing indefinitely and consuming too much memory, the system automatically aggregates repeated calls to the same section within the same parent scope. + +If a profiled section is called multiple times (for example, inside a `for` or `while` loop), the profiler does not create a new child node for each iteration. Instead, it finds the existing child node with the same name, increments its `calls` counter, and adds the elapsed time to `time_in_seconds`. + +# Example of usage + +The following code illustrates how to instrument a function and how the tree hierarchy and loop aggregation behave: + +~~~~{.cxx} +void performComputation(mgis::Context& ctx) +{ + ctx.enableProfiling(true); + + // Start a root section + { + CatchTimeSection(ctx, "IntegrationStep"); + + // Nested section + { + CatchTimeSection(ctx, "Initialization"); + // ... initialization code ... + } + + // Loop with a nested section + for (int i = 0; i < 1000; ++i) { + CatchTimeSection(ctx, "NewtonRaphsonIteration"); + // ... solver code ... + } + } + + // Retrieve and analyze the results + const auto& root = ctx.getProfilingResultTree(); + // 'root' contains 1 child: "IntegrationStep" + // "IntegrationStep" contains 2 children: "Initialization" and "NewtonRaphsonIteration" + // "NewtonRaphsonIteration" will show: calls = 1000 +} +~~~~ + +In this example, despite the `NewtonRaphsonIteration` section being timed 1000 times, only one node is created in the tree under `IntegrationStep`, with its `calls` attribute set to `1000` and its `time_in_seconds` representing the total time spent across all iterations. + +> **Note** +> +> Exhaustive examples and unit tests of the profiling system, including edge cases, can be found in the `tests/ProfilingTest.cxx` file. \ No newline at end of file diff --git a/include/CMakeLists.txt b/include/CMakeLists.txt index fed701f6f..0cdffc34e 100644 --- a/include/CMakeLists.txt +++ b/include/CMakeLists.txt @@ -7,6 +7,8 @@ mgis_header(MGIS Contract.hxx) mgis_header(MGIS Contract.ixx) mgis_header(MGIS Context.hxx) mgis_header(MGIS Context.ixx) +mgis_header(MGIS ProfilingData.hxx) +mgis_header(MGIS Profiling.hxx) mgis_header(MGIS ErrorBacktrace.hxx) mgis_header(MGIS InvalidResult.hxx) mgis_header(MGIS InvalidResult.ixx) diff --git a/include/MGIS/Context.hxx b/include/MGIS/Context.hxx index d8020f8d8..6733e7811 100644 --- a/include/MGIS/Context.hxx +++ b/include/MGIS/Context.hxx @@ -10,11 +10,14 @@ #include #include #include +#include #include "MGIS/Config.hxx" #include "MGIS/Raise.hxx" #include "MGIS/LogStream.hxx" #include "MGIS/VerbosityLevel.hxx" #include "MGIS/ErrorBacktrace.hxx" +#include "MGIS/ProfilingData.hxx" +#include "MGIS/Profiling.hxx" namespace mgis { @@ -29,7 +32,7 @@ namespace mgis { /*! * \brief a class used to pass an execution context to most methods of - * `MGIS` and gather information (error, logs). + * `MGIS` and gather information (error, logs, profiling). * * The default logging stream is the one returned by the * `mgis::getDefaultLogStream` free function. @@ -71,6 +74,7 @@ namespace mgis { //! \brief reference to the context that created the failure handler Context &ctx; }; + /*! * \brief default constructor * @@ -78,6 +82,7 @@ namespace mgis { * `getDefaultVerbosityLevel` function. */ Context() noexcept; + /*! * \brief constructor for an initializer * \param[in] i: initializer @@ -90,11 +95,65 @@ namespace mgis { Context &operator=(const Context &) = delete; //! \return the verbosity level [[nodiscard]] const VerbosityLevel &getVerbosityLevel() const noexcept; + /*! * \brief change the level of verbosity * \param[in] l: the new verbose level */ void setVerbosityLevel(const VerbosityLevel) noexcept; + + /*! + * \brief enable or disable profiling + * \param[in] b: a boolean value stating whether profiling shall be enabled + * + * \note when profiling is disabled, profiling sections introduce + * almost no overhead. + */ + void enableProfiling(const bool) noexcept; + + /*! + * \return true if profiling is enabled, false otherwise + */ + [[nodiscard]] bool isProfilingEnabled() const noexcept; + + /*! + * \brief start a new profiling section + * \param[in] name: name of the profiling section + * \param[in] enabled: boolean stating whether this profiling section + * shall effectively collect timing information + * + * \return a profiling section object + * + * \note the returned object relies on RAII semantics: + * timing starts during construction and stops during destruction. + */ + [[nodiscard]] ProfilingSection startNewProfiling( + std::string, + bool) noexcept; + + /*! + * \brief push a new profiling node into the current execution stack + * \param[in] name: name of the profiling section + * + * \note this method is meant to be called internally by the + * `Profiling` class during its construction. + */ + void pushProfilingNode(std::string) noexcept; + + /*! + * \brief pop the current profiling node from the execution stack and accumulate time + * \param[in] dt: execution time of the section in seconds + * + * \note this method is meant to be called internally by the + * `Profiling` class during its destruction. + */ + void popProfilingNode(double) noexcept; + + /*! + * \return the root node of the profiling results tree gathered during execution + */ + [[nodiscard]] const ProfilingData& getProfilingResultTree() const noexcept; + /*! * \return a failure handler * \tparam policy: policy used to treat a failure @@ -104,18 +163,22 @@ namespace mgis { [[nodiscard]] FailureHandler getFailureHandler() { return FailureHandler{*this}; } + //! \return a failure handler throwing exception in case of failure [[nodiscard]] FailureHandler getThrowingFailureHandler() noexcept; + //! \return a failure handler aborting the execution in case of failure [[nodiscard]] FailureHandler getFatalFailureHandler() noexcept; + /*! * \brief set the current log stream. * \param[in] s: log stream * \note the user is responsible for ensuring that the given object is alive */ void setLogStream(std::ostream &) noexcept; + /*! * \brief set the current log stream. * \param[in] s: log stream @@ -124,17 +187,21 @@ namespace mgis { * free function. */ void setLogStream(std::shared_ptr) noexcept; + //! \return a pointer to a log stream. This pointer may be null. [[nodiscard]] std::shared_ptr getLogStreamPointer() const noexcept; + //! \brief reset the default log stream void resetLogStream() noexcept; + /*! - * \brief disable the default log stream + * \brief disable the default log stream * * \note logging is disable by creating a no-op output stream */ void disableLogStream() noexcept; + /*! * \return the current log stream * @@ -142,6 +209,7 @@ namespace mgis { * `getDefaultLogStream` for details. */ [[nodiscard]] std::ostream &log() noexcept; + /*! * \brief display the given arguments in the log stream if the current * verbosity level (as returned by the `getVerbosityLevel` method) is @@ -156,6 +224,7 @@ namespace mgis { */ template std::ostream &log(const VerbosityLevel, Args &&...) noexcept; + /*! * \brief a simple wrapper around the `log` method to print a warning * @@ -164,6 +233,7 @@ namespace mgis { */ template void warning(Args &&...) noexcept; + /*! * \brief a simple wrapper around the `log` method which sets the minimun * verbosity level to `verboseDebug` @@ -175,6 +245,7 @@ namespace mgis { */ template void debug(Args &&...) noexcept; + //! \brief destructor ~Context() noexcept override; @@ -182,19 +253,36 @@ namespace mgis { //! \brief printing the error message on the log stream and abort the //! execution [[noreturn]] void abort(); + //! \brief current log stream std::variant> log_stream; + /*! * \brief local level of verbosity, initialize by the * global option returned by the `getVerbosityLevel` * function */ VerbosityLevel verbosity; + + //! \brief boolean stating whether profiling is enabled + bool profiling_enabled = false; + + //! \brief root node of the profiling tree containing all recorded sections + ProfilingData root_profiling_data; + + /*! + * \brief Keeps track of the current path in the profiling tree. + * + * \note This stack does not manage memory. The lifetime and memory management of + * the ProfilingData nodes are strictly handled by the tree structure itself. + */ + std::vector profiling_stack; + }; // end of class Context } // end of namespace mgis #include "MGIS/Context.ixx" -#endif /* LIB_MGIS_CONTEXT_HXX */ +#endif /* LIB_MGIS_CONTEXT_HXX */ \ No newline at end of file diff --git a/include/MGIS/Profiling.hxx b/include/MGIS/Profiling.hxx new file mode 100644 index 000000000..abdd8dd72 --- /dev/null +++ b/include/MGIS/Profiling.hxx @@ -0,0 +1,47 @@ +#ifndef LIB_MGIS_PROFILING_HXX +#define LIB_MGIS_PROFILING_HXX 1 + +#include +#include +#include "MGIS/Config.hxx" + +#define MGIS_CONCAT(a, b) MGIS_CONCAT_INNER(a, b) +#define MGIS_CONCAT_INNER(a, b) a##b +#define MGIS_VARNAME() MGIS_CONCAT(mgis_timer_, __COUNTER__) + +#define CatchTimeSection(CTX, NAME) \ + mgis::ProfilingSection MGIS_VARNAME()(CTX, NAME, (CTX).isProfilingEnabled()) +#define CatchLocalTimeSection(CTX, NAME, IS_ENABLED) \ + mgis::ProfilingSection MGIS_VARNAME()(CTX, NAME, IS_ENABLED) + +namespace mgis { + + class Context; + + class MGIS_EXPORT ProfilingSection { + public: + //! \brief Standard constructor (active or inactive depending on the 'enabled' flag) + ProfilingSection(Context& ctx, + std::string, + bool) noexcept; + + //! \brief Default constructor (fallback, always inactive) + ProfilingSection() noexcept : ctx_ptr(nullptr), active(false) {} + + ~ProfilingSection() noexcept; + + ProfilingSection(const ProfilingSection&) = delete; + ProfilingSection& operator=(const ProfilingSection&) = delete; + + ProfilingSection(ProfilingSection&&) = delete; + ProfilingSection& operator=(ProfilingSection&&) = delete; + + private: + Context* ctx_ptr; + bool active; + std::chrono::high_resolution_clock::time_point start; + }; + +} // end of namespace mgis + +#endif \ No newline at end of file diff --git a/include/MGIS/ProfilingData.hxx b/include/MGIS/ProfilingData.hxx new file mode 100644 index 000000000..3b45234ed --- /dev/null +++ b/include/MGIS/ProfilingData.hxx @@ -0,0 +1,21 @@ +#ifndef LIB_MGIS_PROFILING_DATA_HXX +#define LIB_MGIS_PROFILING_DATA_HXX + +#include +#include +#include +#include + +namespace mgis { + + struct ProfilingData { + std::string name; + double time_in_seconds = 0.0; + std::size_t calls = 0; + // For building profiling tree + std::vector> children; + }; + +} // end of namespace mgis + +#endif \ No newline at end of file diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 13e8ff84c..018237b82 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -5,6 +5,7 @@ list(APPEND MFrontGenericInterface_SOURCES LogStream.cxx ErrorBacktrace.cxx Context.cxx + Profiling.cxx Contract.cxx ThreadPool.cxx ThreadedTaskResult.cxx diff --git a/src/Context.cxx b/src/Context.cxx index f9472fca6..929961b0d 100644 --- a/src/Context.cxx +++ b/src/Context.cxx @@ -1,4 +1,3 @@ - /*! * \file src/Context.cxx * \brief This file implements the `Context` class @@ -6,17 +5,27 @@ */ #include +#include #include "MGIS/LogStream.hxx" #include "MGIS/Context.hxx" namespace mgis { Context::Context() noexcept - : verbosity(mgis::getDefaultVerbosityLevel()) { // - } // end of Context + : verbosity(mgis::getDefaultVerbosityLevel()) { + // Initialisation de la racine du profilage + this->root_profiling_data.name = "root"; + this->root_profiling_data.calls = 1; + this->profiling_stack.push_back(&this->root_profiling_data); + } // end of Context Context::Context(const ContextInitializer &i) noexcept - : verbosity(i.verbosity) {} // end of Context + : verbosity(i.verbosity) { + // Initialisation de la racine du profilage + this->root_profiling_data.name = "root"; + this->root_profiling_data.calls = 1; + this->profiling_stack.push_back(&this->root_profiling_data); + } // end of Context const VerbosityLevel &Context::getVerbosityLevel() const noexcept { return this->verbosity; @@ -26,6 +35,60 @@ namespace mgis { this->verbosity = l; } // end of setVerbosityLevel + void Context::enableProfiling(const bool b) noexcept { + this->profiling_enabled = b; + } // end of enableProfiling + + bool Context::isProfilingEnabled() const noexcept { + return this->profiling_enabled; + } // end of isProfilingEnabled + + ProfilingSection + Context::startNewProfiling(std::string name, bool enabled) noexcept { + return ProfilingSection{*this, std::move(name), enabled}; + } // end of startNewProfiling + + void Context::pushProfilingNode(std::string name) noexcept { + if (this->profiling_stack.empty()) return; + + ProfilingData* current = this->profiling_stack.back(); + + auto it = std::find_if( + current->children.begin(), + current->children.end(), + [&name](const std::unique_ptr& child) { + return child->name == name; + }); + + if (it != current->children.end()) { + this->profiling_stack.push_back(it->get()); + } else { + auto new_node = std::make_unique(); + new_node->name = std::move(name); + + ProfilingData* ptr = new_node.get(); + current->children.push_back(std::move(new_node)); + this->profiling_stack.push_back(ptr); + } + } // end of pushProfilingNode + + void Context::popProfilingNode(double dt) noexcept { + if (this->profiling_stack.size() > 1) { + ProfilingData* current = this->profiling_stack.back(); + current->time_in_seconds += dt; + current->calls += 1; + + this->profiling_stack.pop_back(); + } else if (this->profiling_stack.size() == 1) { + this->profiling_stack.back()->time_in_seconds += dt; + } + } // end of popProfilingNode + + const ProfilingData& + Context::getProfilingResultTree() const noexcept { + return this->root_profiling_data; + } // end of getProfilingResultTree + void Context::setLogStream(std::ostream &s) noexcept { this->log_stream = &s; } // end of setLogStream @@ -97,4 +160,4 @@ namespace mgis { Context::~Context() noexcept = default; -} // end of namespace mgis +} // end of namespace mgis \ No newline at end of file diff --git a/src/Profiling.cxx b/src/Profiling.cxx new file mode 100644 index 000000000..484bcfb2b --- /dev/null +++ b/src/Profiling.cxx @@ -0,0 +1,31 @@ +/*! + * \file src/Profiling.cxx + * \brief This file implements the `Profiling` class + */ + +#include "MGIS/Profiling.hxx" +#include "MGIS/Context.hxx" + +namespace mgis { + + ProfilingSection::ProfilingSection(Context& c, + std::string n, + bool enabled) noexcept + : ctx_ptr(&c), + active(enabled) { + if (this->active && this->ctx_ptr != nullptr) { + this->ctx_ptr->pushProfilingNode(std::move(n)); + this->start = std::chrono::high_resolution_clock::now(); + } + } // end of ProfilingSection + + ProfilingSection::~ProfilingSection() noexcept { + if (this->active && this->ctx_ptr != nullptr) { + const auto end = std::chrono::high_resolution_clock::now(); + const std::chrono::duration dt = end - this->start; + + this->ctx_ptr->popProfilingNode(dt.count()); + } + } // end of ~ProfilingSection + +} // end of namespace mgis \ No newline at end of file diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 8ce24c456..499697c6c 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -468,6 +468,15 @@ if(MGIS_HAVE_TFEL) PROPERTY ENVIRONMENT "PATH=$\;${MGIS_PATH_STRING}") endif((CMAKE_HOST_WIN32) AND (NOT MSYS)) + add_executable(ProfilingTest + EXCLUDE_FROM_ALL ProfilingTest.cxx) + target_link_libraries(ProfilingTest PRIVATE MFrontGenericInterface tfel::TFELTests) + add_test(NAME ProfilingTest COMMAND ProfilingTest) + add_dependencies(check ProfilingTest) + if((CMAKE_HOST_WIN32) AND (NOT MSYS)) + set_property(TEST ProfilingTest + PROPERTY ENVIRONMENT "PATH=$\;${MGIS_PATH_STRING}") + endif((CMAKE_HOST_WIN32) AND (NOT MSYS)) add_executable(OptionalReferenceTest EXCLUDE_FROM_ALL OptionalReferenceTest.cxx) diff --git a/tests/ProfilingTest.cxx b/tests/ProfilingTest.cxx new file mode 100644 index 000000000..17a4d0577 --- /dev/null +++ b/tests/ProfilingTest.cxx @@ -0,0 +1,140 @@ +/*! + * \file tests/ProfilingTest.cxx + * \brief Unit tests for the MGIS profiling system via Context + * \author Julien Rigal + * \date 2026 + */ + +#include +#include +#include +#include + +#include "TFEL/Tests/TestCase.hxx" +#include "TFEL/Tests/TestProxy.hxx" +#include "TFEL/Tests/TestManager.hxx" + +#include "MGIS/Context.hxx" +#include "MGIS/Profiling.hxx" +#include "MGIS/ProfilingData.hxx" + +struct ProfilingTest final : public tfel::tests::TestCase { + ProfilingTest() + : tfel::tests::TestCase("MGIS/Profiling", "ProfilingSystemTests") { + } // end of ProfilingTest + + tfel::tests::TestResult execute() override { + this->testToggle(); + this->testTreeHierarchy(); + this->testAccumulation(); + this->testDisabledState(); + this->testLocalForcedState(); + return this->result; + } + + private: + void testToggle() { + mgis::Context ctx; + + // By default + ctx.enableProfiling(false); + TFEL_TESTS_ASSERT(!ctx.isProfilingEnabled()); + + ctx.enableProfiling(true); + TFEL_TESTS_ASSERT(ctx.isProfilingEnabled()); + } + + void testTreeHierarchy() { + mgis::Context ctx; + ctx.enableProfiling(true); + + // Simulate a nested structure + { + CatchTimeSection(ctx, "Parent"); + { + CatchTimeSection(ctx, "Child1"); + } + { + CatchTimeSection(ctx, "Child2"); + } + } + + const auto& root = ctx.getProfilingResultTree(); + + // The root must have exactly 1 child ("Parent") + TFEL_TESTS_ASSERT(root.children.size() == 1); + + const auto& parent = root.children[0]; + TFEL_TESTS_CHECK_EQUAL(parent->name, "Parent"); + TFEL_TESTS_CHECK_EQUAL(parent->calls, 1u); + TFEL_TESTS_ASSERT(parent->time_in_seconds >= 0.0); + + // "Parent" must have exactly 2 children ("Child1" and "Child2") + TFEL_TESTS_ASSERT(parent->children.size() == 2); + TFEL_TESTS_CHECK_EQUAL(parent->children[0]->name, "Child1"); + TFEL_TESTS_CHECK_EQUAL(parent->children[1]->name, "Child2"); + } + + void testAccumulation() { + mgis::Context ctx; + ctx.enableProfiling(true); + + // Simulate a loop to check that "calls" is incremented + { + CatchTimeSection(ctx, "Loop"); + for (int i = 0; i < 5; ++i) { + CatchTimeSection(ctx, "Body"); + } + } + + const auto& root = ctx.getProfilingResultTree(); + TFEL_TESTS_ASSERT(root.children.size() == 1); + + const auto& loop = root.children[0]; + TFEL_TESTS_CHECK_EQUAL(loop->name, "Loop"); + TFEL_TESTS_CHECK_EQUAL(loop->calls, 1u); + + TFEL_TESTS_ASSERT(loop->children.size() == 1); + const auto& body = loop->children[0]; + TFEL_TESTS_CHECK_EQUAL(body->name, "Body"); + TFEL_TESTS_CHECK_EQUAL(body->calls, 5u); // If the loop ran five times, we have a problem + } + + void testDisabledState() { + mgis::Context ctx; + ctx.enableProfiling(false); // Profiling disabled + + { + CatchTimeSection(ctx, "ShouldNotAppear"); + } + + // The tree must be empty because the block was inactive + const auto& root = ctx.getProfilingResultTree(); + TFEL_TESTS_ASSERT(root.children.empty()); + } + + void testLocalForcedState() { + mgis::Context ctx; + ctx.enableProfiling(false); // Global profiling disabled + + { + // Force local activation + CatchLocalTimeSection(ctx, "ForcedSection", true); + } + + // The node then must exist + const auto& root = ctx.getProfilingResultTree(); + TFEL_TESTS_ASSERT(root.children.size() == 1); + TFEL_TESTS_CHECK_EQUAL(root.children[0]->name, "ForcedSection"); + } +}; + +TFEL_TESTS_GENERATE_PROXY(ProfilingTest, "ProfilingTest"); + +/* coverity [UNCAUGHT_EXCEPT]*/ +int main() { + auto& m = tfel::tests::TestManager::getTestManager(); + m.addTestOutput(std::cout); + m.addXMLTestOutput("ProfilingSystemTests.xml"); + return m.execute().success() ? EXIT_SUCCESS : EXIT_FAILURE; +} \ No newline at end of file