fix: debug memcpy chip

benchmarks/guest/fibonacci/Cargo.toml

@@ -7,4 +7,5 @@ edition.workspace = true
 openvm = { workspace = true, features = ["std"] }
 
 [features]
-default = []
+default = ["custom-memcpy"]
+custom-memcpy = []

benchmarks/guest/fibonacci/src/main.rs

@@ -1,44 +1,79 @@
 use core::ptr;
+#[cfg(test)]
+use rand::{rngs::StdRng, Rng, SeedableRng};
+#[cfg(test)]
+use test_case::test_case;
 
 openvm::entry!(main);
 
-/// Moves all the elements of `src` into `dst`, leaving `src` empty.
 #[no_mangle]
 pub fn append<T>(dst: &mut [T], src: &mut [T], shift: usize) {
     let src_len = src.len();
-    let dst_len = dst.len();
+    let _dst_len = dst.len();
 
     unsafe {
         // The call to add is always safe because `Vec` will never
         // allocate more than `isize::MAX` bytes.
         let dst_ptr = dst.as_mut_ptr().wrapping_add(shift);
         let src_ptr = src.as_ptr();
-        println!("dst_ptr: {:?}", dst_ptr);
-        println!("src_ptr: {:?}", src_ptr);
-        println!("src_len: {:?}", src_len);
+        println!("dst_ptr: {}", dst_ptr as usize); // these have the same pointer destination (basically), in between runs
+        println!("src_ptr: {}", src_ptr as usize);
+        println!("src_len: {}", src_len);
 
-        // The two regions cannot overlap because mutable references do
-        // not alias, and two different vectors cannot own the same
-        // memory.
         ptr::copy_nonoverlapping(src_ptr, dst_ptr, src_len);
     }
 }
