diff --git a/src/message/ReactionStatistics.hpp b/src/message/ReactionStatistics.hpp index b3e953cc4..8246e6b36 100644 --- a/src/message/ReactionStatistics.hpp +++ b/src/message/ReactionStatistics.hpp @@ -26,10 +26,11 @@ #include #include #include -#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}; }; diff --git a/src/util/CallbackGenerator.hpp b/src/util/CallbackGenerator.hpp index 7234d13e7..13b5b2fe3 100644 --- a/src/util/CallbackGenerator.hpp +++ b/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); diff --git a/src/util/usage_clock.cpp b/src/util/usage_clock.cpp new file mode 100644 index 000000000..ccd05ac3d --- /dev/null +++ b/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>(time)); + } + return time_point(); + } + +} // namespace util +} // namespace NUClear + +#else + #include + +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 diff --git a/src/util/usage_clock.hpp b/src/util/usage_clock.hpp new file mode 100644 index 000000000..6854b24c1 --- /dev/null +++ b/src/util/usage_clock.hpp @@ -0,0 +1,30 @@ +#ifndef NUCLEAR_UTIL_USAGE_CLOCK_HPP +#define NUCLEAR_UTIL_USAGE_CLOCK_HPP + +#include + +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; ///< 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 diff --git a/tests/tests/api/ReactionStatisticsTiming.cpp b/tests/tests/api/ReactionStatisticsTiming.cpp new file mode 100644 index 000000000..caa239075 --- /dev/null +++ b/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 +#include + +#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> code_events; +/// NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables) +std::vector> stat_events; + +struct Usage { + std::map real; + std::map 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 { +public: + TestReactor(std::unique_ptr environment) : TestBase(std::move(environment)) { + + on>, 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()); + code_events.emplace_back("Finished " + initial_name + ":" + heavy_name, NUClear::clock::now()); + }); + on>().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>, 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()); + code_events.emplace_back("Finished " + initial_name + ":" + light_name, NUClear::clock::now()); + }); + on>().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>().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().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>()); + }); + } +}; +} // namespace + +TEST_CASE("Testing reaction statistics timing", "[api][reactionstatistics][timing]") { + + NUClear::Configuration config; + config.thread_count = 1; + NUClear::PowerPlant plant(config); + plant.install(); + 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>& events) { + std::vector 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 delta_code_events = make_delta(code_events); + std::vector delta_stat_events = make_delta(stat_events); + + const std::vector 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); +}