diff --git a/testing/file_test/file_test_base.cpp b/testing/file_test/file_test_base.cpp index 0804a19c2c7c..5f572927ee76 100644 --- a/testing/file_test/file_test_base.cpp +++ b/testing/file_test/file_test_base.cpp @@ -22,6 +22,7 @@ #include "testing/file_test/file_test_base.h" #include +#include #include #include #include @@ -65,6 +66,9 @@ ABSL_FLAG(unsigned int, threads, 0, ABSL_FLAG(bool, dump_output, false, "Instead of verifying files match test output, directly dump output " "to stderr."); +ABSL_FLAG(int, print_slowest_tests, 5, + "The number of tests to print when showing slowest tests. Set to 0 " + "to disabling printing. Set to -1 to print all tests."); namespace Carbon::Testing { @@ -86,6 +90,9 @@ struct FileTestInfo { // changed) the test file. This may be true even if output passes test // expectations. bool autoupdate_differs = false; + + // Time spent in the test total, including processing and autoupdate. + std::chrono::milliseconds elapsed_ms = std::chrono::milliseconds(0); }; // Adapts a `FileTestBase` instance to gtest for outputting results. @@ -363,6 +370,7 @@ static auto SingleThreaded(llvm::ArrayRef tests) -> bool { // CrashRecoveryContext. static auto RunSingleTestHelper(FileTestInfo& test, FileTestBase& test_instance) -> void { + Timer timer; // Add a crash trace entry with the single-file test command. std::string test_command = GetBazelCommand(BazelMode::Test, test.test_name); llvm::PrettyStackTraceString stack_trace_entry(test_command.c_str()); @@ -372,10 +380,12 @@ static auto RunSingleTestHelper(FileTestInfo& test, FileTestBase& test_instance) !err.ok()) { test.test_result = std::move(err).error(); } + test.elapsed_ms += timer.elapsed_ms(); } // Runs a single test. Uses a CrashRecoveryContext, and returns false on a -// crash. +// crash. For test_elapsed_ms, try to exclude time spent waiting on +// output_mutex. static auto RunSingleTest(FileTestInfo& test, bool single_threaded, std::mutex& output_mutex) -> bool { std::unique_ptr test_instance(test.factory_fn()); @@ -386,8 +396,11 @@ static auto RunSingleTest(FileTestInfo& test, bool single_threaded, } // Load expected output. + Timer process_timer; test.test_result = ProcessTestFile(test_instance->test_name(), absl::GetFlag(FLAGS_autoupdate)); + test.elapsed_ms = process_timer.elapsed_ms(); + if (test.test_result->ok()) { // Execution must be serialized for either serial tests or console // output. @@ -418,9 +431,11 @@ static auto RunSingleTest(FileTestInfo& test, bool single_threaded, return true; } + Timer autoupdate_timer; test.autoupdate_differs = RunAutoupdater(test_instance.get(), **test.test_result, /*dry_run=*/!absl::GetFlag(FLAGS_autoupdate)); + test.elapsed_ms += autoupdate_timer.elapsed_ms(); std::unique_lock lock(output_mutex); if (absl::GetFlag(FLAGS_dump_output)) { @@ -447,8 +462,11 @@ auto FileTestEventListener::OnTestProgramStart( } else { // Enable the CRC for use in `RunSingleTest`. llvm::CrashRecoveryContext::Enable(); - pool = std::make_unique(llvm::ThreadPoolStrategy{ - .ThreadsRequested = absl::GetFlag(FLAGS_threads)}); + llvm::ThreadPoolStrategy thread_strategy = { + .ThreadsRequested = absl::GetFlag(FLAGS_threads), + // Disable hyper threads to reduce contention. + .UseHyperThreads = false}; + pool = std::make_unique(thread_strategy); } if (!absl::GetFlag(FLAGS_dump_output)) { llvm::errs() << "Running tests with " << pool->getMaxConcurrency() @@ -457,12 +475,15 @@ auto FileTestEventListener::OnTestProgramStart( // Guard access to output (stdout and stderr). std::mutex output_mutex; - std::atomic crashed = false; + std::atomic crashed = false; + Timer all_timer; + int run_count = 0; for (auto& test : tests_) { if (!test.registered_test->should_run()) { continue; } + ++run_count; pool->async([&] { // If any thread crashed, don't try running more. @@ -482,7 +503,37 @@ auto FileTestEventListener::OnTestProgramStart( // We expect to have leaked memory if one or more of our tests crashed. std::abort(); } - llvm::errs() << "\nDone!\n"; + + // Calculate the total test time. + auto all_elapsed_ms = all_timer.elapsed_ms(); + auto total_elapsed_ms = std::chrono::milliseconds(0); + for (auto& test : tests_) { + total_elapsed_ms += test.elapsed_ms; + } + + llvm::errs() << "\nRan " << run_count << " tests in " + << all_elapsed_ms.count() << " ms wall time, " + << total_elapsed_ms.count() << " ms across threads\n"; + + // When there are multiple tests, give additional timing details, particularly + // slowest tests. + auto print_slowest_tests = absl::GetFlag(FLAGS_print_slowest_tests); + if (run_count > 1 && print_slowest_tests != 0) { + llvm::errs() << " Slowest tests:\n"; + llvm::sort(tests_, [](const FileTestInfo& lhs, const FileTestInfo& rhs) { + return lhs.elapsed_ms > rhs.elapsed_ms; + }); + int count = print_slowest_tests > 0 ? print_slowest_tests : run_count; + for (const auto& test : tests_.take_front(count)) { + std::chrono::milliseconds run_ms(0); + if (test.test_result && test.test_result->ok()) { + run_ms = test.test_result.value()->run_elapsed_ms; + } + llvm::errs() << " - " << test.test_name << ": " + << test.elapsed_ms.count() << " ms, " << run_ms.count() + << " ms in Run\n"; + } + } } // Implements main() within the Carbon::Testing namespace for convenience. diff --git a/testing/file_test/run_test.cpp b/testing/file_test/run_test.cpp index 66d7cf4782c1..1426c23ceaa7 100644 --- a/testing/file_test/run_test.cpp +++ b/testing/file_test/run_test.cpp @@ -164,11 +164,13 @@ auto RunTestFile(const FileTestBase& test_base, bool dump_output, llvm::raw_svector_ostream output_stream(test_file.actual_stdout); llvm::raw_svector_ostream error_stream(test_file.actual_stderr); + Timer timer; ErrorOr run_result = dump_output ? test_base.Run(test_args_ref, fs, input_stream, llvm::outs(), llvm::errs()) : test_base.Run(test_args_ref, fs, input_stream, output_stream, error_stream); + test_file.run_elapsed_ms = timer.elapsed_ms(); // Ensure stdout/stderr are always fetched, even when discarded on error. if (test_file.capture_console_output) { diff --git a/testing/file_test/test_file.h b/testing/file_test/test_file.h index d0fad8e1d94c..1161b3298981 100644 --- a/testing/file_test/test_file.h +++ b/testing/file_test/test_file.h @@ -7,6 +7,7 @@ #include +#include #include #include "llvm/ADT/SmallString.h" @@ -16,6 +17,20 @@ namespace Carbon::Testing { +// A small timer for getting elapsed durations. +class Timer { + public: + explicit Timer() : start_(std::chrono::steady_clock::now()) {} + + auto elapsed_ms() -> std::chrono::milliseconds { + return std::chrono::duration_cast( + std::chrono::steady_clock::now() - start_); + } + + private: + std::chrono::steady_clock::time_point start_; +}; + // Encapsulates test context generated by processing and running. // // Note this should remain internal to `FileTestBase`, not exposed to individual @@ -84,6 +99,9 @@ struct TestFile { llvm::SmallString<16> actual_stderr; FileTestBase::RunResult run_result = {.success = false}; + + // Time spent inside FileTestBase::Run. + std::chrono::milliseconds run_elapsed_ms = std::chrono::milliseconds(0); }; // Processes the test input, producing test files and expected output. diff --git a/toolchain/autoupdate_testdata.py b/toolchain/autoupdate_testdata.py index 2d25e45c4db7..f794f3492524 100755 --- a/toolchain/autoupdate_testdata.py +++ b/toolchain/autoupdate_testdata.py @@ -42,6 +42,10 @@ def main() -> None: # Parse arguments. parser = argparse.ArgumentParser(__doc__) parser.add_argument("--non-fatal-checks", action="store_true") + parser.add_argument( + "--print_slowest_tests", default=0, help="Forwarded to file_test" + ) + parser.add_argument("--threads", help="Forwarded to file_test") parser.add_argument("files", nargs="*") args = parser.parse_args() @@ -64,7 +68,11 @@ def main() -> None: "//toolchain/testing:file_test", "--", "--autoupdate", + "--print_slowest_tests", + str(args.print_slowest_tests), ] + if args.threads: + argv += ["--threads", args.threads] # Support specifying tests to update, such as: # ./autoupdate_testdata.py lex/**/* if args.files: