feat: add basic profiling to benchmarks

Cargo.toml

@@ -11,6 +11,10 @@ keywords = ["internet-computer", "dfinity", "stable-structures"]
 include = ["src", "Cargo.toml", "LICENSE", "README.md"]
 repository = "https://github.com/dfinity/stable-structures"
 
+[dependencies]
+# An optional dependency to profile parts of the code.
+profiler = { path = "./profiler", optional = true }
+
 [dev-dependencies]
 criterion = "0.4.0"
 ic-cdk = "0.6.8"

benches/benches.rs

@@ -144,6 +144,10 @@ fn execution_instructions(arguments: ExecutionArguments) -> u64 {
     let stderr = String::from_utf8(output.stderr).unwrap();
     assert!(output.status.success(), "{stdout}\n{stderr}");
 
+    // Output logs from the canister as it contains profiling data.
+    println!("");
+    println!("{}", stderr);
+
     // Convert result formatted as "(1_000_000 : nat64)" to u64.
     let result = stdout
         .trim()

benchmark-canisters/Cargo.toml

@@ -8,5 +8,6 @@ edition = "2021"
 [dependencies]
 ic-cdk = "0.6.8"
 ic-cdk-macros = "0.6.8"
-ic-stable-structures = { path = "../" }
+ic-stable-structures = { path = "../", features = ["profiler"] }
+profiler = { path = "../profiler" }
 tiny-rng = "0.2.0"

benchmark-canisters/src/main.rs

@@ -8,8 +8,32 @@ mod vec;
 /// Returns the number of instructions consumed by the given function.
 pub(crate) fn count_instructions<R>(f: impl FnOnce() -> R) -> u64 {
     let start = ic_cdk::api::performance_counter(0);
+    profiler::reset();
     f();
-    ic_cdk::api::performance_counter(0) - start
+    let total_instructions = ic_cdk::api::performance_counter(0) - start;
+
+    let profiling_results: std::collections::BTreeMap<_, _> = profiler::get_results()
+        .into_iter()
+        .map(|(k, v)| {
+            (
+                k,
+                format!("{} ({}%)", format_num(v), ((v * 100) / total_instructions)),
+            )
+        })
+        .collect();
+    ic_cdk::api::print(&format!("{:#?}", profiling_results));
+    total_instructions
+}
+
+fn format_num(num: u64) -> String {
+    num.to_string()
+        .as_bytes()
+        .rchunks(3)
+        .rev()
+        .map(std::str::from_utf8)
+        .collect::<Result<Vec<&str>, _>>()
+        .unwrap()
+        .join("_")
 }
 
 const fn max_size<A: Storable>() -> u32 {

src/btreemap/node/v2.rs

@@ -112,6 +112,9 @@ impl<K: Storable + Ord + Clone> Node<K> {
 
     /// Loads a v2 node from memory at the given address.
     pub(super) fn load_v2<M: Memory>(address: Address, page_size: PageSize, memory: &M) -> Self {
+        #[cfg(feature = "profiler")]
+        let _p = profiler::profile("node_load_v2");
+
         // Load the node, including any overflows, into a buffer.
         let node_buf = read_node(address, page_size.get(), memory);
 
@@ -192,6 +195,9 @@ impl<K: Storable + Ord + Clone> Node<K> {
 
     // Saves the node to memory.
     pub(super) fn save_v2<M: Memory>(&self, allocator: &mut Allocator<M>) {
+        #[cfg(feature = "profiler")]
+        let _p = profiler::profile("node_save_v2");
+
         let page_size = self.version.page_size().get();
         assert!(page_size >= MINIMUM_PAGE_SIZE);
         assert_eq!(self.keys.len(), self.encoded_values.borrow().len());
@@ -255,7 +261,7 @@ impl<K: Storable + Ord + Clone> Node<K> {
     ) {
         // Compute how many overflow pages are needed.
         let additional_pages_needed = if buf.len() > page_size {
-            debug_assert!(page_size >= PAGE_OVERFLOW_DATA_OFFSET.into());
+            debug_assert!(page_size >= PAGE_OVERFLOW_DATA_OFFSET.get() as usize);
             let overflow_page_capacity = page_size - PAGE_OVERFLOW_DATA_OFFSET.get() as usize;
             let overflow_data_len = buf.len() - page_size;