Add some coarse debug information to semantics. (#2382)

Example stack:

```
1.	node_stack_:
	0.	FunctionDefinitionStart
	1.	ReturnStatement -> node1
2.	node_block_stack_:
	0.	block0
	1.	block1
```

Example trace output:

```
*** SemanticsParseTreeHandler::Build Begin ***
Push 0: FunctionIntroducer
Push 1: DeclaredName
Push 2: ParameterListEnd
Pop 2: ParameterListEnd
Push 2: ParameterList
Pop 2: ParameterList
Pop 0: FunctionIntroducer
AddNode block0: FunctionDeclaration()
AddNode block0: BindName(ident0, node0)
AddNode block0: FunctionDefinition(node0, block1)
Push 0: FunctionDefinitionStart
Push 1: Literal -> IntegerLiteral
AddNode block1: IntegerLiteral(int0): node_xref1
Push 2: StatementEnd
Pop 2: StatementEnd
Pop 1: any (Literal) -> node0
Push 1: ReturnStatement -> ReturnExpression
AddNode block1: ReturnExpression(node0)
Pop 0: FunctionDefinitionStart
Push 0: FunctionDefinition
*** SemanticsParseTreeHandler::Build End ***
cross_reference_irs.size == 2,
cross_references = {
  node_xref0 = "xref(ir0, block0, node0)";
  node_xref1 = "xref(ir0, block0, node1)";
},
identifiers = {
  ident0 = "Foo";
},
integer_literals = {
  int0 = 0;
},
node_blocks = {
  block0 = {
    node0 = FunctionDeclaration();
    node1 = BindName(ident0, node0);
    node2 = FunctionDefinition(node0, block1);
  },
  block1 = {
    node0 = IntegerLiteral(int0): node_xref1;
    node1 = ReturnExpression(node0);
  },
}
```

Co-authored-by: Chandler Carruth <chandlerc@gmail.com>

bazel/testing/lit.cfg.py

@@ -66,6 +66,7 @@ def add_substitutions():
         f"{run_explorer} --parser_debug --trace_file=- | "
         f"{filecheck_allow_unmatched}",
     )
+    add_substitution("FileCheck-allow-unmatched", filecheck_allow_unmatched)
     add_substitution("FileCheck-strict", filecheck_strict)
     add_substitution("not", tools["not"])
 

common/BUILD

@@ -120,3 +120,22 @@ cc_test(
         "@llvm-project//llvm:Support",
     ],
 )
+
+cc_library(
+    name = "vlog",
+    srcs = ["vlog_internal.h"],
+    hdrs = ["vlog.h"],
+    deps = [
+        "@llvm-project//llvm:Support",
+    ],
+)
+
+cc_test(
+    name = "vlog_test",
+    srcs = ["vlog_test.cpp"],
+    deps = [
+        ":vlog",
+        "//common:gtest_main",
+        "@com_google_googletest//:gtest",
+    ],
+)

common/check.h