+#[cfg_attr(test, test_case(0, 100, 42))] // shift, length
+#[cfg_attr(test, test_case(1, 100, 42))]
+#[cfg_attr(test, test_case(2, 100, 42))]
+#[cfg_attr(test, test_case(3, 100, 42))]
+fn test1(shift: usize, length: usize, seed: u64) {
+    let n: usize = length;
 
-pub fn main() {
-    let mut a: [u8; 1000] = [1; 1000];
-    let mut b: [u8; 500] = [2; 500];
+    let mut a: Vec<u8> = vec![0; 2 * n];
+    let mut b: Vec<u8> = vec![2; n];
 
-    let shift: usize = 0;
-    append(&mut a, &mut b, shift);
+    let mut rng = StdRng::seed_from_u64(seed); // fixed seed
+    for i in 0..n {
+        b[i] = rng.gen::<u8>();
+    }
+    println!("b: {:?}", b);
+    append(&mut a[..], &mut b[..], shift);
 
-    for i in 0..1000 {
+    println!("a: {:?}", a);
+    println!("b: {:?}", b);
+    let mut idx = 0;
+    for i in 0..(2 * n) {
         if i < shift || i >= shift + b.len() {
-            assert_eq!(a[i], 1);
+            assert_eq!(a[i], 0);
         } else {
-            assert_eq!(a[i], 2);
+            assert_eq!(a[i], b[idx]);
+            idx += 1;
         }
     }
+}
+pub fn main() {
+    const n: usize = 32;
+
+    let mut a: [u8; 2 * n] = [0; 2 * n];
+    let mut b: [u8; n] = [2; n];
+
+    let shift: usize = 1;
+    for i in 0..n {
+        b[i] = (7 * i + 13) as u8;
+    }
+    println!("b: {:?}", b);
+    append(&mut a, &mut b, shift);
 
     println!("a: {:?}", a);
     println!("b: {:?}", b);
-}
+    let mut idx = 0;
+    for i in 0..2 * n {
+        if i < shift || i >= shift + b.len() {
+            assert_eq!(a[i], 0);
+        } else {
+            assert_eq!(a[i], b[idx]);
+            idx += 1;
+        }
+    }
+}

crates/toolchain/openvm/Cargo.toml

@@ -28,13 +28,15 @@ num-bigint.workspace = true
 chrono = { version = "0.4", default-features = false, features = ["serde"] }
 
 [features]
-default = ["getrandom-unsupported"]
+default = ["getrandom-unsupported", "custom-memcpy"]
 # Defines a custom getrandom backend that always errors. This feature should be enabled if you are sure getrandom is never used but it is pulled in as a compilation dependency.
 getrandom-unsupported = ["dep:getrandom", "dep:getrandom-v02"]
 # The zkVM uses a bump-pointer heap allocator by default which does not free
 # memory. This will use a slower linked-list heap allocator to reclaim memory.
 heap-embedded-alloc = ["openvm-platform/heap-embedded-alloc"]
 std = ["serde/std", "openvm-platform/std"]
+# Enable custom memcpy implementation with specialized instructions
+custom-memcpy = []
 
 [package.metadata.cargo-shear]
 ignored = ["openvm-custom-insn", "getrandom"]

crates/vm/src/arch/execution_mode/metered/ctx.rs

@@ -225,6 +225,14 @@ impl<const PAGE_BITS: usize> ExecutionCtxTrait for MeteredCtx<PAGE_BITS> {
 impl<const PAGE_BITS: usize> MeteredExecutionCtxTrait for MeteredCtx<PAGE_BITS> {
     #[inline(always)]
     fn on_height_change(&mut self, chip_idx: usize, height_delta: u32) {
+        // if chip_idx == 10 {
+        //     eprintln!(
+        //         "crates/vm/src/arch/execution_mode/metered/ctx.rs::on_height_change: AIR[10] height change: {} -> {} (delta: {})",
+        //         self.trace_heights[10],
+        //         self.trace_heights[10].wrapping_add(height_delta),
+        //         height_delta
+        //     );
+        // }
         debug_assert!(
             chip_idx < self.trace_heights.len(),
             "chip_idx out of bounds"

crates/vm/src/arch/interpreter.rs

@@ -766,6 +766,9 @@ where
                         pre_compute: buf,
                     }
                 } else if let Some(&executor_idx) = inventory.instruction_lookup.get(&inst.opcode) {
+                    // if inst.opcode.as_usize() == 595 {  // MULHU opcode
+                    //     println!("crates/vm/src/arch/interpreter.rs::get_metered_pre_compute_instructions: MULHU instruction (opcode 595) being routed to metered execution, executor_idx: {}", executor_idx);
+                    // }
                     let executor_idx = executor_idx as usize;
                     let executor = inventory
                         .executors

crates/vm/src/arch/record_arena.rs

@@ -90,8 +90,15 @@ impl<F: Field> MatrixRecordArena<F> {
     }
 
     pub fn alloc_buffer(&mut self, num_rows: usize) -> &mut [u8] {
-        let start = self.trace_offset;
+        let start: usize = self.trace_offset;
         self.trace_offset += num_rows * self.width;
+
+        // eprintln!("matrix record arena alloc buffer called");
+        // eprintln!("width = {:?}", self.width);
+        // eprintln!("num_rows = {:?}", num_rows);
+        // eprintln!("start = {:?}", start);
+        // eprintln!("trace_offset = {:?}", self.trace_offset);
+
         let row_slice = &mut self.trace_buffer[start..self.trace_offset];
         let size = size_of_val(row_slice);
         let ptr = row_slice as *mut [F] as *mut u8;
@@ -111,6 +118,15 @@ impl<F: Field> Arena for MatrixRecordArena<F> {
     fn with_capacity(height: usize, width: usize) -> Self {
         let height = next_power_of_two_or_zero(height);
         let trace_buffer = F::zero_vec(height * width);
+        // eprintln!(
+        //     "crates/vm/src/arch/record_arena.rs::with_capacity: with capacity called, height = {:?}, width = {:?}",
+        //     height, width
+        // );
+        // height * width is wrong?
+        // i think bug is here? on constructor the trace buffer
+        // isn't allocated to be the correct size
+        // eprintln!("height, width = {:?}, {:?}", height, width);
+        // eprintln!("trace_buffer.len() = {:?}", trace_buffer.len());
         Self {
             trace_buffer,
             width,
@@ -133,6 +149,10 @@ impl<F: Field> RowMajorMatrixArena<F> for MatrixRecordArena<F> {
     fn set_capacity(&mut self, trace_height: usize) {
         let size = trace_height * self.width;
         // PERF: use memset
+        // eprintln!("set_capacity called");
+        // eprintln!("size = {:?}", size);
+        // eprintln!("trace_height = {:?}", trace_height);
+        // eprintln!("self.width = {:?}", self.width);
         self.trace_buffer.resize(size, F::ZERO);
     }
 
@@ -145,6 +165,7 @@ impl<F: Field> RowMajorMatrixArena<F> for MatrixRecordArena<F> {
     }
 
     fn into_matrix(mut self) -> RowMajorMatrix<F> {
+        // eprintln!("into_matrix called");
         let width = self.width();
         assert_eq!(self.trace_offset() % width, 0);
         let rows_used = self.trace_offset() / width;
@@ -158,6 +179,7 @@ impl<F: Field> RowMajorMatrixArena<F> for MatrixRecordArena<F> {
             let height = self.trace_buffer.len() / width;
             assert!(height.is_power_of_two() || height == 0);
         }
+        // eprintln!("into_matrix done");
         RowMajorMatrix::new(self.trace_buffer, self.width)
     }
 }
@@ -534,6 +556,13 @@ where
     [u8]: CustomBorrow<'a, R, MultiRowLayout<M>>,
 {
     fn alloc(&'a mut self, layout: MultiRowLayout<M>) -> R {
+        // alloc override of the alloc function in the trait
+
+        // eprintln!("MatrixRecordArena::alloc override called");
+        // eprintln!(
+        //     "layout.metadata.get_num_rows() = {:?}",
+        //     layout.metadata.get_num_rows()
+        // );
         let buffer = self.alloc_buffer(layout.metadata.get_num_rows());
         let record: R = buffer.custom_borrow(layout);
         record
@@ -548,6 +577,7 @@ where
     R: SizedRecord<MultiRowLayout<M>>,
 {
     fn alloc(&'a mut self, layout: MultiRowLayout<M>) -> R {
+        eprintln!("DenseRecordArena::alloc override called");
         let record_size = R::size(&layout);
         let record_alignment = R::alignment(&layout);
         let aligned_record_size = record_size.next_multiple_of(record_alignment);
@@ -669,6 +699,7 @@ where
     C: SizedRecord<AdapterCoreLayout<M>>,
 {
     fn alloc(&'a mut self, layout: AdapterCoreLayout<M>) -> (A, C) {
+        eprintln!("DenseRecordArena2::alloc override called");
         let adapter_alignment = A::alignment(&layout);
         let core_alignment = C::alignment(&layout);
         let adapter_size = A::size(&layout);

crates/vm/src/arch/testing/cpu.rs

@@ -544,6 +544,9 @@ where
     {
         assert!(self.memory.is_none(), "Memory must be finalized");
         let (airs, ctxs): (Vec<_>, Vec<_>) = self.air_ctxs.into_iter().unzip();
+        // for (ctx, air) in ctxs.clone().iter().zip(airs.iter()) {
+        //     eprintln!("{}: {}", air.name(), ctx.main_trace_height());
+        // }
         engine_provider().run_test_impl(airs, ctxs)
     }
 }

crates/vm/src/arch/vm.rs

@@ -457,6 +457,11 @@ where
         <VB::VmConfig as VmExecutionConfig<Val<E::SC>>>::Executor:
             PreflightExecutor<Val<E::SC>, VB::RecordArena>,
     {
+        // eprintln!("crates/vm/src/arch/vm.rs::execute_preflight");
+        // eprintln!("=== TRACE HEIGHTS PASSED TO EXECUTE_PREFLIGHT ===");
+        // for (air_idx, &height) in trace_heights.iter().enumerate() {
+        //     eprintln!("AIR[{}]: trace_height={}", air_idx, height);
+        // }
         debug_assert!(interpreter
             .executor_idx_to_air_idx
             .iter()
@@ -473,6 +478,34 @@ where
         let capacities = zip_eq(trace_heights, main_widths)
             .map(|(&h, w)| (h as usize, w))
             .collect::<Vec<_>>();
+
+        let executor_idx_to_air_idx = self.executor_idx_to_air_idx();
+
+        // Debug logging for capacities and AIR mapping
+        // eprintln!("=== CAPACITY DEBUG INFO ===");
+        // for (air_idx, &(height, width)) in capacities.iter().enumerate() {
+        //     eprintln!(
+        //         "AIR[{}]: height={}, width={}, total_elements={}",
+        //         air_idx,
+        //         height,
+        //         width,
+        //         height * width
+        //     );
+        // }
+
+        // eprintln!("=== EXECUTOR TO AIR MAPPING ===");
+        // for (executor_idx, &air_idx) in executor_idx_to_air_idx.iter().enumerate() {
+        //     eprintln!("Executor[{}] -> AIR[{}]", executor_idx, air_idx);
+        // }
+        let executor_inventory = &self.executor().inventory;
+
+        // Find all opcodes that map to executor index 14
+        // eprintln!("=== OPCODES FOR EXECUTOR[14] ===");
+        // for (opcode, &executor_idx) in &executor_inventory.instruction_lookup {
+        //     if executor_idx == 14 {
+        //         eprintln!("Opcode {} -> Executor[{}]", opcode, executor_idx);
+        //     }
+        // }
         let ctx = PreflightCtx::new_with_capacity(&capacities, instret_end);
 
         let system_config: &SystemConfig = self.config().as_ref();
@@ -1003,7 +1036,6 @@ where
                 &trace_heights,
             )?;
             state = Some(to_state);
-
             let mut ctx = vm.generate_proving_ctx(system_records, record_arenas)?;
             modify_ctx(seg_idx, &mut ctx);
             let proof = vm.engine.prove(vm.pk(), ctx);
@@ -1327,6 +1359,7 @@ pub fn debug_proving_ctx<E, VB>(
             )
         }));
     vm.engine.debug(&airs, &pks, &proof_inputs);
+    eprintln!("End of function VM debug");
 }
 
 #[cfg(feature = "metrics")]

crates/vm/src/system/memory/controller/mod.rs

@@ -364,6 +364,10 @@ pub struct MemoryAuxColsFactory<'a, F> {
 impl<F: PrimeField32> MemoryAuxColsFactory<'_, F> {
     /// Fill the trace assuming `prev_timestamp` is already provided in `buffer`.
     pub fn fill(&self, prev_timestamp: u32, timestamp: u32, buffer: &mut MemoryBaseAuxCols<F>) {
+        // eprintln!(
+        //     "fill prev_timestamp: {:?}, timestamp: {:?}",
+        //     prev_timestamp, timestamp
+        // );
         self.generate_timestamp_lt(prev_timestamp, timestamp, &mut buffer.timestamp_lt_aux);
         // Safety: even if prev_timestamp were obtained by transmute_ref from
         // `buffer.prev_timestamp`, this should still work because it is a direct assignment

crates/vm/src/utils/stark_utils.rs

@@ -5,7 +5,9 @@ use openvm_stark_backend::{
     p3_field::PrimeField32,
 };
 use openvm_stark_sdk::{
-    config::{baby_bear_poseidon2::BabyBearPoseidon2Config, setup_tracing, FriParameters},
+    config::{
+        baby_bear_poseidon2::BabyBearPoseidon2Config, setup_tracing_with_log_level, FriParameters,
+    },
     engine::{StarkFriEngine, VerificationDataWithFriParams},
     p3_baby_bear::BabyBear,
 };
@@ -108,7 +110,7 @@ where
         + PreflightExecutor<Val<E::SC>, VB::RecordArena>,
     Com<E::SC>: AsRef<[Val<E::SC>; CHUNK]> + From<[Val<E::SC>; CHUNK]>,
 {
-    setup_tracing();
+    setup_tracing_with_log_level(tracing::Level::DEBUG);
     let engine = E::new(fri_params);
     let (mut vm, pk) = VirtualMachine::<E, VB>::new_with_keygen(engine, builder, config)?;
     let vk = pk.get_vk();
@@ -150,9 +152,11 @@ where
         let ctx = vm.generate_proving_ctx(system_records, record_arenas)?;
         if debug {
             debug_proving_ctx(&vm, &pk, &ctx);
+            eprintln!("End of function stark_utils debug");
         }
         let proof = vm.engine.prove(vm.pk(), ctx);
         proofs.push(proof);
+        eprintln!("End of function stark_utils prove");
     }
     assert!(proofs.len() >= min_segments);
     vm.verify(&vk, &proofs)

extensions/algebra/tests/src/lib.rs

@@ -137,7 +137,7 @@ mod tests {
     }
 
     #[test]
-    fn test_complex() -> Result<()> {
+    fn test_complex1() -> Result<()> {
         let config = test_rv32modularwithfp2_config(vec![(
             "Complex".to_string(),
             SECP256K1_CONFIG.modulus.clone(),

extensions/ecc/tests/Cargo.toml

@@ -16,6 +16,7 @@ openvm-ecc-transpiler.workspace = true
 openvm-ecc-circuit.workspace = true
 openvm-rv32im-transpiler.workspace = true
 openvm-memcpy-transpiler.workspace = true
+openvm-keccak256-transpiler.workspace = true
 openvm-toolchain-tests = { path = "../../../crates/toolchain/tests" }
 openvm-sdk.workspace = true
 serde.workspace = true

extensions/ecc/tests/programs/openvm_k256.toml

@@ -1,6 +1,7 @@
 [app_vm_config.rv32i]
 [app_vm_config.rv32m]
 [app_vm_config.io]
+[app_vm_config.memcpy]
 
 [app_vm_config.modular]
 supported_moduli = [

extensions/ecc/tests/programs/openvm_k256_keccak.toml

@@ -2,6 +2,7 @@
 [app_vm_config.rv32m]
 [app_vm_config.io]
 [app_vm_config.keccak]
+[app_vm_config.memcpy]
 
 [app_vm_config.modular]
 supported_moduli = [

extensions/ecc/tests/programs/openvm_p256.toml

@@ -1,7 +1,9 @@
 [app_vm_config.rv32i]
 [app_vm_config.rv32m]
 [app_vm_config.io]
+[app_vm_config.memcpy]
 [app_vm_config.modular]
+
 supported_moduli = [
     "115792089210356248762697446949407573530086143415290314195533631308867097853951",
     "115792089210356248762697446949407573529996955224135760342422259061068512044369",