From 48f62ed0a0c5a107b4eccb7ef7240ead39999b2d Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Fri, 4 Apr 2025 10:45:14 +0200 Subject: [PATCH 01/12] debug BTreeMap --- .gitignore | 2 + Cargo.lock | 70 ++++++++++++++++++++++++++------ Cargo.toml | 1 + src/btreemap.rs | 26 +++++++++++- src/btreemap/allocator.rs | 1 + src/debug.rs | 84 +++++++++++++++++++++++++++++++++++++++ src/lib.rs | 2 + 7 files changed, 173 insertions(+), 13 deletions(-) create mode 100644 src/debug.rs 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 b06a7f65..8feba6c9 100644 --- a/src/btreemap.rs +++ b/src/btreemap.rs @@ -105,6 +105,20 @@ 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(); + for s in stats { + crate::debug::print(format!("{}: {:?}", s.0, s.1)); + } + } } #[derive(PartialEq, Debug)] @@ -214,6 +228,7 @@ where version: Version::V2(page_size), length: 0, _phantom: PhantomData, + destructor: Destructor::default(), }; btree.save(); @@ -241,6 +256,7 @@ where }), length: 0, _phantom: PhantomData, + destructor: Destructor::default(), }; btree.save(); @@ -290,6 +306,7 @@ where version, length: header.length, _phantom: PhantomData, + destructor: Destructor::default(), } } @@ -521,7 +538,14 @@ where } fn get_helper(&self, node_addr: Address, key: &K) -> Option> { - let node = self.load_node(node_addr); + #[cfg(feature = "canbench-rs")] + let _p = crate::debug::InstructionCounter::new("get_helper"); + //let node = self.load_node(node_addr); + let node = { + #[cfg(feature = "canbench-rs")] + let _p = crate::debug::InstructionCounter::new("load_node"); + self.load_node(node_addr) + }; match node.search(key) { Ok(idx) => Some(node.into_entry(idx, self.memory()).1), Err(idx) => { 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/debug.rs b/src/debug.rs new file mode 100644 index 00000000..401f7af3 --- /dev/null +++ b/src/debug.rs @@ -0,0 +1,84 @@ +use std::cell::RefCell; +use std::collections::BTreeMap; + +thread_local! { + static STATS: RefCell> = const { RefCell::new(BTreeMap::new()) }; +} + +pub struct InstructionCounter { + name: &'static str, + start_instructions: u64, +} + +#[derive(Clone, Copy)] +pub struct Stats { + total_instructions: u64, + 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(()) + } +} + +impl InstructionCounter { + pub fn new(name: &'static str) -> Self { + Self { + name, + start_instructions: instruction_count(), + } + } +} + +impl Drop for InstructionCounter { + fn drop(&mut self) { + let elapsed = instruction_count() - self.start_instructions; + STATS.with(|c| { + let mut stats = c.borrow_mut(); + let entry = stats.entry(self.name).or_insert(Stats { + total_instructions: 0, + call_count: 0, + }); + entry.total_instructions += elapsed; + entry.call_count += 1; + }); + } +} + +pub fn get_stats() -> Vec<(&'static str, Stats)> { + STATS.with(|c| { + let stats = c.borrow(); + 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 + }) +} + +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}"); + } +} 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; From b5390e45413a518a4d1217977faa6256a747ca09 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Fri, 4 Apr 2025 10:48:35 +0200 Subject: [PATCH 02/12] . --- src/btreemap.rs | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/src/btreemap.rs b/src/btreemap.rs index 8feba6c9..318f38b9 100644 --- a/src/btreemap.rs +++ b/src/btreemap.rs @@ -546,8 +546,20 @@ where let _p = crate::debug::InstructionCounter::new("load_node"); self.load_node(node_addr) }; - match node.search(key) { - Ok(idx) => Some(node.into_entry(idx, self.memory()).1), + let search = { + #[cfg(feature = "canbench-rs")] + let _p = crate::debug::InstructionCounter::new("search"); + node.search(key) + }; + match search { + Ok(idx) => { + let result = { + #[cfg(feature = "canbench-rs")] + let _p = crate::debug::InstructionCounter::new("into_entry"); + node.into_entry(idx, self.memory()).1 + }; + Some(result) + } Err(idx) => { match node.node_type() { NodeType::Leaf => None, // Key not found. From ebadff8bcd101180a9d41c89ef76b6569c7aa086 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Fri, 4 Apr 2025 11:06:13 +0200 Subject: [PATCH 03/12] fix overlapping scopes --- src/debug.rs | 78 ++++++++++++++++++++++++++++++++++++++++++++-------- 1 file changed, 67 insertions(+), 11 deletions(-) diff --git a/src/debug.rs b/src/debug.rs index 401f7af3..338fabe3 100644 --- a/src/debug.rs +++ b/src/debug.rs @@ -7,11 +7,12 @@ thread_local! { pub struct InstructionCounter { name: &'static str, - start_instructions: u64, } #[derive(Clone, Copy)] pub struct Stats { + start_instructions: Option, + running_count: u64, total_instructions: u64, call_count: u64, } @@ -27,24 +28,41 @@ impl std::fmt::Debug for Stats { impl InstructionCounter { pub fn new(name: &'static str) -> Self { - Self { - name, - start_instructions: instruction_count(), - } + let start = instruction_count(); + STATS.with(|c| { + let mut stats = c.borrow_mut(); + let entry = stats.entry(name).or_insert(Stats { + start_instructions: Some(start), + running_count: 0, + total_instructions: 0, + call_count: 0, + }); + if entry.running_count == 0 { + entry.start_instructions = Some(start); + } + entry.running_count += 1; + }); + Self { name } } } impl Drop for InstructionCounter { fn drop(&mut self) { - let elapsed = instruction_count() - self.start_instructions; STATS.with(|c| { let mut stats = c.borrow_mut(); - let entry = stats.entry(self.name).or_insert(Stats { - total_instructions: 0, - call_count: 0, + let entry = stats.entry(self.name).or_insert_with(|| { + panic!("InstructionCounter not initialized"); }); - entry.total_instructions += elapsed; - entry.call_count += 1; + entry.running_count -= 1; + if entry.running_count == 0 { + let elapsed = instruction_count() + - entry + .start_instructions + .expect("start_instructions is None"); + entry.start_instructions = None; + entry.total_instructions += elapsed; + entry.call_count += 1; + } }); } } @@ -82,3 +100,41 @@ pub fn print(msg: String) { println!("{msg}"); } } + +/* + +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 + +=== +*/ From 55c60d1f4e844b33735fbf0e4d94f917f75500b6 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Fri, 4 Apr 2025 11:07:14 +0200 Subject: [PATCH 04/12] . --- src/debug.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/debug.rs b/src/debug.rs index 338fabe3..4a509ba3 100644 --- a/src/debug.rs +++ b/src/debug.rs @@ -61,8 +61,8 @@ impl Drop for InstructionCounter { .expect("start_instructions is None"); entry.start_instructions = None; entry.total_instructions += elapsed; - entry.call_count += 1; } + entry.call_count += 1; }); } } @@ -104,19 +104,19 @@ pub fn print(msg: String) { /* get_helper: -total_instructions : 1152818806, +total_instructions : 1152818806, call_count : 10000 load_node: -total_instructions : 903703200, +total_instructions : 903703200, call_count : 48674 search: -total_instructions : 108924141, +total_instructions : 108924141, call_count : 48674 into_entry: -total_instructions : 31619452, +total_instructions : 31619452, call_count : 10000 === From 51cc254fbd847f30028ce2552106922ce350235f Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Fri, 4 Apr 2025 11:08:32 +0200 Subject: [PATCH 05/12] . --- src/debug.rs | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/debug.rs b/src/debug.rs index 4a509ba3..71972a52 100644 --- a/src/debug.rs +++ b/src/debug.rs @@ -28,17 +28,17 @@ impl std::fmt::Debug for Stats { impl InstructionCounter { pub fn new(name: &'static str) -> Self { - let start = instruction_count(); + let now = instruction_count(); STATS.with(|c| { let mut stats = c.borrow_mut(); let entry = stats.entry(name).or_insert(Stats { - start_instructions: Some(start), + start_instructions: Some(now), running_count: 0, total_instructions: 0, call_count: 0, }); if entry.running_count == 0 { - entry.start_instructions = Some(start); + entry.start_instructions = Some(now); } entry.running_count += 1; }); @@ -49,13 +49,14 @@ impl InstructionCounter { impl Drop for InstructionCounter { fn drop(&mut self) { STATS.with(|c| { + let now = instruction_count(); let mut stats = c.borrow_mut(); let entry = stats.entry(self.name).or_insert_with(|| { panic!("InstructionCounter not initialized"); }); entry.running_count -= 1; if entry.running_count == 0 { - let elapsed = instruction_count() + let elapsed = now - entry .start_instructions .expect("start_instructions is None"); From a0e4dcbfbe3b7819d4ea0e04df15a3e4a9452ba7 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Fri, 4 Apr 2025 11:09:47 +0200 Subject: [PATCH 06/12] . --- src/debug.rs | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/src/debug.rs b/src/debug.rs index 71972a52..b3487cef 100644 --- a/src/debug.rs +++ b/src/debug.rs @@ -104,6 +104,23 @@ pub fn print(msg: String) { /* +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 From 4e5d4fbbfbe86f8066d070fb2a3bc8edc0e61325 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Tue, 8 Apr 2025 18:35:07 +0200 Subject: [PATCH 07/12] . --- src/btreemap.rs | 26 ++++++++++++++++++++------ 1 file changed, 20 insertions(+), 6 deletions(-) diff --git a/src/btreemap.rs b/src/btreemap.rs index f875990b..4fe8ef55 100644 --- a/src/btreemap.rs +++ b/src/btreemap.rs @@ -554,21 +554,21 @@ where let _p = crate::debug::InstructionCounter::new("traverse"); let node = { - #[cfg(feature = "canbench-rs")] - let _p = crate::debug::InstructionCounter::new("load_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"); + // #[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"); + // #[cfg(feature = "canbench-rs")] + // let _p = crate::debug::InstructionCounter::new("f"); Some(f(node, idx)) } @@ -579,6 +579,20 @@ where } } + /* + $ canbench btreemap_get_blob_8_1024_v2 --show-canister-output + + 2021-05-06 19:17:10.000000003 UTC: [Canister lxzze-o7777-77777-aaaaa-cai] traverse: Stats: + total_instructions : 346544276, + call_count : 48669 + + Benchmark: btreemap_get_blob_8_1024_v2 + total: + instructions: 355.58 M (regressed by 18.64%) + heap_increase: 0 pages (no change) + stable_memory_increase: 0 pages (no change) + */ + /// Returns `true` if the map contains no elements. pub fn is_empty(&self) -> bool { self.length == 0 From 0ee45d202298dda8b0700d3b7634e20ba5ca9b83 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Tue, 8 Apr 2025 19:47:55 +0200 Subject: [PATCH 08/12] linked list --- src/debug.rs | 117 +++++++++++++++++++++++++++++++-------------------- 1 file changed, 71 insertions(+), 46 deletions(-) diff --git a/src/debug.rs b/src/debug.rs index b3487cef..d095e4f1 100644 --- a/src/debug.rs +++ b/src/debug.rs @@ -1,14 +1,47 @@ use std::cell::RefCell; -use std::collections::BTreeMap; +use std::collections::LinkedList; thread_local! { - static STATS: RefCell> = const { RefCell::new(BTreeMap::new()) }; + 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 { + let time = instruction_count(); + ENTRIES.with(|c| { + c.borrow_mut().push_back(Measurement { + name, + time, + is_start: true, + }); + }); + Self { name } + } +} + +impl Drop for InstructionCounter { + fn drop(&mut self) { + let time = instruction_count(); + ENTRIES.with(|c| { + c.borrow_mut().push_back(Measurement { + name: self.name, + time, + is_start: false, + }); + }); + } +} + #[derive(Clone, Copy)] pub struct Stats { start_instructions: Option, @@ -26,55 +59,47 @@ impl std::fmt::Debug for Stats { } } -impl InstructionCounter { - pub fn new(name: &'static str) -> Self { - let now = instruction_count(); - STATS.with(|c| { - let mut stats = c.borrow_mut(); - let entry = stats.entry(name).or_insert(Stats { - start_instructions: Some(now), +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 entry.running_count == 0 { - entry.start_instructions = Some(now); + 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; + } } - entry.running_count += 1; - }); - Self { name } - } -} - -impl Drop for InstructionCounter { - fn drop(&mut self) { - STATS.with(|c| { - let now = instruction_count(); - let mut stats = c.borrow_mut(); - let entry = stats.entry(self.name).or_insert_with(|| { - panic!("InstructionCounter not initialized"); - }); - entry.running_count -= 1; - if entry.running_count == 0 { - let elapsed = now - - entry - .start_instructions - .expect("start_instructions is None"); - entry.start_instructions = None; - entry.total_instructions += elapsed; - } - entry.call_count += 1; - }); - } -} - -pub fn get_stats() -> Vec<(&'static str, Stats)> { - STATS.with(|c| { - let stats = c.borrow(); - 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 - }) + } + }); + + 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 { From 725f8ae1e70c12a1cf2989d7961f9af4553cb060 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Tue, 8 Apr 2025 19:58:49 +0200 Subject: [PATCH 09/12] . --- src/btreemap.rs | 23 ++++++++++++++--------- src/debug.rs | 28 +++++++++++++--------------- 2 files changed, 27 insertions(+), 24 deletions(-) diff --git a/src/btreemap.rs b/src/btreemap.rs index 4fe8ef55..26f53124 100644 --- a/src/btreemap.rs +++ b/src/btreemap.rs @@ -115,8 +115,13 @@ 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 { - crate::debug::print(format!("{}: {:?}", s.0, s.1)); + let percent = (s.1.total_instructions as f64 / sum_instructions as f64) * 100.0; + crate::debug::print(format!( + "{}: {:?} ({:>3.1} %), {}", + s.0, s.1.total_instructions, percent, s.1.call_count + )); } } } @@ -550,25 +555,25 @@ where where F: Fn(Node, usize) -> R + Clone, { - #[cfg(feature = "canbench-rs")] - let _p = crate::debug::InstructionCounter::new("traverse"); + // #[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"); + #[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"); + #[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"); + #[cfg(feature = "canbench-rs")] + let _p = crate::debug::InstructionCounter::new("f"); Some(f(node, idx)) } diff --git a/src/debug.rs b/src/debug.rs index d095e4f1..1463e798 100644 --- a/src/debug.rs +++ b/src/debug.rs @@ -17,11 +17,10 @@ pub struct InstructionCounter { impl InstructionCounter { pub fn new(name: &'static str) -> Self { - let time = instruction_count(); ENTRIES.with(|c| { c.borrow_mut().push_back(Measurement { name, - time, + time: instruction_count(), is_start: true, }); }); @@ -31,11 +30,10 @@ impl InstructionCounter { impl Drop for InstructionCounter { fn drop(&mut self) { - let time = instruction_count(); ENTRIES.with(|c| { c.borrow_mut().push_back(Measurement { name: self.name, - time, + time: instruction_count(), is_start: false, }); }); @@ -46,8 +44,8 @@ impl Drop for InstructionCounter { pub struct Stats { start_instructions: Option, running_count: u64, - total_instructions: u64, - call_count: u64, + pub total_instructions: u64, + pub call_count: u64, } impl std::fmt::Debug for Stats { @@ -89,15 +87,15 @@ pub fn get_stats() -> Vec<(&'static str, Stats)> { 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.push(( + // "get_stats", + // Stats { + // start_instructions: None, + // running_count: 0, + // total_instructions: instruction_count() - start, + // call_count: 1, + // }, + // )); stats_vec } From cdf719a053c158ed1f9ca4eea7241cbde00b663e Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Tue, 8 Apr 2025 20:00:44 +0200 Subject: [PATCH 10/12] . --- src/btreemap.rs | 14 ++++---------- 1 file changed, 4 insertions(+), 10 deletions(-) diff --git a/src/btreemap.rs b/src/btreemap.rs index 26f53124..da978194 100644 --- a/src/btreemap.rs +++ b/src/btreemap.rs @@ -119,7 +119,7 @@ impl Drop for Destructor { for s in stats { let percent = (s.1.total_instructions as f64 / sum_instructions as f64) * 100.0; crate::debug::print(format!( - "{}: {:?} ({:>3.1} %), {}", + "{}: {:?} ({:>5.1} %), {}", s.0, s.1.total_instructions, percent, s.1.call_count )); } @@ -587,15 +587,9 @@ where /* $ canbench btreemap_get_blob_8_1024_v2 --show-canister-output - 2021-05-06 19:17:10.000000003 UTC: [Canister lxzze-o7777-77777-aaaaa-cai] traverse: Stats: - total_instructions : 346544276, - call_count : 48669 - - Benchmark: btreemap_get_blob_8_1024_v2 - total: - instructions: 355.58 M (regressed by 18.64%) - heap_increase: 0 pages (no change) - stable_memory_increase: 0 pages (no change) + 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. From 74793e70ba6ea16a541ff3a3bed4361cfb2d2785 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Tue, 8 Apr 2025 20:06:45 +0200 Subject: [PATCH 11/12] . --- src/btreemap.rs | 12 +++---- src/btreemap/node/v2.rs | 72 ++++++++++++++++++++++++++++------------- 2 files changed, 55 insertions(+), 29 deletions(-) diff --git a/src/btreemap.rs b/src/btreemap.rs index da978194..9695e49b 100644 --- a/src/btreemap.rs +++ b/src/btreemap.rs @@ -559,21 +559,21 @@ where // let _p = crate::debug::InstructionCounter::new("traverse"); let node = { - #[cfg(feature = "canbench-rs")] - let _p = crate::debug::InstructionCounter::new("load_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"); + // #[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"); + // #[cfg(feature = "canbench-rs")] + // let _p = crate::debug::InstructionCounter::new("f"); Some(f(node, idx)) } diff --git a/src/btreemap/node/v2.rs b/src/btreemap/node/v2.rs index f559d777..17681a5f 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,50 @@ 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); + } } + /* + 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 + */ + Self { address, keys_and_encoded_values: keys_encoded_values, From 196c19019d0ac288c311811fe8cc767da3d69321 Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Wed, 9 Apr 2025 15:13:22 +0200 Subject: [PATCH 12/12] debug data --- src/btreemap/node/v2.rs | 31 +++++++++++++++++++++++++++---- 1 file changed, 27 insertions(+), 4 deletions(-) diff --git a/src/btreemap/node/v2.rs b/src/btreemap/node/v2.rs index 17681a5f..7b0bc9f2 100644 --- a/src/btreemap/node/v2.rs +++ b/src/btreemap/node/v2.rs @@ -199,10 +199,33 @@ impl Node { } /* - 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_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 {