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=- | "