Skip to content

Commit

Permalink
Merge pull request #4490 from randombit/jack/timer-units
Browse files Browse the repository at this point in the history 
Add option to quote performance in microseconds or nanoseconds
  • Loading branch information
@randombit
randombit authored Dec 23, 2024
2 parents c795370 + 8a191df commit 6471abd
Show file tree
Hide file tree
Showing 5 changed files with 88 additions and 135 deletions.
49 changes: 0 additions & 49 deletions src/cli/perf_rng.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,8 +6,6 @@

#include "perf.h"

#include "../tests/test_rng.h" // FIXME
#include <botan/entropy_src.h>
#include <botan/rng.h>

#if defined(BOTAN_HAS_COMPRESSION)
Expand Down Expand Up @@ -96,51 +94,4 @@ class PerfTest_Rng final : public PerfTest {

BOTAN_REGISTER_PERF_TEST("RNG", PerfTest_Rng);

class PerfTest_Entropy final : public PerfTest {
public:
void go(const PerfConfig& config) override {
Botan::Entropy_Sources& srcs = Botan::Entropy_Sources::global_sources();

for(auto src : srcs.enabled_sources()) {
size_t entropy_bits = 0;
Botan_Tests::SeedCapturing_RNG rng;

auto timer = config.make_timer(src);
timer->run([&]() { entropy_bits = srcs.poll_just(rng, src); });

size_t compressed_size = 0;

#if defined(BOTAN_HAS_ZLIB)
auto comp = Botan::Compression_Algorithm::create("zlib");

if(comp) {
Botan::secure_vector<uint8_t> compressed;
compressed.assign(rng.seed_material().begin(), rng.seed_material().end());
comp->start(9);
comp->finish(compressed);

compressed_size = compressed.size();
}
#endif

std::ostringstream msg;

msg << "Entropy source " << src << " output " << rng.seed_material().size() << " bytes"
<< " estimated entropy " << entropy_bits << " in " << timer->milliseconds() << " ms";

if(compressed_size > 0) {
msg << " output compressed to " << compressed_size << " bytes";
}

msg << " total samples " << rng.samples() << "\n";

timer->set_custom_msg(msg.str());

config.record_result(*timer);
}
}
};

BOTAN_REGISTER_PERF_TEST("entropy", PerfTest_Entropy);

} // namespace Botan_CLI
84 changes: 82 additions & 2 deletions src/cli/speed.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -189,13 +189,79 @@ std::vector<size_t> unique_buffer_sizes(const std::string& cmdline_arg) {
return std::vector<size_t>(buf.begin(), buf.end());
}

std::string format_timer(const Timer& t, size_t time_unit) {
constexpr size_t MiB = 1024 * 1024;

std::ostringstream oss;

oss << t.get_name() << " ";

const uint64_t events = t.events();

if(t.buf_size() == 0) {
// Report operations/time unit

if(events == 0) {
oss << "no events ";
} else {
oss << static_cast<uint64_t>(t.events_per_second()) << ' ' << t.doing() << "/sec; ";

if(time_unit == 1000) {
oss << std::setprecision(2) << std::fixed << (t.milliseconds() / events) << " ms/op ";
} else if(time_unit == 1000 * 1000) {
oss << std::setprecision(2) << std::fixed << (t.microseconds() / events) << " us/op ";
} else if(time_unit == 1000 * 1000 * 1000) {
oss << std::setprecision(0) << std::fixed << (t.nanoseconds() / events) << " ns/op ";
}

if(t.cycles_consumed() != 0 && events > 0) {
const double cycles_per_op = static_cast<double>(t.cycles_consumed()) / events;
const int precision = (cycles_per_op < 10000) ? 2 : 0;
oss << std::fixed << std::setprecision(precision) << cycles_per_op << " cycles/op ";
}

oss << "(" << events << " " << (events == 1 ? "op" : "ops") << " in " << t.milliseconds() << " ms)";
}
} else {
// Bulk op - report bytes/time unit

const double MiB_total = static_cast<double>(events) / MiB;
const double MiB_per_sec = MiB_total / t.seconds();

if(!t.doing().empty()) {
oss << t.doing() << " ";
}

if(t.buf_size() > 0) {
oss << "buffer size " << t.buf_size() << " bytes: ";
}

if(events == 0) {
oss << "N/A ";
} else {
oss << std::fixed << std::setprecision(3) << MiB_per_sec << " MiB/sec ";
}

if(t.cycles_consumed() != 0 && events > 0) {
const double cycles_per_byte = static_cast<double>(t.cycles_consumed()) / events;
oss << std::fixed << std::setprecision(2) << cycles_per_byte << " cycles/byte ";
}

oss << "(" << MiB_total << " MiB in " << t.milliseconds() << " ms)";
}

oss << "\n";

return oss.str();
}

} // namespace

