chore: align debug logging between AVM sim & witgen (#9498)

barretenberg/cpp/src/barretenberg/vm/avm/trace/execution.cpp

@@ -288,9 +288,12 @@ std::vector<Row> Execution::gen_trace(std::vector<FF> const& calldata,
     // on opcode logic and therefore is not maintained here. However, the next opcode in the execution
     // is determined by this value which require read access to the code below.
     uint32_t pc = 0;
-    while ((pc = trace_builder.getPc()) < instructions.size()) {
+    uint32_t counter = 0;
+    while ((pc = trace_builder.get_pc()) < instructions.size()) {
         auto inst = instructions.at(pc);
-        debug("[@" + std::to_string(pc) + "] " + inst.to_string());
+
+        debug("[PC:" + std::to_string(pc) + "] [IC:" + std::to_string(counter++) + "] " + inst.to_string() +
+              " (gasLeft l2=" + std::to_string(trace_builder.get_l2_gas_left()) + ")");
 
         switch (inst.op_code) {
             // Compute
@@ -654,6 +657,7 @@ std::vector<Row> Execution::gen_trace(std::vector<FF> const& calldata,
             break;
         }
         case OpCode::REVERT_8: {
+            info("HIT REVERT_8  ", "[PC=" + std::to_string(pc) + "] " + inst.to_string());
             auto ret = trace_builder.op_revert(std::get<uint8_t>(inst.operands.at(0)),
                                                std::get<uint8_t>(inst.operands.at(1)),
                                                std::get<uint8_t>(inst.operands.at(2)));
@@ -662,6 +666,7 @@ std::vector<Row> Execution::gen_trace(std::vector<FF> const& calldata,
             break;
         }
         case OpCode::REVERT_16: {
+            info("HIT REVERT_16 ", "[PC=" + std::to_string(pc) + "] " + inst.to_string());
             auto ret = trace_builder.op_revert(std::get<uint8_t>(inst.operands.at(0)),
                                                std::get<uint16_t>(inst.operands.at(1)),
                                                std::get<uint16_t>(inst.operands.at(2)));

barretenberg/cpp/src/barretenberg/vm/avm/trace/gas_trace.cpp

@@ -26,6 +26,9 @@ void AvmGasTraceBuilder::set_initial_gas(uint32_t l2_gas, uint32_t da_gas)
 
 uint32_t AvmGasTraceBuilder::get_l2_gas_left() const
 {
+    if (gas_trace.size() == 0) {
+        return initial_l2_gas;
+    }
     return gas_trace.back().remaining_l2_gas;
 }
 

barretenberg/cpp/src/barretenberg/vm/avm/trace/helper.cpp

@@ -1,4 +1,5 @@
 #include "barretenberg/vm/avm/trace/helper.hpp"
+#include "barretenberg/vm/avm/trace/common.hpp"
 #include "barretenberg/vm/avm/trace/mem_trace.hpp"
 #include <algorithm>
 #include <cassert>
@@ -75,6 +76,29 @@ std::string to_hex(bb::avm_trace::AvmMemoryTag tag)
     return to_hex(static_cast<uint8_t>(tag));
 }
 
+std::string to_name(bb::avm_trace::AvmMemoryTag tag)
+{
+    switch (tag) {
+    case bb::avm_trace::AvmMemoryTag::FF:
+        return "Field";
+    case bb::avm_trace::AvmMemoryTag::U1:
+        return "Uint1";
+    case bb::avm_trace::AvmMemoryTag::U8:
+        return "Uint8";
+    case bb::avm_trace::AvmMemoryTag::U16:
+        return "Uint16";
+    case bb::avm_trace::AvmMemoryTag::U32:
+        return "Uint32";
+    case bb::avm_trace::AvmMemoryTag::U64:
+        return "Uint64";
+    case bb::avm_trace::AvmMemoryTag::U128:
+        return "Uint128";
+    default:
+        throw std::runtime_error("Invalid memory tag");
+        break;
+    }
+}
+
 /**
  *
  *  ONLY FOR TESTS - Required by dsl module and therefore cannot be moved to test/helpers.test.cpp

barretenberg/cpp/src/barretenberg/vm/avm/trace/helper.hpp

@@ -230,6 +230,8 @@ std::string to_hex(T value)
 
 std::string to_hex(bb::avm_trace::AvmMemoryTag tag);
 
+std::string to_name(bb::avm_trace::AvmMemoryTag tag);
+
 // Mutate the inputs
 void inject_end_gas_values(VmPublicInputs& public_inputs, std::vector<Row>& trace);
 

barretenberg/cpp/src/barretenberg/vm/avm/trace/mem_trace.cpp

@@ -1,5 +1,6 @@
 #include "barretenberg/vm/avm/trace/mem_trace.hpp"
 #include "barretenberg/vm/avm/trace/common.hpp"
+#include "barretenberg/vm/avm/trace/helper.hpp"
 #include "barretenberg/vm/avm/trace/trace.hpp"
 
 #include <cstdint>
@@ -29,6 +30,19 @@ std::vector<AvmMemTraceBuilder::MemoryTraceEntry> AvmMemTraceBuilder::finalize()
     return std::move(mem_trace);
 }
 
+void AvmMemTraceBuilder::debug_mem_trace_entry(MemoryTraceEntry entry)
+{
+    std::string suffix;
+    if (entry.m_space_id == INTERNAL_CALL_SPACE_ID) {
+        suffix = " (INTERNAL CALL STACK OP)";
+    }
+    if (entry.m_rw) {
+        debug("set(", entry.m_addr, ", ", to_name(entry.w_in_tag), "(", entry.m_val, "))", suffix);
+    } else {
+        debug("get(", entry.m_addr, ", ", to_name(entry.r_in_tag), "(", entry.m_val, "))", suffix);
+    }
+}
+
 /**
  * @brief A method to insert a row/entry in the memory trace.
  *
@@ -73,6 +87,8 @@ void AvmMemTraceBuilder::insert_in_mem_trace(uint8_t space_id,
         mem_trace_entry.poseidon_mem_op = true;
         break;
     }
+
+    debug_mem_trace_entry(mem_trace_entry);
     mem_trace.emplace_back(mem_trace_entry);
 }
 
@@ -114,17 +130,19 @@ void AvmMemTraceBuilder::load_mismatch_tag_in_mem_trace(uint8_t space_id,
     // Lookup counter hint, used for #[INCL_MAIN_TAG_ERR] lookup (joined on clk)
     m_tag_err_lookup_counts[m_clk]++;
 
-    mem_trace.emplace_back(MemoryTraceEntry{ .m_space_id = space_id,
-                                             .m_clk = m_clk,
-                                             .m_sub_clk = m_sub_clk,
-                                             .m_addr = m_addr,
-                                             .m_val = m_val,
-                                             .m_tag = m_tag,
-                                             .r_in_tag = r_in_tag,
-                                             .w_in_tag = w_in_tag,
-                                             .m_tag_err = true,
-                                             .m_one_min_inv = one_min_inv,
-                                             .m_tag_err_count_relevant = tag_err_count_relevant });
+    auto mem_trace_entry = MemoryTraceEntry({ .m_space_id = space_id,
+                                              .m_clk = m_clk,
+                                              .m_sub_clk = m_sub_clk,
+                                              .m_addr = m_addr,
+                                              .m_val = m_val,
+                                              .m_tag = m_tag,
+                                              .r_in_tag = r_in_tag,
+                                              .w_in_tag = w_in_tag,
+                                              .m_tag_err = true,
+                                              .m_one_min_inv = one_min_inv,
+                                              .m_tag_err_count_relevant = tag_err_count_relevant });
+    debug_mem_trace_entry(mem_trace_entry);
+    mem_trace.emplace_back(mem_trace_entry);
 }
 
 /**
@@ -224,7 +242,7 @@ AvmMemTraceBuilder::MemEntry AvmMemTraceBuilder::read_and_load_mov_opcode(uint8_
     auto& mem_space = memory.at(space_id);
     MemEntry mem_entry = mem_space.contains(addr) ? mem_space.at(addr) : MemEntry{};
 
-    mem_trace.emplace_back(MemoryTraceEntry{
+    auto mem_trace_entry = MemoryTraceEntry({
         .m_space_id = space_id,
         .m_clk = clk,
         .m_sub_clk = SUB_CLK_LOAD_A,
@@ -235,6 +253,8 @@ AvmMemTraceBuilder::MemEntry AvmMemTraceBuilder::read_and_load_mov_opcode(uint8_
         .w_in_tag = mem_entry.tag,
         .m_sel_mov_ia_to_ic = true,
     });
+    debug_mem_trace_entry(mem_trace_entry);
+    mem_trace.emplace_back(mem_trace_entry);
 
     return mem_entry;
 }
@@ -258,7 +278,7 @@ AvmMemTraceBuilder::MemEntry AvmMemTraceBuilder::read_and_load_jumpi_opcode(uint
     auto& mem_space = memory.at(space_id);
     MemEntry cond_mem_entry = mem_space.contains(cond_addr) ? mem_space.at(cond_addr) : MemEntry{};
 
-    mem_trace.emplace_back(MemoryTraceEntry{
+    auto mem_trace_entry = MemoryTraceEntry({
         .m_space_id = space_id,
         .m_clk = clk,
         .m_sub_clk = SUB_CLK_LOAD_D,
@@ -268,6 +288,8 @@ AvmMemTraceBuilder::MemEntry AvmMemTraceBuilder::read_and_load_jumpi_opcode(uint
         .r_in_tag = cond_mem_entry.tag,
         .w_in_tag = cond_mem_entry.tag,
     });
+    debug_mem_trace_entry(mem_trace_entry);
+    mem_trace.emplace_back(mem_trace_entry);
 
     return cond_mem_entry;
 }
@@ -295,7 +317,7 @@ AvmMemTraceBuilder::MemEntry AvmMemTraceBuilder::read_and_load_cast_opcode(uint8
     auto& mem_space = memory.at(space_id);
     MemEntry mem_entry = mem_space.contains(addr) ? mem_space.at(addr) : MemEntry{};
 
-    mem_trace.emplace_back(MemoryTraceEntry{
+    auto mem_trace_entry = MemoryTraceEntry({
         .m_space_id = space_id,
         .m_clk = clk,
         .m_sub_clk = SUB_CLK_LOAD_A,
@@ -305,6 +327,8 @@ AvmMemTraceBuilder::MemEntry AvmMemTraceBuilder::read_and_load_cast_opcode(uint8
         .r_in_tag = mem_entry.tag,
         .w_in_tag = w_in_tag,
     });
+    debug_mem_trace_entry(mem_trace_entry);
+    mem_trace.emplace_back(mem_trace_entry);
 
     return mem_entry;
 }

barretenberg/cpp/src/barretenberg/vm/avm/trace/mem_trace.hpp

@@ -115,6 +115,8 @@ class AvmMemTraceBuilder {
     // Global Memory table (used for simulation): (space_id, (address, mem_entry))
     std::array<std::unordered_map<uint32_t, MemEntry>, NUM_MEM_SPACES> memory;
 
+    static void debug_mem_trace_entry(MemoryTraceEntry entry);
+
     void insert_in_mem_trace(uint8_t space_id,
                              uint32_t m_clk,
                              uint32_t m_sub_clk,

barretenberg/cpp/src/barretenberg/vm/avm/trace/trace.hpp

@@ -35,7 +35,9 @@ class AvmTraceBuilder {
                     uint32_t side_effect_counter = 0,
                     std::vector<FF> calldata = {});
 
-    uint32_t getPc() const { return pc; }
+    uint32_t get_pc() const { return pc; }
+    uint32_t get_l2_gas_left() const { return gas_trace_builder.get_l2_gas_left(); }
+    uint32_t get_da_gas_left() const { return gas_trace_builder.get_da_gas_left(); }
 
     // Compute - Arithmetic
     void op_add(uint8_t indirect, uint32_t a_offset, uint32_t b_offset, uint32_t dst_offset);

yarn-project/simulator/src/avm/avm_simulator.ts

@@ -85,6 +85,7 @@ export class AvmSimulator {
     try {
       // Execute instruction pointed to by the current program counter
       // continuing until the machine state signifies a halt
+      let instrCounter = 0;
       while (!machineState.getHalted()) {
         const instruction = instructions[machineState.pc];
         assert(
@@ -96,7 +97,9 @@ export class AvmSimulator {
         const instrPc = machineState.pc; // Save PC before executing instruction (for profiling)
 
         this.log.debug(
-          `@${machineState.pc} ${instruction.toString()} (l2=${machineState.l2GasLeft} da=${machineState.daGasLeft})`,
+          `[PC:${machineState.pc}] [IC:${instrCounter++}] ${instruction.toString()} (gasLeft l2=${
+            machineState.l2GasLeft
+          } da=${machineState.daGasLeft})`,
         );
         // Execute the instruction.
         // Normal returns and reverts will return normally here.