From 04d9a7b53394f92d3df569f8ff4d0fcce12507d6 Mon Sep 17 00:00:00 2001 From: Prabhat Sachdeva Date: Thu, 8 Jun 2023 23:19:13 +0530 Subject: [PATCH] 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 --- explorer/README.md | 20 ++++++ explorer/common/trace_stream.h | 49 +++++++++++++- explorer/file_test.cpp | 1 + explorer/interpreter/BUILD | 1 + explorer/interpreter/exec_program.cpp | 20 +++++- explorer/lit_testdata/trace.carbon | 65 ++++++++++++++----- explorer/main.cpp | 39 +++++++++-- .../parse_and_execute/parse_and_execute.cpp | 18 ++++- testing/lit_test/lit.cfg.py | 5 +- 9 files changed, 188 insertions(+), 30 deletions(-) diff --git a/explorer/README.md b/explorer/README.md index c5eaf0ecf34f..a042b2020dff 100644 --- a/explorer/README.md +++ b/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 diff --git a/explorer/common/trace_stream.h b/explorer/common/trace_stream.h index 330c38ca91d4..ffa24a6dee78 100644 --- a/explorer/common/trace_stream.h +++ b/explorer/common/trace_stream.h @@ -5,8 +5,10 @@ #ifndef CARBON_EXPLORER_COMMON_TRACE_STREAM_H_ #define CARBON_EXPLORER_COMMON_TRACE_STREAM_H_ +#include #include #include +#include #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(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 allowed_phases_list) { + if (allowed_phases_list.empty()) { + allowed_phases_.set(static_cast(ProgramPhase::Execution)); + } else { + for (auto phase : allowed_phases_list) { + if (phase == ProgramPhase::All) { + allowed_phases_.set(); + } else { + allowed_phases_.set(static_cast(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 auto operator<<(T&& message) const -> llvm::raw_ostream& { @@ -53,8 +94,10 @@ class TraceStream { } private: - std::optional> stream_; bool in_prelude_ = false; + std::optional> stream_; + ProgramPhase current_phase_ = ProgramPhase::Unknown; + std::bitset(ProgramPhase::Last) + 1> allowed_phases_; }; } // namespace Carbon diff --git a/explorer/file_test.cpp b/explorer/file_test.cpp index 9aced92ee1a0..46a1b7f7b318 100644 --- a/explorer/file_test.cpp +++ b/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. diff --git a/explorer/interpreter/BUILD b/explorer/interpreter/BUILD index 83e52485c586..74b868178272 100644 --- a/explorer/interpreter/BUILD +++ b/explorer/interpreter/BUILD @@ -63,6 +63,7 @@ cc_library( ":resolve_unformed", ":type_checker", "//common:check", + "//common:error", "//common:ostream", "//explorer/ast", "//explorer/common:arena", diff --git a/explorer/interpreter/exec_program.cpp b/explorer/interpreter/exec_program.cpp index 7ec5b00bf2d0..2e2d47757071 100644 --- a/explorer/interpreter/exec_program.cpp +++ b/explorer/interpreter/exec_program.cpp @@ -7,8 +7,10 @@ #include #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, AST ast, Nonnull trace_stream, Nonnull print_stream) -> ErrorOr { + 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, AST ast, *trace_stream << *ast.declarations[i]; } } + SourceLocation source_loc("", 0); ast.main_call = arena->New( source_loc, arena->New(source_loc, "Main"), arena->New(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, AST ast, *trace_stream << *ast.declarations[i]; } } + trace_stream->set_current_phase(ProgramPhase::Unknown); return ast; } auto ExecProgram(Nonnull arena, AST ast, Nonnull trace_stream, Nonnull print_stream) -> ErrorOr { + 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 diff --git a/explorer/lit_testdata/trace.carbon b/explorer/lit_testdata/trace.carbon index c95abf1946ee..7097d9d48730 100644 --- a/explorer/lit_testdata/trace.carbon +++ b/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. (: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. (:0) ---> +// EXEC:STDOUT: --- step exp Main() .0. (: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; diff --git a/explorer/main.cpp b/explorer/main.cpp index 2ca8fe012ac7..77b95a20e895 100644 --- a/explorer/main.cpp +++ b/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 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 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"; diff --git a/explorer/parse_and_execute/parse_and_execute.cpp b/explorer/parse_and_execute/parse_and_execute.cpp index 06f52d40b9a0..52a474152580 100644 --- a/explorer/parse_and_execute/parse_and_execute.cpp +++ b/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( duration) .count() << "ms\n"; + trace_stream->set_current_phase(ProgramPhase::Unknown); } }); + return exit_scope_function; } static auto ParseAndExecuteHelper(std::function(Arena*)> parse, @@ -65,13 +67,25 @@ static auto ParseAndExecuteHelper(std::function(Arena*)> parse, } // Run the program. + trace_stream->set_current_phase(ProgramPhase::Execution); ErrorOr 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; }); } diff --git a/testing/lit_test/lit.cfg.py b/testing/lit_test/lit.cfg.py index 3661487652cf..067e59ba14f8 100644 --- a/testing/lit_test/lit.cfg.py +++ b/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=- | "