@@ -9,12 +9,6 @@
 
 namespace Carbon {
 
-// Raw exiting stream. This should be used when building other forms of exiting
-// macros like those below. It evaluates to a temporary `ExitingStream` object
-// that can be manipulated, streamed into, and then will exit the program.
-#define CARBON_RAW_EXITING_STREAM() \
-  Carbon::Internal::ExitingStream::Helper() | Carbon::Internal::ExitingStream()
-
 // Checks the given condition, and if it's false, prints a stack, streams the
 // error message, then exits. This should be used for unexpected errors, such as
 // a bug in the application.
@@ -23,7 +17,7 @@ namespace Carbon {
 //   CARBON_CHECK(is_valid) << "Data is not valid!";
 #define CARBON_CHECK(...)                                                   \
   (__VA_ARGS__) ? (void)0                                                   \
-                : CARBON_RAW_EXITING_STREAM()                               \
+                : CARBON_CHECK_INTERNAL_STREAM()                            \
                       << "CHECK failure at " << __FILE__ << ":" << __LINE__ \
                       << ": " #__VA_ARGS__                                  \
                       << Carbon::Internal::ExitingStream::AddSeparator()
@@ -41,8 +35,8 @@ namespace Carbon {
 //
 // For example:
 //   CARBON_FATAL() << "Unreachable!";
-#define CARBON_FATAL()        \
-  CARBON_RAW_EXITING_STREAM() \
+#define CARBON_FATAL()           \
+  CARBON_CHECK_INTERNAL_STREAM() \
       << "FATAL failure at " << __FILE__ << ":" << __LINE__ << ": "
 
 }  // namespace Carbon

common/check_internal.h

@@ -72,4 +72,10 @@ class ExitingStream {
 
 }  // namespace Carbon::Internal
 
+// Raw exiting stream. This should be used when building forms of exiting
+// macros. It evaluates to a temporary `ExitingStream` object that can be
+// manipulated, streamed into, and then will exit the program.
+#define CARBON_CHECK_INTERNAL_STREAM() \
+  Carbon::Internal::ExitingStream::Helper() | Carbon::Internal::ExitingStream()
+
 #endif  // CARBON_COMMON_CHECK_INTERNAL_H_

common/vlog.h

@@ -0,0 +1,22 @@
+// Part of the Carbon Language project, under the Apache License v2.0 with LLVM
+// Exceptions. See /LICENSE for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+
+#ifndef CARBON_COMMON_VLOG_H_
+#define CARBON_COMMON_VLOG_H_
+
+#include "common/vlog_internal.h"
+
+namespace Carbon {
+
+// Logs when verbose logging is enabled (vlog_stream_ is non-null).
+//
+// For example:
+//   CARBON_VLOG() << "Verbose message";
+#define CARBON_VLOG()                 \
+  (vlog_stream_ == nullptr) ? (void)0 \
+                            : CARBON_VLOG_INTERNAL_STREAM(vlog_stream_)
+
+}  // namespace Carbon
+
+#endif  // CARBON_COMMON_VLOG_H_

common/vlog_internal.h

@@ -0,0 +1,56 @@
+// Part of the Carbon Language project, under the Apache License v2.0 with LLVM
+// Exceptions. See /LICENSE for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+
+#ifndef CARBON_COMMON_VLOG_INTERNAL_H_
+#define CARBON_COMMON_VLOG_INTERNAL_H_
+
+#include <cstdlib>
+
+#include "llvm/Support/raw_ostream.h"
+
+namespace Carbon::Internal {
+
+// Wraps a stream and exiting for fatal errors. Should only be used by check.h
+// macros.
+class VLoggingStream {
+ public:
+  // Internal type used in macros to dispatch to the `operator|` overload.
+  struct Helper {};
+
+  VLoggingStream(llvm::raw_ostream* stream)
+      // Prefix the buffer with the current bug report message.
+      : stream_(stream) {}
+
+  ~VLoggingStream() = default;
+
+  // If the bool cast occurs, it's because the condition is false. This supports
+  // && short-circuiting the creation of ExitingStream.
+  explicit operator bool() const { return true; }
+
+  // Forward output to llvm::errs.
+  template <typename T>
+  auto operator<<(const T& message) -> VLoggingStream& {
+    *stream_ << message;
+    return *this;
+  }
+
+  // Low-precedence binary operator overload used in vlog.h macros.
+  friend auto operator|(Helper /*helper*/, VLoggingStream& /*stream*/) -> void {
+  }
+
+ private:
+  [[noreturn]] auto Done() -> void;
+
+  llvm::raw_ostream* stream_;
+};
+
+}  // namespace Carbon::Internal
+
+// Raw logging stream. This should be used when building forms of vlog
+// macros.
+#define CARBON_VLOG_INTERNAL_STREAM(stream)    \
+  Carbon::Internal::VLoggingStream::Helper() | \
+      Carbon::Internal::VLoggingStream(stream)
+
+#endif  // CARBON_COMMON_VLOG_INTERNAL_H_

common/vlog_test.cpp

@@ -0,0 +1,49 @@
+// Part of the Carbon Language project, under the Apache License v2.0 with LLVM
+// Exceptions. See /LICENSE for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+
+#include "common/vlog.h"
+
+#include <gmock/gmock.h>
+#include <gtest/gtest.h>
+
+namespace Carbon::Testing {
+namespace {
+
+using ::testing::IsEmpty;
+using ::testing::StrEq;
+
+// Helper class with a vlog_stream_ member for CARBON_VLOG.
+class VLogger {
+ public:
+  explicit VLogger(bool enable) : buffer_(buffer_str_) {
+    if (enable) {
+      vlog_stream_ = &buffer_;
+    }
+  }
+
+  void VLog() { CARBON_VLOG() << "Test\n"; }
+
+  auto buffer() -> llvm::StringRef { return buffer_str_; }
+
+ private:
+  std::string buffer_str_;
+  llvm::raw_string_ostream buffer_;
+
+  llvm::raw_ostream* vlog_stream_ = nullptr;
+};
+
+TEST(VLogTest, Enabled) {
+  VLogger vlog(/*enable=*/true);
+  vlog.VLog();
+  EXPECT_THAT(vlog.buffer(), StrEq("Test\n"));
+}
+
+TEST(VLogTest, Disabled) {
+  VLogger vlog(/*enable=*/false);
+  vlog.VLog();
+  EXPECT_THAT(vlog.buffer(), IsEmpty());
+}
+
+}  // namespace
+}  // namespace Carbon::Testing

toolchain/driver/driver.cpp

@@ -40,7 +40,11 @@ auto Driver::RunFullCommand(llvm::ArrayRef<llvm::StringRef> args) -> bool {
   DiagnosticConsumer* consumer = &ConsoleDiagnosticConsumer();
   std::unique_ptr<SortingDiagnosticConsumer> sorting_consumer;
   // TODO: Figure out a command-line support library, this is temporary.
-  if (!args.empty() && args[0] == "--print-errors=streamed") {
+  if (!args.empty() && args[0] == "-v") {
+    args = args.drop_front();
+    // Note this implies streamed output in order to interleave.
+    vlog_stream_ = &error_stream_;
+  } else if (!args.empty() && args[0] == "--print-errors=streamed") {
     args = args.drop_front();
   } else {
     sorting_consumer = std::make_unique<SortingDiagnosticConsumer>(*consumer);
@@ -170,8 +174,8 @@ auto Driver::RunDumpSubcommand(DiagnosticConsumer& consumer,
   }
 
   const SemanticsIR builtin_ir = SemanticsIR::MakeBuiltinIR();
-  const SemanticsIR semantics_ir =
-      SemanticsIR::MakeFromParseTree(builtin_ir, tokenized_source, parse_tree);
+  const SemanticsIR semantics_ir = SemanticsIR::MakeFromParseTree(
+      builtin_ir, tokenized_source, parse_tree, vlog_stream_);
   if (dump_mode == DumpMode::SemanticsIR) {
     consumer.Flush();
     semantics_ir.Print(output_stream_);

toolchain/driver/driver.h

@@ -67,6 +67,7 @@ class Driver {
 
   llvm::raw_ostream& output_stream_;
   llvm::raw_ostream& error_stream_;
+  llvm::raw_ostream* vlog_stream_ = nullptr;
 };
 
 }  // namespace Carbon

toolchain/parser/parser.h

@@ -225,8 +225,8 @@ class Parser {
   // Pushes a constructed state onto the stack.
   auto PushState(StateStackEntry state) -> void {
     state_stack_.push_back(state);
-    // Verify the stack doesn't grow unbounded by programming error.
-    CARBON_CHECK(state_stack_.size() < (1 << 20));
+    CARBON_CHECK(state_stack_.size() < (1 << 20))
+        << "Excessive stack size: likely infinite loop";
   }
 
   // Propagates an error up the state stack, to the parent state.

toolchain/semantics/BUILD

@@ -29,20 +29,21 @@ cc_library(
 cc_library(
     name = "semantics_ir",
     srcs = [
-        "semantics_parse_tree_handler.cpp",
         "semantics_ir.cpp",
         "semantics_node.cpp",
+        "semantics_parse_tree_handler.cpp",
     ],
     hdrs = [
-        "semantics_parse_tree_handler.h",
         "semantics_ir.h",
         "semantics_node.h",
+        "semantics_parse_tree_handler.h",
     ],
     deps = [
         ":semantics_builtin_kind",
         ":semantics_node_kind",
         "//common:check",
         "//common:ostream",
+        "//common:vlog",
         "//toolchain/lexer:token_kind",
         "//toolchain/lexer:tokenized_buffer",
         "//toolchain/parser:parse_node_kind",

toolchain/semantics/semantics_ir.cpp

@@ -46,10 +46,11 @@ auto SemanticsIR::MakeBuiltinIR() -> SemanticsIR {
 
 auto SemanticsIR::MakeFromParseTree(const SemanticsIR& builtin_ir,
                                     const TokenizedBuffer& tokens,
-                                    const ParseTree& parse_tree)
+                                    const ParseTree& parse_tree,
+                                    llvm::raw_ostream* vlog_stream)
     -> SemanticsIR {
   SemanticsIR semantics(builtin_ir);
-  SemanticsParseTreeHandler(tokens, parse_tree, semantics).Build();
+  SemanticsParseTreeHandler(tokens, parse_tree, semantics, vlog_stream).Build();
   return semantics;
 }
 

toolchain/semantics/semantics_ir.h

@@ -52,7 +52,8 @@ class SemanticsIR {
   // Adds the IR for the provided ParseTree.
   static auto MakeFromParseTree(const SemanticsIR& builtin_ir,
                                 const TokenizedBuffer& tokens,
-                                const ParseTree& parse_tree) -> SemanticsIR;
+                                const ParseTree& parse_tree,
+                                llvm::raw_ostream* vlog_stream) -> SemanticsIR;
 
   // Prints the full IR.
   auto Print(llvm::raw_ostream& out) const -> void;

toolchain/semantics/semantics_parse_tree_handler.cpp

@@ -4,6 +4,8 @@
 
 #include "toolchain/semantics/semantics_parse_tree_handler.h"
 
+#include "common/vlog.h"
+#include "llvm/Support/PrettyStackTrace.h"
 #include "toolchain/lexer/token_kind.h"
 #include "toolchain/lexer/tokenized_buffer.h"
 #include "toolchain/parser/parse_node_kind.h"
@@ -11,7 +13,56 @@
 
 namespace Carbon {
 
+class SemanticsParseTreeHandler::PrettyStackTraceNodeStack
+    : public llvm::PrettyStackTraceEntry {
+ public:
+  explicit PrettyStackTraceNodeStack(const SemanticsParseTreeHandler* handler)
+      : handler_(handler) {}
+  ~PrettyStackTraceNodeStack() override = default;
+
+  auto print(llvm::raw_ostream& output) const -> void override {
+    output << "node_stack_:\n";
+    for (int i = 0; i < static_cast<int>(handler_->node_stack_.size()); ++i) {
+      const auto& entry = handler_->node_stack_[i];
+      output << "\t" << i << ".\t"
+             << handler_->parse_tree_->node_kind(entry.parse_node);
+      if (entry.result_id) {
+        output << " -> " << *entry.result_id;
+      }
+      output << "\n";
+    }
+  }
+
+ private:
+  const SemanticsParseTreeHandler* handler_;
+};
+
+class SemanticsParseTreeHandler::PrettyStackTraceNodeBlockStack
+    : public llvm::PrettyStackTraceEntry {
+ public:
+  explicit PrettyStackTraceNodeBlockStack(
+      const SemanticsParseTreeHandler* handler)
+      : handler_(handler) {}
+  ~PrettyStackTraceNodeBlockStack() override = default;
+
+  auto print(llvm::raw_ostream& output) const -> void override {
+    output << "node_block_stack_:\n";
+    for (int i = 0; i < static_cast<int>(handler_->node_block_stack_.size());
+         ++i) {
+      const auto& entry = handler_->node_block_stack_[i];
+      output << "\t" << i << ".\t" << entry << "\n";
+    }
+  }
+
+ private:
+  const SemanticsParseTreeHandler* handler_;
+};
+
 auto SemanticsParseTreeHandler::Build() -> void {
+  PrettyStackTraceNodeStack pretty_node_stack(this);
+  PrettyStackTraceNodeBlockStack pretty_node_block_stack(this);
+
+  CARBON_VLOG() << "*** SemanticsParseTreeHandler::Build Begin ***\n";
   // Add a block for the ParseTree.
   node_block_stack_.push_back(semantics_->AddNodeBlock());
 
@@ -33,6 +84,7 @@ auto SemanticsParseTreeHandler::Build() -> void {
         CARBON_CHECK(it == range.end())
             << "FileEnd should always be last, found "
             << parse_tree_->node_kind(*it);
+        CARBON_VLOG() << "*** SemanticsParseTreeHandler::Build End ***\n";
         return;
       }
       case ParseNodeKind::InfixOperator(): {
@@ -69,43 +121,58 @@ auto SemanticsParseTreeHandler::Build() -> void {
 }
 
 auto SemanticsParseTreeHandler::AddNode(SemanticsNode node) -> SemanticsNodeId {
+  CARBON_VLOG() << "AddNode " << node_block_stack_.back() << ": " << node
+                << "\n";
   return semantics_->AddNode(node_block_stack_.back(), node);
 }
 
 auto SemanticsParseTreeHandler::Push(ParseTree::Node parse_node) -> void {
+  CARBON_VLOG() << "Push " << node_stack_.size() << ": "
+                << parse_tree_->node_kind(parse_node) << "\n";
+  CARBON_CHECK(node_stack_.size() < (1 << 20))
+      << "Excessive stack size: likely infinite loop";
   node_stack_.push_back({parse_node, llvm::None});
 }
 
 auto SemanticsParseTreeHandler::Push(ParseTree::Node parse_node,
                                      SemanticsNode node) -> void {
+  CARBON_VLOG() << "Push " << node_stack_.size() << ": "
+                << parse_tree_->node_kind(parse_node) << " -> " << node.kind()
+                << "\n";
+  CARBON_CHECK(node_stack_.size() < (1 << 20))
+      << "Excessive stack size: likely infinite loop";
   auto node_id = AddNode(node);
   node_stack_.push_back({parse_node, node_id});
 }
 
 auto SemanticsParseTreeHandler::Pop(ParseNodeKind pop_parse_kind) -> void {
-  auto back = node_stack_.back();
+  auto back = node_stack_.pop_back_val();
   auto parse_kind = parse_tree_->node_kind(back.parse_node);
+  CARBON_VLOG() << "Pop " << node_stack_.size() << ": " << pop_parse_kind
+                << "\n";
   CARBON_CHECK(parse_kind == pop_parse_kind)
       << "Expected " << pop_parse_kind << ", found " << parse_kind;
   CARBON_CHECK(!back.result_id) << "Expected no result ID on " << parse_kind;
-  node_stack_.pop_back();
 }
 
 auto SemanticsParseTreeHandler::PopWithResult() -> SemanticsNodeId {
-  auto back = node_stack_.back();
+  auto back = node_stack_.pop_back_val();
   auto node_id = *back.result_id;
-  node_stack_.pop_back();
+  CARBON_VLOG() << "Pop " << node_stack_.size() << ": any ("
+                << parse_tree_->node_kind(back.parse_node) << ") -> " << node_id
+                << "\n";
   return node_id;
 }
 
 auto SemanticsParseTreeHandler::PopWithResult(ParseNodeKind pop_parse_kind)
     -> SemanticsNodeId {
-  auto back = node_stack_.back();
+  auto back = node_stack_.pop_back_val();
   auto parse_kind = parse_tree_->node_kind(back.parse_node);
   auto node_id = *back.result_id;
+  CARBON_VLOG() << "Pop " << node_stack_.size() << ": " << pop_parse_kind
+                << ") -> " << node_id << "\n";
   CARBON_CHECK(parse_kind == pop_parse_kind)
       << "Expected " << pop_parse_kind << ", found " << parse_kind;
-  node_stack_.pop_back();
   return node_id;
 }
 

toolchain/semantics/semantics_parse_tree_handler.h

@@ -17,13 +17,22 @@ class SemanticsParseTreeHandler {
   // Stores references for work.
   explicit SemanticsParseTreeHandler(const TokenizedBuffer& tokens,
                                      const ParseTree& parse_tree,
-                                     SemanticsIR& semantics)
-      : tokens_(&tokens), parse_tree_(&parse_tree), semantics_(&semantics) {}
+                                     SemanticsIR& semantics,
+                                     llvm::raw_ostream* vlog_stream)
+      : tokens_(&tokens),
+        parse_tree_(&parse_tree),
+        semantics_(&semantics),
+        vlog_stream_(vlog_stream) {}
 
   // Outputs the ParseTree information into SemanticsIR.
   auto Build() -> void;
 
  private:
+  // Prints the node_stack_ on stack dumps.
+  class PrettyStackTraceNodeStack;
+  // Prints the node_block_stack_ on stack dumps.
+  class PrettyStackTraceNodeBlockStack;
+
   struct TraversalStackEntry {
     ParseTree::Node parse_node;
     llvm::Optional<SemanticsNodeId> result_id;
@@ -72,6 +81,9 @@ class SemanticsParseTreeHandler {
   // The SemanticsIR being added to.
   SemanticsIR* semantics_;
 
+  // Whether to print verbose output.
+  llvm::raw_ostream* vlog_stream_;
+
   // The stack during Build. Will contain file-level parse nodes on return.
   llvm::SmallVector<TraversalStackEntry> node_stack_;
 

toolchain/semantics/testdata/basics/verbose.carbon

@@ -0,0 +1,14 @@
+// Part of the Carbon Language project, under the Apache License v2.0 with LLVM
+// Exceptions. See /LICENSE for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+// NOAUTOUPDATE
+// RUN: %{carbon} -v dump semantics-ir %s | %{FileCheck-allow-unmatched}
+//
+// Only checks a couple statements in order to minimize manual update churn.
+// CHECK:STDERR: Push 0: FunctionIntroducer
+// CHECK:STDERR: AddNode block0: BindName(ident0, node0)
+
+fn Foo() {
+  return;
+}