chore(avm): add debugging info and trace dump (#6979)

Now if you pass `--avm-dump-trace /tmp/trace.csv` you'll get a dump of
the whole trace.

You will also get extra debug logs _on debug builds_ once
#6978 is fixed.

barretenberg/cpp/src/barretenberg/bb/log.hpp

@@ -1,15 +1,8 @@
 #pragma once
-#include <barretenberg/common/log.hpp>
-#include <iostream>
-
-extern bool verbose;
 
-template <typename... Args> inline void vinfo(Args... args)
-{
-    if (verbose) {
-        info(args...);
-    }
-}
+#include <cstdint>
+#include <iostream>
+#include <vector>
 
 /**
  * @brief Writes raw bytes of the vector to stdout

barretenberg/cpp/src/barretenberg/bb/main.cpp

@@ -16,6 +16,7 @@
 #include "log.hpp"
 #include <barretenberg/common/benchmark.hpp>
 #include <barretenberg/common/container.hpp>
+#include <barretenberg/common/log.hpp>
 #include <barretenberg/common/timer.hpp>
 #include <barretenberg/dsl/acir_format/acir_to_constraint_buf.hpp>
 #include <barretenberg/dsl/acir_proofs/acir_composer.hpp>
@@ -35,7 +36,6 @@ std::string getHomeDir()
 }
 
 std::string CRS_PATH = getHomeDir() + "/.bb-crs";
-bool verbose = false;
 
 const std::filesystem::path current_path = std::filesystem::current_path();
 const auto current_dir = current_path.filename().string();
@@ -69,7 +69,7 @@ void init_grumpkin_crs(size_t eccvm_dyadic_circuit_size)
 // TODO(https://github.com/AztecProtocol/barretenberg/issues/811) adapt for grumpkin
 acir_proofs::AcirComposer verifier_init()
 {
-    acir_proofs::AcirComposer acir_composer(0, verbose);
+    acir_proofs::AcirComposer acir_composer(0, verbose_logging);
     auto g2_data = get_bn254_g2_data(CRS_PATH);
     srs::init_crs_factory({}, g2_data);
     return acir_composer;
@@ -135,7 +135,7 @@ bool proveAndVerify(const std::string& bytecodePath, const std::string& witnessP
     auto constraint_system = get_constraint_system(bytecodePath, /*honk_recursion=*/false);
     auto witness = get_witness(witnessPath);
 
-    acir_proofs::AcirComposer acir_composer{ 0, verbose };
+    acir_proofs::AcirComposer acir_composer{ 0, verbose_logging };
     acir_composer.create_circuit(constraint_system, witness);
 
     init_bn254_crs(acir_composer.get_dyadic_circuit_size());
