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 CPU time that this reaction took to execute
+        util::user_cpu_clock::duration user_cpu_time{};
+        /// @brief The amount of kernel time that this reaction took to execute
+        util::kernel_cpu_clock::duration kernel_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 user_start     = util::user_cpu_clock::now();
+                                         auto kernel_start   = util::kernel_cpu_clock::now();
 
                                          // We have to catch any exceptions
                                          try {
@@ -122,8 +124,10 @@ namespace util {
                                              task.stats->exception = std::current_exception();
                                          }
 
-                                         // Our finish time
-                                         task.stats->finished = clock::now();
+                                         // Finish times in same order
+                                         task.stats->finished        = clock::now();
+                                         task.stats->user_cpu_time   = util::user_cpu_clock::now() - user_start;
+                                         task.stats->kernel_cpu_time = util::kernel_cpu_clock::now() - kernel_start;
 
                                          // Run our postconditions
                                          DSL::postcondition(task);

src/util/usage_clock.cpp

@@ -0,0 +1,113 @@
+#include "usage_clock.hpp"
+
+
+// Linux
+#if defined(__linux__)
+    #include <sys/resource.h>
+
+namespace NUClear {
+namespace util {
+
+    user_cpu_clock::time_point user_cpu_clock::now() noexcept {
+        rusage usage{};
+        if (::getrusage(RUSAGE_THREAD, &usage) == 0) {
+            return time_point(std::chrono::seconds(usage.ru_utime.tv_sec)
+                              + std::chrono::microseconds(usage.ru_utime.tv_usec));
+        }
+        return {};
+    }
+
+    kernel_cpu_clock::time_point kernel_cpu_clock::now() noexcept {
+        rusage usage{};
+        if (::getrusage(RUSAGE_THREAD, &usage) == 0) {
+            return time_point(std::chrono::seconds(usage.ru_stime.tv_sec)
+                              + std::chrono::microseconds(usage.ru_stime.tv_usec));
+        }
+        return {};
+    }
+
+}  // namespace util
+}  // namespace NUClear
+
+// Mac OS X
+#elif defined(__MACH__) && defined(__APPLE__)
+
+    #include <errno.h>
+    #include <mach/mach.h>
+    #include <sys/resource.h>
+
+namespace NUClear {
+namespace util {
+
+    user_cpu_clock::time_point user_cpu_clock::now() noexcept {
+        thread_basic_info_data_t info{};
+        mach_msg_type_number_t info_count = THREAD_BASIC_INFO_COUNT;
+        kern_return_t kern_err;
+
+        mach_port_t port = mach_thread_self();
+        kern_err         = thread_info(port, THREAD_BASIC_INFO, reinterpret_cast<thread_info_t>(&info), &info_count);
+        mach_port_deallocate(mach_task_self(), port);
+
+        if (kern_err == KERN_SUCCESS) {
+            return time_point(std::chrono::seconds(info.user_time.seconds)
+                              + std::chrono::microseconds(info.user_time.microseconds));
+        }
+        return time_point();
+    }
+
+    kernel_cpu_clock::time_point kernel_cpu_clock::now() noexcept {
+        thread_basic_info_data_t info{};
+        mach_msg_type_number_t info_count = THREAD_BASIC_INFO_COUNT;
+        kern_return_t kern_err;
+
+        mach_port_t port = mach_thread_self();
+        kern_err         = thread_info(port, THREAD_BASIC_INFO, reinterpret_cast<thread_info_t>(&info), &info_count);
+        mach_port_deallocate(mach_task_self(), port);
+
+        if (kern_err == KERN_SUCCESS) {
+            return time_point(std::chrono::seconds(info.system_time.seconds)
+                              + std::chrono::microseconds(info.system_time.microseconds));
+        }
+        return time_point();
+    }
+
+}  // namespace util
+}  // namespace NUClear
+
+// Windows
+#elif defined(_WIN32)
+    #include "platform.hpp"
+
+namespace NUClear {
+namespace util {
+
+    user_cpu_clock::time_point user_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;
+            return time_point(std::chrono::duration<uint64_t, std::ratio<1LL, 10000000LL>>(time));
+        }
+        return time_point();
+    }
+
+    kernel_cpu_clock::time_point kernel_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(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
+
+#endif  // OS

src/util/usage_clock.hpp

@@ -0,0 +1,32 @@
+#ifndef NUCLEAR_UTIL_USAGE_CLOCK_HPP
+#define NUCLEAR_UTIL_USAGE_CLOCK_HPP
+
+#include <chrono>
+
+namespace NUClear {
+namespace util {
+
+    struct user_cpu_clock {
+        using duration              = std::chrono::nanoseconds;
+        using rep                   = duration::rep;
+        using period                = duration::period;
+        using time_point            = std::chrono::time_point<user_cpu_clock>;
+        static const bool is_steady = true;
+
+        static time_point now() noexcept;
+    };
+
+    struct kernel_cpu_clock {
+        using duration              = std::chrono::nanoseconds;
+        using rep                   = duration::rep;
+        using period                = duration::period;
+        using time_point            = std::chrono::time_point<kernel_cpu_clock>;
+        static const bool is_steady = true;
+
+        static time_point now() noexcept;
+    };
+
+}  // namespace util
+}  // namespace NUClear
+
+#endif  // NUCLEAR_UTIL_USAGE_CLOCK_HPP

tests/api/ReactionStatisticsTiming.cpp

@@ -0,0 +1,166 @@
+/*
+ * 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 <catch.hpp>
+#include <nuclear>
+
+#include "test_util/TestBase.hpp"
+
+// Anonymous namespace to keep everything file local
+namespace {
+
+/// @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>> events;
+
+struct Usage {
+    // NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
+    std::map<std::string, NUClear::clock::duration> real;
+    // NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
+    std::map<std::string, NUClear::util::user_cpu_clock::duration> user;
+    // NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
+    std::map<std::string, NUClear::util::kernel_cpu_clock::duration> kernel;
+};
+Usage usage;
+
+struct DoTest {};
+struct HeavyTask {};
+struct LightTask {};
+
+constexpr std::chrono::milliseconds STEP = std::chrono::milliseconds(100);
+const std::string heavy_name             = "Heavy";
+const std::string light_name             = "Light";
+const std::string initial_name           = "Initial";
+
+using NUClear::message::ReactionStatistics;
+
+class TestReactor : public test_util::TestBase<TestReactor> {
+public:
+    TestReactor(std::unique_ptr<NUClear::Environment> environment) : TestBase(std::move(environment)) {
+
+        // This reaction is here to emit something from a ReactionStatistics trigger
+        // This shouldn't cause reaction statistics of their own otherwise everything would explode
+        on<Trigger<Step<1>>>().then(initial_name, [this] {
+            events.emplace_back("Code: Started " + initial_name, NUClear::clock::now());
+
+            events.emplace_back("Code: Emit " + heavy_name, NUClear::clock::now());
+            emit(std::make_unique<HeavyTask>());
+            events.emplace_back("Code: Emitted " + heavy_name, NUClear::clock::now());
+
+            // Wait a step to separate out the start times (and the heavy task execution time)
+            std::this_thread::sleep_for(STEP);
+
+            events.emplace_back("Code: Emit " + light_name, NUClear::clock::now());
+            emit(std::make_unique<LightTask>());
+            events.emplace_back("Code: Emit " + light_name, NUClear::clock::now());
+
+            events.emplace_back("Code: Finished " + initial_name, NUClear::clock::now());
+        });
+
+        on<Trigger<HeavyTask>>().then(heavy_name, [] {
+            events.emplace_back("Code: Started " + heavy_name, NUClear::clock::now());
+
+            // Wait using CPU power
+            auto start = NUClear::clock::now();
+            while (NUClear::clock::now() - start < STEP) {
+            }
+
+            events.emplace_back("Code: Finished " + heavy_name, NUClear::clock::now());
+        });
+
+        on<Trigger<LightTask>>().then(light_name, [] {
+            events.emplace_back("Code: Started " + light_name, NUClear::clock::now());
+
+            // Wait by sleeping
+            std::this_thread::sleep_for(STEP);
+
+            events.emplace_back("Code: Finished " + light_name, NUClear::clock::now());
+        });
+
+
+        on<Trigger<ReactionStatistics>>().then([this](const ReactionStatistics& stats) {
+            if (stats.identifiers.reactor == reactor_name
+                && (stats.identifiers.name == initial_name || stats.identifiers.name == heavy_name
+                    || stats.identifiers.name == light_name)) {
+                events.emplace_back("Stat: Emitted " + stats.identifiers.name, stats.emitted);
+                events.emplace_back("Stat: Started " + stats.identifiers.name, stats.started);
+                events.emplace_back("Stat: Finished " + stats.identifiers.name, stats.finished);
+
+                usage.real[stats.identifiers.name]   = stats.finished - stats.started;
+                usage.user[stats.identifiers.name]   = stats.user_cpu_time;
+                usage.kernel[stats.identifiers.name] = stats.kernel_cpu_time;
+            }
+        });
+
+        on<Startup>().then("Startup", [this] { 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();
+
+    // The events are added in a different order due to stats running after, so sort it to be in the same order
+    std::sort(events.begin(), events.end(), [](const auto& lhs, const auto& rhs) { return lhs.second < rhs.second; });
+
+    // Convert the events to delta strings where 1 unit is 1 step unit
+    std::vector<std::string> delta_events;
+    auto first = events.front().second;
+    for (auto& event : events) {
+        auto delta = event.second - first;
+        auto units = std::chrono::duration_cast<std::chrono::nanoseconds>(delta).count()
+                     / std::chrono::duration_cast<std::chrono::nanoseconds>(STEP).count();
+        delta_events.push_back(event.first + " @ Step " + std::to_string(units));
+    }
+
+    const std::vector<std::string> expected = {
+        "Stat: Emitted Initial @ Step 0",  "Stat: Started Initial @ Step 0",  "Code: Started Initial @ Step 0",
+        "Code: Emit Heavy @ Step 0",       "Stat: Emitted Heavy @ Step 0",    "Code: Emitted Heavy @ Step 0",
+        "Code: Emit Light @ Step 1",       "Stat: Emitted Light @ Step 1",    "Code: Emit Light @ Step 1",
+        "Code: Finished Initial @ Step 1", "Stat: Finished Initial @ Step 1", "Stat: Started Heavy @ Step 1",
+        "Code: Started Heavy @ Step 1",    "Code: Finished Heavy @ Step 2",   "Stat: Finished Heavy @ Step 2",
+        "Stat: Started Light @ Step 2",    "Code: Started Light @ Step 2",    "Code: Finished Light @ Step 3",
+        "Stat: Finished Light @ Step 3",
+    };
+
+    // Make an info print the diff in an easy to read way if we fail
+    INFO(test_util::diff_string(expected, delta_events));
+
+    // Check the events fired in order and only those events
+    REQUIRE(delta_events == expected);
+
+    // Check that the amount of CPU time spent is at least reasonable for each of the reactions
+
+    // Most of initial real time should be spent sleeping
+    REQUIRE(usage.user[initial_name] + usage.kernel[initial_name] < usage.real[initial_name] / 2);
+
+    // Most of heavy real time should be cpu time
+    REQUIRE(usage.user[heavy_name] + usage.kernel[heavy_name] > usage.real[heavy_name] / 2);
+
+    // Most of light real time should be sleeping
+    REQUIRE(usage.user[light_name] + usage.kernel[light_name] < usage.real[light_name] / 2);
+}