Repository: carbon-language/carbon-lang
File: testing/file_test/file_test_base.cpp (C++)

Code before:
        std::chrono::steady_clock::now() - start_);
  }

 private:
  std::chrono::steady_clock::time_point start_;
};

// Runs a single test. Uses a CrashRecoveryContext, and returns false on a
// crash. For test_elapsed_ms, try to exclude time spent waiting on
// output_mutex.
static auto RunSingleTest(FileTestInfo& test,
                          std::chrono::milliseconds& test_elapsed_ms,
                          bool single_threaded, std::mutex& output_mutex)
    -> bool {
  std::unique_ptr<FileTestBase> test_instance(test.factory_fn());

  if (absl::GetFlag(FLAGS_dump_output)) {
    std::unique_lock<std::mutex> lock(output_mutex);
    llvm::errs() << "\n--- Dumping: " << test.test_name << "\n\n";
  }

  // 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.
    std::unique_lock<std::mutex> output_lock;

    if ((*test.test_result)->capture_console_output ||
        !test_instance->AllowParallelRun()) {
      output_lock = std::unique_lock<std::mutex>(output_mutex);
    }

    Timer test_timer;
    if (single_threaded) {
      RunSingleTestHelper(test, *test_instance);
    } else {
      // Use a crash recovery context to try to get a stack trace when
      // multiple threads may crash in parallel, which otherwise leads to the
      // program aborting without printing a stack trace.
      llvm::CrashRecoveryContext crc;
      crc.DumpStackAndCleanupOnFailure = true;
      if (!crc.RunSafely([&] { RunSingleTestHelper(test, *test_instance); })) {
        return false;
      }
    }
    test_elapsed_ms += test_timer.elapsed_ms();

Review comment (performance):
I would perhaps naively have expected the timer to only capture the time taken to run the test, not the time processing inputs and autoupdating the output file. Is the goal here to determine which tests are exercising slow parts of the toolchain, or detecting slowness in the `file_test` process?

Code after:
static auto RunSingleTest(FileTestInfo& test, bool single_threaded,
                          std::mutex& output_mutex) -> bool {
  std::unique_ptr<FileTestBase> test_instance(test.factory_fn());

  if (absl::GetFlag(FLAGS_dump_output)) {
    std::unique_lock<std::mutex> lock(output_mutex);
    llvm::errs() << "\n--- Dumping: " << test.test_name << "\n\n";
  }

  // 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.
    std::unique_lock<std::mutex> output_lock;

    if ((*test.test_result)->capture_console_output ||
        !test_instance->AllowParallelRun()) {
      output_lock = std::unique_lock<std::mutex>(output_mutex);
    }

    if (single_threaded) {
      RunSingleTestHelper(test, *test_instance);
    } else {
      // Use a crash recovery context to try to get a stack trace when
      // multiple threads may crash in parallel, which otherwise leads to the
      // program aborting without printing a stack trace.
      llvm::CrashRecoveryContext crc;
      crc.DumpStackAndCleanupOnFailure = true;
      if (!crc.RunSafely([&] { RunSingleTestHelper(test, *test_instance); })) {
        return false;
      }
    }
  }

  if (!test.test_result->ok()) {
    std::unique_lock<std::mutex> lock(output_mutex);
    llvm::errs() << "\n" << test.test_result->error().message() << "\n";
    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();