@@ -286,7 +286,7 @@ void prove(const std::string& bytecodePath, const std::string& witnessPath, cons
     auto constraint_system = get_constraint_system(bytecodePath, /*honk_recursion=*/false);
     auto witness = get_witness(witnessPath);
 
-    acir_proofs::AcirComposer acir_composer{ 0, verbose };
+    acir_proofs::AcirComposer acir_composer{ 0, verbose_logging };
     acir_composer.create_circuit(constraint_system, witness);
     init_bn254_crs(acir_composer.get_dyadic_circuit_size());
     acir_composer.init_proving_key();
@@ -316,7 +316,7 @@ void gateCount(const std::string& bytecodePath, bool honk_recursion)
     auto constraint_systems = get_constraint_systems(bytecodePath, honk_recursion);
     size_t i = 0;
     for (auto constraint_system : constraint_systems) {
-        acir_proofs::AcirComposer acir_composer(0, verbose);
+        acir_proofs::AcirComposer acir_composer(0, verbose_logging);
         acir_composer.create_circuit(constraint_system);
         auto circuit_size = acir_composer.get_total_circuit_size();
 
@@ -383,7 +383,7 @@ bool verify(const std::string& proof_path, const std::string& vk_path)
 void write_vk(const std::string& bytecodePath, const std::string& outputPath)
 {
     auto constraint_system = get_constraint_system(bytecodePath, /*honk_recursion=*/false);
-    acir_proofs::AcirComposer acir_composer{ 0, verbose };
+    acir_proofs::AcirComposer acir_composer{ 0, verbose_logging };
     acir_composer.create_circuit(constraint_system);
     init_bn254_crs(acir_composer.get_dyadic_circuit_size());
     acir_composer.init_proving_key();
@@ -401,7 +401,7 @@ void write_vk(const std::string& bytecodePath, const std::string& outputPath)
 void write_pk(const std::string& bytecodePath, const std::string& outputPath)
 {
     auto constraint_system = get_constraint_system(bytecodePath, /*honk_recursion=*/false);
-    acir_proofs::AcirComposer acir_composer{ 0, verbose };
+    acir_proofs::AcirComposer acir_composer{ 0, verbose_logging };
     acir_composer.create_circuit(constraint_system);
     init_bn254_crs(acir_composer.get_dyadic_circuit_size());
     auto pk = acir_composer.init_proving_key();
@@ -535,19 +535,29 @@ void avm_prove(const std::filesystem::path& bytecode_path,
                const std::filesystem::path& hints_path,
                const std::filesystem::path& output_path)
 {
-    // Get Bytecode
-    std::vector<uint8_t> const bytecode =
-        bytecode_path.extension() == ".gz" ? gunzip(bytecode_path) : read_file(bytecode_path);
+    std::vector<uint8_t> const bytecode = read_file(bytecode_path);
     std::vector<fr> const calldata = many_from_buffer<fr>(read_file(calldata_path));
     std::vector<fr> const public_inputs_vec = many_from_buffer<fr>(read_file(public_inputs_path));
     auto const avm_hints = bb::avm_trace::ExecutionHints::from(read_file(hints_path));
 
+    vinfo("bytecode size: ", bytecode.size());
+    vinfo("calldata size: ", calldata.size());
+    vinfo("public_inputs size: ", public_inputs_vec.size());
+    vinfo("hints.storage_value_hints size: ", avm_hints.storage_value_hints.size());
+    vinfo("hints.note_hash_exists_hints size: ", avm_hints.note_hash_exists_hints.size());
+    vinfo("hints.nullifier_exists_hints size: ", avm_hints.nullifier_exists_hints.size());
+    vinfo("hints.l1_to_l2_message_exists_hints size: ", avm_hints.l1_to_l2_message_exists_hints.size());
+    vinfo("hints.externalcall_hints size: ", avm_hints.externalcall_hints.size());
+    vinfo("hints.contract_instance_hints size: ", avm_hints.contract_instance_hints.size());
+
     // Hardcoded circuit size for now, with enough to support 16-bit range checks
     init_bn254_crs(1 << 17);
 
     // Prove execution and return vk
     auto const [verification_key, proof] =
         avm_trace::Execution::prove(bytecode, calldata, public_inputs_vec, avm_hints);
+    vinfo("------- PROVING DONE -------");
+
     // TODO(ilyas): <#4887>: Currently we only need these two parts of the vk, look into pcs_verification key reqs
     std::vector<uint64_t> vk_vector = { verification_key.circuit_size, verification_key.num_public_inputs };
     std::vector<fr> vk_as_fields = { verification_key.circuit_size, verification_key.num_public_inputs };
@@ -779,7 +789,7 @@ void prove_output_all(const std::string& bytecodePath, const std::string& witnes
     auto constraint_system = get_constraint_system(bytecodePath, /*honk_recursion=*/false);
     auto witness = get_witness(witnessPath);
 
-    acir_proofs::AcirComposer acir_composer{ 0, verbose };
+    acir_proofs::AcirComposer acir_composer{ 0, verbose_logging };
     acir_composer.create_circuit(constraint_system, witness);
     init_bn254_crs(acir_composer.get_dyadic_circuit_size());
     acir_composer.init_proving_key();
@@ -831,7 +841,7 @@ int main(int argc, char* argv[])
 {
     try {
         std::vector<std::string> args(argv + 1, argv + argc);
-        verbose = flag_present(args, "-v") || flag_present(args, "--verbose");
+        verbose_logging = flag_present(args, "-v") || flag_present(args, "--verbose_logging");
         if (args.empty()) {
             std::cerr << "No command provided.\n";
             return 1;
@@ -905,6 +915,8 @@ int main(int argc, char* argv[])
             std::filesystem::path avm_hints_path = get_option(args, "--avm-hints", "./target/avm_hints.bin");
             // This outputs both files: proof and vk, under the given directory.
             std::filesystem::path output_path = get_option(args, "-o", "./proofs");
+            extern std::filesystem::path avm_dump_trace_path;
+            avm_dump_trace_path = get_option(args, "--avm-dump-trace", "");
             avm_prove(avm_bytecode_path, avm_calldata_path, avm_public_inputs_path, avm_hints_path, output_path);
         } else if (command == "avm_verify") {
             return avm_verify(proof_path, vk_path) ? 0 : 1;

barretenberg/cpp/src/barretenberg/common/log.cpp

@@ -0,0 +1,2 @@
+// Used for `vinfo` in log.hpp.
+bool verbose_logging = false;

barretenberg/cpp/src/barretenberg/common/log.hpp

@@ -47,7 +47,7 @@ template <typename... Args> std::string benchmark_format(Args... args)
     return os.str();
 }
 
-#if NDEBUG
+#ifndef NDEBUG
 template <typename... Args> inline void debug(Args... args)
 {
     logstr(format(args...).c_str());
@@ -61,6 +61,14 @@ template <typename... Args> inline void info(Args... args)
     logstr(format(args...).c_str());
 }
 
+extern bool verbose_logging;
+template <typename... Args> inline void vinfo(Args... args)
+{
+    if (verbose_logging) {
+        info(args...);
+    }
+}
+
 template <typename... Args> inline void important(Args... args)
 {
     logstr(format("important: ", args...).c_str());

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_alu.hpp

@@ -127,6 +127,8 @@ template <typename FF> struct Avm_aluRow {
     FF avm_alu_u8_r1{};
     FF avm_alu_u8_r1_shift{};
     FF avm_alu_u8_tag{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_alu(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_binary.hpp

@@ -22,6 +22,8 @@ template <typename FF> struct Avm_binaryRow {
     FF avm_binary_mem_tag_ctr_shift{};
     FF avm_binary_op_id{};
     FF avm_binary_op_id_shift{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_binary(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_conversion.hpp

@@ -8,6 +8,8 @@ namespace bb::Avm_vm {
 
 template <typename FF> struct Avm_conversionRow {
     FF avm_conversion_to_radix_le_sel{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_conversion(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_keccakf1600.hpp

@@ -8,6 +8,8 @@ namespace bb::Avm_vm {
 
 template <typename FF> struct Avm_keccakf1600Row {
     FF avm_keccakf1600_keccakf1600_sel{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_keccakf1600(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_kernel.hpp

@@ -38,6 +38,8 @@ template <typename FF> struct Avm_kernelRow {
     FF avm_main_sel_op_nullifier_exists{};
     FF avm_main_sel_op_sload{};
     FF avm_main_sel_op_sstore{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_kernel(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_main.hpp

@@ -119,6 +119,8 @@ template <typename FF> struct Avm_mainRow {
     FF avm_main_space_id{};
     FF avm_main_tag_err{};
     FF avm_main_w_in_tag{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_main(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_mem.hpp

@@ -45,6 +45,8 @@ template <typename FF> struct Avm_memRow {
     FF avm_mem_val{};
     FF avm_mem_val_shift{};
     FF avm_mem_w_in_tag{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_mem(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_pedersen.hpp

@@ -8,6 +8,8 @@ namespace bb::Avm_vm {
 
 template <typename FF> struct Avm_pedersenRow {
     FF avm_pedersen_pedersen_sel{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_pedersen(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_poseidon2.hpp

@@ -8,6 +8,8 @@ namespace bb::Avm_vm {
 
 template <typename FF> struct Avm_poseidon2Row {
     FF avm_poseidon2_poseidon_perm_sel{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_poseidon2(int index)

barretenberg/cpp/src/barretenberg/relations/generated/avm/avm_sha256.hpp

@@ -8,6 +8,8 @@ namespace bb::Avm_vm {
 
 template <typename FF> struct Avm_sha256Row {
     FF avm_sha256_sha256_compression_sel{};
+
+    [[maybe_unused]] static std::vector<std::string> names();
 };
 
 inline std::string get_relation_label_avm_sha256(int index)

barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_deserialization.cpp

@@ -179,6 +179,8 @@ std::vector<Instruction> Deserialization::parse(std::vector<uint8_t> const& byte
     size_t pos = 0;
     const auto length = bytecode.size();
 
+    debug("------- PARSING BYTECODE -------");
+    debug("Parsing bytecode of length: " + std::to_string(length));
     while (pos < length) {
         const uint8_t opcode_byte = bytecode.at(pos);
 
@@ -242,12 +244,12 @@ std::vector<Instruction> Deserialization::parse(std::vector<uint8_t> const& byte
         }
 
         std::vector<Operand> operands;
-
         for (OperandType const& opType : inst_format) {
             // No underflow as while condition guarantees pos <= length (after pos++)
             if (length - pos < OPERAND_TYPE_SIZE.at(opType)) {
-                throw_or_abort("Operand is missing at position " + std::to_string(pos) +
-                               " for opcode: " + to_hex(opcode));
+                throw_or_abort("Operand is missing at position " + std::to_string(pos) + " for opcode " +
+                               to_hex(opcode) + " not enough bytes for operand type " +
+                               std::to_string(static_cast<int>(opType)));
             }
 
             switch (opType) {
@@ -298,7 +300,9 @@ std::vector<Instruction> Deserialization::parse(std::vector<uint8_t> const& byte
             }
             pos += OPERAND_TYPE_SIZE.at(opType);
         }
-        instructions.emplace_back(opcode, operands);
+        auto instruction = Instruction(opcode, operands);
+        debug(instruction.to_string());
+        instructions.emplace_back(std::move(instruction));
     }
     return instructions;
 };

barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_execution.cpp

@@ -1,4 +1,5 @@
 #include "barretenberg/vm/avm_trace/avm_execution.hpp"
+#include "barretenberg/bb/log.hpp"
 #include "barretenberg/common/serialize.hpp"
 #include "barretenberg/vm/avm_trace/avm_common.hpp"
 #include "barretenberg/vm/avm_trace/avm_deserialization.hpp"
@@ -16,13 +17,17 @@
 #include <cassert>
 #include <cstddef>
 #include <cstdint>
+#include <filesystem>
 #include <string>
 #include <tuple>
 #include <variant>
 #include <vector>
 
 using namespace bb;
 
+// Set in BB's main.cpp.
+std::filesystem::path avm_dump_trace_path;
+
 namespace bb::avm_trace {
 
 /**
@@ -56,8 +61,14 @@ std::tuple<AvmFlavor::VerificationKey, HonkProof> Execution::prove(std::vector<u
     }
 
     auto instructions = Deserialization::parse(bytecode);
-    std::vector<FF> returndata{};
+    vinfo("Deserialized " + std::to_string(instructions.size()) + " instructions");
+
+    std::vector<FF> returndata;
     auto trace = gen_trace(instructions, returndata, calldata, public_inputs_vec, execution_hints);
+    if (!avm_dump_trace_path.empty()) {
+        info("Dumping trace as CSV to: " + avm_dump_trace_path.string());
+        dump_trace_as_csv(trace, avm_dump_trace_path);
+    }
     auto circuit_builder = bb::AvmCircuitBuilder();
     circuit_builder.set_trace(std::move(trace));
 
@@ -291,6 +302,7 @@ std::vector<Row> Execution::gen_trace(std::vector<Instruction> const& instructio
                                       ExecutionHints const& execution_hints)
 
 {
+    vinfo("------- GENERATING TRACE -------");
     // TODO(https://github.com/AztecProtocol/aztec-packages/issues/6718): construction of the public input columns
     // should be done in the kernel - this is stubbed and underconstrained
     VmPublicInputs public_inputs = convert_public_inputs(public_inputs_vec);
@@ -302,6 +314,7 @@ std::vector<Row> Execution::gen_trace(std::vector<Instruction> const& instructio
     uint32_t pc = 0;
     while ((pc = trace_builder.getPc()) < instructions.size()) {
         auto inst = instructions.at(pc);
+        debug("[@" + std::to_string(pc) + "] " + inst.to_string());
 
         // TODO: We do not yet support the indirect flag. Therefore we do not extract
         // inst.operands(0) (i.e. the indirect flag) when processiing the instructions.

barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_helper.cpp

@@ -1,5 +1,6 @@
 #include "barretenberg/vm/avm_trace/avm_helper.hpp"
 #include "barretenberg/vm/avm_trace/avm_mem_trace.hpp"
+#include "barretenberg/vm/generated/avm_circuit_builder.hpp"
 
 namespace bb::avm_trace {
 
@@ -99,6 +100,21 @@ void log_avm_trace(std::vector<Row> const& trace, size_t beg, size_t end, bool e
     }
 }
 
+void dump_trace_as_csv(std::vector<Row> const& trace, std::filesystem::path const& filename)
+{
+    std::ofstream file;
+    file.open(filename);
+
+    for (const auto& row_name : Row::names()) {
+        file << row_name << ",";
+    }
+    file << std::endl;
+
+    for (const auto& row : trace) {
+        file << row << std::endl;
+    }
+}
+
 bool is_operand_indirect(uint8_t ind_value, uint8_t operand_idx)
 {
     if (operand_idx > 7) {