xref: /system/ulib/perftest/runner.cpp

// 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(&regex, regex_string, REG_EXTENDED);
    if (err != 0) {
        char msg[256];
        msg[0] = '\0';
        regerror(err, &regex, 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(&regex, 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(&regex);

    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