blob: c1a657835e040526f9afa4153b70808280e98058 [file] [log] [blame]
// 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