Add fields to reaction statistics to track CPU time

src/message/ReactionStatistics.hpp

@@ -26,10 +26,11 @@
 #include <exception>
 #include <string>
 #include <vector>
-#include "../id.hpp"
 
 #include "../clock.hpp"
+#include "../id.hpp"
 #include "../threading/ReactionIdentifiers.hpp"
+#include "../util/usage_clock.hpp"
 
 namespace NUClear {
 namespace message {
@@ -74,6 +75,10 @@ namespace message {
         clock::time_point started{};
         /// @brief The time that execution finished on this reaction
         clock::time_point finished{};
+        /// @brief The amount of real time that this reaction took to execute
+        std::chrono::steady_clock::duration real_time{};
+        /// @brief The amount of CPU time that this reaction took to execute
+        util::cpu_clock::duration cpu_time{};
         /// @brief An exception pointer that can be rethrown (if the reaction threw an exception)
         std::exception_ptr exception{nullptr};
     };

src/util/CallbackGenerator.hpp

@@ -109,8 +109,10 @@ namespace util {
                                          // Update our thread's priority to the correct level
                                          update_current_thread_priority(task.priority);
 
-                                         // Record our start time
+                                         // Start times
                                          task.stats->started = clock::now();
+                                         auto real_start     = std::chrono::steady_clock::now();
+                                         auto cpu_start      = util::cpu_clock::now();
 
                                          // We have to catch any exceptions
                                          try {
@@ -122,9 +124,16 @@ namespace util {
                                              task.stats->exception = std::current_exception();
                                          }
 
-                                         // Our finish time
+                                         // Finish times in same order
                                          task.stats->finished = clock::now();
 
+                                         auto real_end = std::chrono::steady_clock::now();
+                                         auto cpu_end  = util::cpu_clock::now();
+
+                                         // Calculate the time taken
+                                         task.stats->cpu_time  = cpu_end - cpu_start;
+                                         task.stats->real_time = real_end - real_start;
+
                                          // Run our postconditions
                                          DSL::postcondition(task);
 

src/util/usage_clock.cpp

@@ -0,0 +1,43 @@
+#include "usage_clock.hpp"
+
+
+// Windows
+#if defined(_WIN32)
+    #include "platform.hpp"
+
+namespace NUClear {
+namespace util {
+
+    cpu_clock::time_point cpu_clock::now() noexcept {
+        FILETIME creation_time;
+        FILETIME exit_time;
+        FILETIME kernel_time;
+        FILETIME user_time;
+        if (GetThreadTimes(GetCurrentThread(), &creation_time, &exit_time, &kernel_time, &user_time) != -1) {
+            // Time in in 100 nanosecond intervals
+            uint64_t time = ((uint64_t(user_time.dwHighDateTime) << 32) | user_time.dwLowDateTime)
+                            + ((uint64_t(kernel_time.dwHighDateTime) << 32) | kernel_time.dwLowDateTime);
+            return time_point(std::chrono::duration<uint64_t, std::ratio<1LL, 10000000LL>>(time));
+        }
+        return time_point();
+    }
+
+}  // namespace util
+}  // namespace NUClear
+
+#else
+    #include <ctime>
+
+namespace NUClear {
+namespace util {
+
+    cpu_clock::time_point cpu_clock::now() noexcept {
+        timespec ts{};
+        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts);
+        return time_point(std::chrono::seconds(ts.tv_sec) + std::chrono::nanoseconds(ts.tv_nsec));
+    }
+
+}  // namespace util
+}  // namespace NUClear
+
+#endif  // _WIN32

src/util/usage_clock.hpp

@@ -0,0 +1,30 @@
+#ifndef NUCLEAR_UTIL_USAGE_CLOCK_HPP
+#define NUCLEAR_UTIL_USAGE_CLOCK_HPP
+
+#include <chrono>
+
+namespace NUClear {
+namespace util {
+
+    /**
+     * @brief A clock that measures CPU time.
+     */
+    struct cpu_clock {
+        using duration              = std::chrono::nanoseconds;            ///< The duration type of the clock.
+        using rep                   = duration::rep;                       ///< The representation type of the duration.
+        using period                = duration::period;                    ///< The tick period of the clock.
+        using time_point            = std::chrono::time_point<cpu_clock>;  ///< The time point type of the clock.
+        static const bool is_steady = true;                                ///< Indicates if the clock is steady.
+
+        /**
+         * @brief Get the current time point of the cpu clock for the current thread
+         *
+         * @return The current time point.
+         */
+        static time_point now() noexcept;
+    };
+
+}  // namespace util
+}  // namespace NUClear
+
+#endif  // NUCLEAR_UTIL_USAGE_CLOCK_HPP

tests/tests/api/ReactionStatisticsTiming.cpp

@@ -0,0 +1,172 @@
+/*
+ * MIT License
+ *
+ * Copyright (c) 2023 NUClear Contributors
+ *
+ * This file is part of the NUClear codebase.
+ * See https://github.com/Fastcode/NUClear for further info.
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy of this software and associated
+ * documentation files (the "Software"), to deal in the Software without restriction, including without limitation the
+ * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the Software, and to
+ * permit persons to whom the Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE
+ * WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
+ * COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR
+ * OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+ */
+
+#include <catch2/catch_test_macros.hpp>
+#include <nuclear>
+
+#include "test_util/TestBase.hpp"
+#include "test_util/TimeUnit.hpp"
+
+// Anonymous namespace to keep everything file local
+namespace {
+
+using TimeUnit = test_util::TimeUnit;
+
+/// @brief Events that occur during the test and the time they occur
+/// NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
+std::vector<std::pair<std::string, NUClear::clock::time_point>> code_events;
+/// NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
+std::vector<std::pair<std::string, NUClear::clock::time_point>> stat_events;
+
+struct Usage {
+    std::map<std::string, std::chrono::steady_clock::duration> real;
+    std::map<std::string, NUClear::util::cpu_clock::duration> cpu;
+};
+
+// NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
+Usage usage;
+
+struct DoTest {};
+struct HeavyTask {};
+struct LightTask {};
+
+const std::string heavy_name   = "Heavy";    // NOLINT(cert-err58-cpp)
+const std::string light_name   = "Light";    // NOLINT(cert-err58-cpp)
+const std::string initial_name = "Initial";  // NOLINT(cert-err58-cpp)
+constexpr int scale            = 5;          // Number of time units to sleep/wait for
+
+using NUClear::message::ReactionStatistics;
+
+class TestReactor : public test_util::TestBase<TestReactor> {
+public:
+    TestReactor(std::unique_ptr<NUClear::Environment> environment) : TestBase(std::move(environment)) {
+
+        on<Trigger<Step<1>>, Priority::LOW>().then(initial_name + ":" + heavy_name, [this] {
+            code_events.emplace_back("Started " + initial_name + ":" + heavy_name, NUClear::clock::now());
+            code_events.emplace_back("Emitted " + heavy_name, NUClear::clock::now());
+            emit(std::make_unique<HeavyTask>());
+            code_events.emplace_back("Finished " + initial_name + ":" + heavy_name, NUClear::clock::now());
+        });
+        on<Trigger<HeavyTask>>().then(heavy_name, [] {
+            code_events.emplace_back("Started " + heavy_name, NUClear::clock::now());
+            auto start = NUClear::clock::now();
+            while (NUClear::clock::now() - start < TimeUnit(scale)) {
+            }
+            code_events.emplace_back("Finished " + heavy_name, NUClear::clock::now());
+        });
+
+        on<Trigger<Step<1>>, Priority::LOW>().then(initial_name + ":" + light_name, [this] {
+            code_events.emplace_back("Started " + initial_name + ":" + light_name, NUClear::clock::now());
+            code_events.emplace_back("Emitted " + light_name, NUClear::clock::now());
+            emit(std::make_unique<LightTask>());
+            code_events.emplace_back("Finished " + initial_name + ":" + light_name, NUClear::clock::now());
+        });
+        on<Trigger<LightTask>>().then(light_name, [] {
+            code_events.emplace_back("Started " + light_name, NUClear::clock::now());
+            std::this_thread::sleep_for(TimeUnit(scale));
+            code_events.emplace_back("Finished " + light_name, NUClear::clock::now());
+        });
+
+        on<Trigger<ReactionStatistics>>().then([](const ReactionStatistics& stats) {
+            // Check the name ends with light_name or heavy_name
+            if (stats.identifiers.name.substr(stats.identifiers.name.size() - light_name.size()) == light_name
+                || stats.identifiers.name.substr(stats.identifiers.name.size() - heavy_name.size()) == heavy_name) {
+
+                stat_events.emplace_back("Emitted " + stats.identifiers.name, stats.emitted);
+                stat_events.emplace_back("Started " + stats.identifiers.name, stats.started);
+                stat_events.emplace_back("Finished " + stats.identifiers.name, stats.finished);
+
+                usage.real[stats.identifiers.name] = stats.real_time;
+                usage.cpu[stats.identifiers.name]  = stats.cpu_time;
+            }
+        });
+
+        on<Startup>().then("Startup", [this] {
+            auto start = NUClear::clock::now();
+            code_events.emplace_back("Emitted " + initial_name + ":" + heavy_name, start);
+            code_events.emplace_back("Emitted " + initial_name + ":" + light_name, start);
+            emit(std::make_unique<Step<1>>());
+        });
+    }
+};
+}  // namespace
+
+TEST_CASE("Testing reaction statistics timing", "[api][reactionstatistics][timing]") {
+
+    NUClear::Configuration config;
+    config.thread_count = 1;
+    NUClear::PowerPlant plant(config);
+    plant.install<TestReactor>();
+    plant.start();
+
+    // Sort the stats events by timestamp as they are not always going to be in order due to how stats are processed
+    std::stable_sort(stat_events.begin(), stat_events.end(), [](const auto& lhs, const auto& rhs) {
+        return lhs.second < rhs.second;
+    });
+
+
+    auto make_delta = [](const std::vector<std::pair<std::string, NUClear::clock::time_point>>& events) {
+        std::vector<std::string> delta_events;
+        auto first = events.front().second;
+        for (const auto& event : events) {
+            auto delta = event.second - first;
+            auto units = test_util::round_to_test_units(delta / scale).count();
+            delta_events.push_back(event.first + " @ Step " + std::to_string(units));
+        }
+        return delta_events;
+    };
+
+    // Convert the events to delta strings where 1 unit is 1 step unit
+    std::vector<std::string> delta_code_events = make_delta(code_events);
+    std::vector<std::string> delta_stat_events = make_delta(stat_events);
+
+    const std::vector<std::string> expected = {
+        "Emitted Initial:Heavy @ Step 0",
+        "Emitted Initial:Light @ Step 0",
+        "Started Initial:Heavy @ Step 0",
+        "Emitted Heavy @ Step 0",
+        "Finished Initial:Heavy @ Step 0",
+        "Started Heavy @ Step 0",
+        "Finished Heavy @ Step 1",
+        "Started Initial:Light @ Step 1",
+        "Emitted Light @ Step 1",
+        "Finished Initial:Light @ Step 1",
+        "Started Light @ Step 1",
+        "Finished Light @ Step 2",
+    };
+
+
+    /* Info Scope */ {
+        INFO("Code Events:\n" << test_util::diff_string(expected, delta_code_events));
+        REQUIRE(delta_code_events == expected);
+    }
+    /* Info Scope */ {
+        INFO("Statistic Events:\n" << test_util::diff_string(expected, delta_stat_events));
+        REQUIRE(delta_stat_events == expected);
+    }
+
+    // Most of heavy real time should be cpu time
+    REQUIRE(usage.cpu[heavy_name] > usage.real[heavy_name] / 2);
+
+    // Most of light real time should be sleeping
+    REQUIRE(usage.cpu[light_name] < usage.real[light_name] / 2);
+}