class Speed final : public Command {
public:
Speed() :
Command(
"speed --msec=500 --format=default --ecc-groups= --buf-size=1024 --clear-cpuid= --cpu-clock-speed=0 --cpu-clock-ratio=1.0 *algos") {
"speed --msec=500 --format=default --time-unit=ms --ecc-groups= --buf-size=1024 --clear-cpuid= --cpu-clock-speed=0 --cpu-clock-ratio=1.0 *algos") {
}

static std::vector<std::string> default_benchmark_list() {
Expand Down Expand Up @@ -303,6 +369,18 @@ class Speed final : public Command {

double clock_cycle_ratio = std::strtod(clock_ratio.c_str(), nullptr);

m_time_unit = [](std::string_view tu) {
if(tu == "ms") {
return 1000;
} else if(tu == "us") {
return 1000 * 1000;
} else if(tu == "ns") {
return 1000 * 1000 * 1000;
} else {
throw CLI_Usage_Error("Unknown time unit (supported: ms, us, ns)");
}
}(get_arg("time-unit"));

/*
* This argument is intended to be the ratio between the cycle counter
* and the actual machine cycles. It is extremely unlikely that there is
Expand Down Expand Up @@ -396,6 +474,7 @@ class Speed final : public Command {
}

private:
size_t m_time_unit = 0;
uint64_t m_cycles_consumed = 0;
uint64_t m_ns_taken = 0;
std::unique_ptr<Summary> m_summary;
Expand All @@ -407,7 +486,8 @@ class Speed final : public Command {
if(m_json) {
m_json->add(t);
} else {
output() << t.to_string() << std::flush;
output() << format_timer(t, m_time_unit);

if(m_summary) {
m_summary->add(t);
}
Expand Down
67 changes: 0 additions & 67 deletions src/cli/timer.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -75,71 +75,4 @@ bool Timer::operator<(const Timer& other) const {
return (this->get_name() < other.get_name());
}

std::string Timer::to_string() const {
if(!m_custom_msg.empty()) {
return m_custom_msg;
} else if(this->buf_size() == 0) {
return result_string_ops();
} else {
return result_string_bps();
}
}

std::string Timer::result_string_bps() const {
const size_t MiB = 1024 * 1024;

const double MiB_total = static_cast<double>(events()) / MiB;
const double MiB_per_sec = MiB_total / seconds();

std::ostringstream oss;
oss << get_name();

if(!doing().empty()) {
oss << " " << doing();
}

if(buf_size() > 0) {
oss << " buffer size " << buf_size() << " bytes:";
}

if(events() == 0) {
oss << " "
<< "N/A";
} else {
oss << " " << std::fixed << std::setprecision(3) << MiB_per_sec << " MiB/sec";
}

if(cycles_consumed() != 0) {
const double cycles_per_byte = static_cast<double>(cycles_consumed()) / events();
oss << " " << std::fixed << std::setprecision(2) << cycles_per_byte << " cycles/byte";
}

oss << " (" << MiB_total << " MiB in " << milliseconds() << " ms)\n";

return oss.str();
}

std::string Timer::result_string_ops() const {
std::ostringstream oss;

oss << get_name() << " ";

if(events() == 0) {
oss << "no events\n";
} else {
oss << static_cast<uint64_t>(events_per_second()) << ' ' << doing() << "/sec; " << std::setprecision(2)
<< std::fixed << ms_per_event() << " ms/op";

if(cycles_consumed() != 0) {
const double cycles_per_op = static_cast<double>(cycles_consumed()) / events();
const int precision = (cycles_per_op < 10000) ? 2 : 0;
oss << " " << std::fixed << std::setprecision(precision) << cycles_per_op << " cycles/op";
}

oss << " (" << events() << " " << (events() == 1 ? "op" : "ops") << " in " << milliseconds() << " ms)\n";
}

return oss.str();
}

} // namespace Botan_CLI
14 changes: 5 additions & 9 deletions src/cli/timer.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,10 +65,14 @@ class Timer final {

uint64_t value() const { return m_time_used; }

double seconds() const { return milliseconds() / 1000.0; }
double seconds() const { return value() / 1000000000.0; }

double milliseconds() const { return value() / 1000000.0; }

double microseconds() const { return value() / 1000.0; }

double nanoseconds() const { return static_cast<double>(value()); }

double ms_per_event() const { return milliseconds() / events(); }

uint64_t cycles_consumed() const {
Expand All @@ -92,16 +96,9 @@ class Timer final {

double seconds_per_event() const { return events() > 0 ? seconds() / events() : 0.0; }

void set_custom_msg(std::string_view s) { m_custom_msg = s; }

bool operator<(const Timer& other) const;

std::string to_string() const;

private:
std::string result_string_bps() const;
std::string result_string_ops() const;

// const data
std::string m_name, m_doing;
size_t m_buf_size;
Expand All @@ -110,7 +107,6 @@ class Timer final {
uint64_t m_clock_speed;

// set at runtime
std::string m_custom_msg;
uint64_t m_event_count = 0;

uint64_t m_time_used = 0;
Expand Down
9 changes: 1 addition & 8 deletions src/scripts/test_cli.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1690,7 +1690,7 @@ def cli_speed_table_tests(_tmp_dir):
logging.error("Unexpected trailing message got %s", output[10])

def cli_speed_invalid_option_tests(_tmp_dir):
speed_usage = "Usage: speed --msec=500 --format=default --ecc-groups= --buf-size=1024 --clear-cpuid= --cpu-clock-speed=0 --cpu-clock-ratio=1.0 *algos"
speed_usage = "Usage: speed --msec=500 --format=default --time-unit=ms --ecc-groups= --buf-size=1024 --clear-cpuid= --cpu-clock-speed=0 --cpu-clock-ratio=1.0 *algos"

test_cli("speed", ["--buf-size=0", "--msec=1", "AES-128"],
expected_stderr="Usage error: Cannot have a zero-sized buffer\n%s" % (speed_usage))
Expand Down Expand Up @@ -1762,13 +1762,6 @@ def cli_speed_tests(_tmp_dir):
if format_re.match(line) is None:
logging.error("Unexpected line %s", line)

# Entropy source rdseed output 128 bytes estimated entropy 0 in 0.02168 ms total samples 32
output = test_cli("speed", ["--msec=%d" % (msec), "entropy"], None).split('\n')
format_re = re.compile(r'^Entropy source [_a-z0-9]+ output [0-9]+ bytes estimated entropy [0-9]+ in [0-9]+\.[0-9]+ ms .*total samples [0-9]+')
for line in output:
if format_re.match(line) is None:
logging.error("Unexpected line %s", line)

output = test_cli("speed", ["--msec=%d" % (msec), "zfec"], None).split('\n')
format_re = re.compile(r'^zfec [0-9]+/[0-9]+ (encode|decode) buffer size [0-9]+ bytes: [0-9]+\.[0-9]+ MiB/sec .*\([0-9]+\.[0-9]+ MiB in [0-9]+\.[0-9]+ ms')
for line in output:
Expand Down

0 comments on commit 6471abd

Please sign in to comment.