Improved trace output selection using program phase filtering (#2851)

By implementing these improvements, users will have the ability to choose specific parts of the trace output.

Currently, when executing a file using the explorer with the --trace_file=- or --trace_file=filename.txt flag, the resulting output is an extensive and verbose log containing all the information.

In this PR, I have introduced the `ProgramPhase` enum class, which have distinct phases encountered during the compilation of a program in the explorer. Each member of this enum class corresponds to a specific phase, signifying the relevant information to be included in the trace output.

The phases covered by the `ProgramPhase` enum class are as follows:

1. Printing the source program
2. Name resolution
3. Control flow resolution
4. Type checking
5. Unformed variable resolution
6. Printing declarations
7. Printing the timings
8. Printing whole output.

These phases can be selected by passing the following compiler flags along with `--trace_file=-`.
`-trace_source_program`, `-trace_name_resolution`, `-trace_control_flow_resolution`, `-trace_type_checking`, `-trace_unformed_variables_resolution`, `-trace_declarations`, `-trace_execution`, `-trace_timing` and `-trace_all`. If none of these flags is passed only execution trace will be added to the output.

Co-authored-by: Richard Smith <richard@metafoo.co.uk>

explorer/README.md

@@ -168,6 +168,26 @@ performed during execution.
 Printing directly to the standard output using the `--trace_file` option is
 supported by passing `-` in place of a filepath (`--trace_file=-`).
 
+To customize the trace output and include specific information, you can use the
+following compiler options along with `--trace_file=...` option:
+
+-   `-trace_source_program`: Include trace output for the source program phase.
+-   `-trace_name_resolution`: Include trace output for the name resolution
+    phase.
+-   `-trace_control_flow_resolution`: Include trace output for the control flow
+    resolution phase.
+-   `-trace_type_checking`: Include trace output for the type checking phase.
+-   `-trace_unformed_variables_resolution`: Include trace output for the
+    unformed variables resolution phase.
+-   `-trace_declarations`: Include trace output for printing declarations.
+-   `-trace_execution`: Include trace output for program execution.
+-   `-trace_timing`: Include timing logs indicating the time taken by each
+    phase.
+-   `-trace_all`: Include trace output for all phases.
+
+By default, only execution trace will be added to the trace output. You can use
+combination of these options to include trace of multiple program phases.
+
 ### State of the Program
 
 The state of the program is printed in the following format, which consists of

explorer/common/trace_stream.h

@@ -5,8 +5,10 @@
 #ifndef CARBON_EXPLORER_COMMON_TRACE_STREAM_H_
 #define CARBON_EXPLORER_COMMON_TRACE_STREAM_H_
 
+#include <bitset>
 #include <optional>
 #include <string>
+#include <vector>
 
 #include "common/check.h"
 #include "common/ostream.h"
@@ -14,6 +16,22 @@
 
 namespace Carbon {
 
+// Enumerates the phases of the program used for tracing and controlling which
+// program phases are included for tracing.
+enum class ProgramPhase {
+  Unknown,                     // Represents an unknown program phase.
+  SourceProgram,               // Phase for the source program.
+  NameResolution,              // Phase for name resolution.
+  ControlFlowResolution,       // Phase for control flow resolution.
+  TypeChecking,                // Phase for type checking.
+  UnformedVariableResolution,  // Phase for unformed variables resolution.
+  Declarations,                // Phase for printing declarations.
+  Execution,                   // Phase for program execution.
+  Timing,                      // Phase for timing logs.
+  All,                         // Represents all program phases.
+  Last = All                   // Last program phase indicator.
+};
+
 // Encapsulates the trace stream so that we can cleanly disable tracing while
 // the prelude is being processed. The prelude is expected to take a
 // disproprotionate amount of time to log, so we try to avoid it.
@@ -26,8 +44,11 @@ namespace Carbon {
 class TraceStream {
  public:
   // Returns true if tracing is currently enabled.
+  // TODO: use current source location for file context based filtering instead
+  // of just checking if current code context is Prelude.
   auto is_enabled() const -> bool {
-    return stream_.has_value() && !in_prelude_;
+    return stream_.has_value() && !in_prelude_ &&
+           allowed_phases_[static_cast<int>(current_phase_)];
   }
 
   // Sets whether the prelude is being skipped.
@@ -38,12 +59,32 @@ class TraceStream {
     stream_ = stream;
   }
 
+  auto set_current_phase(ProgramPhase current_phase) -> void {
+    current_phase_ = current_phase;
+  }
+
+  auto set_allowed_phases(std::vector<ProgramPhase> allowed_phases_list) {
+    if (allowed_phases_list.empty()) {
+      allowed_phases_.set(static_cast<int>(ProgramPhase::Execution));
+    } else {
+      for (auto phase : allowed_phases_list) {
+        if (phase == ProgramPhase::All) {
+          allowed_phases_.set();
+        } else {
+          allowed_phases_.set(static_cast<int>(phase));
+        }
+      }
+    }
+  }
+
   // Returns the internal stream. Requires is_enabled.
   auto stream() const -> llvm::raw_ostream& {
-    CARBON_CHECK(is_enabled());
+    CARBON_CHECK(is_enabled() && stream_.has_value());
     return **stream_;
   }
 
+  auto current_phase() const -> ProgramPhase { return current_phase_; }
+
   // Outputs a trace message. Requires is_enabled.
   template <typename T>
   auto operator<<(T&& message) const -> llvm::raw_ostream& {
@@ -53,8 +94,10 @@ class TraceStream {
   }
 
  private:
-  std::optional<Nonnull<llvm::raw_ostream*>> stream_;
   bool in_prelude_ = false;
+  std::optional<Nonnull<llvm::raw_ostream*>> stream_;
+  ProgramPhase current_phase_ = ProgramPhase::Unknown;
+  std::bitset<static_cast<int>(ProgramPhase::Last) + 1> allowed_phases_;
 };
 
 }  // namespace Carbon

explorer/file_test.cpp

@@ -47,6 +47,7 @@ class ParseAndExecuteTestFile : public FileTestBase {
     llvm::raw_string_ostream trace_stream_ostream(trace_stream_str);
     if (trace_) {
       trace_stream.set_stream(&trace_stream_ostream);
+      trace_stream.set_allowed_phases({ProgramPhase::All});
     }
 
     // Set the location of the prelude.

explorer/interpreter/BUILD

@@ -63,6 +63,7 @@ cc_library(
         ":resolve_unformed",
         ":type_checker",
         "//common:check",
+        "//common:error",
         "//common:ostream",
         "//explorer/ast",
         "//explorer/common:arena",

explorer/interpreter/exec_program.cpp

@@ -7,8 +7,10 @@
 #include <variant>
 
 #include "common/check.h"
+#include "common/error.h"
 #include "common/ostream.h"
 #include "explorer/common/arena.h"
+#include "explorer/common/trace_stream.h"
 #include "explorer/interpreter/interpreter.h"
 #include "explorer/interpreter/resolve_control_flow.h"
 #include "explorer/interpreter/resolve_names.h"
@@ -21,6 +23,7 @@ namespace Carbon {
 auto AnalyzeProgram(Nonnull<Arena*> arena, AST ast,
                     Nonnull<TraceStream*> trace_stream,
                     Nonnull<llvm::raw_ostream*> print_stream) -> ErrorOr<AST> {
+  trace_stream->set_current_phase(ProgramPhase::SourceProgram);
   if (trace_stream->is_enabled()) {
     *trace_stream << "********** source program **********\n";
     for (int i = ast.num_prelude_declarations;
@@ -28,33 +31,39 @@ auto AnalyzeProgram(Nonnull<Arena*> arena, AST ast,
       *trace_stream << *ast.declarations[i];
     }
   }
+
   SourceLocation source_loc("<Main()>", 0);
   ast.main_call = arena->New<CallExpression>(
       source_loc, arena->New<IdentifierExpression>(source_loc, "Main"),
       arena->New<TupleLiteral>(source_loc));
   // Although name resolution is currently done once, generic programming
   // (particularly templates) may require more passes.
+  trace_stream->set_current_phase(ProgramPhase::NameResolution);
   if (trace_stream->is_enabled()) {
     *trace_stream << "********** resolving names **********\n";
   }
   CARBON_RETURN_IF_ERROR(ResolveNames(ast));
 
+  trace_stream->set_current_phase(ProgramPhase::ControlFlowResolution);
   if (trace_stream->is_enabled()) {
     *trace_stream << "********** resolving control flow **********\n";
   }
   CARBON_RETURN_IF_ERROR(ResolveControlFlow(ast));
 
+  trace_stream->set_current_phase(ProgramPhase::TypeChecking);
   if (trace_stream->is_enabled()) {
     *trace_stream << "********** type checking **********\n";
   }
   CARBON_RETURN_IF_ERROR(
       TypeChecker(arena, trace_stream, print_stream).TypeCheck(ast));
 
+  trace_stream->set_current_phase(ProgramPhase::UnformedVariableResolution);
   if (trace_stream->is_enabled()) {
     *trace_stream << "********** resolving unformed variables **********\n";
   }
   CARBON_RETURN_IF_ERROR(ResolveUnformed(ast));
 
+  trace_stream->set_current_phase(ProgramPhase::Declarations);
   if (trace_stream->is_enabled()) {
     *trace_stream << "********** printing declarations **********\n";
     for (int i = ast.num_prelude_declarations;
@@ -62,16 +71,25 @@ auto AnalyzeProgram(Nonnull<Arena*> arena, AST ast,
       *trace_stream << *ast.declarations[i];
     }
   }
+  trace_stream->set_current_phase(ProgramPhase::Unknown);
   return ast;
 }
 
 auto ExecProgram(Nonnull<Arena*> arena, AST ast,
                  Nonnull<TraceStream*> trace_stream,
                  Nonnull<llvm::raw_ostream*> print_stream) -> ErrorOr<int> {
+  trace_stream->set_current_phase(ProgramPhase::Execution);
   if (trace_stream->is_enabled()) {
     *trace_stream << "********** starting execution **********\n";
   }
-  return InterpProgram(ast, arena, trace_stream, print_stream);
+  CARBON_ASSIGN_OR_RETURN(
+      auto interpreter_result,
+      InterpProgram(ast, arena, trace_stream, print_stream));
+  if (trace_stream->is_enabled()) {
+    *trace_stream << "interpreter result: " << interpreter_result << "\n";
+  }
+  trace_stream->set_current_phase(ProgramPhase::Unknown);
+  return interpreter_result;
 }
 
 }  // namespace Carbon

explorer/lit_testdata/trace.carbon

@@ -3,23 +3,58 @@
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 // A lot of output is elided: this is only checking for a few things for simple
-// sanity checking on --parser_debug --trace_file=- output.
+// sanity checking on --parser_debug --trace_file=- along with filter flags output.
 //
 // NOAUTOUPDATE
-// RUN: %{explorer-run-trace}
-// CHECK:STDOUT: ********** source program **********
-// CHECK-NOT:STDOUT: interface ImplicitAs {
-// CHECK:STDOUT: interface TestInterface {
-// CHECK:STDOUT: ********** type checking **********
-// CHECK:STDOUT: ** declaring interface TestInterface
-// CHECK:STDOUT: ********** resolving unformed variables **********
-// CHECK:STDOUT: ********** printing declarations **********
-// CHECK:STDOUT: interface TestInterface {
-// CHECK:STDOUT: ********** starting execution **********
-// CHECK:STDOUT: ********** initializing globals **********
-// CHECK:STDOUT: ********** calling main function **********
-// CHECK:STDOUT: --- step exp Main() .0. (<Main()>:0) --->
-// CHECK:STDOUT: result: 0
+// RUN: %{explorer-run} --parser_debug --trace_file=- | %{FileCheck-allow-unmatched} --check-prefixes=NO-SOURCE,NO-NAMES,NO-PRELUDE,NO-FLOW,NO-TYPE,NO-UNFORMED,NO-DECLS,EXEC,NO-TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_execution | %{FileCheck-allow-unmatched} --check-prefixes=NO-SOURCE,NO-NAMES,NO-PRELUDE,NO-FLOW,NO-TYPE,NO-UNFORMED,NO-DECLS,EXEC,NO-TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_source_program | %{FileCheck-allow-unmatched} --check-prefixes=SOURCE,NO-NAMES,NO-PRELUDE,NO-FLOW,NO-TYPE,NO-UNFORMED,NO-DECLS,NO-EXEC,NO-TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_name_resolution | %{FileCheck-allow-unmatched} --check-prefixes=NO-SOURCE,NAMES,NO-PRELUDE,NO-FLOW,NO-TYPE,NO-UNFORMED,NO-DECLS,NO-EXEC,NO-TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_control_flow_resolution | %{FileCheck-allow-unmatched} --check-prefixes=NO-SOURCE,NO-NAMES,NO-PRELUDE,FLOW,NO-TYPE,NO-UNFORMED,NO-DECLS,NO-EXEC,NO-TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_type_checking | %{FileCheck-allow-unmatched} --check-prefixes=NO-SOURCE,NO-NAMES,NO-PRELUDE,NO-FLOW,TYPE,NO-UNFORMED,NO-DECLS,NO-EXEC,NO-TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_unformed_variables_resolution | %{FileCheck-allow-unmatched} --check-prefixes=NO-SOURCE,NO-NAMES,NO-PRELUDE,NO-FLOW,NO-TYPE,UNFORMED,NO-DECLS,NO-EXEC,NO-TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_declarations | %{FileCheck-allow-unmatched} --check-prefixes=NO-SOURCE,NO-NAMES,NO-PRELUDE,NO-FLOW,NO-TYPE,NO-UNFORMED,DECLS,NO-EXEC,NO-TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_timing | %{FileCheck-allow-unmatched} --check-prefixes=NO-SOURCE,NO-NAMES,NO-PRELUDE,NO-FLOW,NO-TYPE,NO-UNFORMED,NO-DECLS,NO-EXEC,TIMING
+// RUN: %{explorer-run} --parser_debug --trace_file=- -trace_all | %{FileCheck-allow-unmatched} --check-prefixes=SOURCE,NAMES,NO-PRELUDE,FLOW,TYPE,UNFORMED,DECLS,EXEC,TIMING
+// NO-SOURCE-NOT:STDOUT: ********** source program **********
+//        SOURCE:STDOUT: ********** source program **********
+// NO-SOURCE-NOT:STDOUT: interface TestInterface {
+//        SOURCE:STDOUT: interface TestInterface {
+// NO-NAMES-NOT:STDOUT: ********** resolving names **********
+//        NAMES:STDOUT: ********** resolving names **********
+// NO-PRELUDE-NOT:STDOUT: interface ImplicitAs {
+// NO-FLOW-NOT:STDOUT: ********** resolving control flow **********
+//        FLOW:STDOUT: ********** resolving control flow **********
+// NO-TYPE-NOT:STDOUT: ********** type checking **********
+//        TYPE:STDOUT: ********** type checking **********
+// NO-TYPE-NOT:STDOUT: ** declaring interface TestInterface
+//        TYPE:STDOUT: ** declaring interface TestInterface
+// NO-UNFORMED-NOT:STDOUT: ********** resolving unformed variables **********
+//        UNFORMED:STDOUT: ********** resolving unformed variables **********
+// NO-DECLS-NOT:STDOUT: ********** printing declarations **********
+//        DECLS:STDOUT: ********** printing declarations **********
+// NO-DECLS-NOT:STDOUT: interface TestInterface {
+//        DECLS:STDOUT: interface TestInterface {
+// NO-EXEC-NOT:STDOUT: ********** starting execution **********
+//        EXEC:STDOUT: ********** starting execution **********
+// NO-EXEC-NOT:STDOUT: ********** initializing globals **********
+//        EXEC:STDOUT: ********** initializing globals **********
+// NO-EXEC-NOT:STDOUT: ********** calling main function **********
+//        EXEC:STDOUT: ********** calling main function **********
+// NO-EXEC-NOT:STDOUT: --- step exp Main() .0. (<Main()>:0) --->
+//        EXEC:STDOUT: --- step exp Main() .0. (<Main()>:0) --->
+// NO-EXEC-NOT:STDOUT: interpreter result: 0
+//        EXEC:STDOUT: interpreter result: 0
+// NO-TIMING-NOT:STDOUT: ********** printing timing **********
+//        TIMING:STDOUT: ********** printing timing **********
+// NO-TIMING-NOT:STDOUT: Time elapsed in ExecProgram: {{[0-9]+}}ms
+//        TIMING:STDOUT: Time elapsed in ExecProgram: {{[0-9]+}}ms
+// NO-TIMING-NOT:STDOUT: Time elapsed in AnalyzeProgram: {{[0-9]+}}ms
+//        TIMING:STDOUT: Time elapsed in AnalyzeProgram: {{[0-9]+}}ms
+// NO-TIMING-NOT:STDOUT: Time elapsed in AddPrelude: {{[0-9]+}}ms
+//        TIMING:STDOUT: Time elapsed in AddPrelude: {{[0-9]+}}ms
+// NO-TIMING-NOT:STDOUT: Time elapsed in Parse: {{[0-9]+}}ms
+//        TIMING:STDOUT: Time elapsed in Parse: {{[0-9]+}}ms
 
 package ExplorerTest api;
 

explorer/main.cpp

@@ -32,6 +32,7 @@ namespace path = llvm::sys::path;
 auto ExplorerMain(int argc, char** argv, void* static_for_main_addr,
                   llvm::StringRef relative_prelude_path) -> int {
   llvm::setBugReportMsg(
+
       "Please report issues to "
       "https://github.com/carbon-language/carbon-lang/issues and include the "
       "crash backtrace.\n");
@@ -49,6 +50,36 @@ auto ExplorerMain(int argc, char** argv, void* static_for_main_addr,
       "trace_file",
       cl::desc("Output file for tracing; set to `-` to output to stdout."));
 
+  cl::list<ProgramPhase> allowed_program_phases(
+      cl::desc("Select the program phases to include in the output. By "
+               "default, only the execution trace will be added to the trace "
+               "output. Use a combination of the following flags to include "
+               "outputs for multiple phases:"),
+      cl::values(
+          clEnumValN(ProgramPhase::SourceProgram, "trace_source_program",
+                     "Include trace output for the Source Program phase."),
+          clEnumValN(ProgramPhase::NameResolution, "trace_name_resolution",
+                     "Include trace output for the Name Resolution phase."),
+          clEnumValN(
+              ProgramPhase::ControlFlowResolution,
+              "trace_control_flow_resolution",
+              "Include trace output for the Control Flow Resolution phase."),
+          clEnumValN(ProgramPhase::TypeChecking, "trace_type_checking",
+                     "Include trace output for the Type Checking phase."),
+          clEnumValN(ProgramPhase::UnformedVariableResolution,
+                     "trace_unformed_variables_resolution",
+                     "Include trace output for the Unformed Variables "
+                     "Resolution phase."),
+          clEnumValN(ProgramPhase::Declarations, "trace_declarations",
+                     "Include trace output for printing Declarations."),
+          clEnumValN(ProgramPhase::Execution, "trace_execution",
+                     "Include trace output for Program Execution."),
+          clEnumValN(
+              ProgramPhase::Timing, "trace_timing",
+              "Include timing logs for each phase, indicating the time taken."),
+          clEnumValN(ProgramPhase::All, "trace_all",
+                     "Include trace output for all phases.")));
+
   // Use the executable path as a base for the relative prelude path.
   std::string exe =
       llvm::sys::fs::getMainExecutable(argv[0], static_for_main_addr);
@@ -66,7 +97,10 @@ auto ExplorerMain(int argc, char** argv, void* static_for_main_addr,
   // Set up a stream for trace output.
   std::unique_ptr<llvm::raw_ostream> scoped_trace_stream;
   TraceStream trace_stream;
+
   if (!trace_file_name.empty()) {
+    // Adding allowed phases in the trace_stream
+    trace_stream.set_allowed_phases(allowed_program_phases);
     if (trace_file_name == "-") {
       trace_stream.set_stream(&llvm::outs());
     } else {
@@ -87,11 +121,6 @@ auto ExplorerMain(int argc, char** argv, void* static_for_main_addr,
   if (result.ok()) {
     // Print the return code to stdout.
     llvm::outs() << "result: " << *result << "\n";
-
-    // When there's a dedicated trace file, print the return code to it too.
-    if (scoped_trace_stream) {
-      trace_stream << "result: " << *result << "\n";
-    }
     return EXIT_SUCCESS;
   } else {
     llvm::errs() << result.error() << "\n";

explorer/parse_and_execute/parse_and_execute.cpp

@@ -23,16 +23,18 @@ static auto PrintTimingOnExit(TraceStream* trace_stream, const char* label,
   auto end = std::chrono::steady_clock::now();
   auto duration = end - *cursor;
   *cursor = end;
-
-  return llvm::make_scope_exit([=]() {
+  auto exit_scope_function = llvm::make_scope_exit([=]() {
+    trace_stream->set_current_phase(ProgramPhase::Timing);
     if (trace_stream->is_enabled()) {
       *trace_stream << "Time elapsed in " << label << ": "
                     << std::chrono::duration_cast<std::chrono::milliseconds>(
                            duration)
                            .count()
                     << "ms\n";
+      trace_stream->set_current_phase(ProgramPhase::Unknown);
     }
   });
+  return exit_scope_function;
 }
 
 static auto ParseAndExecuteHelper(std::function<ErrorOr<AST>(Arena*)> parse,
@@ -65,13 +67,25 @@ static auto ParseAndExecuteHelper(std::function<ErrorOr<AST>(Arena*)> parse,
     }
 
     // Run the program.
+    trace_stream->set_current_phase(ProgramPhase::Execution);
     ErrorOr<int> exec_result =
         ExecProgram(&arena, *analyze_result, trace_stream, print_stream);
     auto print_exec_time =
         PrintTimingOnExit(trace_stream, "ExecProgram", &cursor);
+
     if (!exec_result.ok()) {
       return ErrorBuilder() << "RUNTIME ERROR: " << exec_result.error();
     }
+    trace_stream->set_current_phase(ProgramPhase::Unknown);
+
+    auto print_trace_timing_heading = llvm::make_scope_exit([=]() {
+      trace_stream->set_current_phase(ProgramPhase::Timing);
+      if (trace_stream->is_enabled()) {
+        *trace_stream << "********** printing timing **********\n";
+      }
+      trace_stream->set_current_phase(ProgramPhase::Unknown);
+    });
+
     return exec_result;
   });
 }

testing/lit_test/lit.cfg.py

@@ -61,10 +61,7 @@ def add_substitutions():
     add_substitution(
         "carbon-run-tokens", f"{run_carbon} dump tokens %s | {filecheck_strict}"
     )
-    add_substitution(
-        "explorer-run",
-        f"{run_explorer} | {filecheck_strict}",
-    )
+    add_substitution("explorer-run", f"{run_explorer}")
     add_substitution(
         "explorer-run-trace",
         f"{run_explorer} --parser_debug --trace_file=- | "