diff --git a/CMakeLists.txt b/CMakeLists.txt index 4d82f05f4cd..048634af400 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -406,6 +406,12 @@ set (Seastar_DEBUG_SHARED_PTR STRING "Enable shared_ptr debugging. Can be ON, OFF or DEFAULT (which enables it for Debug and Sanitize)") +set (Seastar_PERF_TESTS_HONOR_DECLARED_RATE + "DEFAULT" + CACHE + STRING + "Honor an iteration rate declared by a perf test. Can be ON, OFF or DEFAULT (which enables it for release builds)") + # # Useful (non-cache) variables. # @@ -1364,6 +1370,16 @@ if (Seastar_INSTALL OR Seastar_TESTING) add_library (Seastar::seastar_perf_testing ALIAS seastar_perf_testing) target_compile_definitions (seastar_perf_testing PRIVATE ${Seastar_PRIVATE_COMPILE_DEFINITIONS}) + # A declared iteration rate only holds for an optimized build, so by default + # only those honor one. configure.py's release mode maps to RelWithDebInfo. + tri_state_option (${Seastar_PERF_TESTS_HONOR_DECLARED_RATE} + DEFAULT_BUILD_TYPES "Release" "RelWithDebInfo" + CONDITION condition) + if (condition) + target_compile_definitions (seastar_perf_testing + PUBLIC + $<${condition}:SEASTAR_PERF_TESTS_HONOR_DECLARED_RATE=1>) + endif () target_compile_options (seastar_perf_testing PRIVATE ${Seastar_PRIVATE_CXX_FLAGS}) target_link_libraries (seastar_perf_testing diff --git a/configure.py b/configure.py index bd9d667b48b..66c8dcfd9c0 100755 --- a/configure.py +++ b/configure.py @@ -212,6 +212,11 @@ def resolve_compilers_for_compiler_cache(args, compiler_cache): name='debug-shared-ptr', dest="debug_shared_ptr", help='Debug shared_ptr') +add_tristate( + arg_parser, + name='perf-test-declared-rates', + dest='perf_test_declared_rates', + help='honoring the iteration rates declared by perf tests') add_tristate( arg_parser, name='io_uring', @@ -318,6 +323,8 @@ def configure_mode(mode): tr(args.deferred_action_require_noexcept, 'DEFERRED_ACTION_REQUIRE_NOEXCEPT'), tr(args.unused_result_error, 'UNUSED_RESULT_ERROR'), tr(args.debug_shared_ptr, 'DEBUG_SHARED_PTR', value_when_none='default'), + tr(args.perf_test_declared_rates, 'PERF_TESTS_HONOR_DECLARED_RATE', + value_when_none='DEFAULT'), ] if not which('ninja-build') and which('ninja'): diff --git a/include/seastar/testing/perf_tests.hh b/include/seastar/testing/perf_tests.hh index f7f68c8baf5..41173608c13 100644 --- a/include/seastar/testing/perf_tests.hh +++ b/include/seastar/testing/perf_tests.hh @@ -41,11 +41,45 @@ using seastar::future; using seastar::noncopyable_function; using seastar::is_future; +// Whether a rate declared with perf_tests::test_options::iters_per_sec is +// honored. Such a rate is measured on an optimized build, and a build with +// sanitizers, debug checks or no inlining runs an order of magnitude slower, so +// holding the iteration count fixed there would stretch every run by that +// factor to produce numbers that are not comparable to an optimized build's +// anyway. The build system therefore opts in: seastar's CMake build defines +// this for the release build types and its Bazel build for optimized builds. +// Everywhere else a declared rate is ignored and the count is calibrated by the +// dry run as usual. +#ifndef SEASTAR_PERF_TESTS_HONOR_DECLARED_RATE +#define SEASTAR_PERF_TESTS_HONOR_DECLARED_RATE 0 +#endif + namespace perf_tests { // The type of the pre-run hook. See PERF_PRE_RUN_HOOK. using pre_run_hook = noncopyable_function; +// Optional declarations about a test, passed as a trailing argument to the +// PERF_TEST macros with designated initializers: +// +// PERF_TEST(my_group, my_case, .iters_per_sec = 10'000'000) { ... } +// +// Default initializing this struct results in the default options. +struct test_options { + // The number of iterations the test completes in one second. When non-zero, + // the iteration count of a run is fixed at iters_per_sec * --duration rather + // than being calibrated by a timed dry run, so every run executes the same + // number of iterations no matter what machine it runs on, and the duration + // of a run becomes the approximate quantity instead. An explicit + // --iterations takes precedence over this value, which is in turn only + // honored in a build that sets SEASTAR_PERF_TESTS_HONOR_DECLARED_RATE. + // + // A double so that a rate can be written in scientific notation - .iters_per_sec + // = 1.2e6 as well as 1'200'000. A value that is not finite and positive is + // ignored, leaving the count to be calibrated. + double iters_per_sec = 0; +}; + namespace internal { struct config; @@ -127,6 +161,7 @@ inline perf_stats& perf_stats::operator-=(perf_stats b) { class performance_test { std::string _test_case; std::string _test_group; + test_options _options; uint64_t _single_run_iterations = 0; std::atomic _max_single_run_iterations; @@ -160,15 +195,18 @@ protected: void start_run(); run_result stop_run(); public: - performance_test(const std::string& test_case, const std::string& test_group) + performance_test(const std::string& test_case, const std::string& test_group, + test_options options = {}) : _test_case(test_case) , _test_group(test_group) + , _options(options) { } virtual ~performance_test() = default; const std::string& test_case() const { return _test_case; } const std::string& test_group() const { return _test_group; } + const test_options& options() const { return _options; } std::string name() const { return fmt::format("{}.{}", test_group(), test_case()); } void run(const config&); @@ -236,8 +274,9 @@ public: template struct test_registrar { - test_registrar(const std::string& test_group, const std::string& test_case) { - auto test = std::make_unique>(test_case, test_group); + test_registrar(const std::string& test_group, const std::string& test_case, + test_options options = {}) { + auto test = std::make_unique>(test_case, test_group, options); performance_test::register_test(std::move(test)); } }; @@ -284,38 +323,48 @@ void do_not_optimize(const T& v) // the test function shall return either size_t or future for synchronous and // asynchronous cases respectively. The returned value shall be the number of iterations // done in a single test run. +// +// All four macros accept an optional trailing argument declaring perf_tests::test_options +// for the test, written with designated initializers: +// +// PERF_TEST(my_group, my_case, .iters_per_sec = 10'000'000) { ... } +// -#define PERF_TEST_F(test_group, test_case) \ +#define PERF_TEST_F(test_group, test_case, ...) \ struct test_##test_group##_##test_case : test_group { \ [[gnu::always_inline]] inline auto run(); \ }; \ static ::perf_tests::internal::test_registrar \ - test_##test_group##_##test_case##_registrar(#test_group, #test_case); \ + test_##test_group##_##test_case##_registrar(#test_group, #test_case \ + __VA_OPT__(, ::perf_tests::test_options{__VA_ARGS__})); \ [[gnu::always_inline]] auto test_##test_group##_##test_case::run() -#define PERF_TEST(test_group, test_case) \ +#define PERF_TEST(test_group, test_case, ...) \ struct test_##test_group##_##test_case { \ [[gnu::always_inline]] inline auto run(); \ }; \ static ::perf_tests::internal::test_registrar \ - test_##test_group##_##test_case##_registrar(#test_group, #test_case); \ + test_##test_group##_##test_case##_registrar(#test_group, #test_case \ + __VA_OPT__(, ::perf_tests::test_options{__VA_ARGS__})); \ [[gnu::always_inline]] auto test_##test_group##_##test_case::run() -#define PERF_TEST_C(test_group, test_case) \ +#define PERF_TEST_C(test_group, test_case, ...) \ struct test_##test_group##_##test_case : test_group { \ inline future<> run(); \ }; \ static ::perf_tests::internal::test_registrar \ - test_##test_group##_##test_case##_registrar(#test_group, #test_case); \ + test_##test_group##_##test_case##_registrar(#test_group, #test_case \ + __VA_OPT__(, ::perf_tests::test_options{__VA_ARGS__})); \ future<> test_##test_group##_##test_case::run() -#define PERF_TEST_CN(test_group, test_case) \ +#define PERF_TEST_CN(test_group, test_case, ...) \ struct test_##test_group##_##test_case : test_group { \ inline future run(); \ }; \ static ::perf_tests::internal::test_registrar \ - test_##test_group##_##test_case##_registrar(#test_group, #test_case); \ + test_##test_group##_##test_case##_registrar(#test_group, #test_case \ + __VA_OPT__(, ::perf_tests::test_options{__VA_ARGS__})); \ future test_##test_group##_##test_case::run() diff --git a/tests/perf/perf-tests.md b/tests/perf/perf-tests.md index dcfd84b5bbe..476d5b23a1d 100644 --- a/tests/perf/perf-tests.md +++ b/tests/perf/perf-tests.md @@ -16,15 +16,20 @@ combined.one_row 745336 691.218ns 0.175ns 689.073ns combined.single_active 7871 85.271us 76.185ns 85.145us 108.316us ``` -`perf-tests` allows limiting the number of iterations or the duration of each run. In the latter case there is an additional dry run used to estimate how many iterations can be run in the specified time. The measured runs are limited by that number of iterations. This means that there is no overhead caused by timers and that each run consists of the same number of iterations. +`perf-tests` allows limiting the number of iterations or the duration of each +run. If duration is used, the implementation depends on whether a test declares +iters_per_sec. If it does the total iteration count is calculated directly +based on that value, and if not an additional dry run is used to estimate how +many iterations can be run in the specified time. ### Flags -* `-i ` or `--iterations ` – limits the number of iterations in each run to no more than `n` (0 for unlimited) -* `-d ` or `--duration ` – limits the duration of each run to no more than `t` seconds (0 for unlimited) +* `-i ` or `--iterations ` – fixes the number of iterations in each run at `n`, however long that takes (0 to let `--duration` decide) +* `-d ` or `--duration ` – limits the duration of each run to no more than `t` seconds, unless `--iterations` has already fixed the count (0 for unlimited) * `-r ` or `--runs ` – the number of runs of each test to execute * `-t ` or `--tests ` – executes only tests which names match any regular expression in a comma-separated list `regexs` * `--list` – lists all available tests +* `--suggest-rates` – after the results, print the iteration rate measured for each test as a `.iters_per_sec` declaration to paste into its `PERF_TEST` macro * `--overhead-threshold ` – warn if measurement overhead exceeds this percentage (default: 10) * `--fail-on-high-overhead` – fail the test run if any test exceeds the overhead threshold @@ -138,3 +143,46 @@ WARNING: test 'example.my_test' has high measurement overhead: 15.2% (threshold: ``` You can adjust the threshold with `--overhead-threshold `, or fail the test run entirely when overhead is too high with `--fail-on-high-overhead`. + +### Fixed iteration counts + +Calibrating the iteration count with a dry run keeps the duration of a run stable, but makes the number of iterations depend on how fast the machine is and on whatever else it was doing during the dry run. A test which declares how many iterations it completes in one second gets the opposite trade-off: the count is fixed at the declared rate times `--duration`, no dry run is used to pick it, and the duration of a run becomes the approximate quantity. + +```c++ +PERF_TEST(example, declared_rate, .iters_per_sec = 10'000'000) +{ + auto v = compute_value(); + perf_tests::do_not_optimize(v); +} +``` + +The rate is a `double`, so it can be written in scientific notation - `.iters_per_sec = 1.2e6` as well as `1'200'000`. + +A declared rate is only honored in a release build. The rate is a measurement of one, and a build with sanitizers or debug checks runs an order of magnitude slower, so holding the count fixed there would stretch every run by that factor to produce numbers that are not comparable to a release build's anyway. The opt-in is the `SEASTAR_PERF_TESTS_HONOR_DECLARED_RATE` macro, which the CMake build defines for the release build types and the Bazel build for `--config=release`. Either can be told otherwise, to hold the count fixed in a slow build or to calibrate it in a fast one: pass `--enable-perf-test-declared-rates` or `--disable-perf-test-declared-rates` to `configure.py`, or set `--@seastar//:perf_test_declared_rates` under Bazel. In a build which does not honor them the count is calibrated by the dry run as usual, and the configuration header says so: + +``` +declared rates: ignored (not a release build) +``` + +With the default `--duration 1` that test runs exactly 10,000,000 iterations per run; with `--duration 5`, exactly 50,000,000. The rate is expressed in the same iterations that `--iterations` limits and the `iters` column reports, so a test which returns an iteration count from its body declares its rate in those inner iterations. + +An explicit `--iterations` overrides the declaration, and `--duration 0` (no duration limit) disables it, since there is then no duration to scale by. + +The rate is a measurement, so the framework will take it for you: `--suggest-rates` prints one pasteable declaration per test, measured on the wall clock (what `--duration` actually limits) and rounded to two significant digits. + +``` +measured iteration rates, to declare in the PERF_TEST macro so that a +run's iteration count no longer depends on the speed of the machine: + + example.simple1 .iters_per_sec = 2'700'000'000 + example.declared_rate .iters_per_sec = 52'000'000 + example.big_inner_loop .iters_per_sec = 540 +``` + +It works whether or not the test already declares a rate, so the same command both writes the declarations and refreshes them. + +A declared rate is a measurement of one machine, so it only approximates the duration on another. It does not affect the reported results, which are always per-iteration, so a rate that is out of date costs nothing but a run that is shorter or longer than asked for. Once a run strays more than a factor of two from the requested duration, the achieved rate is reported so the declaration can be refreshed: + +``` +WARNING: test 'example.declared_rate' declares 100000 iterations/s but achieved 2.87e+07/s, so each run took 3.484ms rather than the requested 1.000s +``` diff --git a/tests/perf/perf_tests.cc b/tests/perf/perf_tests.cc index f5900fd160f..3106830a2e7 100644 --- a/tests/perf/perf_tests.cc +++ b/tests/perf/perf_tests.cc @@ -270,6 +270,9 @@ void time_measurement_stop_iteration() { std::map parameters; +// Iteration rates measured for --suggest-rates, in the order the tests ran. +std::vector> suggested_rates; + std::string get_parameter(std::string name) { auto it = parameters.find(name); return it == parameters.end() ? "" : it->second; @@ -305,6 +308,9 @@ struct config { unsigned random_seed = 0; double overhead_threshold = 0.1; // warn if overhead exceeds this ratio (e.g., 0.1 = 10%) bool fail_on_high_overhead = false; // fail the test run if overhead exceeds threshold + bool suggest_rates = false; // report each test's measured iteration rate + // a test declares a rate that this build does not honor + bool ignored_declared_rates = false; }; // absorbs a single metric across all runs and calculates summary statistics @@ -352,6 +358,7 @@ struct float_stats { struct result { result(size_t run_count) : runtime{run_count}, + walltime{run_count}, allocs{run_count}, tasks{run_count}, inst{run_count}, @@ -365,6 +372,10 @@ struct result { unsigned runs = 0; float_stats runtime; + // Wall-clock length of a run, which for a test using start/stop_measuring_time + // is longer than runtime. Not reported as a column; it is what --duration + // limits, so it is what a declared iteration rate has to predict. + float_stats walltime; float_stats<> allocs; float_stats<> tasks; @@ -705,7 +716,7 @@ struct stdout_printer : text_printer { : text_printer(columns, options) {} virtual void print_configuration(const config& c) override { - fmt::print("{:<25} {}\n{:<25} {}\n{:<25} {}\n{:<25} {}\n{:<25} {}\n{:<25} {} ({})\n\n", + fmt::print("{:<25} {}\n{:<25} {}\n{:<25} {}\n{:<25} {}\n{:<25} {}\n{:<25} {} ({})\n", "single run iterations:", c.single_run_iterations, "single run duration:", duration { double(c.single_run_duration.count()) }, "number of runs:", c.number_of_runs, @@ -714,6 +725,11 @@ struct stdout_printer : text_printer { "start/stop overhead:", duration { measure_time->start_stop_overhead() }, duration { measure_time->start_stop_overhead_external() }); + if (c.ignored_declared_rates) { + fmt::print("{:<25} {}\n", "declared rates:", "ignored (not a release build)"); + } + fmt::print("\n"); + print_header_row(); } }; @@ -791,25 +807,48 @@ static std::FILE* maybe_open(const sstring& filename) { return ret; } +// How far the rate a test declares may be out before its runs are reported as +// straying from the requested duration, as a factor either way. +static constexpr double DECLARED_RATE_DRIFT_FACTOR = 2.; + void performance_test::do_run(const config& conf) { - _max_single_run_iterations = conf.single_run_iterations; - if (!_max_single_run_iterations) { - _max_single_run_iterations = std::numeric_limits::max(); + // Non-zero when the iteration count of a run is known up front, either + // because specified with --iterations or because the test declared + // iters_per_sec and this build honors that, so it can be calculated + // directly. + uint64_t fixed_iterations = conf.single_run_iterations; + bool from_declared_rate = false; + if (SEASTAR_PERF_TESTS_HONOR_DECLARED_RATE && !fixed_iterations + && std::isfinite(_options.iters_per_sec) + && _options.iters_per_sec > 0 && conf.single_run_duration.count()) { + auto seconds = std::chrono::duration(conf.single_run_duration).count(); + fixed_iterations = std::max(1, std::llround(_options.iters_per_sec * seconds)); + from_declared_rate = true; } + _max_single_run_iterations = fixed_iterations ? fixed_iterations + : std::numeric_limits::max(); + signal_timer tmr([this] { _max_single_run_iterations.store(0, std::memory_order_relaxed); }); - // dry run, estimate the number of iterations + // One run ahead of the measured ones: a dry run whose iteration count + // calibrates the measured runs, or, when the count is already fixed, a + // warm-up of the same length as those runs, keeping first-run effects (cold + // caches, the allocator growing its pools) out of the measured ones. if (conf.single_run_duration.count()) { // switch out of seastar thread yield().then([&] { - tmr.arm(conf.single_run_duration); + if (!fixed_iterations) { + tmr.arm(conf.single_run_duration); + } return do_single_run().finally([&] { - tmr.cancel(); - _max_single_run_iterations = _single_run_iterations; + if (!fixed_iterations) { + tmr.cancel(); + _max_single_run_iterations = _single_run_iterations; + } }); }).get(); } @@ -821,7 +860,9 @@ void performance_test::do_run(const config& conf) // switch out of seastar thread yield().then([&] { _single_run_iterations = 0; - return do_single_run().then([&] (run_result rr) { + auto wall_start = clock_type::now(); + return do_single_run().then([&, wall_start] (run_result rr) { + clock_type::duration wall = clock_type::now() - wall_start; clock_type::duration dt = rr.duration; double ns = std::chrono::duration_cast(dt).count(); @@ -830,6 +871,7 @@ void performance_test::do_run(const config& conf) }; add(r.runtime, ns); + add(r.walltime, std::chrono::duration_cast(wall).count()); total_iterations += _single_run_iterations; @@ -854,6 +896,30 @@ void performance_test::do_run(const config& conf) rp->print_result(r); } + // The rate at which the test iterates, on the wall clock because that is what + // --duration limits and so what a declared rate has to predict. + constexpr double ns_per_second = 1e9; + const double median_wall = r.walltime.stats().med; // per iteration, in nanoseconds + const double measured_rate = median_wall > 0 ? ns_per_second / median_wall : 0; + + if (conf.suggest_rates) { + suggested_rates.emplace_back(name(), measured_rate); + } + + // A declared rate is measured on one machine and decays as the test changes, + // so it only ever approximates the duration of a run. Warn once it is stale + // enough that runs are nowhere near the requested duration. + if (from_declared_rate) { + double drift = measured_rate / _options.iters_per_sec; + if (drift > DECLARED_RATE_DRIFT_FACTOR || drift < 1. / DECLARED_RATE_DRIFT_FACTOR) { + fmt::print("WARNING: test '{}' declares {} iterations/s but achieved {:.3g}/s, " + "so each run took {} rather than the requested {}\n", + name(), _options.iters_per_sec, measured_rate, + duration { fixed_iterations * median_wall }, + duration { double(conf.single_run_duration.count()) }); + } + } + // Check if overhead exceeds threshold and warn/fail double median_overhead = r.overhead.stats().med; if (median_overhead > conf.overhead_threshold) { @@ -890,6 +956,42 @@ void performance_test::register_test(std::unique_ptr test) all_tests().emplace_back(std::move(test)); } +// Format a rate as a C++ integer literal with digit separators, rounded to two +// significant digits. A declared rate only has to predict the length of a run, so +// carrying more digits than that into the source would be false precision. +static std::string format_rate_literal(double rate) { + uint64_t value = 1; + if (rate > 1) { + double scale = std::pow(10., std::max(0., std::floor(std::log10(rate)) - 1)); + value = static_cast(std::llround(rate / scale) * scale); + } + auto digits = fmt::format("{}", value); + std::string literal; + for (size_t i = 0; i < digits.size(); i++) { + if (i && (digits.size() - i) % 3 == 0) { + literal += '\''; + } + literal += digits[i]; + } + return literal; +} + +static void print_suggested_rates() { + if (suggested_rates.empty()) { + return; + } + size_t width = 0; + for (auto& [name, rate] : suggested_rates) { + width = std::max(width, name.size()); + } + fmt::print("\nmeasured iteration rates, to declare in the PERF_TEST macro so that a\n" + "run's iteration count no longer depends on the speed of the machine:\n\n"); + for (auto& [name, rate] : suggested_rates) { + fmt::print(" {:<{}} .iters_per_sec = {}\n", name, width, format_rate_literal(rate)); + } + fmt::print("\n"); +} + void run_all(const std::vector& test_patterns, config& conf) { std::vector regexes; regexes.reserve(test_patterns.size()); @@ -905,12 +1007,16 @@ void run_all(const std::vector& test_patterns, config& conf) { }; size_t max_name_column_length = 0; size_t matched_count = 0; + bool any_declared_rate = false; for (auto& t : all_tests()) { if (match(t.get())) { max_name_column_length = std::max(max_name_column_length, t->name().size()); ++matched_count; + any_declared_rate |= t->options().iters_per_sec > 0; } } + conf.ignored_declared_rates + = any_declared_rate && !SEASTAR_PERF_TESTS_HONOR_DECLARED_RATE; if (!regexes.empty() && matched_count == 0) { fmt::print(stderr, "WARNING: no tests matched the given pattern(s):"); for (auto& pat : test_patterns) { @@ -938,6 +1044,9 @@ void run_all(const std::vector& test_patterns, config& conf) { for (auto& rp : conf.printers) { rp->print_summary(total_duration); } + if (conf.suggest_rates) { + print_suggested_rates(); + } } } @@ -970,6 +1079,7 @@ int main(int ac, char** av) ("overhead-threshold", bpo::value()->default_value(0.1), "warn if overhead exceeds this ratio (default: 0.1 = 10%)") ("fail-on-high-overhead", "fail the test run if any test exceeds the overhead threshold") + ("suggest-rates", "report the iteration rate measured for each test, as the .iters_per_sec declaration to paste into its PERF_TEST macro") ("no-perf-counters", "disable hardware perf counters (inst/cycles)") ("parameter", bpo::value>(), "specify test-specific parameters") ; @@ -989,6 +1099,7 @@ int main(int ac, char** av) conf.random_seed = app.configuration()["random-seed"].as(); conf.overhead_threshold = app.configuration()["overhead-threshold"].as(); conf.fail_on_high_overhead = app.configuration().count("fail-on-high-overhead") > 0; + conf.suggest_rates = app.configuration().count("suggest-rates") > 0; std::vector tests_to_run; if (app.configuration().count("test")) { diff --git a/tests/perf/perf_tests_perf.cc b/tests/perf/perf_tests_perf.cc index 135378d8530..19fc9997ffb 100644 --- a/tests/perf/perf_tests_perf.cc +++ b/tests/perf/perf_tests_perf.cc @@ -116,6 +116,18 @@ PERF_TEST_CN(fixture, test_coro_n) { PERF_TEST(perf_tests, test_empty) { } +// Declares its iteration rate, so the framework fixes the iteration count of +// every run at that rate times the requested duration. +PERF_TEST(fixed_iters, declared_rate, .iters_per_sec = 2.8e7) { + loop(100); +} + +// Declares a rate it cannot come close to, so that its runs are far shorter +// than the requested duration and the drift warning fires. +PERF_TEST(fixed_iters, stale_declared_rate, .iters_per_sec = 100'000) { + loop(100); +} + PERF_TEST(perf_tests, test_timer_overhead) { constexpr auto TIMER_LOOPS = 1000; for (size_t i = 0; i < TIMER_LOOPS; i++) {