bench: switch to std::chrono for time measurements

std::chrono removes portability issues.

Rather than storing doubles, store the untouched time_points. Then
convert to nanoseconds for display. This allows for maximum precision, while
keeping results comparable between differing hardware/operating systems.

Also, display full nanosecond counts rather than sub-second floats.
This commit is contained in:
Cory Fields 2017-10-25 16:38:24 -04:00
parent 57ee73990f
commit c515d266ec
3 changed files with 31 additions and 29 deletions

View file

@ -8,29 +8,22 @@
#include <assert.h> #include <assert.h>
#include <iostream> #include <iostream>
#include <iomanip> #include <iomanip>
#include <sys/time.h>
benchmark::BenchRunner::BenchmarkMap &benchmark::BenchRunner::benchmarks() { benchmark::BenchRunner::BenchmarkMap &benchmark::BenchRunner::benchmarks() {
static std::map<std::string, benchmark::BenchFunction> benchmarks_map; static std::map<std::string, benchmark::BenchFunction> benchmarks_map;
return benchmarks_map; return benchmarks_map;
} }
static double gettimedouble(void) {
struct timeval tv;
gettimeofday(&tv, nullptr);
return tv.tv_usec * 0.000001 + tv.tv_sec;
}
benchmark::BenchRunner::BenchRunner(std::string name, benchmark::BenchFunction func) benchmark::BenchRunner::BenchRunner(std::string name, benchmark::BenchFunction func)
{ {
benchmarks().insert(std::make_pair(name, func)); benchmarks().insert(std::make_pair(name, func));
} }
void void
benchmark::BenchRunner::RunAll(double elapsedTimeForOne) benchmark::BenchRunner::RunAll(benchmark::duration elapsedTimeForOne)
{ {
perf_init(); perf_init();
std::cout << "#Benchmark" << "," << "count" << "," << "min" << "," << "max" << "," << "average" << "," std::cout << "#Benchmark" << "," << "count" << "," << "min(ns)" << "," << "max(ns)" << "," << "average(ns)" << ","
<< "min_cycles" << "," << "max_cycles" << "," << "average_cycles" << "\n"; << "min_cycles" << "," << "max_cycles" << "," << "average_cycles" << "\n";
for (const auto &p: benchmarks()) { for (const auto &p: benchmarks()) {
@ -46,16 +39,17 @@ bool benchmark::State::KeepRunning()
++count; ++count;
return true; return true;
} }
double now; time_point now;
uint64_t nowCycles; uint64_t nowCycles;
if (count == 0) { if (count == 0) {
lastTime = beginTime = now = gettimedouble(); lastTime = beginTime = now = clock::now();
lastCycles = beginCycles = nowCycles = perf_cpucycles(); lastCycles = beginCycles = nowCycles = perf_cpucycles();
} }
else { else {
now = gettimedouble(); now = clock::now();
double elapsed = now - lastTime; auto elapsed = now - lastTime;
double elapsedOne = elapsed / (countMask + 1); auto elapsedOne = elapsed / (countMask + 1);
if (elapsedOne < minTime) minTime = elapsedOne; if (elapsedOne < minTime) minTime = elapsedOne;
if (elapsedOne > maxTime) maxTime = elapsedOne; if (elapsedOne > maxTime) maxTime = elapsedOne;
@ -70,8 +64,8 @@ bool benchmark::State::KeepRunning()
// The restart avoids including the overhead of this code in the measurement. // The restart avoids including the overhead of this code in the measurement.
countMask = ((countMask<<3)|7) & ((1LL<<60)-1); countMask = ((countMask<<3)|7) & ((1LL<<60)-1);
count = 0; count = 0;
minTime = std::numeric_limits<double>::max(); minTime = duration::max();
maxTime = std::numeric_limits<double>::min(); maxTime = duration::zero();
minCycles = std::numeric_limits<uint64_t>::max(); minCycles = std::numeric_limits<uint64_t>::max();
maxCycles = std::numeric_limits<uint64_t>::min(); maxCycles = std::numeric_limits<uint64_t>::min();
return true; return true;
@ -94,9 +88,13 @@ bool benchmark::State::KeepRunning()
assert(count != 0 && "count == 0 => (now == 0 && beginTime == 0) => return above"); assert(count != 0 && "count == 0 => (now == 0 && beginTime == 0) => return above");
// Output results // Output results
double average = (now-beginTime)/count; // Duration casts are only necessary here because hardware with sub-nanosecond clocks
// will lose precision.
int64_t min_elapsed = std::chrono::duration_cast<std::chrono::nanoseconds>(minTime).count();
int64_t max_elapsed = std::chrono::duration_cast<std::chrono::nanoseconds>(maxTime).count();
int64_t avg_elapsed = std::chrono::duration_cast<std::chrono::nanoseconds>((now-beginTime)/count).count();
int64_t averageCycles = (nowCycles-beginCycles)/count; int64_t averageCycles = (nowCycles-beginCycles)/count;
std::cout << std::fixed << std::setprecision(15) << name << "," << count << "," << minTime << "," << maxTime << "," << average << "," std::cout << std::fixed << std::setprecision(15) << name << "," << count << "," << min_elapsed << "," << max_elapsed << "," << avg_elapsed << ","
<< minCycles << "," << maxCycles << "," << averageCycles << "\n"; << minCycles << "," << maxCycles << "," << averageCycles << "\n";
std::cout.copyfmt(std::ios(nullptr)); std::cout.copyfmt(std::ios(nullptr));

View file

@ -9,6 +9,7 @@
#include <limits> #include <limits>
#include <map> #include <map>
#include <string> #include <string>
#include <chrono>
#include <boost/preprocessor/cat.hpp> #include <boost/preprocessor/cat.hpp>
#include <boost/preprocessor/stringize.hpp> #include <boost/preprocessor/stringize.hpp>
@ -37,11 +38,15 @@ BENCHMARK(CODE_TO_TIME);
namespace benchmark { namespace benchmark {
using clock = std::chrono::high_resolution_clock;
using time_point = clock::time_point;
using duration = clock::duration;
class State { class State {
std::string name; std::string name;
double maxElapsed; duration maxElapsed;
double beginTime; time_point beginTime, lastTime;
double lastTime, minTime, maxTime; duration minTime, maxTime;
uint64_t count; uint64_t count;
uint64_t countMask; uint64_t countMask;
uint64_t beginCycles; uint64_t beginCycles;
@ -49,9 +54,9 @@ namespace benchmark {
uint64_t minCycles; uint64_t minCycles;
uint64_t maxCycles; uint64_t maxCycles;
public: public:
State(std::string _name, double _maxElapsed) : name(_name), maxElapsed(_maxElapsed), count(0) { State(std::string _name, duration _maxElapsed) : name(_name), maxElapsed(_maxElapsed), count(0) {
minTime = std::numeric_limits<double>::max(); minTime = duration::max();
maxTime = std::numeric_limits<double>::min(); maxTime = duration::zero();
minCycles = std::numeric_limits<uint64_t>::max(); minCycles = std::numeric_limits<uint64_t>::max();
maxCycles = std::numeric_limits<uint64_t>::min(); maxCycles = std::numeric_limits<uint64_t>::min();
countMask = 1; countMask = 1;
@ -69,7 +74,7 @@ namespace benchmark {
public: public:
BenchRunner(std::string name, BenchFunction func); BenchRunner(std::string name, BenchFunction func);
static void RunAll(double elapsedTimeForOne=1.0); static void RunAll(duration elapsedTimeForOne = std::chrono::seconds(1));
}; };
} }

View file

@ -6,7 +6,6 @@
#include "bench.h" #include "bench.h"
#include "bloom.h" #include "bloom.h"
#include "utiltime.h"
static void RollingBloom(benchmark::State& state) static void RollingBloom(benchmark::State& state)
{ {
@ -23,10 +22,10 @@ static void RollingBloom(benchmark::State& state)
data[2] = count >> 16; data[2] = count >> 16;
data[3] = count >> 24; data[3] = count >> 24;
if (countnow == nEntriesPerGeneration) { if (countnow == nEntriesPerGeneration) {
int64_t b = GetTimeMicros(); auto b = benchmark::clock::now();
filter.insert(data); filter.insert(data);
int64_t e = GetTimeMicros(); auto total = std::chrono::duration_cast<std::chrono::nanoseconds>(benchmark::clock::now() - b).count();
std::cout << "RollingBloom-refresh,1," << (e-b)*0.000001 << "," << (e-b)*0.000001 << "," << (e-b)*0.000001 << "\n"; std::cout << "RollingBloom-refresh,1," << total << "," << total << "," << total << "\n";
countnow = 0; countnow = 0;
} else { } else {
filter.insert(data); filter.insert(data);