Allow selection of verbosity level for vtrace_fmt! messages

xls/dslx/bytecode/bytecode.h

@@ -330,21 +330,26 @@ class Bytecode {
     TraceData& operator=(TraceData&& other) = default;
 
     TraceData(std::vector<FormatStep> steps,
-              std::vector<ValueFormatDescriptor> value_fmt_descs)
+              std::vector<ValueFormatDescriptor> value_fmt_descs,
+              std::optional<int64_t> verbosity = std::nullopt)
         : steps_(std::move(steps)),
-          value_fmt_descs_(std::move(value_fmt_descs)) {}
+          value_fmt_descs_(std::move(value_fmt_descs)),
+          verbosity_(verbosity) {}
 
     absl::Span<const FormatStep> steps() const { return steps_; }
     absl::Span<const ValueFormatDescriptor> value_fmt_descs() const {
       return value_fmt_descs_;
     }
+    const std::optional<int64_t> verbosity() const { return verbosity_; }
 
    private:
     std::vector<FormatStep> steps_;
 
     // For default formatting of struct operands we hold metadata that allows us
     // to format them in more detail (struct name, fields, etc).
     std::vector<ValueFormatDescriptor> value_fmt_descs_;
+    // Verbosity of the `vtrace` messages
+    std::optional<int64_t> verbosity_;
   };
 
   // Information necessary for channel operations.

xls/dslx/bytecode/bytecode_emitter.cc

@@ -1025,9 +1025,19 @@ absl::Status BytecodeEmitter::HandleFormatMacro(const FormatMacro* node) {
 
   CHECK(node->macro() == "trace_fmt!" || node->macro() == "vtrace_fmt!")
       << "Expected trace_fmt! or vtrace_fmt! but got: " << node->macro();
+  std::optional<int64_t> verbosity = std::nullopt;
+  if (node->verbosity().has_value()) {
+    XLS_ASSIGN_OR_RETURN(InterpValue verbosity_val,
+                         type_info_->GetConstExpr(*node->verbosity()));
+    absl::StatusOr<int64_t> verbosity_as_int64 =
+        verbosity_val.GetBitValueViaSign();
+    if (verbosity_as_int64.ok()) {
+      verbosity = *verbosity_as_int64;
+    }
+  }
   Bytecode::TraceData trace_data(
       std::vector<FormatStep>(node->format().begin(), node->format().end()),
-      std::move(value_fmt_descs));
+      std::move(value_fmt_descs), verbosity);
   bytecode_.push_back(
       Bytecode(node->span(), Bytecode::Op::kTraceFmt, std::move(trace_data)));
   return absl::OkStatus();

xls/dslx/bytecode/bytecode_interpreter.cc

@@ -1579,7 +1579,10 @@ absl::Status BytecodeInterpreter::EvalTraceFmt(const Bytecode& bytecode) {
                        bytecode.trace_data());
   XLS_ASSIGN_OR_RETURN(std::string message,
                        TraceDataToString(*trace_data, stack_));
