1// Copyright 2018 The Fuchsia Authors. All rights reserved. 2// Use of this source code is governed by a BSD-style license that can be 3// found in the LICENSE file. 4 5#include <perftest/runner.h> 6 7#include <getopt.h> 8#include <pthread.h> 9#include <regex.h> 10 11#include <fbl/function.h> 12#include <fbl/string.h> 13#include <fbl/string_printf.h> 14#include <fbl/vector.h> 15#include <lib/async-loop/cpp/loop.h> 16#include <trace-engine/context.h> 17#include <trace-engine/instrumentation.h> 18#include <trace-provider/provider.h> 19#include <trace/event.h> 20#include <unittest/unittest.h> 21#include <zircon/assert.h> 22#include <zircon/syscalls.h> 23 24namespace perftest { 25namespace { 26 27// g_tests needs to be POD because this list is populated by constructors. 28// We don't want g_tests to have a constructor that might get run after 29// items have been added to the list, because that would clobber the list. 30internal::TestList* g_tests; 31 32class RepeatStateImpl : public RepeatState { 33public: 34 RepeatStateImpl(uint32_t run_count) 35 : run_count_(run_count) {} 36 37 void SetBytesProcessedPerRun(uint64_t bytes) override { 38 if (started_) { 39 SetError("SetBytesProcessedPerRun() was called after KeepRunning()"); 40 return; 41 } 42 if (bytes == 0) { 43 SetError("Zero argument to SetBytesProcessedPerRun()"); 44 return; 45 } 46 if (bytes_processed_per_run_ != 0) { 47 SetError("Multiple calls to SetBytesProcessedPerRun()"); 48 return; 49 } 50 bytes_processed_per_run_ = bytes; 51 } 52 53 void DeclareStep(const char* name) override { 54 if (started_) { 55 SetError("DeclareStep() was called after KeepRunning()"); 56 return; 57 } 58 step_names_.push_back(name); 59 } 60 61 void NextStep() override { 62 if (unlikely(next_idx_ >= end_of_run_idx_)) { 63 SetError("Too many calls to NextStep()"); 64 return; 65 } 66 timestamps_[next_idx_] = zx_ticks_get(); 67 ++next_idx_; 68 } 69 70 bool KeepRunning() override { 71 uint64_t timestamp = zx_ticks_get(); 72 if (unlikely(next_idx_ != end_of_run_idx_)) { 73 // Slow path, including error cases. 74 if (error_) { 75 return false; 76 } 77 if (started_) { 78 SetError("Wrong number of calls to NextStep()"); 79 return false; 80 } 81 // First call to KeepRunning(). 82 step_count_ = static_cast<uint32_t>(step_names_.size()); 83 if (step_count_ == 0) { 84 step_count_ = 1; 85 } 86 // Add 1 because we store timestamps for the start of each test 87 // run (which serve as timestamps for the end of the previous 88 // test run), plus one more timestamp for the end of the last 89 // test run. 90 timestamps_size_ = run_count_ * step_count_ + 1; 91 timestamps_.reset(new uint64_t[timestamps_size_]); 92 // Clear the array in order to fault in the pages. This should 93 // prevent page faults occurring as we cross page boundaries 94 // when writing a test's running times (which would affect the 95 // first test case but not later test cases). 96 memset(timestamps_.get(), 0, 97 sizeof(timestamps_[0]) * timestamps_size_); 98 next_idx_ = 1; 99 end_of_run_idx_ = step_count_; 100 started_ = true; 101 timestamps_[0] = zx_ticks_get(); 102 return run_count_ != 0; 103 } 104 if (unlikely(next_idx_ == timestamps_size_ - 1)) { 105 // End reached. 106 if (finished_) { 107 SetError("Too many calls to KeepRunning()"); 108 return false; 109 } 110 timestamps_[next_idx_] = timestamp; 111 finished_ = true; 112 return false; 113 } 114 timestamps_[next_idx_] = timestamp; 115 ++next_idx_; 116 end_of_run_idx_ += step_count_; 117 return true; 118 } 119 120 // Returns nullptr on success, or an error string on failure. 121 const char* RunTestFunc(const char* test_name, 122 const fbl::Function<TestFunc>& test_func) { 123 TRACE_DURATION("perftest", "test_group", "test_name", test_name); 124 overall_start_time_ = zx_ticks_get(); 125 bool result = test_func(this); 126 overall_end_time_ = zx_ticks_get(); 127 if (error_) { 128 return error_; 129 } 130 if (!finished_) { 131 return "Too few calls to KeepRunning()"; 132 } 133 if (!result) { 134 return "Test function returned false"; 135 } 136 return nullptr; 137 } 138 139 void CopyTimeResults(const char* test_suite, const char* test_name, 140 ResultsSet* dest) const { 141 // bytes_processed_per_run is used for calculating throughput, but 142 // throughput is only really meaningful to calculate for the test 143 // overall, not for individual steps. Therefore we only report 144 // bytes_processed_per_run on the overall times. 145 146 // Report the times for each test run. 147 if (step_count_ == 1 || bytes_processed_per_run_ != 0) { 148 TestCaseResults* results = dest->AddTestCase( 149 test_suite, test_name, "nanoseconds"); 150 results->bytes_processed_per_run = bytes_processed_per_run_; 151 CopyStepTimes(0, step_count_, results); 152 } 153 154 if (step_count_ > 1) { 155 // Report times for individual steps. 156 for (uint32_t step = 0; step < step_count_; ++step) { 157 fbl::String name = fbl::StringPrintf( 158 "%s.%s", test_name, step_names_[step].c_str()); 159 TestCaseResults* results = dest->AddTestCase( 160 test_suite, name, "nanoseconds"); 161 CopyStepTimes(step, step + 1, results); 162 } 163 } 164 } 165 166 // Output a trace event for each of the test runs. Since we do this 167 // after the test runs took place (using the timestamps we recorded), 168 // we avoid incurring the overhead of the tracing system on each test 169 // run. 170 void WriteTraceEvents() { 171 trace_string_ref_t category_ref; 172 trace_context_t* context = 173 trace_acquire_context_for_category("perftest", &category_ref); 174 if (!context) { 175 return; 176 } 177 trace_thread_ref_t thread_ref; 178 trace_context_register_current_thread(context, &thread_ref); 179 180 auto WriteEvent = [&](trace_string_ref_t* name_ref, 181 uint64_t start_time, uint64_t end_time) { 182 trace_context_write_duration_begin_event_record( 183 context, start_time, 184 &thread_ref, &category_ref, name_ref, nullptr, 0); 185 trace_context_write_duration_end_event_record( 186 context, end_time, 187 &thread_ref, &category_ref, name_ref, nullptr, 0); 188 }; 189 190 trace_string_ref_t test_setup_string; 191 trace_string_ref_t test_run_string; 192 trace_string_ref_t test_step_string; 193 trace_string_ref_t test_teardown_string; 194 trace_context_register_string_literal( 195 context, "test_setup", &test_setup_string); 196 trace_context_register_string_literal( 197 context, "test_run", &test_run_string); 198 trace_context_register_string_literal( 199 context, "test_step", &test_step_string); 200 trace_context_register_string_literal( 201 context, "test_teardown", &test_teardown_string); 202 203 WriteEvent(&test_setup_string, overall_start_time_, timestamps_[0]); 204 for (uint32_t run = 0; run < run_count_; ++run) { 205 WriteEvent(&test_run_string, 206 GetTimestamp(run, 0), 207 GetTimestamp(run + 1, 0)); 208 if (step_count_ > 1) { 209 for (uint32_t step = 0; step < step_count_; ++step) { 210 WriteEvent(&test_step_string, 211 GetTimestamp(run, step), 212 GetTimestamp(run, step + 1)); 213 } 214 } 215 } 216 WriteEvent(&test_teardown_string, 217 timestamps_[timestamps_size_ - 1], overall_end_time_); 218 } 219 220private: 221 void SetError(const char* str) { 222 if (!error_) { 223 error_ = str; 224 } 225 } 226 227 // The start and end times of run R are GetTimestamp(R, 0) and 228 // GetTimestamp(R+1, 0). 229 // The start and end times of step S within run R are GetTimestamp(R, 230 // S) and GetTimestamp(R, S+1). 231 uint64_t GetTimestamp(uint32_t run_number, uint32_t step_number) const { 232 uint32_t index = run_number * step_count_ + step_number; 233 ZX_ASSERT(step_number <= step_count_); 234 ZX_ASSERT(index < timestamps_size_); 235 return timestamps_[index]; 236 } 237 238 void CopyStepTimes(uint32_t start_step_index, uint32_t end_step_index, 239 TestCaseResults* results) const { 240 double nanoseconds_per_tick = 241 1e9 / static_cast<double>(zx_ticks_per_second()); 242 243 // Copy the timing results, converting timestamps to elapsed times. 244 results->values.reserve(run_count_); 245 for (uint32_t run = 0; run < run_count_; ++run) { 246 uint64_t time_taken = (GetTimestamp(run, end_step_index) - 247 GetTimestamp(run, start_step_index)); 248 results->AppendValue( 249 static_cast<double>(time_taken) * nanoseconds_per_tick); 250 } 251 } 252 253 // Number of test runs that we intend to do. 254 uint32_t run_count_; 255 // Number of steps per test run. Once initialized, this is >= 1. 256 uint32_t step_count_; 257 // Names for steps. May be empty if the test has only one step. 258 fbl::Vector<fbl::String> step_names_; 259 // error_ is set to non-null if an error occurs. 260 const char* error_ = nullptr; 261 // Array of timestamps for the starts and ends of test runs and of 262 // steps within runs. GetTimestamp() describes the array layout. 263 fbl::unique_ptr<uint64_t[]> timestamps_; 264 // Number of elements allocated for timestamps_ array. 265 uint32_t timestamps_size_ = 0; 266 // Whether the first KeepRunning() call has occurred. 267 bool started_ = false; 268 // Whether the last KeepRunning() call has occurred. 269 bool finished_ = false; 270 // Next index in timestamps_ for writing a timestamp to. The initial 271 // value helps catch invalid NextStep() calls. 272 uint32_t next_idx_ = ~static_cast<uint32_t>(0); 273 // Index in timestamp_ for writing the end of the current run. 274 uint32_t end_of_run_idx_ = 0; 275 // Start time, before the test's setup phase. 276 uint64_t overall_start_time_; 277 // End time, after the test's teardown phase. 278 uint64_t overall_end_time_; 279 // Used for calculating throughput in bytes per unit time. 280 uint64_t bytes_processed_per_run_ = 0; 281}; 282 283} // namespace 284 285void RegisterTest(const char* name, fbl::Function<TestFunc> test_func) { 286 if (!g_tests) { 287 g_tests = new internal::TestList; 288 } 289 internal::NamedTest new_test{name, fbl::move(test_func)}; 290 g_tests->push_back(fbl::move(new_test)); 291} 292 293bool RunTest(const char* test_suite, const char* test_name, 294 const fbl::Function<TestFunc>& test_func, 295 uint32_t run_count, ResultsSet* results_set, 296 fbl::String* error_out) { 297 RepeatStateImpl state(run_count); 298 const char* error = state.RunTestFunc(test_name, test_func); 299 if (error) { 300 if (error_out) { 301 *error_out = error; 302 } 303 return false; 304 } 305 306 state.CopyTimeResults(test_suite, test_name, results_set); 307 state.WriteTraceEvents(); 308 return true; 309} 310 311namespace internal { 312 313bool RunTests(const char* test_suite, TestList* test_list, uint32_t run_count, 314 const char* regex_string, FILE* log_stream, 315 ResultsSet* results_set) { 316 // Compile the regular expression. 317 regex_t regex; 318 int err = regcomp(®ex, regex_string, REG_EXTENDED); 319 if (err != 0) { 320 char msg[256]; 321 msg[0] = '\0'; 322 regerror(err, ®ex, msg, sizeof(msg)); 323 fprintf(log_stream, 324 "Compiling the regular expression \"%s\" failed: %s\n", 325 regex_string, msg); 326 return false; 327 } 328 329 bool found_regex_match = false; 330 bool ok = true; 331 for (const internal::NamedTest& test_case : *test_list) { 332 const char* test_name = test_case.name.c_str(); 333 bool matched_regex = regexec(®ex, test_name, 0, nullptr, 0) == 0; 334 if (!matched_regex) { 335 continue; 336 } 337 found_regex_match = true; 338 339 // Log in a format similar to gtest's output, so that this will 340 // look familiar to readers and to allow parsing by tools that can 341 // parse gtest's output. 342 fprintf(log_stream, "[ RUN ] %s\n", test_name); 343 344 fbl::String error_string; 345 if (!RunTest(test_suite, test_name, test_case.test_func, run_count, 346 results_set, &error_string)) { 347 fprintf(log_stream, "Error: %s\n", error_string.c_str()); 348 fprintf(log_stream, "[ FAILED ] %s\n", test_name); 349 ok = false; 350 continue; 351 } 352 fprintf(log_stream, "[ OK ] %s\n", test_name); 353 } 354 355 regfree(®ex); 356 357 if (!found_regex_match) { 358 // Report an error so that this doesn't fail silently if the regex 359 // is wrong. 360 fprintf(log_stream, 361 "The regular expression \"%s\" did not match any tests\n", 362 regex_string); 363 return false; 364 } 365 return ok; 366} 367 368void ParseCommandArgs(int argc, char** argv, CommandArgs* dest) { 369 static const struct option opts[] = { 370 {"out", required_argument, nullptr, 'o'}, 371 {"filter", required_argument, nullptr, 'f'}, 372 {"runs", required_argument, nullptr, 'r'}, 373 {"enable-tracing", no_argument, nullptr, 't'}, 374 {"startup-delay", required_argument, nullptr, 'd'}, 375 }; 376 optind = 1; 377 for (;;) { 378 int opt = getopt_long(argc, argv, "", opts, nullptr); 379 if (opt < 0) { 380 break; 381 } 382 switch (opt) { 383 case 'o': 384 dest->output_filename = optarg; 385 break; 386 case 'f': 387 dest->filter_regex = optarg; 388 break; 389 case 'r': { 390 // Convert string to number (uint32_t). 391 char* end; 392 long val = strtol(optarg, &end, 0); 393 // Check that the string contains only a positive number and 394 // that the number doesn't overflow. 395 if (val != static_cast<uint32_t>(val) || *end != '\0' || 396 *optarg == '\0' || val == 0) { 397 fprintf(stderr, "Invalid argument for --runs: \"%s\"\n", 398 optarg); 399 exit(1); 400 } 401 dest->run_count = static_cast<uint32_t>(val); 402 break; 403 } 404 case 't': 405 dest->enable_tracing = true; 406 break; 407 case 'd': { 408 // Convert string to number (double type). 409 char* end; 410 double val = strtod(optarg, &end); 411 if (*end != '\0' || *optarg == '\0') { 412 fprintf(stderr, 413 "Invalid argument for --startup-delay: \"%s\"\n", 414 optarg); 415 exit(1); 416 } 417 dest->startup_delay_seconds = val; 418 break; 419 } 420 default: 421 // getopt_long() will have printed an error already. 422 exit(1); 423 } 424 } 425 if (optind < argc) { 426 fprintf(stderr, "Unrecognized argument: \"%s\"\n", argv[optind]); 427 exit(1); 428 } 429} 430 431} // namespace internal 432 433static void* TraceProviderThread(void* thread_arg) { 434 async::Loop loop(&kAsyncLoopConfigNoAttachToThread); 435 trace::TraceProvider provider(loop.dispatcher()); 436 loop.Run(); 437 return nullptr; 438} 439 440static void StartTraceProvider() { 441 pthread_t tid; 442 int err = pthread_create(&tid, nullptr, TraceProviderThread, nullptr); 443 ZX_ASSERT(err == 0); 444 err = pthread_detach(tid); 445 ZX_ASSERT(err == 0); 446} 447 448static bool PerfTestMode(const char* test_suite, int argc, char** argv) { 449 internal::CommandArgs args; 450 internal::ParseCommandArgs(argc, argv, &args); 451 452 if (args.enable_tracing) { 453 StartTraceProvider(); 454 } 455 zx_duration_t duration = 456 static_cast<zx_duration_t>(ZX_SEC(1) * args.startup_delay_seconds); 457 zx_nanosleep(zx_deadline_after(duration)); 458 459 ResultsSet results; 460 bool success = RunTests(test_suite, g_tests, args.run_count, 461 args.filter_regex, stdout, &results); 462 463 printf("\n"); 464 results.PrintSummaryStatistics(stdout); 465 printf("\n"); 466 467 if (args.output_filename) { 468 if (!results.WriteJSONFile(args.output_filename)) { 469 exit(1); 470 } 471 } 472 473 return success; 474} 475 476int PerfTestMain(int argc, char** argv, const char* test_suite) { 477 if (argc == 2 && (strcmp(argv[1], "-h") == 0 || 478 strcmp(argv[1], "--help") == 0)) { 479 printf("Usage:\n" 480 " %s -p [options] # run in \"perf test mode\"\n" 481 " %s # run in \"unit test mode\"\n" 482 "\n" 483 "\"Unit test mode\" runs perf tests as unit tests. " 484 "This means it only checks that the perf tests pass. " 485 "It only does a small number of runs of each test, and it " 486 "does not report their performance. Additionally, it runs " 487 "all of the unit tests in the executable (i.e. those that " 488 "use the unittest library).\n" 489 "\n" 490 "\"Perf test mode\" runs many iterations of each perf test, " 491 "and reports the performance results. It does not run any " 492 "unittest test cases.\n" 493 "\n" 494 "Options:\n" 495 " --out FILENAME\n" 496 " Filename to write JSON results data to. If this is " 497 "omitted, no JSON output is produced. JSON output will conform to this schema: " 498 "//zircon/system/ulib/perftest/performance-results-schema.json\n" 499 " --filter REGEX\n" 500 " Regular expression that specifies a subset of tests " 501 "to run. By default, all the tests are run.\n" 502 " --runs NUMBER\n" 503 " Number of times to run each test.\n" 504 " --enable-tracing\n" 505 " Enable use of Fuchsia tracing: Enable registering as a " 506 "TraceProvider. This is off by default because the " 507 "TraceProvider gets registered asynchronously on a background " 508 "thread (see TO-650), and that activity could introduce noise " 509 "to the tests.\n" 510 " --startup-delay SECONDS\n" 511 " Delay in seconds to wait on startup, after registering " 512 "a TraceProvider. This allows working around a race condition " 513 "where tracing misses initial events from newly-registered " 514 "TraceProviders (see TO-650).\n", 515 argv[0], argv[0]); 516 return 1; 517 } 518 519 bool success = true; 520 521 //��Check whether to run in perf test mode. 522 if (argc >= 2 && strcmp(argv[1], "-p") == 0) { 523 // Drop the "-p" argument. Keep argv[0] because getopt_long() 524 // prints it in error messages. 525 argv[1] = argv[0]; 526 argc--; 527 argv++; 528 if (!PerfTestMode(test_suite, argc, argv)) { 529 success = false; 530 } 531 } else { 532 printf("Running perf tests in unit test mode...\n"); 533 { 534 // Run each test a small number of times to ensure that doing 535 // multiple runs works OK. 536 const int kRunCount = 3; 537 ResultsSet unused_results; 538 if (!RunTests(test_suite, g_tests, kRunCount, "", stdout, &unused_results)) { 539 success = false; 540 } 541 } 542 543 // In unit test mode, we pass all command line arguments on to the 544 // unittest library. 545 printf("Running unit tests...\n"); 546 if (!unittest_run_all_tests(argc, argv)) { 547 success = false; 548 } 549 } 550 551 return success ? 0 : 1; 552} 553 554} // namespace perftest 555