Commit 2291cd22 authored by Pádraig Ó Conbhuí's avatar Pádraig Ó Conbhuí
Browse files

Add call count setting and incrementing functionality

parent 1aa5df34
Pipeline #2542 failed with stages
in 2 minutes and 36 seconds
......@@ -4,8 +4,8 @@
#include <catch2/catch.hpp>
#include <numeric>
#include <chrono>
#include <numeric>
#include <vector>
// Muck up optimization
......@@ -13,21 +13,20 @@ volatile extern size_t v;
volatile size_t v = 10;
// Keep the result of t
template<typename T>
void use(const T& t) {
v = std::accumulate(t.begin(), t.end(), size_t(0));
v = 10;
template <typename T> void use(const T &t) {
v = std::accumulate(t.begin(), t.end(), size_t(0));
v = 10;
}
// Generate a vector using v so it can't be
// optimized by the compiler (heap elision etc.)
static std::vector<size_t> to_measure() {
std::vector<size_t> value;
value.resize(v);
for(size_t i=0; i<v; i++) {
value[i] = v*i;
}
return value;
std::vector<size_t> value;
value.resize(v);
for (size_t i = 0; i < v; i++) {
value[i] = v * i;
}
return value;
}
TEST_CASE("perforate::scoped_trace", "[scoped_trace][benchmark]") {
......@@ -40,26 +39,35 @@ TEST_CASE("perforate::scoped_trace", "[scoped_trace][benchmark]") {
// Measure the "PERFORATE_SCOPED_TRACE overhead to a loop with PERForate"
// Assume it's around 100ns.
{
PERFORATE_SCOPED_TRACE("perforate::scope_trace loop overhead x1e6");
for(size_t i=0; i<1000000; i++) {
PERFORATE_SCOPED_TRACE("perforate::scope_trace overhead measured");
constexpr size_t number_of_iterations = 1000000;
PERFORATE_SCOPED_TRACE("empty loop containing perforate::scope_trace")
.call_count(number_of_iterations);
for (size_t i = 0; i < number_of_iterations; i++) {
PERFORATE_SCOPED_TRACE("perforate::scope_trace from inside empty loop");
}
}
// Measure difference between PERFORATE_SCOPE_TRACE inside and outside a loop
// with a workload
{
constexpr size_t number_of_iterations = 1000000;
// Outside loop
{
PERFORATE_SCOPED_TRACE("external measurement x1e6");
for(size_t i=0; i<1000000; i++) {
use(to_measure());
}
PERFORATE_SCOPED_TRACE("measuring work outside loop")
.call_count(number_of_iterations);
for (size_t i = 0; i < number_of_iterations; i++) {
use(to_measure());
}
}
// Inside loop
for(size_t i=0; i<1000000; i++) {
PERFORATE_SCOPED_TRACE("internal measurement");
use(to_measure());
for (size_t i = 0; i < number_of_iterations; i++) {
PERFORATE_SCOPED_TRACE("measuring work inside loop");
use(to_measure());
}
}
}
......@@ -17,12 +17,10 @@
#include <cstddef>
#include <cstdlib>
// Some configuration options
#ifndef PERFORATE_OPTIONS_ENABLED_DEFAULT
#define PERFORATE_OPTIONS_ENABLED_DEFAULT true
#endif // PERFORATE_OPTIONS_ENABLED_DEFAULT
#endif // PERFORATE_OPTIONS_ENABLED_DEFAULT
// Optional C++ version specific bits
#if __cplusplus >= 201703L
......@@ -150,21 +148,20 @@ void print_range_stats(Stream &stream, const Stats &stats) {
}
template <typename Stream, typename StatsPtrIterator>
void print_range_stats_list(Stream &stream,
StatsPtrIterator stats_ptrs_begin,
void print_range_stats_list(Stream &stream, StatsPtrIterator stats_ptrs_begin,
StatsPtrIterator stats_ptrs_end) {
const auto empty = [](const auto &stats) {
return stats->range_name() == nullptr;
};
const auto registry_empty = std::all_of(stats_ptrs_begin,
stats_ptrs_end, empty);
const auto registry_empty =
std::all_of(stats_ptrs_begin, stats_ptrs_end, empty);
if (!registry_empty) {
stream << "\n------------"
<< "\nRange Stats:"
<< "\n------------\n";
for(; stats_ptrs_begin != stats_ptrs_end; ++stats_ptrs_begin) {
stream << "\n----------------"
<< "\nPERForate Stats:"
<< "\n----------------\n";
for (; stats_ptrs_begin != stats_ptrs_end; ++stats_ptrs_begin) {
if ((*stats_ptrs_begin)->range_name() == nullptr)
continue;
......@@ -320,9 +317,11 @@ public:
return default_sort_config();
return std::string{sort_config_env};
}());
sort_range_stats_list(m_range_stats_list.begin(), m_range_stats_list.end(), sort_config);
sort_range_stats_list(m_range_stats_list.begin(), m_range_stats_list.end(),
sort_config);
print_range_stats_list(std::cout, m_range_stats_list.cbegin(), m_range_stats_list.cend());
print_range_stats_list(std::cout, m_range_stats_list.cbegin(),
m_range_stats_list.cend());
}
};
......@@ -339,6 +338,7 @@ class scoped_trace {
using time_point = typename Clock::time_point;
time_point m_t0 = Clock::now();
int64_t m_call_count = 1;
static constexpr time_point t_disabled() {
using duration = typename Clock::duration;
......@@ -366,19 +366,31 @@ public:
// Move constructor marks other as inactive
scoped_trace(scoped_trace &&other)
: m_t0{std::exchange(other.m_t0, t_disabled())} {
: m_t0{std::exchange(other.m_t0, t_disabled())},
m_call_count{std::exchange(other.m_call_count, 0)} {
assert(other.m_t0 == t_disabled());
assert(other.m_call_count == 0);
}
scoped_trace &operator=(scoped_trace &&other) = delete;
scoped_trace call_count(int64_t n) && {
m_call_count = n;
return std::move(*this);
}
scoped_trace& operator++() {
++m_call_count;
return *this;
}
~scoped_trace() {
if (m_t0 != t_disabled()) {
if (m_call_count != 0) {
const auto now = Clock::now();
const auto delta = now - m_t0;
auto &s = stats();
s.add_range(delta, 1);
s.add_range(delta, m_call_count);
if (AggregateCount != 0 && s.call_count() % AggregateCount == 0) {
detail::print_range_stats(std::cout, s);
......
......@@ -168,10 +168,24 @@ TEST_CASE("test_clock sanity check", "[test_clock]") {
}
}
TEST_CASE("scoped_trace should trace / time a scope", "[scoped_trace]") {
// Find the range_stats from the range_stats_list by name
static const perforate::detail::range_stats &find_stats(const char *name) {
const auto &stats_list =
perforate::detail::per_tag_range_stats::policy().range_stats_list();
const auto stats_it = std::find_if(
std::cbegin(stats_list), std::cend(stats_list), [&](const auto *stats) {
if (stats->range_name() == nullptr)
return false;
return std::string{stats->range_name()} == name;
});
REQUIRE(stats_it != std::cend(stats_list));
return **stats_it;
};
TEST_CASE("scoped_trace should trace / time a scope", "[scoped_trace]") {
SECTION("scoped_trace should create an entry in range_stats_list") {
class st_1_tag;
......@@ -182,20 +196,14 @@ TEST_CASE("scoped_trace should trace / time a scope", "[scoped_trace]") {
test_clock::elapsed_time = std::chrono::seconds(10);
}
const auto stats_it = std::find_if(
std::cbegin(stats_list), std::cend(stats_list), [](const auto *stats) {
if (stats->range_name() == nullptr)
return false;
return std::string{stats->range_name()} == "test::st_1";
});
const auto &stats = find_stats("test::st_1");
REQUIRE(stats_it != std::cend(stats_list));
REQUIRE(std::string{(**stats_it).range_name()} == "test::st_1");
REQUIRE((**stats_it).accumulated_time() == std::chrono::seconds(10));
REQUIRE((**stats_it).call_count() == 1);
REQUIRE(std::string{stats.range_name()} == "test::st_1");
REQUIRE(stats.accumulated_time() == std::chrono::seconds(10));
REQUIRE(stats.call_count() == 1);
// Expect the value found to equal the actual value
REQUIRE(&**stats_it ==
REQUIRE(&stats ==
&perforate::detail::per_tag_range_stats::value<st_1_tag>());
}
......@@ -211,42 +219,60 @@ TEST_CASE("scoped_trace should trace / time a scope", "[scoped_trace]") {
test_clock::elapsed_time += std::chrono::seconds{i * i};
}
const auto stats_it = std::find_if(
std::cbegin(stats_list), std::cend(stats_list), [](const auto *stats) {
if (stats->range_name() == nullptr)
return false;
return std::string{stats->range_name()} == "test::st_2";
});
REQUIRE(stats_it != std::cend(stats_list));
const auto &stats = find_stats("test::st_2");
REQUIRE((**stats_it).call_count() == num_calls);
REQUIRE(stats.call_count() == num_calls);
const std::chrono::seconds expected_elapsed =
test_clock::elapsed_time - num_calls * std::chrono::seconds(1);
REQUIRE((**stats_it).accumulated_time() == expected_elapsed);
REQUIRE(stats.accumulated_time() == expected_elapsed);
}
SECTION("calls per scope should be settable / incrementable") {
SECTION("using the call_count method during construction") {
test_clock::elapsed_time = std::chrono::seconds{0};
const size_t num_calls = 100;
{
const auto st =
perforate::scoped_trace<class st_3_tag, 0, test_clock>{"test::st_3"}
.call_count(num_calls);
test_clock::elapsed_time += std::chrono::seconds{1};
}
const auto &stats = find_stats("test::st_3");
REQUIRE(stats.call_count() == num_calls);
REQUIRE(stats.accumulated_time() == std::chrono::seconds{1});
}
SECTION("using the pre-increment operator in a loop") {
test_clock::elapsed_time = std::chrono::seconds{0};
const size_t num_calls = 100;
{
auto st =
perforate::scoped_trace<class st_4_tag, 0, test_clock>{"test::st_4"}
.call_count(0);
for (size_t i = 0; i < num_calls; i++) {
++st;
test_clock::elapsed_time += std::chrono::seconds{1};
}
}
const auto &stats = find_stats("test::st_4");
REQUIRE(stats.call_count() == num_calls);
REQUIRE(stats.accumulated_time() == std::chrono::seconds{num_calls});
}
}
}
TEST_CASE("scoped_trace helper functions and macros", "[scoped_trace]") {
// Find the range_stats from the range_stats_list by name
const auto find_stats =
[](const char *name) -> const perforate::detail::range_stats & {
const auto &stats_list =
perforate::detail::per_tag_range_stats::policy().range_stats_list();
const auto stats_it = std::find_if(
std::cbegin(stats_list), std::cend(stats_list), [&](const auto *stats) {
if (stats->range_name() == nullptr)
return false;
return std::string{stats->range_name()} == name;
});
REQUIRE(stats_it != std::cend(stats_list));
return **stats_it;
};
SECTION("make_scoped_trace and end_scoped_trace") {
class mst_1_tag;
......
Supports Markdown
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment