Collect timing data per unit for each phase (#4512)

This PR adds a `--dump-timings` flag to the `compile` subcommand
(similar to the existing `--dump-mem-usage` flag), which collects timing
data per compilation unit for each compilation phase. For example, on my
2020 M1 MacBook:

```
$ bazel build -c opt //toolchain
$ bazel-bin/toolchain/install/run_carbon compile --phase=lower --dump-timings examples/sieve.carbon | tail
...
---
filename:        'examples/sieve.carbon'
nanoseconds:
  lex:             30792
  parse:           25458
  check:           226625
  lower:           1136958
  Total:           1419833
...
```

Most of the changes are pretty straightforward. There were a couple I
wasn't sure about though; let me know if I should change:

- new `Timings` class in its own file, pretty similar to the existing
`MemUsage` class
- added a `timings_` field to the `CompilationUnit` class
- added a `timings` field to the `Check::Unit` struct
- renamed `CheckParseTree` function to `CheckParseTreeInner` for ease of
timing with early `return`

---------

Co-authored-by: Jon Ross-Perkins <[email protected]>

toolchain/base/BUILD

@@ -42,6 +42,15 @@ cc_library(
     ],
 )
 
+cc_library(
+    name = "timings",
+    hdrs = ["timings.h"],
+    deps = [
+        ":yaml",
+        "@llvm-project//llvm:Support",
+    ],
+)
+
 cc_library(
     name = "value_ids",
     hdrs = ["value_ids.h"],

toolchain/base/timings.h

@@ -0,0 +1,53 @@
+// Part of the Carbon Language project, under the Apache License v2.0 with LLVM
+// Exceptions. See /LICENSE for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+
+#ifndef CARBON_TOOLCHAIN_BASE_TIMINGS_H_
+#define CARBON_TOOLCHAIN_BASE_TIMINGS_H_
+
+#include "llvm/ADT/SmallVector.h"
+#include "llvm/ADT/StringRef.h"
+#include "toolchain/base/yaml.h"
+
+namespace Carbon {
+
+// Helps track timings for a compile.
+class Timings {
+ public:
+  // Adds tracking for nanoseconds, paired with the given label.
+  auto Add(std::string label, std::chrono::nanoseconds nanoseconds) -> void {
+    timings_.push_back({.label = std::move(label), .nanoseconds = nanoseconds});
+  }
+
+  auto OutputYaml(llvm::StringRef filename) const -> Yaml::OutputMapping {
+    // Explicitly copy the filename.
+    return Yaml::OutputMapping([&, filename](Yaml::OutputMapping::Map map) {
+      map.Add("filename", filename);
+      map.Add("nanoseconds",
+              Yaml::OutputMapping([&](Yaml::OutputMapping::Map label_map) {
+                std::chrono::nanoseconds total_nanoseconds(0);
+                for (const auto& entry : timings_) {
+                  total_nanoseconds += entry.nanoseconds;
+                  label_map.Add(entry.label, static_cast<int64_t>(
+                                                 entry.nanoseconds.count()));
+                }
+                label_map.Add("Total",
+                              static_cast<int64_t>(total_nanoseconds.count()));
+              }));
+    });
+  }
+
+ private:
+  // Timing for a specific label.
+  struct Entry {
+    std::string label;
+    std::chrono::nanoseconds nanoseconds;
+  };
+
+  // The accumulated data on timings.
+  llvm::SmallVector<Entry> timings_;
+};
+
+}  // namespace Carbon
+
+#endif  // CARBON_TOOLCHAIN_BASE_TIMINGS_H_

toolchain/check/BUILD

@@ -118,6 +118,7 @@ cc_library(
         "//toolchain/base:kind_switch",
         "//toolchain/base:pretty_stack_trace_function",
         "//toolchain/base:shared_value_stores",
+        "//toolchain/base:timings",
         "//toolchain/diagnostics:diagnostic_emitter",
         "//toolchain/diagnostics:format_providers",
         "//toolchain/lex:token_index",

toolchain/check/check.cpp

@@ -894,7 +894,7 @@ static auto ProcessNodeIds(Context& context, llvm::raw_ostream* vlog_stream,
 }
 
 // Produces and checks the IR for the provided Parse::Tree.
-static auto CheckParseTree(
+static auto CheckParseTreeInner(
     llvm::MutableArrayRef<Parse::NodeLocConverter> node_converters,
     UnitInfo& unit_info, int total_ir_count, llvm::raw_ostream* vlog_stream)
     -> void {
@@ -950,6 +950,19 @@ static auto CheckParseTree(
 #endif
 }
 
+// Measures duration to produce and check the IR for the provided Parse::Tree.
+static auto CheckParseTree(
+    llvm::MutableArrayRef<Parse::NodeLocConverter> node_converters,
+    UnitInfo& unit_info, int total_ir_count, llvm::raw_ostream* vlog_stream)
+    -> void {
+  auto start_time = std::chrono::steady_clock::now();
+  CheckParseTreeInner(node_converters, unit_info, total_ir_count, vlog_stream);
+  if (auto& timings = *(unit_info.unit->timings)) {
+    auto end_time = std::chrono::steady_clock::now();
+    timings->Add("check", end_time - start_time);
+  }
+}
+
 // The package and library names, used as map keys.
 using ImportKey = std::pair<llvm::StringRef, llvm::StringRef>;
 

toolchain/check/check.h

@@ -7,6 +7,7 @@
 
 #include "common/ostream.h"
 #include "toolchain/base/shared_value_stores.h"
+#include "toolchain/base/timings.h"
 #include "toolchain/check/sem_ir_diagnostic_converter.h"
 #include "toolchain/diagnostics/diagnostic_emitter.h"
 #include "toolchain/lex/tokenized_buffer.h"
@@ -19,6 +20,7 @@ namespace Carbon::Check {
 // Checking information that's tracked per file.
 struct Unit {
   SharedValueStores* value_stores;
+  std::optional<Timings>* timings;
   const Lex::TokenizedBuffer* tokens;
   const Parse::Tree* parse_tree;
   DiagnosticConsumer* consumer;

toolchain/driver/BUILD

@@ -112,6 +112,7 @@ cc_library(
         "//common:vlog",
         "//toolchain/base:pretty_stack_trace_function",
         "//toolchain/base:shared_value_stores",
+        "//toolchain/base:timings",
         "//toolchain/check",
         "//toolchain/codegen",
         "//toolchain/diagnostics:diagnostic_emitter",

toolchain/driver/compile_subcommand.cpp

@@ -7,6 +7,7 @@
 #include "common/vlog.h"
 #include "llvm/ADT/ScopeExit.h"
 #include "toolchain/base/pretty_stack_trace_function.h"
+#include "toolchain/base/timings.h"
 #include "toolchain/check/check.h"
 #include "toolchain/codegen/codegen.h"
 #include "toolchain/diagnostics/sorting_diagnostic_consumer.h"
@@ -236,6 +237,14 @@ Dumps the amount of memory used.
 )""",
       },
       [&](auto& arg_b) { arg_b.Set(&dump_mem_usage); });
+  b.AddFlag(
+      {
+          .name = "dump-timings",
+          .help = R"""(
+Dumps the duration of each phase for each compilation unit.
+)""",
+      },
+      [&](auto& arg_b) { arg_b.Set(&dump_timings); });
   b.AddFlag(
       {
           .name = "prelude-import",
@@ -346,6 +355,9 @@ class CompilationUnit {
     if (options_.dump_mem_usage && IncludeInDumps()) {
       mem_usage_ = MemUsage();
     }
+    if (options_.dump_timings && IncludeInDumps()) {
+      timings_ = Timings();
+    }
   }
 
   // Loads source and lexes it. Returns true on success.
@@ -364,8 +376,13 @@ class CompilationUnit {
     }
     CARBON_VLOG("*** SourceBuffer ***\n```\n{0}\n```\n", source_->text());
 
+    auto start_time = std::chrono::steady_clock::now();
     LogCall("Lex::Lex",
             [&] { tokens_ = Lex::Lex(value_stores_, *source_, *consumer_); });
+    if (timings_) {
+      auto end_time = std::chrono::steady_clock::now();
+      timings_->Add("lex", end_time - start_time);
+    }
     if (options_.dump_tokens && IncludeInDumps()) {
       consumer_->Flush();
       tokens_->Print(driver_env_->output_stream,
@@ -384,9 +401,14 @@ class CompilationUnit {
   auto RunParse() -> void {
     CARBON_CHECK(tokens_);
 
+    auto start_time = std::chrono::steady_clock::now();
     LogCall("Parse::Parse", [&] {
       parse_tree_ = Parse::Parse(*tokens_, *consumer_, vlog_stream_);
     });
+    if (timings_) {
+      auto end_time = std::chrono::steady_clock::now();
+      timings_->Add("parse", end_time - start_time);
+    }
     if (options_.dump_parse_tree && IncludeInDumps()) {
       consumer_->Flush();
       const auto& tree_and_subtrees = GetParseTreeAndSubtrees();
@@ -410,6 +432,7 @@ class CompilationUnit {
     CARBON_CHECK(parse_tree_);
     return {
         .value_stores = &value_stores_,
+        .timings = &timings_,
         .tokens = &*tokens_,
         .parse_tree = &*parse_tree_,
         .consumer = consumer_,
@@ -460,6 +483,7 @@ class CompilationUnit {
   auto RunLower(const Check::SemIRDiagnosticConverter& converter) -> void {
     CARBON_CHECK(sem_ir_);
 
+    auto start_time = std::chrono::steady_clock::now();
     LogCall("Lower::LowerToLLVM", [&] {
       llvm_context_ = std::make_unique<llvm::LLVMContext>();
       // TODO: Consider disabling instruction naming by default if we're not
@@ -469,6 +493,10 @@ class CompilationUnit {
                                    converter, input_filename_, *sem_ir_,
                                    &inst_namer, vlog_stream_);
     });
+    if (timings_) {
+      auto end_time = std::chrono::steady_clock::now();
+      timings_->Add("lower", end_time - start_time);
+    }
     if (vlog_stream_) {
       CARBON_VLOG("*** llvm::Module ***\n");
       module_->print(*vlog_stream_, /*AAW=*/nullptr,
@@ -483,7 +511,12 @@ class CompilationUnit {
 
   auto RunCodeGen() -> void {
     CARBON_CHECK(module_);
+    auto start_time = std::chrono::steady_clock::now();
     LogCall("CodeGen", [&] { success_ = RunCodeGenHelper(); });
+    if (timings_) {
+      auto end_time = std::chrono::steady_clock::now();
+      timings_->Add("codegen", end_time - start_time);
+    }
   }
 
   // Runs post-compile logic. This is always called, and called after all other
@@ -498,6 +531,10 @@ class CompilationUnit {
       Yaml::Print(driver_env_->output_stream,
                   mem_usage_->OutputYaml(input_filename_));
     }
+    if (timings_) {
+      Yaml::Print(driver_env_->output_stream,
+                  timings_->OutputYaml(input_filename_));
+    }
 
     // The diagnostics consumer must be flushed before compilation artifacts are
     // destructed, because diagnostics can refer to their state.
@@ -625,6 +662,8 @@ class CompilationUnit {
 
   // Tracks memory usage of the compile.
   std::optional<MemUsage> mem_usage_;
+  // Tracks timings of the compile.
+  std::optional<Timings> timings_;
 
   // These are initialized as steps are run.
   std::optional<SourceBuffer> source_;

toolchain/driver/compile_subcommand.h

@@ -50,6 +50,7 @@ struct CompileOptions {
   bool dump_llvm_ir = false;
   bool dump_asm = false;
   bool dump_mem_usage = false;
+  bool dump_timings = false;
   bool include_diagnostic_kind = false;
   bool stream_errors = false;
   bool preorder_parse_tree = false;

toolchain/driver/testdata/dump_timings.carbon

@@ -0,0 +1,21 @@
+// Part of the Carbon Language project, under the Apache License v2.0 with LLVM
+// Exceptions. See /LICENSE for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+// ARGS: compile --dump-timings --phase=check %s
+//
+// SET-CHECK-SUBSET
+//
+// NOAUTOUPDATE
+// TIP: To test this file alone, run:
+// TIP:   bazel test //toolchain/testing:file_test --test_arg=--file_tests=toolchain/driver/testdata/dump_timings.carbon
+// TIP: To dump output, run:
+// TIP:   bazel run //toolchain/testing:file_test -- --dump_output --file_tests=toolchain/driver/testdata/dump_timings.carbon
+
+// CHECK:STDOUT: filename:        dump_timings.carbon
+// CHECK:STDOUT: nanoseconds:
+// CHECK:STDOUT:   lex:             {{\d+}}
+// CHECK:STDOUT:   parse:           {{\d+}}
+// CHECK:STDOUT:   check:           {{\d+}}
+// CHECK:STDOUT:   Total:           {{\d+}}
+// CHECK:STDOUT: ...