-  if (events_.has_value()) {
+  // Exclude "vtrace" messages if the verbosity level is set to a value higher
+  // than the verbosity level passed by the "max_trace_verbosity" flag.
+  if (events_.has_value() &&
+      (*trace_data->verbosity() <= *options_.max_trace_verbosity())) {
     (*events_)->AddTraceStatementMessage(import_data_->file_table(),
                                          bytecode.source_span(), message);
   }

xls/dslx/bytecode/bytecode_interpreter_options.h

@@ -92,6 +92,18 @@ class BytecodeInterpreterOptions {
   }
   std::optional<int64_t> max_ticks() const { return max_ticks_; }
 
+  // Store verbosity level from the `max_trace_verbosity` flag. Used to filter
+  // `vtrace` messages if their verbosity level is set higher than the verbosity
+  // level passed by the flag.
+  BytecodeInterpreterOptions& max_trace_verbosity(
+      std::optional<int64_t> value) {
+    max_trace_verbosity_ = value;
+    return *this;
+  }
+  std::optional<int64_t> max_trace_verbosity() const {
+    return max_trace_verbosity_;
+  }
+
   void set_validate_final_stack_depth(bool enabled) {
     validate_final_stack_depth_ = enabled;
   }
@@ -114,6 +126,7 @@ class BytecodeInterpreterOptions {
   bool trace_channels_ = false;
   bool trace_calls_ = false;
   std::optional<int64_t> max_ticks_;
+  std::optional<int64_t> max_trace_verbosity_;
   bool validate_final_stack_depth_ = true;
   FormatPreference format_preference_ = FormatPreference::kDefault;
 };

xls/dslx/bytecode/bytecode_interpreter_test.cc

@@ -223,6 +223,25 @@ fn main() -> () {
   EXPECT_EQ(value, InterpValue::MakeUnit());
 }
 
+TEST_F(BytecodeInterpreterTest, VtraceFmtBitsValueDefaultFormat) {
+  constexpr std::string_view kProgram = R"(
+fn main() -> () {
+  vtrace_fmt!(u32:2, "{}", u32:2);
+  vtrace_fmt!(u32:6, "{}", u32:6);
+  vtrace_fmt!(u32:10, "{}", u32:10);
+  vtrace_fmt!(u32:16, "{}", u32:16);
+}
+)";
+  DslxInterpreterEvents events;
+  XLS_ASSERT_OK_AND_ASSIGN(
+      InterpValue value,
+      Interpret(kProgram, "main", /*args=*/{},
+                BytecodeInterpreterOptions().max_trace_verbosity(8), nullptr,
+                &events));
+  EXPECT_THAT(events.GetTraceMessageStrings(), testing::ElementsAre("2", "6"));
+  EXPECT_EQ(value, InterpValue::MakeUnit());
+}
+
 TEST_F(BytecodeInterpreterTest, TraceFmtBitsValueHexFormat) {
   constexpr std::string_view kProgram = R"(
 fn main() -> () {

xls/dslx/interpreter_main.cc

@@ -94,6 +94,9 @@ ABSL_FLAG(bool, trace_calls, false,
 ABSL_FLAG(int64_t, max_ticks, 100000,
           "If non-zero, the maximum number of ticks to execute on any proc. If "
           "exceeded an error is returned.");
+ABSL_FLAG(int64_t, max_trace_verbosity, 0,
+          "Maximum verbosity for traces. Traces with higher verbosity are "
+          "stripped from the output. 0 by default.");
 ABSL_FLAG(std::string, evaluator, "dslx-interpreter",
           "What evaluator should be used to actually execute the dslx test. "
           "'dslx-interpreter' is the DSLX bytecode interpreter. 'ir-jit' is "
@@ -116,11 +119,6 @@ enum class CompareFlag : uint8_t {
   kJit,
   kInterpreter,
 };
-enum class EvaluatorType : uint8_t {
-  kDslxInterpreter,
-  kIrInterpreter,
-  kIrJit,
-};
 
 absl::StatusOr<EvaluatorType> GetEvaluatorType(std::string_view text) {
   if (text == "interpreter" || text == "dslx-interpreter") {
@@ -174,6 +172,11 @@ absl::StatusOr<TestResult> RealMain(
                                    : TypeInferenceVersion::kVersion1)
           : std::nullopt;
 
+  std::optional<int64_t> max_trace_verbosity =
+      absl::GetFlag(FLAGS_max_trace_verbosity) == 0
+          ? std::nullopt
+          : std::optional<int64_t>(absl::GetFlag(FLAGS_max_trace_verbosity));
+
   RealFilesystem vfs;
 
   XLS_ASSIGN_OR_RETURN(std::string program,
@@ -248,6 +251,8 @@ absl::StatusOr<TestResult> RealMain(
       .trace_channels = trace_channels,
       .trace_calls = trace_calls,
       .max_ticks = max_ticks,
+      .max_trace_verbosity = max_trace_verbosity,
+      .evaluator = evaluator,
   };
 
   // Create a results proto if requested and plumb it through options.

xls/dslx/interpreter_test.py

@@ -471,6 +471,42 @@ def test_trace_fmt_tuple_of_enum(self):
     self.assertIn('MyEnum::TWO', stderr)
     self.assertIn('0x2a', stderr)
 
+  def test_vtrace_fmt_ir_interpreter(self):
+    """Checks whether vtrace logs are displayed according to the selected level of verbosity."""
+    program = """
+    const VERBOSITY_LEV_0 = u32:0;
+    const VERBOSITY_LEV_1 = u32:8;
+    const VERBOSITY_LEV_2 = u32:16;
+
+    fn vtrace_fmt_example(a: u32, b: u32) -> u32 {
+      vtrace_fmt!(VERBOSITY_LEV_0, "Verbosity level: {:d}", VERBOSITY_LEV_0);
+      vtrace_fmt!(VERBOSITY_LEV_1, "Verbosity level: {:d}", VERBOSITY_LEV_1);
+      vtrace_fmt!(VERBOSITY_LEV_2, "Verbosity level: {:d}", VERBOSITY_LEV_2);
+      trace_fmt!("Trace verification.");
+      a + b
+    }
+
+    #[test]
+    fn vtrace_test() {
+      assert_eq(vtrace_fmt_example(u32:1, u32:2), u32:3);
+    }
+    """
+    stderr = self._parse_and_test(
+        program,
+        want_error=False,
+        alsologtostderr=True,
+        extra_flags=(
+          '--log_prefix=false',
+          '--compare=none',
+          '--max_trace_verbosity=10',
+          '--evaluator=ir-interpreter',
+         ),
+    )
+    self.assertIn('Verbosity level: 0', stderr)
+    self.assertIn('Verbosity level: 8', stderr)
+    self.assertNotIn('Verbosity level: 16', stderr)
+    self.assertIn('Trace verification.', stderr)
+
   def test_trace_calls(self):
     """Tests that --trace_calls emits call traces with args and return values.
 

xls/dslx/ir_convert/convert_format_macro.cc

@@ -154,13 +154,11 @@ absl::Status Flatten(const ValueFormatDescriptor& vfd, const BValue& v,
 
 }  // namespace
 
-absl::StatusOr<BValue> ConvertFormatMacro(const FormatMacro& node,
-                                          const BValue& entry_token,
-                                          const BValue& control_predicate,
-                                          absl::Span<const BValue> arg_vals,
-                                          int64_t verbosity,
-                                          const TypeInfo& current_type_info,
-                                          BuilderBase& function_builder) {
+absl::StatusOr<BValue> ConvertFormatMacro(
+    const FormatMacro& node, const BValue& entry_token,
+    const BValue& control_predicate, absl::Span<const BValue> arg_vals,
+    int64_t verbosity, const TypeInfo& current_type_info,
+    BuilderBase& function_builder, const SourceInfo& loc) {
   // This is the data we build up for the final "trace" operation we place in
   // the IR -- there is a sequence of format steps and a corresponding set of
   // ir_args that are interpolated into the format steps.
@@ -191,9 +189,8 @@ absl::StatusOr<BValue> ConvertFormatMacro(const FormatMacro& node,
       next_argno += 1;
     }
   }
-
   return function_builder.Trace(entry_token, control_predicate, ir_args,
-                                fmt_steps, verbosity);
+                                fmt_steps, verbosity, loc);
 }
 
 }  // namespace xls::dslx

xls/dslx/ir_convert/convert_format_macro.h

@@ -43,13 +43,11 @@ namespace xls::dslx {
 //    operation on.
 //
 // Returns the trace (IR operation) token.
-absl::StatusOr<BValue> ConvertFormatMacro(const FormatMacro& node,
-                                          const BValue& entry_token,
-                                          const BValue& control_predicate,
-                                          absl::Span<const BValue> arg_vals,
-                                          int64_t verbosity,
-                                          const TypeInfo& current_type_info,
-                                          BuilderBase& function_builder);
+absl::StatusOr<BValue> ConvertFormatMacro(
+    const FormatMacro& node, const BValue& entry_token,
+    const BValue& control_predicate, absl::Span<const BValue> arg_vals,
+    int64_t verbosity, const TypeInfo& current_type_info,
+    BuilderBase& function_builder, const SourceInfo& loc);
 
 }  // namespace xls::dslx
 

xls/dslx/ir_convert/function_converter.cc

@@ -2595,17 +2595,21 @@ absl::Status FunctionConverter::HandleFormatMacro(const FormatMacro* node) {
     }
     verbosity = *verbosity_value;
   }
-  XLS_ASSIGN_OR_RETURN(
-      BValue trace_result_token,
-      ConvertFormatMacro(*node, implicit_token_data_->entry_token,
-                         control_predicate, args, verbosity,
-                         *current_type_info_, *function_builder_));
-
-  implicit_token_data_->control_tokens.push_back(trace_result_token);
-
-  // The result of the trace is the output token, so pass it along.
-  Def(node, [&](const SourceInfo& loc) { return trace_result_token; });
-  tokens_.push_back(trace_result_token);
+  return DefWithStatus(node,
+                       [&](const SourceInfo& loc) -> absl::StatusOr<BValue> {
+                         XLS_ASSIGN_OR_RETURN(
+                             BValue trace_result_token,
+                             ConvertFormatMacro(
+                                 *node, implicit_token_data_->entry_token,
+                                 control_predicate, args, verbosity,
+                                 *current_type_info_, *function_builder_, loc));
+
+                         implicit_token_data_->control_tokens.push_back(
+                             trace_result_token);
+                         tokens_.push_back(trace_result_token);
+                         return trace_result_token;
+                       })
+      .status();
   return absl::OkStatus();
 }
 

xls/dslx/run_routines/run_routines.cc

@@ -1036,6 +1036,7 @@ absl::StatusOr<TestResultData> AbstractTestRunner::ParseAndTest(
         .trace_channels(options.trace_channels)
         .trace_calls(options.trace_calls)
         .max_ticks(options.max_ticks)
+        .max_trace_verbosity(options.max_trace_verbosity)
         .format_preference(options.format_preference);
     if (std::holds_alternative<TestFunction*>(*member)) {
       XLS_ASSIGN_OR_RETURN(
@@ -1058,6 +1059,26 @@ absl::StatusOr<TestResultData> AbstractTestRunner::ParseAndTest(
       *result_proto->mutable_events() = test_events.AsProto();
     }
 
+    // Display vtrace messages according to the value of the
+    // `max_trace_verbosity` flag for other evaluators than the DSLX
+    // interpreter, because we don't want to duplicate logs
+    if (options.evaluator != EvaluatorType::kDslxInterpreter) {
+      for (const auto& msg : test_events.AsProto().trace_msgs()) {
+        int64_t verbosity =
+            msg.has_statement() ? msg.statement().verbosity() : 0;
+        if (verbosity <= options.max_trace_verbosity) {
+          std::string message = msg.message();
+          if (msg.has_location()) {
+            message = absl::StrFormat(
+                "[%s:%d:%d] %s",
+                std::filesystem::path(msg.location().filename()).filename(),
+                msg.location().line(), msg.location().column(), msg.message());
+          }
+          std::cerr << message << '\n';
+        }
+      }
+    }
+
     if (out.result.ok()) {
       // Add to the tracking data.
       result.AddTestCase(test_xml::TestCase{

xls/dslx/run_routines/run_routines.h

@@ -56,6 +56,12 @@
 
 namespace xls::dslx {
 
+enum class EvaluatorType : uint8_t {
+  kDslxInterpreter,
+  kIrInterpreter,
+  kIrJit,
+};
+
 // Abstract API used for comparing DSLX-interpreter results to executed IR
 // results. This is a virtual API to help decouple from implementation details
 // like whether the JIT is available or only interpretation, or whether we
@@ -111,6 +117,8 @@ struct ParseAndTestOptions {
   bool trace_channels = false;
   bool trace_calls = false;
   std::optional<int64_t> max_ticks;
+  std::optional<int64_t> max_trace_verbosity;
+  std::optional<EvaluatorType> evaluator;
   std::function<std::unique_ptr<VirtualizableFilesystem>()> vfs_factory =
       nullptr;
 

xls/examples/BUILD

@@ -1541,3 +1541,27 @@ xls_dslx_verilog(
     library = ":const_match_dslx",
     verilog_file = "const_match.sv",
 )
+
+xls_dslx_library(
+    name = "vtrace_fmt_dslx",
+    srcs = [ "vtrace_fmt.x" ],
+)
+
+xls_dslx_test(
+    name = "vtrace_fmt_dslx_test",
+    library = "vtrace_fmt_dslx",
+)
+
+xls_dslx_verilog(
+    name = "vtrace_fmt_verilog",
+    codegen_args = {
+        "delay_model": "asap7",
+        "max_trace_verbosity": "2",
+        "pipeline_stages": "2",
+        "reset": "rst",
+    },
+    dslx_top = "vtrace_fmt_example",
+    library = ":vtrace_fmt_dslx",
+    tags = ["manual"],
+    verilog_file = "vtrace_fmt.sv",
+)