Explorer: add blank lines between trace of different sections (#3096)

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 <typename T>
   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<SourceLocation> source_loc_ = std::nullopt;
   std::optional<Nonnull<llvm::raw_ostream*>> stream_;

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

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` (<Main()>: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 `()` (<Main()>: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()` (<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`]  (<Main()>:0) --->
 // CHECK:STDOUT: <[] stack-pop:  ValueExpressionAction pos: 1 `Main()` results: [`0`]  (<Main()>:0)
 // CHECK:STDOUT: ==> interpreter result: 0
+// CHECK:STDOUT:
+// CHECK:STDOUT:
 // CHECK:STDOUT: * * * * * * * * * *  printing timing  * * * * * * * * * *
 // CHECK:STDOUT: ---------------------------------------------------------
 // CHECK:STDOUT: Time elapsed in ExecProgram: {{\d+}}ms

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` (<Main()>: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 `()` (<Main()>: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()` (<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<Allocation(1)>`] (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<Allocation(1)>`]  (phase_all.carbon:17) --->
 // CHECK:STDOUT: <[] stack-pop:  ValueExpressionAction pos: 1 `x` results: [`ref_expr<Allocation(1)>`]  (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`]  (<Main()>:0) --->
 // CHECK:STDOUT: <[] stack-pop:  ValueExpressionAction pos: 1 `Main()` results: [`1`]  (<Main()>:0)
 // CHECK:STDOUT: ==> interpreter result: 1
+// CHECK:STDOUT:
+// CHECK:STDOUT:
 // CHECK:STDOUT: * * * * * * * * * *  printing timing  * * * * * * * * * *
 // CHECK:STDOUT: ---------------------------------------------------------
 // CHECK:STDOUT: Time elapsed in ExecProgram: {{\d+}}ms

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()` (<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<Allocation(1)>`] (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;

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;