499 lines · plain
1// Copyright 2015 Google Inc. All rights reserved.2//3// Licensed under the Apache License, Version 2.0 (the "License");4// you may not use this file except in compliance with the License.5// You may obtain a copy of the License at6//7// http://www.apache.org/licenses/LICENSE-2.08//9// Unless required by applicable law or agreed to in writing, software10// distributed under the License is distributed on an "AS IS" BASIS,11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.12// See the License for the specific language governing permissions and13// limitations under the License.14 15#include "benchmark_runner.h"16 17#include "benchmark/benchmark.h"18#include "benchmark_api_internal.h"19#include "internal_macros.h"20 21#ifndef BENCHMARK_OS_WINDOWS22#if !defined(BENCHMARK_OS_FUCHSIA) && !defined(BENCHMARK_OS_QURT)23#include <sys/resource.h>24#endif25#include <sys/time.h>26#include <unistd.h>27#endif28 29#include <algorithm>30#include <atomic>31#include <climits>32#include <cmath>33#include <condition_variable>34#include <cstdio>35#include <cstdlib>36#include <fstream>37#include <iostream>38#include <limits>39#include <memory>40#include <string>41#include <thread>42#include <utility>43 44#include "check.h"45#include "colorprint.h"46#include "commandlineflags.h"47#include "complexity.h"48#include "counter.h"49#include "internal_macros.h"50#include "log.h"51#include "mutex.h"52#include "perf_counters.h"53#include "re.h"54#include "statistics.h"55#include "string_util.h"56#include "thread_manager.h"57#include "thread_timer.h"58 59namespace benchmark {60 61namespace internal {62 63MemoryManager* memory_manager = nullptr;64 65namespace {66 67static constexpr IterationCount kMaxIterations = 1000000000000;68const double kDefaultMinTime =69 std::strtod(::benchmark::kDefaultMinTimeStr, /*p_end*/ nullptr);70 71BenchmarkReporter::Run CreateRunReport(72 const benchmark::internal::BenchmarkInstance& b,73 const internal::ThreadManager::Result& results,74 IterationCount memory_iterations,75 const MemoryManager::Result* memory_result, double seconds,76 int64_t repetition_index, int64_t repeats) {77 // Create report about this benchmark run.78 BenchmarkReporter::Run report;79 80 report.run_name = b.name();81 report.family_index = b.family_index();82 report.per_family_instance_index = b.per_family_instance_index();83 report.skipped = results.skipped_;84 report.skip_message = results.skip_message_;85 report.report_label = results.report_label_;86 // This is the total iterations across all threads.87 report.iterations = results.iterations;88 report.time_unit = b.time_unit();89 report.threads = b.threads();90 report.repetition_index = repetition_index;91 report.repetitions = repeats;92 93 if (!report.skipped) {94 if (b.use_manual_time()) {95 report.real_accumulated_time = results.manual_time_used;96 } else {97 report.real_accumulated_time = results.real_time_used;98 }99 report.use_real_time_for_initial_big_o = b.use_manual_time();100 report.cpu_accumulated_time = results.cpu_time_used;101 report.complexity_n = results.complexity_n;102 report.complexity = b.complexity();103 report.complexity_lambda = b.complexity_lambda();104 report.statistics = &b.statistics();105 report.counters = results.counters;106 107 if (memory_iterations > 0) {108 assert(memory_result != nullptr);109 report.memory_result = memory_result;110 report.allocs_per_iter =111 memory_iterations ? static_cast<double>(memory_result->num_allocs) /112 static_cast<double>(memory_iterations)113 : 0;114 }115 116 internal::Finish(&report.counters, results.iterations, seconds,117 b.threads());118 }119 return report;120}121 122// Execute one thread of benchmark b for the specified number of iterations.123// Adds the stats collected for the thread into manager->results.124void RunInThread(const BenchmarkInstance* b, IterationCount iters,125 int thread_id, ThreadManager* manager,126 PerfCountersMeasurement* perf_counters_measurement) {127 internal::ThreadTimer timer(128 b->measure_process_cpu_time()129 ? internal::ThreadTimer::CreateProcessCpuTime()130 : internal::ThreadTimer::Create());131 132 State st =133 b->Run(iters, thread_id, &timer, manager, perf_counters_measurement);134 BM_CHECK(st.skipped() || st.iterations() >= st.max_iterations)135 << "Benchmark returned before State::KeepRunning() returned false!";136 {137 MutexLock l(manager->GetBenchmarkMutex());138 internal::ThreadManager::Result& results = manager->results;139 results.iterations += st.iterations();140 results.cpu_time_used += timer.cpu_time_used();141 results.real_time_used += timer.real_time_used();142 results.manual_time_used += timer.manual_time_used();143 results.complexity_n += st.complexity_length_n();144 internal::Increment(&results.counters, st.counters);145 }146 manager->NotifyThreadComplete();147}148 149double ComputeMinTime(const benchmark::internal::BenchmarkInstance& b,150 const BenchTimeType& iters_or_time) {151 if (!IsZero(b.min_time())) return b.min_time();152 // If the flag was used to specify number of iters, then return the default153 // min_time.154 if (iters_or_time.tag == BenchTimeType::ITERS) return kDefaultMinTime;155 156 return iters_or_time.time;157}158 159IterationCount ComputeIters(const benchmark::internal::BenchmarkInstance& b,160 const BenchTimeType& iters_or_time) {161 if (b.iterations() != 0) return b.iterations();162 163 // We've already concluded that this flag is currently used to pass164 // iters but do a check here again anyway.165 BM_CHECK(iters_or_time.tag == BenchTimeType::ITERS);166 return iters_or_time.iters;167}168 169} // end namespace170 171BenchTimeType ParseBenchMinTime(const std::string& value) {172 BenchTimeType ret;173 174 if (value.empty()) {175 ret.tag = BenchTimeType::TIME;176 ret.time = 0.0;177 return ret;178 }179 180 if (value.back() == 'x') {181 char* p_end;182 // Reset errno before it's changed by strtol.183 errno = 0;184 IterationCount num_iters = std::strtol(value.c_str(), &p_end, 10);185 186 // After a valid parse, p_end should have been set to187 // point to the 'x' suffix.188 BM_CHECK(errno == 0 && p_end != nullptr && *p_end == 'x')189 << "Malformed iters value passed to --benchmark_min_time: `" << value190 << "`. Expected --benchmark_min_time=<integer>x.";191 192 ret.tag = BenchTimeType::ITERS;193 ret.iters = num_iters;194 return ret;195 }196 197 bool has_suffix = value.back() == 's';198 if (!has_suffix) {199 BM_VLOG(0) << "Value passed to --benchmark_min_time should have a suffix. "200 "Eg., `30s` for 30-seconds.";201 }202 203 char* p_end;204 // Reset errno before it's changed by strtod.205 errno = 0;206 double min_time = std::strtod(value.c_str(), &p_end);207 208 // After a successful parse, p_end should point to the suffix 's',209 // or the end of the string if the suffix was omitted.210 BM_CHECK(errno == 0 && p_end != nullptr &&211 ((has_suffix && *p_end == 's') || *p_end == '\0'))212 << "Malformed seconds value passed to --benchmark_min_time: `" << value213 << "`. Expected --benchmark_min_time=<float>x.";214 215 ret.tag = BenchTimeType::TIME;216 ret.time = min_time;217 218 return ret;219}220 221BenchmarkRunner::BenchmarkRunner(222 const benchmark::internal::BenchmarkInstance& b_,223 PerfCountersMeasurement* pcm_,224 BenchmarkReporter::PerFamilyRunReports* reports_for_family_)225 : b(b_),226 reports_for_family(reports_for_family_),227 parsed_benchtime_flag(ParseBenchMinTime(FLAGS_benchmark_min_time)),228 min_time(ComputeMinTime(b_, parsed_benchtime_flag)),229 min_warmup_time((!IsZero(b.min_time()) && b.min_warmup_time() > 0.0)230 ? b.min_warmup_time()231 : FLAGS_benchmark_min_warmup_time),232 warmup_done(!(min_warmup_time > 0.0)),233 repeats(b.repetitions() != 0 ? b.repetitions()234 : FLAGS_benchmark_repetitions),235 has_explicit_iteration_count(b.iterations() != 0 ||236 parsed_benchtime_flag.tag ==237 BenchTimeType::ITERS),238 pool(b.threads() - 1),239 iters(has_explicit_iteration_count240 ? ComputeIters(b_, parsed_benchtime_flag)241 : 1),242 perf_counters_measurement_ptr(pcm_) {243 run_results.display_report_aggregates_only =244 (FLAGS_benchmark_report_aggregates_only ||245 FLAGS_benchmark_display_aggregates_only);246 run_results.file_report_aggregates_only =247 FLAGS_benchmark_report_aggregates_only;248 if (b.aggregation_report_mode() != internal::ARM_Unspecified) {249 run_results.display_report_aggregates_only =250 (b.aggregation_report_mode() &251 internal::ARM_DisplayReportAggregatesOnly);252 run_results.file_report_aggregates_only =253 (b.aggregation_report_mode() & internal::ARM_FileReportAggregatesOnly);254 BM_CHECK(FLAGS_benchmark_perf_counters.empty() ||255 (perf_counters_measurement_ptr->num_counters() == 0))256 << "Perf counters were requested but could not be set up.";257 }258}259 260BenchmarkRunner::IterationResults BenchmarkRunner::DoNIterations() {261 BM_VLOG(2) << "Running " << b.name().str() << " for " << iters << "\n";262 263 std::unique_ptr<internal::ThreadManager> manager;264 manager.reset(new internal::ThreadManager(b.threads()));265 266 // Run all but one thread in separate threads267 for (std::size_t ti = 0; ti < pool.size(); ++ti) {268 pool[ti] = std::thread(&RunInThread, &b, iters, static_cast<int>(ti + 1),269 manager.get(), perf_counters_measurement_ptr);270 }271 // And run one thread here directly.272 // (If we were asked to run just one thread, we don't create new threads.)273 // Yes, we need to do this here *after* we start the separate threads.274 RunInThread(&b, iters, 0, manager.get(), perf_counters_measurement_ptr);275 276 // The main thread has finished. Now let's wait for the other threads.277 manager->WaitForAllThreads();278 for (std::thread& thread : pool) thread.join();279 280 IterationResults i;281 // Acquire the measurements/counters from the manager, UNDER THE LOCK!282 {283 MutexLock l(manager->GetBenchmarkMutex());284 i.results = manager->results;285 }286 287 // And get rid of the manager.288 manager.reset();289 290 // Adjust real/manual time stats since they were reported per thread.291 i.results.real_time_used /= b.threads();292 i.results.manual_time_used /= b.threads();293 // If we were measuring whole-process CPU usage, adjust the CPU time too.294 if (b.measure_process_cpu_time()) i.results.cpu_time_used /= b.threads();295 296 BM_VLOG(2) << "Ran in " << i.results.cpu_time_used << "/"297 << i.results.real_time_used << "\n";298 299 // By using KeepRunningBatch a benchmark can iterate more times than300 // requested, so take the iteration count from i.results.301 i.iters = i.results.iterations / b.threads();302 303 // Base decisions off of real time if requested by this benchmark.304 i.seconds = i.results.cpu_time_used;305 if (b.use_manual_time()) {306 i.seconds = i.results.manual_time_used;307 } else if (b.use_real_time()) {308 i.seconds = i.results.real_time_used;309 }310 311 return i;312}313 314IterationCount BenchmarkRunner::PredictNumItersNeeded(315 const IterationResults& i) const {316 // See how much iterations should be increased by.317 // Note: Avoid division by zero with max(seconds, 1ns).318 double multiplier = GetMinTimeToApply() * 1.4 / std::max(i.seconds, 1e-9);319 // If our last run was at least 10% of FLAGS_benchmark_min_time then we320 // use the multiplier directly.321 // Otherwise we use at most 10 times expansion.322 // NOTE: When the last run was at least 10% of the min time the max323 // expansion should be 14x.324 const bool is_significant = (i.seconds / GetMinTimeToApply()) > 0.1;325 multiplier = is_significant ? multiplier : 10.0;326 327 // So what seems to be the sufficiently-large iteration count? Round up.328 const IterationCount max_next_iters = static_cast<IterationCount>(329 std::llround(std::max(multiplier * static_cast<double>(i.iters),330 static_cast<double>(i.iters) + 1.0)));331 // But we do have *some* limits though..332 const IterationCount next_iters = std::min(max_next_iters, kMaxIterations);333 334 BM_VLOG(3) << "Next iters: " << next_iters << ", " << multiplier << "\n";335 return next_iters; // round up before conversion to integer.336}337 338bool BenchmarkRunner::ShouldReportIterationResults(339 const IterationResults& i) const {340 // Determine if this run should be reported;341 // Either it has run for a sufficient amount of time342 // or because an error was reported.343 return i.results.skipped_ ||344 i.iters >= kMaxIterations || // Too many iterations already.345 i.seconds >=346 GetMinTimeToApply() || // The elapsed time is large enough.347 // CPU time is specified but the elapsed real time greatly exceeds348 // the minimum time.349 // Note that user provided timers are except from this test.350 ((i.results.real_time_used >= 5 * GetMinTimeToApply()) &&351 !b.use_manual_time());352}353 354double BenchmarkRunner::GetMinTimeToApply() const {355 // In order to re-use functionality to run and measure benchmarks for running356 // a warmup phase of the benchmark, we need a way of telling whether to apply357 // min_time or min_warmup_time. This function will figure out if we are in the358 // warmup phase and therefore need to apply min_warmup_time or if we already359 // in the benchmarking phase and min_time needs to be applied.360 return warmup_done ? min_time : min_warmup_time;361}362 363void BenchmarkRunner::FinishWarmUp(const IterationCount& i) {364 warmup_done = true;365 iters = i;366}367 368void BenchmarkRunner::RunWarmUp() {369 // Use the same mechanisms for warming up the benchmark as used for actually370 // running and measuring the benchmark.371 IterationResults i_warmup;372 // Dont use the iterations determined in the warmup phase for the actual373 // measured benchmark phase. While this may be a good starting point for the374 // benchmark and it would therefore get rid of the need to figure out how many375 // iterations are needed if min_time is set again, this may also be a complete376 // wrong guess since the warmup loops might be considerably slower (e.g377 // because of caching effects).378 const IterationCount i_backup = iters;379 380 for (;;) {381 b.Setup();382 i_warmup = DoNIterations();383 b.Teardown();384 385 const bool finish = ShouldReportIterationResults(i_warmup);386 387 if (finish) {388 FinishWarmUp(i_backup);389 break;390 }391 392 // Although we are running "only" a warmup phase where running enough393 // iterations at once without measuring time isn't as important as it is for394 // the benchmarking phase, we still do it the same way as otherwise it is395 // very confusing for the user to know how to choose a proper value for396 // min_warmup_time if a different approach on running it is used.397 iters = PredictNumItersNeeded(i_warmup);398 assert(iters > i_warmup.iters &&399 "if we did more iterations than we want to do the next time, "400 "then we should have accepted the current iteration run.");401 }402}403 404void BenchmarkRunner::DoOneRepetition() {405 assert(HasRepeatsRemaining() && "Already done all repetitions?");406 407 const bool is_the_first_repetition = num_repetitions_done == 0;408 409 // In case a warmup phase is requested by the benchmark, run it now.410 // After running the warmup phase the BenchmarkRunner should be in a state as411 // this warmup never happened except the fact that warmup_done is set. Every412 // other manipulation of the BenchmarkRunner instance would be a bug! Please413 // fix it.414 if (!warmup_done) RunWarmUp();415 416 IterationResults i;417 // We *may* be gradually increasing the length (iteration count)418 // of the benchmark until we decide the results are significant.419 // And once we do, we report those last results and exit.420 // Please do note that the if there are repetitions, the iteration count421 // is *only* calculated for the *first* repetition, and other repetitions422 // simply use that precomputed iteration count.423 for (;;) {424 b.Setup();425 i = DoNIterations();426 b.Teardown();427 428 // Do we consider the results to be significant?429 // If we are doing repetitions, and the first repetition was already done,430 // it has calculated the correct iteration time, so we have run that very431 // iteration count just now. No need to calculate anything. Just report.432 // Else, the normal rules apply.433 const bool results_are_significant = !is_the_first_repetition ||434 has_explicit_iteration_count ||435 ShouldReportIterationResults(i);436 437 if (results_are_significant) break; // Good, let's report them!438 439 // Nope, bad iteration. Let's re-estimate the hopefully-sufficient440 // iteration count, and run the benchmark again...441 442 iters = PredictNumItersNeeded(i);443 assert(iters > i.iters &&444 "if we did more iterations than we want to do the next time, "445 "then we should have accepted the current iteration run.");446 }447 448 // Oh, one last thing, we need to also produce the 'memory measurements'..449 MemoryManager::Result* memory_result = nullptr;450 IterationCount memory_iterations = 0;451 if (memory_manager != nullptr) {452 // TODO(vyng): Consider making BenchmarkReporter::Run::memory_result an453 // optional so we don't have to own the Result here.454 // Can't do it now due to cxx03.455 memory_results.push_back(MemoryManager::Result());456 memory_result = &memory_results.back();457 // Only run a few iterations to reduce the impact of one-time458 // allocations in benchmarks that are not properly managed.459 memory_iterations = std::min<IterationCount>(16, iters);460 memory_manager->Start();461 std::unique_ptr<internal::ThreadManager> manager;462 manager.reset(new internal::ThreadManager(1));463 b.Setup();464 RunInThread(&b, memory_iterations, 0, manager.get(),465 perf_counters_measurement_ptr);466 manager->WaitForAllThreads();467 manager.reset();468 b.Teardown();469 memory_manager->Stop(*memory_result);470 }471 472 // Ok, now actually report.473 BenchmarkReporter::Run report =474 CreateRunReport(b, i.results, memory_iterations, memory_result, i.seconds,475 num_repetitions_done, repeats);476 477 if (reports_for_family) {478 ++reports_for_family->num_runs_done;479 if (!report.skipped) reports_for_family->Runs.push_back(report);480 }481 482 run_results.non_aggregates.push_back(report);483 484 ++num_repetitions_done;485}486 487RunResults&& BenchmarkRunner::GetResults() {488 assert(!HasRepeatsRemaining() && "Did not run all repetitions yet?");489 490 // Calculate additional statistics over the repetitions of this instance.491 run_results.aggregates_only = ComputeStats(run_results.non_aggregates);492 493 return std::move(run_results);494}495 496} // end namespace internal497 498} // end namespace benchmark499