From e0e305536ef23cf3864dd936e8df0ce2300cab1f Mon Sep 17 00:00:00 2001 From: Sam Estep Date: Tue, 12 Nov 2024 15:47:08 -0500 Subject: [PATCH] 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 --- toolchain/base/BUILD | 9 ++++ toolchain/base/timings.h | 53 +++++++++++++++++++ toolchain/check/BUILD | 1 + toolchain/check/check.cpp | 15 +++++- toolchain/check/check.h | 2 + toolchain/driver/BUILD | 1 + toolchain/driver/compile_subcommand.cpp | 39 ++++++++++++++ toolchain/driver/compile_subcommand.h | 1 + toolchain/driver/testdata/dump_timings.carbon | 21 ++++++++ 9 files changed, 141 insertions(+), 1 deletion(-) create mode 100644 toolchain/base/timings.h create mode 100644 toolchain/driver/testdata/dump_timings.carbon diff --git a/toolchain/base/BUILD b/toolchain/base/BUILD index ec307eab6827..cca1cd8204ca 100644 --- a/toolchain/base/BUILD +++ b/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"], diff --git a/toolchain/base/timings.h b/toolchain/base/timings.h new file mode 100644 index 000000000000..dba79090a0ec --- /dev/null +++ b/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( + entry.nanoseconds.count())); + } + label_map.Add("Total", + static_cast(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 timings_; +}; + +} // namespace Carbon + +#endif // CARBON_TOOLCHAIN_BASE_TIMINGS_H_ diff --git a/toolchain/check/BUILD b/toolchain/check/BUILD index 1250f96fa9ef..f78585f30ffc 100644 --- a/toolchain/check/BUILD +++ b/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", diff --git a/toolchain/check/check.cpp b/toolchain/check/check.cpp index a5ec77289589..d3549903b759 100644 --- a/toolchain/check/check.cpp +++ b/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 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 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; diff --git a/toolchain/check/check.h b/toolchain/check/check.h index 01403dfa264e..fbb6cdfe39de 100644 --- a/toolchain/check/check.h +++ b/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; const Lex::TokenizedBuffer* tokens; const Parse::Tree* parse_tree; DiagnosticConsumer* consumer; diff --git a/toolchain/driver/BUILD b/toolchain/driver/BUILD index 9cc9bfc1eb5a..726d2555f861 100644 --- a/toolchain/driver/BUILD +++ b/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", diff --git a/toolchain/driver/compile_subcommand.cpp b/toolchain/driver/compile_subcommand.cpp index 8b38797cc03f..7631fa8fed3b 100644 --- a/toolchain/driver/compile_subcommand.cpp +++ b/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(); // 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 mem_usage_; + // Tracks timings of the compile. + std::optional timings_; // These are initialized as steps are run. std::optional source_; diff --git a/toolchain/driver/compile_subcommand.h b/toolchain/driver/compile_subcommand.h index c96f0c587828..094ad23319b2 100644 --- a/toolchain/driver/compile_subcommand.h +++ b/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; diff --git a/toolchain/driver/testdata/dump_timings.carbon b/toolchain/driver/testdata/dump_timings.carbon new file mode 100644 index 000000000000..b7f809c62dab --- /dev/null +++ b/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: ...