| // Copyright 2018 The Fuchsia Authors. All rights reserved. |
| // Use of this source code is governed by a BSD-style license that can be |
| // found in the LICENSE file. |
| |
| #include <perftest/runner.h> |
| |
| #include <getopt.h> |
| #include <pthread.h> |
| #include <regex.h> |
| |
| #include <fbl/function.h> |
| #include <fbl/string.h> |
| #include <fbl/string_printf.h> |
| #include <fbl/vector.h> |
| #include <lib/async-loop/cpp/loop.h> |
| #include <trace-engine/context.h> |
| #include <trace-engine/instrumentation.h> |
| #include <trace-provider/provider.h> |
| #include <trace/event.h> |
| #include <unittest/unittest.h> |
| #include <zircon/assert.h> |
| #include <zircon/syscalls.h> |
| |
| namespace perftest { |
| namespace { |
| |
| // g_tests needs to be POD because this list is populated by constructors. |
| // We don't want g_tests to have a constructor that might get run after |
| // items have been added to the list, because that would clobber the list. |
| internal::TestList* g_tests; |
| |
| class RepeatStateImpl : public RepeatState { |
| public: |
| RepeatStateImpl(uint32_t run_count) |
| : run_count_(run_count) {} |
| |
| void SetBytesProcessedPerRun(uint64_t bytes) override { |
| if (started_) { |
| SetError("SetBytesProcessedPerRun() was called after KeepRunning()"); |
| return; |
| } |
| if (bytes == 0) { |
| SetError("Zero argument to SetBytesProcessedPerRun()"); |
| return; |
| } |
| if (bytes_processed_per_run_ != 0) { |
| SetError("Multiple calls to SetBytesProcessedPerRun()"); |
| return; |
| } |
| bytes_processed_per_run_ = bytes; |
| } |
| |
| void DeclareStep(const char* name) override { |
| if (started_) { |
| SetError("DeclareStep() was called after KeepRunning()"); |
| return; |
| } |
| step_names_.push_back(name); |
| } |
| |
| void NextStep() override { |
| if (unlikely(next_idx_ >= end_of_run_idx_)) { |
| SetError("Too many calls to NextStep()"); |
| return; |
| } |
| timestamps_[next_idx_] = zx_ticks_get(); |
| ++next_idx_; |
| } |
| |
| bool KeepRunning() override { |
| uint64_t timestamp = zx_ticks_get(); |
| if (unlikely(next_idx_ != end_of_run_idx_)) { |
| // Slow path, including error cases. |
| if (error_) { |
| return false; |
| } |
| if (started_) { |
| SetError("Wrong number of calls to NextStep()"); |
| return false; |
| } |
| // First call to KeepRunning(). |
| step_count_ = static_cast<uint32_t>(step_names_.size()); |
| if (step_count_ == 0) { |
| step_count_ = 1; |
| } |
| // Add 1 because we store timestamps for the start of each test |
| // run (which serve as timestamps for the end of the previous |
| // test run), plus one more timestamp for the end of the last |
| // test run. |
| timestamps_size_ = run_count_ * step_count_ + 1; |
| timestamps_.reset(new uint64_t[timestamps_size_]); |
| // Clear the array in order to fault in the pages. This should |
| // prevent page faults occurring as we cross page boundaries |
| // when writing a test's running times (which would affect the |
| // first test case but not later test cases). |
| memset(timestamps_.get(), 0, |
| sizeof(timestamps_[0]) * timestamps_size_); |
| next_idx_ = 1; |
| end_of_run_idx_ = step_count_; |
| started_ = true; |
| timestamps_[0] = zx_ticks_get(); |
| return run_count_ != 0; |
| } |
| if (unlikely(next_idx_ == timestamps_size_ - 1)) { |
| // End reached. |
| if (finished_) { |
| SetError("Too many calls to KeepRunning()"); |
| return false; |
| } |
| timestamps_[next_idx_] = timestamp; |
| finished_ = true; |
| return false; |
| } |
| timestamps_[next_idx_] = timestamp; |
| ++next_idx_; |
| end_of_run_idx_ += step_count_; |
| return true; |
| } |
| |
| // Returns nullptr on success, or an error string on failure. |
| const char* RunTestFunc(const char* test_name, |
| const fbl::Function<TestFunc>& test_func) { |
| TRACE_DURATION("perftest", "test_group", "test_name", test_name); |
| overall_start_time_ = zx_ticks_get(); |
| bool result = test_func(this); |
| overall_end_time_ = zx_ticks_get(); |
| if (error_) { |
| return error_; |
| } |
| if (!finished_) { |
| return "Too few calls to KeepRunning()"; |
| } |
| if (!result) { |
| return "Test function returned false"; |
| } |
| return nullptr; |
| } |
| |
| void CopyTimeResults(const char* test_suite, const char* test_name, |
| ResultsSet* dest) const { |
| // bytes_processed_per_run is used for calculating throughput, but |
| // throughput is only really meaningful to calculate for the test |
| // overall, not for individual steps. Therefore we only report |
| // bytes_processed_per_run on the overall times. |
| |
| // Report the times for each test run. |
| if (step_count_ == 1 || bytes_processed_per_run_ != 0) { |
| TestCaseResults* results = dest->AddTestCase( |
| test_suite, test_name, "nanoseconds"); |
| results->bytes_processed_per_run = bytes_processed_per_run_; |
| CopyStepTimes(0, step_count_, results); |
| } |
| |
| if (step_count_ > 1) { |
| // Report times for individual steps. |
| for (uint32_t step = 0; step < step_count_; ++step) { |
| fbl::String name = fbl::StringPrintf( |
| "%s.%s", test_name, step_names_[step].c_str()); |
| TestCaseResults* results = dest->AddTestCase( |
| test_suite, name, "nanoseconds"); |
| CopyStepTimes(step, step + 1, results); |
| } |
| } |
| } |
| |
| // Output a trace event for each of the test runs. Since we do this |
| // after the test runs took place (using the timestamps we recorded), |
| // we avoid incurring the overhead of the tracing system on each test |
| // run. |
| void WriteTraceEvents() { |
| trace_string_ref_t category_ref; |
| trace_context_t* context = |
| trace_acquire_context_for_category("perftest", &category_ref); |
| if (!context) { |
| return; |
| } |
| trace_thread_ref_t thread_ref; |
| trace_context_register_current_thread(context, &thread_ref); |
| |
| auto WriteEvent = [&](trace_string_ref_t* name_ref, |
| uint64_t start_time, uint64_t end_time) { |
| trace_context_write_duration_begin_event_record( |
| context, start_time, |
| &thread_ref, &category_ref, name_ref, nullptr, 0); |
| trace_context_write_duration_end_event_record( |
| context, end_time, |
| &thread_ref, &category_ref, name_ref, nullptr, 0); |
| }; |
| |
| trace_string_ref_t test_setup_string; |
| trace_string_ref_t test_run_string; |
| trace_string_ref_t test_step_string; |
| trace_string_ref_t test_teardown_string; |
| trace_context_register_string_literal( |
| context, "test_setup", &test_setup_string); |
| trace_context_register_string_literal( |
| context, "test_run", &test_run_string); |
| trace_context_register_string_literal( |
| context, "test_step", &test_step_string); |
| trace_context_register_string_literal( |
| context, "test_teardown", &test_teardown_string); |
| |
| WriteEvent(&test_setup_string, overall_start_time_, timestamps_[0]); |
| for (uint32_t run = 0; run < run_count_; ++run) { |
| WriteEvent(&test_run_string, |
| GetTimestamp(run, 0), |
| GetTimestamp(run + 1, 0)); |
| if (step_count_ > 1) { |
| for (uint32_t step = 0; step < step_count_; ++step) { |
| WriteEvent(&test_step_string, |
| GetTimestamp(run, step), |
| GetTimestamp(run, step + 1)); |
| } |
| } |
| } |
| WriteEvent(&test_teardown_string, |
| timestamps_[timestamps_size_ - 1], overall_end_time_); |
| } |
| |
| private: |
| void SetError(const char* str) { |
| if (!error_) { |
| error_ = str; |
| } |
| } |
| |
| // The start and end times of run R are GetTimestamp(R, 0) and |
| // GetTimestamp(R+1, 0). |
| // The start and end times of step S within run R are GetTimestamp(R, |
| // S) and GetTimestamp(R, S+1). |
| uint64_t GetTimestamp(uint32_t run_number, uint32_t step_number) const { |
| uint32_t index = run_number * step_count_ + step_number; |
| ZX_ASSERT(step_number <= step_count_); |
| ZX_ASSERT(index < timestamps_size_); |
| return timestamps_[index]; |
| } |
| |
| void CopyStepTimes(uint32_t start_step_index, uint32_t end_step_index, |
| TestCaseResults* results) const { |
| double nanoseconds_per_tick = |
| 1e9 / static_cast<double>(zx_ticks_per_second()); |
| |
| // Copy the timing results, converting timestamps to elapsed times. |
| results->values.reserve(run_count_); |
| for (uint32_t run = 0; run < run_count_; ++run) { |
| uint64_t time_taken = (GetTimestamp(run, end_step_index) - |
| GetTimestamp(run, start_step_index)); |
| results->AppendValue( |
| static_cast<double>(time_taken) * nanoseconds_per_tick); |
| } |
| } |
| |
| // Number of test runs that we intend to do. |
| uint32_t run_count_; |
| // Number of steps per test run. Once initialized, this is >= 1. |
| uint32_t step_count_; |
| // Names for steps. May be empty if the test has only one step. |
| fbl::Vector<fbl::String> step_names_; |
| // error_ is set to non-null if an error occurs. |
| const char* error_ = nullptr; |
| // Array of timestamps for the starts and ends of test runs and of |
| // steps within runs. GetTimestamp() describes the array layout. |
| fbl::unique_ptr<uint64_t[]> timestamps_; |
| // Number of elements allocated for timestamps_ array. |
| uint32_t timestamps_size_ = 0; |
| // Whether the first KeepRunning() call has occurred. |
| bool started_ = false; |
| // Whether the last KeepRunning() call has occurred. |
| bool finished_ = false; |
| // Next index in timestamps_ for writing a timestamp to. The initial |
| // value helps catch invalid NextStep() calls. |
| uint32_t next_idx_ = ~static_cast<uint32_t>(0); |
| // Index in timestamp_ for writing the end of the current run. |
| uint32_t end_of_run_idx_ = 0; |
| // Start time, before the test's setup phase. |
| uint64_t overall_start_time_; |
| // End time, after the test's teardown phase. |
| uint64_t overall_end_time_; |
| // Used for calculating throughput in bytes per unit time. |
| uint64_t bytes_processed_per_run_ = 0; |
| }; |
| |
| } // namespace |
| |
| void RegisterTest(const char* name, fbl::Function<TestFunc> test_func) { |
| if (!g_tests) { |
| g_tests = new internal::TestList; |
| } |
| internal::NamedTest new_test{name, std::move(test_func)}; |
| g_tests->push_back(std::move(new_test)); |
| } |
| |
| bool RunTest(const char* test_suite, const char* test_name, |
| const fbl::Function<TestFunc>& test_func, |
| uint32_t run_count, ResultsSet* results_set, |
| fbl::String* error_out) { |
| RepeatStateImpl state(run_count); |
| const char* error = state.RunTestFunc(test_name, test_func); |
| if (error) { |
| if (error_out) { |
| *error_out = error; |
| } |
| return false; |
| } |
| |
| state.CopyTimeResults(test_suite, test_name, results_set); |
| state.WriteTraceEvents(); |
| return true; |
| } |
| |
| namespace internal { |
| |
| bool RunTests(const char* test_suite, TestList* test_list, uint32_t run_count, |
| const char* regex_string, FILE* log_stream, |
| ResultsSet* results_set) { |
| // Compile the regular expression. |
| regex_t regex; |
| int err = regcomp(®ex, regex_string, REG_EXTENDED); |
| if (err != 0) { |
| char msg[256]; |
| msg[0] = '\0'; |
| regerror(err, ®ex, msg, sizeof(msg)); |
| fprintf(log_stream, |
| "Compiling the regular expression \"%s\" failed: %s\n", |
| regex_string, msg); |
| return false; |
| } |
| |
| bool found_regex_match = false; |
| bool ok = true; |
| for (const internal::NamedTest& test_case : *test_list) { |
| const char* test_name = test_case.name.c_str(); |
| bool matched_regex = regexec(®ex, test_name, 0, nullptr, 0) == 0; |
| if (!matched_regex) { |
| continue; |
| } |
| found_regex_match = true; |
| |
| // Log in a format similar to gtest's output, so that this will |
| // look familiar to readers and to allow parsing by tools that can |
| // parse gtest's output. |
| fprintf(log_stream, "[ RUN ] %s\n", test_name); |
| |
| fbl::String error_string; |
| if (!RunTest(test_suite, test_name, test_case.test_func, run_count, |
| results_set, &error_string)) { |
| fprintf(log_stream, "Error: %s\n", error_string.c_str()); |
| fprintf(log_stream, "[ FAILED ] %s\n", test_name); |
| ok = false; |
| continue; |
| } |
| fprintf(log_stream, "[ OK ] %s\n", test_name); |
| } |
| |
| regfree(®ex); |
| |
| if (!found_regex_match) { |
| // Report an error so that this doesn't fail silently if the regex |
| // is wrong. |
| fprintf(log_stream, |
| "The regular expression \"%s\" did not match any tests\n", |
| regex_string); |
| return false; |
| } |
| return ok; |
| } |
| |
| void ParseCommandArgs(int argc, char** argv, CommandArgs* dest) { |
| static const struct option opts[] = { |
| {"out", required_argument, nullptr, 'o'}, |
| {"filter", required_argument, nullptr, 'f'}, |
| {"runs", required_argument, nullptr, 'r'}, |
| {"enable-tracing", no_argument, nullptr, 't'}, |
| {"startup-delay", required_argument, nullptr, 'd'}, |
| }; |
| optind = 1; |
| for (;;) { |
| int opt = getopt_long(argc, argv, "", opts, nullptr); |
| if (opt < 0) { |
| break; |
| } |
| switch (opt) { |
| case 'o': |
| dest->output_filename = optarg; |
| break; |
| case 'f': |
| dest->filter_regex = optarg; |
| break; |
| case 'r': { |
| // Convert string to number (uint32_t). |
| char* end; |
| long val = strtol(optarg, &end, 0); |
| // Check that the string contains only a positive number and |
| // that the number doesn't overflow. |
| if (val != static_cast<uint32_t>(val) || *end != '\0' || |
| *optarg == '\0' || val == 0) { |
| fprintf(stderr, "Invalid argument for --runs: \"%s\"\n", |
| optarg); |
| exit(1); |
| } |
| dest->run_count = static_cast<uint32_t>(val); |
| break; |
| } |
| case 't': |
| dest->enable_tracing = true; |
| break; |
| case 'd': { |
| // Convert string to number (double type). |
| char* end; |
| double val = strtod(optarg, &end); |
| if (*end != '\0' || *optarg == '\0') { |
| fprintf(stderr, |
| "Invalid argument for --startup-delay: \"%s\"\n", |
| optarg); |
| exit(1); |
| } |
| dest->startup_delay_seconds = val; |
| break; |
| } |
| default: |
| // getopt_long() will have printed an error already. |
| exit(1); |
| } |
| } |
| if (optind < argc) { |
| fprintf(stderr, "Unrecognized argument: \"%s\"\n", argv[optind]); |
| exit(1); |
| } |
| } |
| |
| } // namespace internal |
| |
| static void* TraceProviderThread(void* thread_arg) { |
| async::Loop loop(&kAsyncLoopConfigNoAttachToThread); |
| trace::TraceProvider provider(loop.dispatcher()); |
| loop.Run(); |
| return nullptr; |
| } |
| |
| static void StartTraceProvider() { |
| pthread_t tid; |
| int err = pthread_create(&tid, nullptr, TraceProviderThread, nullptr); |
| ZX_ASSERT(err == 0); |
| err = pthread_detach(tid); |
| ZX_ASSERT(err == 0); |
| } |
| |
| static bool PerfTestMode(const char* test_suite, int argc, char** argv) { |
| internal::CommandArgs args; |
| internal::ParseCommandArgs(argc, argv, &args); |
| |
| if (args.enable_tracing) { |
| StartTraceProvider(); |
| } |
| zx_duration_t duration = |
| static_cast<zx_duration_t>(ZX_SEC(1) * args.startup_delay_seconds); |
| zx_nanosleep(zx_deadline_after(duration)); |
| |
| ResultsSet results; |
| bool success = RunTests(test_suite, g_tests, args.run_count, |
| args.filter_regex, stdout, &results); |
| |
| printf("\n"); |
| results.PrintSummaryStatistics(stdout); |
| printf("\n"); |
| |
| if (args.output_filename) { |
| if (!results.WriteJSONFile(args.output_filename)) { |
| exit(1); |
| } |
| } |
| |
| return success; |
| } |
| |
| int PerfTestMain(int argc, char** argv, const char* test_suite) { |
| if (argc == 2 && (strcmp(argv[1], "-h") == 0 || |
| strcmp(argv[1], "--help") == 0)) { |
| printf("Usage:\n" |
| " %s -p [options] # run in \"perf test mode\"\n" |
| " %s # run in \"unit test mode\"\n" |
| "\n" |
| "\"Unit test mode\" runs perf tests as unit tests. " |
| "This means it only checks that the perf tests pass. " |
| "It only does a small number of runs of each test, and it " |
| "does not report their performance. Additionally, it runs " |
| "all of the unit tests in the executable (i.e. those that " |
| "use the unittest library).\n" |
| "\n" |
| "\"Perf test mode\" runs many iterations of each perf test, " |
| "and reports the performance results. It does not run any " |
| "unittest test cases.\n" |
| "\n" |
| "Options:\n" |
| " --out FILENAME\n" |
| " Filename to write JSON results data to. If this is " |
| "omitted, no JSON output is produced. JSON output will conform to this schema: " |
| "//zircon/system/ulib/perftest/performance-results-schema.json\n" |
| " --filter REGEX\n" |
| " Regular expression that specifies a subset of tests " |
| "to run. By default, all the tests are run.\n" |
| " --runs NUMBER\n" |
| " Number of times to run each test.\n" |
| " --enable-tracing\n" |
| " Enable use of Fuchsia tracing: Enable registering as a " |
| "TraceProvider. This is off by default because the " |
| "TraceProvider gets registered asynchronously on a background " |
| "thread (see TO-650), and that activity could introduce noise " |
| "to the tests.\n" |
| " --startup-delay SECONDS\n" |
| " Delay in seconds to wait on startup, after registering " |
| "a TraceProvider. This allows working around a race condition " |
| "where tracing misses initial events from newly-registered " |
| "TraceProviders (see TO-650).\n", |
| argv[0], argv[0]); |
| return 1; |
| } |
| |
| bool success = true; |
| |
| // Check whether to run in perf test mode. |
| if (argc >= 2 && strcmp(argv[1], "-p") == 0) { |
| // Drop the "-p" argument. Keep argv[0] because getopt_long() |
| // prints it in error messages. |
| argv[1] = argv[0]; |
| argc--; |
| argv++; |
| if (!PerfTestMode(test_suite, argc, argv)) { |
| success = false; |
| } |
| } else { |
| printf("Running perf tests in unit test mode...\n"); |
| { |
| // Run each test a small number of times to ensure that doing |
| // multiple runs works OK. |
| const int kRunCount = 3; |
| ResultsSet unused_results; |
| if (!RunTests(test_suite, g_tests, kRunCount, "", stdout, &unused_results)) { |
| success = false; |
| } |
| } |
| |
| // In unit test mode, we pass all command line arguments on to the |
| // unittest library. |
| printf("Running unit tests...\n"); |
| if (!unittest_run_all_tests(argc, argv)) { |
| success = false; |
| } |
| } |
| |
| return success ? 0 : 1; |
| } |
| |
| } // namespace perftest |