Make it easier to see test performance (#5363)

Trying to make it easier to see possible bottlenecks.

Disabling hyperthreading seems like a significant reduction in
contention (15% improvement for me). Going down by half again reduces a
contention a little further, but not significantly from what I see. My
thought is that just flipping the flag is going to work best for people
cross-system versus a "divide by four", but welcome to other opinions
there. Note, I'm not digging into the source of the contention here,
just observing it.

Current default on my system (equivalent to `--threads=128`):

```
Running tests with 128 thread(s)
...
Ran 1272 tests in 3955 ms wall time, 397615 ms across threads
```

Disabling hyperthreads (equivalent to `--threads=64`):

```
Running tests with 64 thread(s)
...
Ran 1272 tests in 3520 ms wall time, 161957 ms across threads
```

`--threads=32`:
```
Running tests with 32 thread(s)
...
Ran 1272 tests in 3329 ms wall time, 69327 ms across threads
```

And for `./autoupdate_testdata.py --threads=64 --print_slowest_tests=5`:

```
Running tests with 64 thread(s)
...
Ran 1272 tests in 3417 ms wall time, 157946 ms across threads
  Slowest tests:
  - toolchain/lower/testdata/function/generic/call_recursive_basic.carbon: 1508 ms, 1484 ms in Run
  - toolchain/lower/testdata/builtins/print_read.carbon: 1506 ms, 1506 ms in Run
  - toolchain/lower/testdata/array/field.carbon: 1488 ms, 1487 ms in Run
  - toolchain/lower/testdata/builtins/int.carbon: 1482 ms, 1475 ms in Run
  - toolchain/lower/testdata/function/definition/params_one.carbon: 1472 ms, 1471 ms in Run
```

In test:

```
==================== Test output for //toolchain/testing:file_test:
Running tests with 64 thread(s)
...
Ran 1272 tests in 2968 ms wall time, 177732 ms across threads
  Slowest tests:
  - toolchain/lower/testdata/builtins/int.carbon: 1544 ms, 1533 ms in Run
  - toolchain/lower/testdata/array/function_param.carbon: 1539 ms, 1537 ms in Run
  - toolchain/lower/testdata/basics/zero.carbon: 1537 ms, 1536 ms in Run
  - toolchain/lower/testdata/function/call/params_one.carbon: 1535 ms, 1534 ms in Run
  - toolchain/lower/testdata/function/definition/params_zero.carbon: 1531 ms, 1531 ms in Run
[==========] Running 1272 tests from 1 test suite.
[----------] Global test environment set-up.
```

testing/file_test/file_test_base.cpp

@@ -22,6 +22,7 @@
 #include "testing/file_test/file_test_base.h"
 
 #include <atomic>
+#include <chrono>
 #include <cstdlib>
 #include <filesystem>
 #include <functional>
@@ -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<FileTestInfo> 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<FileTestBase> 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<std::mutex> 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::DefaultThreadPool>(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<llvm::DefaultThreadPool>(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<bool> crashed = false;
 
+  std::atomic<bool> 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.

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<FileTestBase::RunResult> 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) {

testing/file_test/test_file.h

@@ -7,6 +7,7 @@
 
 #include <gmock/gmock.h>
 
+#include <chrono>
 #include <string>
 
 #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::milliseconds>(
+        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.

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: