debug: measuring instruction consumption

.gitignore

@@ -6,3 +6,5 @@
 .vscode/
 .idea/
 **/*~
+
+tmp/

Cargo.toml

@@ -15,6 +15,7 @@ version = "0.6.8"
 ic_principal = { version = "0.1.1", default-features = false }
 # An optional dependency to benchmark parts of the code.
 canbench-rs = { version = "0.1.7", optional = true }
+ic-cdk = { version = "0.17.1", default-features = false }
 
 [dev-dependencies]
 candid.workspace = true

src/btreemap.rs

@@ -105,6 +105,25 @@ where
 
     // A marker to communicate to the Rust compiler that we own these types.
     _phantom: PhantomData<(K, V)>,
+
+    destructor: Destructor,
+}
+
+#[derive(Default, Debug)]
+struct Destructor {}
+
+impl Drop for Destructor {
+    fn drop(&mut self) {
+        let stats = crate::debug::get_stats();
+        let sum_instructions: u64 = stats.iter().map(|s| s.1.total_instructions).sum();
+        for s in stats {
+            let percent = (s.1.total_instructions as f64 / sum_instructions as f64) * 100.0;
+            crate::debug::print(format!(
+                "{}: {:?} ({:>5.1} %), {}",
+                s.0, s.1.total_instructions, percent, s.1.call_count
+            ));
+        }
+    }
 }
 
 #[derive(PartialEq, Debug)]
@@ -214,6 +233,7 @@ where
             version: Version::V2(page_size),
             length: 0,
             _phantom: PhantomData,
+            destructor: Destructor::default(),
         };
 
         btree.save_header();
@@ -241,6 +261,7 @@ where
             }),
             length: 0,
             _phantom: PhantomData,
+            destructor: Destructor::default(),
         };
 
         btree.save_header();
@@ -290,6 +311,7 @@ where
             version,
             length: header.length,
             _phantom: PhantomData,
+            destructor: Destructor::default(),
         }
     }
 
@@ -533,17 +555,43 @@ where
     where
         F: Fn(Node<K>, usize) -> R + Clone,
     {
-        let node = self.load_node(node_addr);
-        // Look for the key in the current node.
-        match node.search(key) {
-            Ok(idx) => Some(f(node, idx)), // Key found: apply `f`.
+        // #[cfg(feature = "canbench-rs")]
+        // let _p = crate::debug::InstructionCounter::new("traverse");
+
+        let node = {
+            // #[cfg(feature = "canbench-rs")]
+            // let _p = crate::debug::InstructionCounter::new("load_node");
+            self.load_node(node_addr)
+        };
+
+        let search = {
+            // #[cfg(feature = "canbench-rs")]
+            // let _p = crate::debug::InstructionCounter::new("search");
+            node.search(key)
+        };
+        match search {
+            Ok(idx) => {
+                // Key found: apply `f`.
+                // #[cfg(feature = "canbench-rs")]
+                // let _p = crate::debug::InstructionCounter::new("f");
+
+                Some(f(node, idx))
+            }
             Err(idx) => match node.node_type() {
                 NodeType::Leaf => None, // At a leaf: key not present.
                 NodeType::Internal => self.traverse(node.child(idx), key, f), // Continue search in child.
             },
         }
     }
 
+    /*
+    $ canbench btreemap_get_blob_8_1024_v2 --show-canister-output
+
+    load_node : 262_628_480 ( 81.6 %), 48_669
+    search    :  38_580_885 ( 12.0 %), 48_669
+    f         :  20_445_909 (  6.4 %), 10_000
+    */
+
     /// Returns `true` if the map contains no elements.
     pub fn is_empty(&self) -> bool {
         self.length == 0

src/btreemap/allocator.rs

@@ -29,6 +29,7 @@ const CHUNK_MAGIC: &[u8; 3] = b"CHK"; // btree allocator
 /// # Assumptions:
 ///
 /// * The given memory is not being used by any other data structure.
+#[derive(Debug, Copy, Clone)]
 pub struct Allocator<M: Memory> {
     // The address in memory where the `AllocatorHeader` is stored.
     header_addr: Address,

src/btreemap/node/v2.rs

@@ -114,8 +114,15 @@ impl<K: Storable + Ord + Clone> Node<K> {
         #[cfg(feature = "canbench")]
         let _p = canbench::profile("node_load_v2");
 
+        // #[cfg(feature = "canbench-rs")]
+        // let _p = crate::debug::InstructionCounter::new("load_v2");
+
         // Load the node, including any overflows, into a buffer.
-        let overflows = read_overflows(address, memory);
+        let overflows = {
+            #[cfg(feature = "canbench-rs")]
+            let _p = crate::debug::InstructionCounter::new("read_overflows");
+            read_overflows(address, memory)
+        };
 
         let reader = NodeReader {
             address,
@@ -140,6 +147,8 @@ impl<K: Storable + Ord + Clone> Node<K> {
         offset += ENTRIES_OFFSET;
         let mut children = vec![];
         if node_type == NodeType::Internal {
+            #[cfg(feature = "canbench-rs")]
+            let _p = crate::debug::InstructionCounter::new("read_children");
             // The number of children is equal to the number of entries + 1.
             children.reserve_exact(num_entries + 1);
             for _ in 0..num_entries + 1 {
@@ -152,33 +161,73 @@ impl<K: Storable + Ord + Clone> Node<K> {
         // Load the keys.
         let mut keys_encoded_values = Vec::with_capacity(num_entries);
         let mut buf = vec![];
-        for _ in 0..num_entries {
-            // Load the key's size.
-            let key_size = if K::BOUND.is_fixed_size() {
-                // Key is fixed in size. The size of the key is always its max size.
-                K::BOUND.max_size()
-            } else {
-                // Key is not fixed in size. Read the size from memory.
-                let value = read_u32(&reader, offset);
-                offset += U32_SIZE;
-                value
-            };
-
-            // Load the key.
-            read_to_vec(&reader, offset, &mut buf, key_size as usize);
-            let key = K::from_bytes(Cow::Borrowed(&buf));
-            offset += Bytes::from(key_size);
-            keys_encoded_values.push((key, Value::by_ref(Bytes::from(0usize))));
+        {
+            #[cfg(feature = "canbench-rs")]
+            let _p = crate::debug::InstructionCounter::new("read_keys");
+
+            for _ in 0..num_entries {
+                // Load the key's size.
+                let key_size = if K::BOUND.is_fixed_size() {
+                    // Key is fixed in size. The size of the key is always its max size.
+                    K::BOUND.max_size()
+                } else {
+                    // Key is not fixed in size. Read the size from memory.
+                    let value = read_u32(&reader, offset);
+                    offset += U32_SIZE;
+                    value
+                };
+
+                // Load the key.
+                read_to_vec(&reader, offset, &mut buf, key_size as usize);
+                let key = K::from_bytes(Cow::Borrowed(&buf));
+                offset += Bytes::from(key_size);
+                keys_encoded_values.push((key, Value::by_ref(Bytes::from(0usize))));
+            }
         }
 
         // Load the values
-        for (_key, value) in keys_encoded_values.iter_mut() {
-            // Load the values lazily.
-            *value = Value::by_ref(Bytes::from(offset.get()));
-            let value_size = read_u32(&reader, offset) as usize;
-            offset += U32_SIZE + Bytes::from(value_size as u64);
+        {
+            #[cfg(feature = "canbench-rs")]
+            let _p = crate::debug::InstructionCounter::new("read_values");
+
+            for (_key, value) in keys_encoded_values.iter_mut() {
+                // Load the values lazily.
+                *value = Value::by_ref(Bytes::from(offset.get()));
+                let value_size = read_u32(&reader, offset) as usize;
+                offset += U32_SIZE + Bytes::from(value_size as u64);
+            }
         }
 
+        /*
+        $ canbench btreemap_get_u64_blob_8_v2 --show-canister-output
+
+        read_keys      :   221_987_821 ( 43.0 %), 94018
+        read_values    :   130_187_984 ( 25.2 %), 94018
+        read_children  :   113_994_776 ( 22.1 %), 72846
+        read_overflows :    50_249_184 (  9.7 %), 94018
+
+        $ canbench btreemap_get_blob_4_1024_v2 --show-canister-output
+
+        read_keys      :   247_653_437 ( 49.2 %), 78056
+        read_values    :   116_455_554 ( 23.1 %), 78056
+        read_children  :    98_024_327 ( 19.5 %), 58611
+        read_overflows :    41_560_306 (  8.3 %), 78056
+
+        $ canbench btreemap_get_blob_8_1024_v2 --show-canister-output
+
+        read_keys      :   293_619_121 ( 51.2 %), 91593
+        read_values    :   123_878_903 ( 21.6 %), 91593
+        read_children  :   107_642_317 ( 18.8 %), 71093
+        read_overflows :    48_610_398 (  8.5 %), 91593
+
+        $ canbench btreemap_get_blob_256_1024_v2 --show-canister-output
+
+        read_keys      : 2_590_429_735 ( 89.9 %), 94120
+        read_values    :   129_692_848 (  4.5 %), 94120
+        read_children  :   112_488_061 (  3.9 %), 72949
+        read_overflows :    50_042_554 (  1.7 %), 94120
+        */
+
         Self {
             address,
             keys_and_encoded_values: keys_encoded_values,