diff --git a/.gitignore b/.gitignore index 707f8413..cbad8b17 100644 --- a/.gitignore +++ b/.gitignore @@ -6,3 +6,5 @@ .vscode/ .idea/ **/*~ + +tmp/ diff --git a/Cargo.lock b/Cargo.lock index f1286f1b..8a8fb4d7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -26,8 +26,8 @@ version = "0.1.0" dependencies = [ "canbench-rs", "candid", - "ic-cdk", - "ic-cdk-macros", + "ic-cdk 0.12.1", + "ic-cdk-macros 0.8.4", "ic-stable-structures", "maplit", "serde", @@ -107,7 +107,7 @@ checksum = "e85a8f1ee95044a770b3d5166a12f55814283cb3aed71b81439dc59960ab76c1" dependencies = [ "canbench-rs-macros", "candid", - "ic-cdk", + "ic-cdk 0.12.1", "serde", ] @@ -124,9 +124,9 @@ dependencies = [ [[package]] name = "candid" -version = "0.10.3" +version = "0.10.13" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "182543fbc03b4ad0bfc384e6b68346e0b0aad0b11d075b71b4fcaa5d07f8862c" +checksum = "a253bab4a9be502c82332b60cbeee6202ad0692834efeec95fae9f29db33d692" dependencies = [ "anyhow", "binread", @@ -147,9 +147,9 @@ dependencies = [ [[package]] name = "candid_derive" -version = "0.6.5" +version = "0.6.6" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "970c220da8aa2fa6f7ef5dbbf3ea5b620a59eb3ac107cfb95ae8c6eebdfb7a08" +checksum = "3de398570c386726e7a59d9887b68763c481477f9a043fb998a2e09d428df1a9" dependencies = [ "lazy_static", "proc-macro2", @@ -278,8 +278,21 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9f3d204af0b11c45715169c997858edb58fa8407d08f4fae78a6b415dd39a362" dependencies = [ "candid", - "ic-cdk-macros", - "ic0", + "ic-cdk-macros 0.8.4", + "ic0 0.21.1", + "serde", + "serde_bytes", +] + +[[package]] +name = "ic-cdk" +version = "0.17.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "122efbcb0af5280d408a75a57b7dc6e9d92893bf6ed9cc98fe4dcff51f18b67c" +dependencies = [ + "candid", + "ic-cdk-macros 0.17.1", + "ic0 0.23.0", "serde", "serde_bytes", ] @@ -294,10 +307,24 @@ dependencies = [ "proc-macro2", "quote", "serde", - "serde_tokenstream", + "serde_tokenstream 0.1.7", "syn 1.0.109", ] +[[package]] +name = "ic-cdk-macros" +version = "0.17.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c792bf0d1621c893ccf2bcdeac4ee70121103a03030a1827031a6b3c60488944" +dependencies = [ + "candid", + "proc-macro2", + "quote", + "serde", + "serde_tokenstream 0.2.2", + "syn 2.0.48", +] + [[package]] name = "ic-stable-structures" version = "0.6.8" @@ -305,8 +332,9 @@ dependencies = [ "canbench-rs", "candid", "hex", - "ic-cdk", - "ic-cdk-macros", + "ic-cdk 0.12.1", + "ic-cdk 0.17.1", + "ic-cdk-macros 0.8.4", "ic_principal", "maplit", "proptest", @@ -320,6 +348,12 @@ version = "0.21.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a54b5297861c651551676e8c43df805dad175cc33bc97dbd992edbbb85dcbcdf" +[[package]] +name = "ic0" +version = "0.23.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8de254dd67bbd58073e23dc1c8553ba12fa1dc610a19de94ad2bbcd0460c067f" + [[package]] name = "ic_principal" version = "0.1.1" @@ -602,6 +636,18 @@ dependencies = [ "syn 1.0.109", ] +[[package]] +name = "serde_tokenstream" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "64060d864397305347a78851c51588fd283767e7e7589829e8121d65512340f1" +dependencies = [ + "proc-macro2", + "quote", + "serde", + "syn 2.0.48", +] + [[package]] name = "sha2" version = "0.10.8" diff --git a/Cargo.toml b/Cargo.toml index 7a4c0ab8..cd2bdbc7 100644 --- a/Cargo.toml +++ b/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 diff --git a/src/btreemap.rs b/src/btreemap.rs index e72567e4..9695e49b 100644 --- a/src/btreemap.rs +++ b/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,10 +555,28 @@ where where F: Fn(Node, 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. @@ -544,6 +584,14 @@ where } } + /* + $ 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 diff --git a/src/btreemap/allocator.rs b/src/btreemap/allocator.rs index 68544599..e2ff8b64 100644 --- a/src/btreemap/allocator.rs +++ b/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 { // The address in memory where the `AllocatorHeader` is stored. header_addr: Address, diff --git a/src/btreemap/node/v2.rs b/src/btreemap/node/v2.rs index f559d777..7b0bc9f2 100644 --- a/src/btreemap/node/v2.rs +++ b/src/btreemap/node/v2.rs @@ -114,8 +114,15 @@ impl Node { #[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 Node { 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 Node { // 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, diff --git a/src/debug.rs b/src/debug.rs new file mode 100644 index 00000000..1463e798 --- /dev/null +++ b/src/debug.rs @@ -0,0 +1,181 @@ +use std::cell::RefCell; +use std::collections::LinkedList; + +thread_local! { + static ENTRIES: RefCell> = const { RefCell::new(LinkedList::new()) }; +} + +struct Measurement { + name: &'static str, + time: u64, + is_start: bool, +} + +pub struct InstructionCounter { + name: &'static str, +} + +impl InstructionCounter { + pub fn new(name: &'static str) -> Self { + ENTRIES.with(|c| { + c.borrow_mut().push_back(Measurement { + name, + time: instruction_count(), + is_start: true, + }); + }); + Self { name } + } +} + +impl Drop for InstructionCounter { + fn drop(&mut self) { + ENTRIES.with(|c| { + c.borrow_mut().push_back(Measurement { + name: self.name, + time: instruction_count(), + is_start: false, + }); + }); + } +} + +#[derive(Clone, Copy)] +pub struct Stats { + start_instructions: Option, + running_count: u64, + pub total_instructions: u64, + pub call_count: u64, +} + +impl std::fmt::Debug for Stats { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + writeln!(f, "Stats: ")?; + writeln!(f, "total_instructions : {}, ", self.total_instructions)?; + writeln!(f, "call_count : {}", self.call_count)?; + Ok(()) + } +} + +pub fn get_stats() -> Vec<(&'static str, Stats)> { + let start = instruction_count(); + let mut stats = std::collections::HashMap::new(); + ENTRIES.with(|c| { + for measurement in c.borrow().iter() { + let entry = stats.entry(measurement.name).or_insert(Stats { + start_instructions: None, + running_count: 0, + total_instructions: 0, + call_count: 0, + }); + if measurement.is_start { + entry.call_count += 1; + if entry.running_count == 0 { + entry.start_instructions = Some(measurement.time); + } + entry.running_count += 1; + } else { + entry.running_count -= 1; + if entry.running_count == 0 { + let instructions = measurement.time - entry.start_instructions.unwrap(); + entry.total_instructions += instructions; + } + } + } + }); + + let mut stats_vec: Vec<_> = stats.iter().map(|(&k, &v)| (k, v)).collect(); + stats_vec.sort_by(|a, b| b.1.total_instructions.cmp(&a.1.total_instructions)); + + // stats_vec.push(( + // "get_stats", + // Stats { + // start_instructions: None, + // running_count: 0, + // total_instructions: instruction_count() - start, + // call_count: 1, + // }, + // )); + + stats_vec +} + +fn instruction_count() -> u64 { + #[cfg(target_arch = "wasm32")] + { + ic_cdk::api::performance_counter(0) + } + + #[cfg(not(target_arch = "wasm32"))] + { + // Consider using cpu time here. + 0 + } +} + +pub fn print(msg: String) { + #[cfg(target_arch = "wasm32")] + { + ic_cdk::api::print(msg); + } + + #[cfg(not(target_arch = "wasm32"))] + { + println!("{msg}"); + } +} + +/* + +get_helper: +total_instructions : 1157246368, +call_count : 48674 + +load_node: +total_instructions : 878538985, +call_count : 48674 + +search: +total_instructions : 83613904, +call_count : 48674 + +into_entry: +total_instructions : 26999452, +call_count : 10000 + +=== +get_helper: +total_instructions : 1152818806, +call_count : 10000 + +load_node: +total_instructions : 903703200, +call_count : 48674 + +search: +total_instructions : 108924141, +call_count : 48674 + +into_entry: +total_instructions : 31619452, +call_count : 10000 + +=== +get_helper: +total_instructions : 3605853485, +call_count : 48674 + +load_node: +total_instructions : 853224120, +call_count : 48674 + +search: +total_instructions : 58137654, +call_count : 48674 + +into_entry: +total_instructions : 22348944, +call_count : 10000 + +=== +*/ diff --git a/src/lib.rs b/src/lib.rs index e1d0e1d2..aad7d429 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -31,6 +31,8 @@ pub use storable::Storable; use types::Address; pub use vec_mem::VectorMemory; +mod debug; // TODO: remove debug code. + #[cfg(target_arch = "wasm32")] pub type DefaultMemoryImpl = Ic0StableMemory;