diff --git a/explorer/base/trace_stream.h b/explorer/base/trace_stream.h index 515ab7b15518..6830c814f889 100644 --- a/explorer/base/trace_stream.h +++ b/explorer/base/trace_stream.h @@ -24,7 +24,6 @@ class TraceStream; // 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. @@ -33,6 +32,7 @@ enum class ProgramPhase { Declarations, // Phase for printing declarations. Execution, // Phase for program execution. Timing, // Phase for timing logs. + Unknown, // Represents an unknown program phase. All, // Represents all program phases. Last = All // Last program phase indicator. }; @@ -101,10 +101,22 @@ class TraceStream { auto current_phase() const -> ProgramPhase { return current_phase_; } + auto add_blank_lines(int num_blank_lines) const -> void { + CARBON_CHECK(is_enabled() && stream_); + if (!is_trace_empty_) { + for (int i = 0; i < num_blank_lines; ++i) { + **stream_ << "\n"; + } + } + } + // Outputs a trace message. Requires is_enabled. template auto operator<<(T&& message) const -> llvm::raw_ostream& { CARBON_CHECK(is_enabled() && stream_); + if (is_trace_empty_) { + is_trace_empty_ = false; + } **stream_ << message; return **stream_; } @@ -127,27 +139,33 @@ class TraceStream { auto Pop() const -> llvm::raw_ostream& { return *this << "<[] "; } auto Not() const -> llvm::raw_ostream& { return *this << "-!- "; } auto Skip() const -> llvm::raw_ostream& { return *this << ">>> "; } - auto Source() const -> llvm::raw_ostream& { return *this << "*** "; } + auto Source() const -> llvm::raw_ostream& { + // add a blank line before prefix. + add_blank_lines(1); + return *this << "*** "; + } // Format utility methods void Heading(std::string_view heading) const { - CARBON_CHECK(is_enabled() && stream_); + add_blank_lines(2); const std::string_view stars = "* * * * * * * * * *"; const std::string dashed_line(stars.size() * 2 + heading.size() + 4, '-'); - **stream_ << stars << " " << heading << " " << stars << "\n" - << dashed_line << "\n"; + *this << stars << " " << heading << " " << stars << "\n" + << dashed_line << "\n"; } - void SubHeading(std::string_view heading) const { - CARBON_CHECK(is_enabled() && stream_); + void SubHeading(std::string_view sub_heading) const { + add_blank_lines(1); const std::string_view dashes = "- - - - -"; - const std::string dashed_line(dashes.size() * 2 + heading.size() + 4, '-'); - **stream_ << dashes << " " << heading << " " << dashes << "\n" - << dashed_line << "\n"; + const std::string dashed_line(dashes.size() * 2 + sub_heading.size() + 4, + '-'); + *this << dashes << " " << sub_heading << " " << dashes << "\n" + << dashed_line << "\n"; } private: bool in_prelude_ = false; + mutable bool is_trace_empty_ = true; ProgramPhase current_phase_ = ProgramPhase::Unknown; std::optional source_loc_ = std::nullopt; std::optional> stream_; diff --git a/explorer/interpreter/type_checker.cpp b/explorer/interpreter/type_checker.cpp index fac635065b12..c5fa1f4912a7 100644 --- a/explorer/interpreter/type_checker.cpp +++ b/explorer/interpreter/type_checker.cpp @@ -2378,7 +2378,6 @@ auto TypeChecker::MatchImpl(const InterfaceType& iface, MatchingImplSet::Match match(&matching_impl_set_, &impl, impl_type, &iface); if (trace_stream_->is_enabled()) { - *trace_stream_ << "\n"; trace_stream_->SubHeading("match impl"); trace_stream_->Start() << "looking for `" << *impl_type << "` as `" << iface << "`\n"; diff --git a/explorer/testdata/trace/context_main.carbon b/explorer/testdata/trace/context_main.carbon index a58ee288c07a..34f44a50029f 100644 --- a/explorer/testdata/trace/context_main.carbon +++ b/explorer/testdata/trace/context_main.carbon @@ -25,6 +25,8 @@ fn Main() -> i32 { // CHECK:STDOUT: } // CHECK:STDOUT: // CHECK:STDOUT: } +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * resolving names * * * * * * * * * * // CHECK:STDOUT: --------------------------------------------------------- // CHECK:STDOUT: ==> declared `TestInterface` as `interface TestInterface` in `package` (context_main.carbon:7) @@ -43,11 +45,16 @@ fn Main() -> i32 { // CHECK:STDOUT: <<- finished resolving stmt `{return 0;}` (context_main.carbon:11) // CHECK:STDOUT: <<- finished resolving decl `fn Main` (context_main.carbon:11) // CHECK:STDOUT: ==> resolved `Main` as `fn Main` in `package` (:0) +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * resolving control flow * * * * * * * * * * // CHECK:STDOUT: ---------------------------------------------------------------- // CHECK:STDOUT: ==> flow-resolved return statement `return 0;` in `fn Main` (context_main.carbon:10) +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * type checking * * * * * * * * * * // CHECK:STDOUT: ------------------------------------------------------- +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (context_main.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: interface TestInterface { @@ -56,6 +63,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: ->> declaring `interface TestInterface` (context_main.carbon:7) // CHECK:STDOUT: <<- finished declaring `interface TestInterface` (context_main.carbon:7) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking declaration at (context_main.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: interface TestInterface { @@ -114,6 +122,7 @@ fn Main() -> i32 { // CHECK:STDOUT: `T` as `interface LeftShiftAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface RightShiftAssignWith(U = U)` [0; 1, 1, 0]] // CHECK:STDOUT: <<- finished checking `interface TestInterface` (context_main.carbon:7) +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (context_main.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -135,6 +144,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `i32` results: [`i32`] (context_main.carbon:9) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `i32` results: [`i32`] (context_main.carbon:9) // CHECK:STDOUT: ->> finished declaring function `Main` of type `fn () -> i32` (context_main.carbon:11) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking declaration at (context_main.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -196,6 +206,7 @@ fn Main() -> i32 { // CHECK:STDOUT: `T` as `interface BitXorAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface LeftShiftAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface RightShiftAssignWith(U = U)` [0; 1, 1, 0]] +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (context_main.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -204,6 +215,7 @@ fn Main() -> i32 { // CHECK:STDOUT: // CHECK:STDOUT: ``` // CHECK:STDOUT: ->> checking Block `{return 0;}` (context_main.carbon:11) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (context_main.carbon:10) // CHECK:STDOUT: ``` // CHECK:STDOUT: return 0; @@ -217,12 +229,16 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> checking call to function of type `fn () -> i32` with arguments of type `()` (:0) // CHECK:STDOUT: ->> performing argument deduction for bindings: [] // CHECK:STDOUT: ==> deduction succeeded with results: [] +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * resolving unformed variables * * * * * * * * * * // CHECK:STDOUT: ---------------------------------------------------------------------- // CHECK:STDOUT: ->> resolving-unformed in decl `interface TestInterface` (context_main.carbon:7) // CHECK:STDOUT: ->> resolving-unformed in decl `fn Main` (context_main.carbon:11) // CHECK:STDOUT: ->> resolving-unformed in stmt `{return 0;}` (context_main.carbon:11) // CHECK:STDOUT: ->> resolving-unformed in stmt `return 0;` (context_main.carbon:10) +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * printing declarations * * * * * * * * * * // CHECK:STDOUT: --------------------------------------------------------------- // CHECK:STDOUT: interface TestInterface { @@ -233,12 +249,16 @@ fn Main() -> i32 { // CHECK:STDOUT: } // CHECK:STDOUT: // CHECK:STDOUT: } +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * starting execution * * * * * * * * * * // CHECK:STDOUT: ------------------------------------------------------------ +// CHECK:STDOUT: // CHECK:STDOUT: - - - - - initializing globals - - - - - // CHECK:STDOUT: ------------------------------------------ // CHECK:STDOUT: >[] stack-push: DeclarationAction pos: 0 `interface TestInterface` (context_main.carbon:7) // CHECK:STDOUT: ->> step DeclarationAction pos: 0 `interface TestInterface` (context_main.carbon:7) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (context_main.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: interface TestInterface { @@ -247,6 +267,7 @@ fn Main() -> i32 { // CHECK:STDOUT: <[] stack-pop: DeclarationAction pos: 0 `interface TestInterface` (context_main.carbon:7) // CHECK:STDOUT: >[] stack-push: DeclarationAction pos: 0 `fn Main` (context_main.carbon:11) // CHECK:STDOUT: ->> step DeclarationAction pos: 0 `fn Main` (context_main.carbon:11) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (context_main.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -257,6 +278,7 @@ fn Main() -> i32 { // CHECK:STDOUT: } // CHECK:STDOUT: ``` // CHECK:STDOUT: <[] stack-pop: DeclarationAction pos: 0 `fn Main` (context_main.carbon:11) +// CHECK:STDOUT: // CHECK:STDOUT: - - - - - calling main function - - - - - // CHECK:STDOUT: ------------------------------------------- // CHECK:STDOUT: >[] stack-push: ValueExpressionAction pos: 0 `Main()` (:0) @@ -277,6 +299,7 @@ fn Main() -> i32 { // CHECK:STDOUT: >[] stack-push: ScopeAction pos: 0 scope: [] (None) // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `{return 0;}` (context_main.carbon:11) // CHECK:STDOUT: ->> step StatementAction pos: 0 `{return 0;}` (context_main.carbon:11) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (context_main.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -286,6 +309,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `return 0;` (context_main.carbon:10) // CHECK:STDOUT: ->> step StatementAction pos: 0 `return 0;` (context_main.carbon:10) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (context_main.carbon:10) // CHECK:STDOUT: ``` // CHECK:STDOUT: return 0; @@ -298,6 +322,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `0` results: [`0`] (context_main.carbon:10) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `0` results: [`0`] (context_main.carbon:10) // CHECK:STDOUT: ->> step StatementAction pos: 1 `return 0;` results: [`0`] (context_main.carbon:10) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (context_main.carbon:10) // CHECK:STDOUT: ``` // CHECK:STDOUT: return 0; @@ -319,6 +344,8 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `Main()` results: [`0`] (:0) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `Main()` results: [`0`] (:0) // CHECK:STDOUT: ==> interpreter result: 0 +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * printing timing * * * * * * * * * * // CHECK:STDOUT: --------------------------------------------------------- // CHECK:STDOUT: Time elapsed in ExecProgram: {{\d+}}ms diff --git a/explorer/testdata/trace/phase_all.carbon b/explorer/testdata/trace/phase_all.carbon index ceca5c6b3be9..e60d6f0b764c 100644 --- a/explorer/testdata/trace/phase_all.carbon +++ b/explorer/testdata/trace/phase_all.carbon @@ -39,6 +39,8 @@ fn Main() -> i32 { // CHECK:STDOUT: } // CHECK:STDOUT: // CHECK:STDOUT: } +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * resolving names * * * * * * * * * * // CHECK:STDOUT: --------------------------------------------------------- // CHECK:STDOUT: ==> declared `TestInterface` as `interface TestInterface` in `package` (phase_all.carbon:7) @@ -80,12 +82,17 @@ fn Main() -> i32 { // CHECK:STDOUT: <<- finished resolving stmt `{var x: i32 = N.Foo(0);return x;}` (phase_all.carbon:18) // CHECK:STDOUT: <<- finished resolving decl `fn Main` (phase_all.carbon:18) // CHECK:STDOUT: ==> resolved `Main` as `fn Main` in `package` (:0) +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * resolving control flow * * * * * * * * * * // CHECK:STDOUT: ---------------------------------------------------------------- // CHECK:STDOUT: ==> flow-resolved return statement `return (n + 1);` in `fn N.Foo` (phase_all.carbon:12) // CHECK:STDOUT: ==> flow-resolved return statement `return x;` in `fn Main` (phase_all.carbon:17) +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * type checking * * * * * * * * * * // CHECK:STDOUT: ------------------------------------------------------- +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_all.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: interface TestInterface { @@ -94,6 +101,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: ->> declaring `interface TestInterface` (phase_all.carbon:7) // CHECK:STDOUT: <<- finished declaring `interface TestInterface` (phase_all.carbon:7) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking declaration at (phase_all.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: interface TestInterface { @@ -152,15 +160,18 @@ fn Main() -> i32 { // CHECK:STDOUT: `T` as `interface LeftShiftAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface RightShiftAssignWith(U = U)` [0; 1, 1, 0]] // CHECK:STDOUT: <<- finished checking `interface TestInterface` (phase_all.carbon:7) +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_all.carbon:9) // CHECK:STDOUT: ``` // CHECK:STDOUT: namespace N; // CHECK:STDOUT: ``` +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking declaration at (phase_all.carbon:9) // CHECK:STDOUT: ``` // CHECK:STDOUT: namespace N; // CHECK:STDOUT: ``` // CHECK:STDOUT: ->> checking NamespaceDeclaration `namespace N` (phase_all.carbon:9) +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_all.carbon:13) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Foo (n: i32)-> i32 { @@ -193,6 +204,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `i32` results: [`i32`] (phase_all.carbon:11) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `i32` results: [`i32`] (phase_all.carbon:11) // CHECK:STDOUT: ->> finished declaring function `Foo` of type `fn (i32,) -> i32` (phase_all.carbon:13) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking declaration at (phase_all.carbon:13) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Foo (n: i32)-> i32 { @@ -254,6 +266,7 @@ fn Main() -> i32 { // CHECK:STDOUT: `T` as `interface BitXorAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface LeftShiftAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface RightShiftAssignWith(U = U)` [0; 1, 1, 0]] +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (phase_all.carbon:13) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -262,6 +275,7 @@ fn Main() -> i32 { // CHECK:STDOUT: // CHECK:STDOUT: ``` // CHECK:STDOUT: ->> checking Block `{return (n + 1);}` (phase_all.carbon:13) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (phase_all.carbon:12) // CHECK:STDOUT: ``` // CHECK:STDOUT: return (n + 1); @@ -271,6 +285,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> checking IdentifierExpression `n` (phase_all.carbon:12) // CHECK:STDOUT: ->> checking IntLiteral `1` (phase_all.carbon:12) // CHECK:STDOUT: ->> finished checking function `Foo` (phase_all.carbon:13) +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_all.carbon:18) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -293,6 +308,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `i32` results: [`i32`] (phase_all.carbon:15) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `i32` results: [`i32`] (phase_all.carbon:15) // CHECK:STDOUT: ->> finished declaring function `Main` of type `fn () -> i32` (phase_all.carbon:18) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking declaration at (phase_all.carbon:18) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -355,6 +371,7 @@ fn Main() -> i32 { // CHECK:STDOUT: `T` as `interface BitXorAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface LeftShiftAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface RightShiftAssignWith(U = U)` [0; 1, 1, 0]] +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (phase_all.carbon:18) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -364,6 +381,7 @@ fn Main() -> i32 { // CHECK:STDOUT: // CHECK:STDOUT: ``` // CHECK:STDOUT: ->> checking Block `{var x: i32 = N.Foo(0);return x;}` (phase_all.carbon:18) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (phase_all.carbon:16) // CHECK:STDOUT: ``` // CHECK:STDOUT: var x: i32 = N.Foo(0); @@ -388,6 +406,7 @@ fn Main() -> i32 { // CHECK:STDOUT: <[] stack-pop: ExpressionAction pos: 0 `i32` (phase_all.carbon:16) // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `i32` results: [`i32`] (phase_all.carbon:16) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `i32` results: [`i32`] (phase_all.carbon:16) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (phase_all.carbon:17) // CHECK:STDOUT: ``` // CHECK:STDOUT: return x; @@ -401,6 +420,8 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> checking call to function of type `fn () -> i32` with arguments of type `()` (:0) // CHECK:STDOUT: ->> performing argument deduction for bindings: [] // CHECK:STDOUT: ==> deduction succeeded with results: [] +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * resolving unformed variables * * * * * * * * * * // CHECK:STDOUT: ---------------------------------------------------------------------- // CHECK:STDOUT: ->> resolving-unformed in decl `interface TestInterface` (phase_all.carbon:7) @@ -415,6 +436,8 @@ fn Main() -> i32 { // CHECK:STDOUT: ==> add init `x` (phase_all.carbon:16) // CHECK:STDOUT: ->> resolving-unformed in stmt `return x;` (phase_all.carbon:17) // CHECK:STDOUT: ==> check `x` (phase_all.carbon:17) +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * printing declarations * * * * * * * * * * // CHECK:STDOUT: --------------------------------------------------------------- // CHECK:STDOUT: interface TestInterface { @@ -432,12 +455,16 @@ fn Main() -> i32 { // CHECK:STDOUT: } // CHECK:STDOUT: // CHECK:STDOUT: } +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * starting execution * * * * * * * * * * // CHECK:STDOUT: ------------------------------------------------------------ +// CHECK:STDOUT: // CHECK:STDOUT: - - - - - initializing globals - - - - - // CHECK:STDOUT: ------------------------------------------ // CHECK:STDOUT: >[] stack-push: DeclarationAction pos: 0 `interface TestInterface` (phase_all.carbon:7) // CHECK:STDOUT: ->> step DeclarationAction pos: 0 `interface TestInterface` (phase_all.carbon:7) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_all.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: interface TestInterface { @@ -446,12 +473,14 @@ fn Main() -> i32 { // CHECK:STDOUT: <[] stack-pop: DeclarationAction pos: 0 `interface TestInterface` (phase_all.carbon:7) // CHECK:STDOUT: >[] stack-push: DeclarationAction pos: 0 `namespace N` (phase_all.carbon:9) // CHECK:STDOUT: ->> step DeclarationAction pos: 0 `namespace N` (phase_all.carbon:9) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_all.carbon:9) // CHECK:STDOUT: ``` // CHECK:STDOUT: namespace N;``` // CHECK:STDOUT: <[] stack-pop: DeclarationAction pos: 0 `namespace N` (phase_all.carbon:9) // CHECK:STDOUT: >[] stack-push: DeclarationAction pos: 0 `fn N.Foo` (phase_all.carbon:13) // CHECK:STDOUT: ->> step DeclarationAction pos: 0 `fn N.Foo` (phase_all.carbon:13) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_all.carbon:13) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Foo (n: i32)-> i32 { @@ -464,6 +493,7 @@ fn Main() -> i32 { // CHECK:STDOUT: <[] stack-pop: DeclarationAction pos: 0 `fn N.Foo` (phase_all.carbon:13) // CHECK:STDOUT: >[] stack-push: DeclarationAction pos: 0 `fn Main` (phase_all.carbon:18) // CHECK:STDOUT: ->> step DeclarationAction pos: 0 `fn Main` (phase_all.carbon:18) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_all.carbon:18) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -475,6 +505,7 @@ fn Main() -> i32 { // CHECK:STDOUT: } // CHECK:STDOUT: ``` // CHECK:STDOUT: <[] stack-pop: DeclarationAction pos: 0 `fn Main` (phase_all.carbon:18) +// CHECK:STDOUT: // CHECK:STDOUT: - - - - - calling main function - - - - - // CHECK:STDOUT: ------------------------------------------- // CHECK:STDOUT: >[] stack-push: ValueExpressionAction pos: 0 `Main()` (:0) @@ -495,6 +526,7 @@ fn Main() -> i32 { // CHECK:STDOUT: >[] stack-push: ScopeAction pos: 0 scope: [] (None) // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `{var x: i32 = N.Foo(0);return x;}` (phase_all.carbon:18) // CHECK:STDOUT: ->> step StatementAction pos: 0 `{var x: i32 = N.Foo(0);return x;}` (phase_all.carbon:18) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:18) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -505,6 +537,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `var x: i32 = N.Foo(0);` (phase_all.carbon:16) // CHECK:STDOUT: ->> step StatementAction pos: 0 `var x: i32 = N.Foo(0);` (phase_all.carbon:16) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:16) // CHECK:STDOUT: ``` // CHECK:STDOUT: var x: i32 = N.Foo(0); @@ -535,6 +568,7 @@ fn Main() -> i32 { // CHECK:STDOUT: >[] stack-push: ScopeAction pos: 0 scope: [`n: i32`: `0`] (None) // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `{return (n + 1);}` (phase_all.carbon:13) // CHECK:STDOUT: ->> step StatementAction pos: 0 `{return (n + 1);}` (phase_all.carbon:13) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:13) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -544,6 +578,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `return (n + 1);` (phase_all.carbon:12) // CHECK:STDOUT: ->> step StatementAction pos: 0 `return (n + 1);` (phase_all.carbon:12) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:12) // CHECK:STDOUT: ``` // CHECK:STDOUT: return (n + 1); @@ -572,6 +607,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `(n + 1)` results: [`1`] (phase_all.carbon:12) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `(n + 1)` results: [`1`] (phase_all.carbon:12) // CHECK:STDOUT: ->> step StatementAction pos: 1 `return (n + 1);` results: [`1`] (phase_all.carbon:12) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:12) // CHECK:STDOUT: ``` // CHECK:STDOUT: return (n + 1); @@ -592,6 +628,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step CleanUpAction pos: 0 scope: [] (stack cleanup:1) ---> // CHECK:STDOUT: <[] stack-pop: CleanUpAction pos: 0 scope: [] (stack cleanup:1) // CHECK:STDOUT: ->> step StatementAction pos: 1 `var x: i32 = N.Foo(0);` results: [`1`] (phase_all.carbon:16) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:16) // CHECK:STDOUT: ``` // CHECK:STDOUT: var x: i32 = N.Foo(0); @@ -601,6 +638,7 @@ fn Main() -> i32 { // CHECK:STDOUT: from initializing expression with value `1` // CHECK:STDOUT: <[] stack-pop: StatementAction pos: 1 `var x: i32 = N.Foo(0);` results: [`1`] (phase_all.carbon:16) // CHECK:STDOUT: ->> step StatementAction pos: 1 `{var x: i32 = N.Foo(0);return x;}` scope: [`x: i32`: `lval`] (phase_all.carbon:18) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:18) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -611,6 +649,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `return x;` (phase_all.carbon:17) // CHECK:STDOUT: ->> step StatementAction pos: 0 `return x;` (phase_all.carbon:17) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:17) // CHECK:STDOUT: ``` // CHECK:STDOUT: return x; @@ -624,6 +663,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `x` results: [`ref_expr`] (phase_all.carbon:17) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `x` results: [`ref_expr`] (phase_all.carbon:17) // CHECK:STDOUT: ->> step StatementAction pos: 1 `return x;` results: [`1`] (phase_all.carbon:17) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_all.carbon:17) // CHECK:STDOUT: ``` // CHECK:STDOUT: return x; @@ -652,6 +692,8 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `Main()` results: [`1`] (:0) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `Main()` results: [`1`] (:0) // CHECK:STDOUT: ==> interpreter result: 1 +// CHECK:STDOUT: +// CHECK:STDOUT: // CHECK:STDOUT: * * * * * * * * * * printing timing * * * * * * * * * * // CHECK:STDOUT: --------------------------------------------------------- // CHECK:STDOUT: Time elapsed in ExecProgram: {{\d+}}ms diff --git a/explorer/testdata/trace/phase_execution.carbon b/explorer/testdata/trace/phase_execution.carbon index 12679637e2a6..a335b081f5ec 100644 --- a/explorer/testdata/trace/phase_execution.carbon +++ b/explorer/testdata/trace/phase_execution.carbon @@ -18,10 +18,12 @@ fn Main() -> i32 { // CHECK:STDOUT: * * * * * * * * * * starting execution * * * * * * * * * * // CHECK:STDOUT: ------------------------------------------------------------ +// CHECK:STDOUT: // CHECK:STDOUT: - - - - - initializing globals - - - - - // CHECK:STDOUT: ------------------------------------------ // CHECK:STDOUT: >[] stack-push: DeclarationAction pos: 0 `class T` (phase_execution.carbon:7) // CHECK:STDOUT: ->> step DeclarationAction pos: 0 `class T` (phase_execution.carbon:7) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_execution.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: class T { @@ -30,6 +32,7 @@ fn Main() -> i32 { // CHECK:STDOUT: <[] stack-pop: DeclarationAction pos: 0 `class T` (phase_execution.carbon:7) // CHECK:STDOUT: >[] stack-push: DeclarationAction pos: 0 `fn Main` (phase_execution.carbon:12) // CHECK:STDOUT: ->> step DeclarationAction pos: 0 `fn Main` (phase_execution.carbon:12) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_execution.carbon:12) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -41,6 +44,7 @@ fn Main() -> i32 { // CHECK:STDOUT: } // CHECK:STDOUT: ``` // CHECK:STDOUT: <[] stack-pop: DeclarationAction pos: 0 `fn Main` (phase_execution.carbon:12) +// CHECK:STDOUT: // CHECK:STDOUT: - - - - - calling main function - - - - - // CHECK:STDOUT: ------------------------------------------- // CHECK:STDOUT: >[] stack-push: ValueExpressionAction pos: 0 `Main()` (:0) @@ -61,6 +65,7 @@ fn Main() -> i32 { // CHECK:STDOUT: >[] stack-push: ScopeAction pos: 0 scope: [] (None) // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `{var x: T = {}.(interface ImplicitAs(T = class T).Convert)();return 0;}` (phase_execution.carbon:12) // CHECK:STDOUT: ->> step StatementAction pos: 0 `{var x: T = {}.(interface ImplicitAs(T = class T).Convert)();return 0;}` (phase_execution.carbon:12) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_execution.carbon:12) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -71,6 +76,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `var x: T = {}.(interface ImplicitAs(T = class T).Convert)();` (phase_execution.carbon:10) // CHECK:STDOUT: ->> step StatementAction pos: 0 `var x: T = {}.(interface ImplicitAs(T = class T).Convert)();` (phase_execution.carbon:10) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_execution.carbon:10) // CHECK:STDOUT: ``` // CHECK:STDOUT: var x: T = {}.(interface ImplicitAs(T = class T).Convert)(); @@ -111,6 +117,7 @@ fn Main() -> i32 { // CHECK:STDOUT: >[] stack-push: ScopeAction pos: 0 scope: [`self: Self`: `{}`] (None) // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `{return __intrinsic_implicit_as_convert(self, U);}` (prelude.carbon:{{\d+}}) // CHECK:STDOUT: ->> step StatementAction pos: 0 `{return __intrinsic_implicit_as_convert(self, U);}` (prelude.carbon:{{\d+}}) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (prelude.carbon:{{\d+}}) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -120,6 +127,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `return __intrinsic_implicit_as_convert(self, U);` (prelude.carbon:{{\d+}}) // CHECK:STDOUT: ->> step StatementAction pos: 0 `return __intrinsic_implicit_as_convert(self, U);` (prelude.carbon:{{\d+}}) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (prelude.carbon:{{\d+}}) // CHECK:STDOUT: ``` // CHECK:STDOUT: return __intrinsic_implicit_as_convert(self, U); @@ -148,6 +156,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `__intrinsic_implicit_as_convert(self, U)` results: [`T{}`] (prelude.carbon:{{\d+}}) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `__intrinsic_implicit_as_convert(self, U)` results: [`T{}`] (prelude.carbon:{{\d+}}) // CHECK:STDOUT: ->> step StatementAction pos: 1 `return __intrinsic_implicit_as_convert(self, U);` results: [`T{}`] (prelude.carbon:{{\d+}}) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (prelude.carbon:{{\d+}}) // CHECK:STDOUT: ``` // CHECK:STDOUT: return __intrinsic_implicit_as_convert(self, U); @@ -168,6 +177,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step CleanUpAction pos: 0 scope: [] (stack cleanup:1) ---> // CHECK:STDOUT: <[] stack-pop: CleanUpAction pos: 0 scope: [] (stack cleanup:1) // CHECK:STDOUT: ->> step StatementAction pos: 1 `var x: T = {}.(interface ImplicitAs(T = class T).Convert)();` results: [`T{}`] (phase_execution.carbon:10) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_execution.carbon:10) // CHECK:STDOUT: ``` // CHECK:STDOUT: var x: T = {}.(interface ImplicitAs(T = class T).Convert)(); @@ -177,6 +187,7 @@ fn Main() -> i32 { // CHECK:STDOUT: from initializing expression with value `T{}` // CHECK:STDOUT: <[] stack-pop: StatementAction pos: 1 `var x: T = {}.(interface ImplicitAs(T = class T).Convert)();` results: [`T{}`] (phase_execution.carbon:10) // CHECK:STDOUT: ->> step StatementAction pos: 1 `{var x: T = {}.(interface ImplicitAs(T = class T).Convert)();return 0;}` scope: [`x: T`: `lval`] (phase_execution.carbon:12) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_execution.carbon:12) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -187,6 +198,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: >[] stack-push: StatementAction pos: 0 `return 0;` (phase_execution.carbon:11) // CHECK:STDOUT: ->> step StatementAction pos: 0 `return 0;` (phase_execution.carbon:11) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_execution.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: return 0; @@ -199,6 +211,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `0` results: [`0`] (phase_execution.carbon:11) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `0` results: [`0`] (phase_execution.carbon:11) // CHECK:STDOUT: ->> step StatementAction pos: 1 `return 0;` results: [`0`] (phase_execution.carbon:11) ---> +// CHECK:STDOUT: // CHECK:STDOUT: *** statement at (phase_execution.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: return 0; diff --git a/explorer/testdata/trace/phase_type_checking.carbon b/explorer/testdata/trace/phase_type_checking.carbon index 55e20521c0de..a76dc9b93b71 100644 --- a/explorer/testdata/trace/phase_type_checking.carbon +++ b/explorer/testdata/trace/phase_type_checking.carbon @@ -17,6 +17,7 @@ fn Main() -> i32 { // CHECK:STDOUT: * * * * * * * * * * type checking * * * * * * * * * * // CHECK:STDOUT: ------------------------------------------------------- +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_type_checking.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: interface TestInterface { @@ -25,6 +26,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ``` // CHECK:STDOUT: ->> declaring `interface TestInterface` (phase_type_checking.carbon:7) // CHECK:STDOUT: <<- finished declaring `interface TestInterface` (phase_type_checking.carbon:7) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking declaration at (phase_type_checking.carbon:7) // CHECK:STDOUT: ``` // CHECK:STDOUT: interface TestInterface { @@ -83,6 +85,7 @@ fn Main() -> i32 { // CHECK:STDOUT: `T` as `interface LeftShiftAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface RightShiftAssignWith(U = U)` [0; 1, 1, 0]] // CHECK:STDOUT: <<- finished checking `interface TestInterface` (phase_type_checking.carbon:7) +// CHECK:STDOUT: // CHECK:STDOUT: *** declaration at (phase_type_checking.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -104,6 +107,7 @@ fn Main() -> i32 { // CHECK:STDOUT: ->> step ValueExpressionAction pos: 1 `i32` results: [`i32`] (phase_type_checking.carbon:9) ---> // CHECK:STDOUT: <[] stack-pop: ValueExpressionAction pos: 1 `i32` results: [`i32`] (phase_type_checking.carbon:9) // CHECK:STDOUT: ->> finished declaring function `Main` of type `fn () -> i32` (phase_type_checking.carbon:11) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking declaration at (phase_type_checking.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: fn Main ()-> i32 { @@ -165,6 +169,7 @@ fn Main() -> i32 { // CHECK:STDOUT: `T` as `interface BitXorAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface LeftShiftAssignWith(U = U)` [0; 1, 1, 0], // CHECK:STDOUT: `T` as `interface RightShiftAssignWith(U = U)` [0; 1, 1, 0]] +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (phase_type_checking.carbon:11) // CHECK:STDOUT: ``` // CHECK:STDOUT: { @@ -173,6 +178,7 @@ fn Main() -> i32 { // CHECK:STDOUT: // CHECK:STDOUT: ``` // CHECK:STDOUT: ->> checking Block `{return 0;}` (phase_type_checking.carbon:11) +// CHECK:STDOUT: // CHECK:STDOUT: *** type checking stmt at (phase_type_checking.carbon:10) // CHECK:STDOUT: ``` // CHECK:STDOUT: return 0;