Add Memory Information to Runtime Benchmarks

[shawntabrizi]

It would be nice to see the maximum amount of memory used by an extrinsic during a benchmark.

This could help us detect and catch problems like what happened with elections earlier.

[shawntabrizi]

How would we even do this? is there a way to probe or know when we are using the most memory?

[kianenigma]

I had a good chat about this with @pepyakin. His explanations where clear and shed some light into what we need to look out for. I will do a small recap, but maybe he can answer your question as well ^^.

We have two limits to look out for:

1. The heap pages. This is the total number of pages that we can allocated. We currently limit this to a number between 1 and 65565 (which is the absolute maximum of any wasm execution). Given that the native runtime is at the verge of being tossed, I don't want to even consider it as a backup here. This number basically means all the memory that you use at any point in time. I presume profiling in native can actually be helpful here, as the memory usage is the same.

This number is configurable, currently from the client side and the runtime, and bumping it is not generally frowned upon.

2. Allocator limit: this number is currently hardcoded to 16MiB, and it means that no single allocation can be larger than this amount. Of course, what is an allocation depends on the data type, and how often rustc allocates it, and how you interact with it (e.g. do you grow it dynamically or use ::with_capacity from the get go). But as a rule of thumb, you can assume that for a single Vec<u8>, it can never contain more than 16 * 1024 * 1024 elements, and inserting the 16 * 1024 * 1024 + 1 will almost certainly fail.

We have never increased this number, and doing so is frowned upon since it will have performance compromises, but it is possible in cases of emergency.

All in all, we should also benchmark operations for memory, and actually have more strict measures than weight for it in place. Particularly for hooks, if the weight of a hook goes beyond the limit it is just slow, but if it ever allocates too much it will panic.

---

Other than a laborious profiling via native that I recommended, I think it should be possible to put some traces in FreeingBumpAllocator, and for instance make it print its maximum usage upon Drop? I think then we should get a clear number out of a single runtime api call.

[kianenigma]

I tried something like this, it seems to be inaccurate:

diff --git a/primitives/allocator/Cargo.toml b/primitives/allocator/Cargo.toml
index 1c38cbbb9..39f2a077e 100644
--- a/primitives/allocator/Cargo.toml
+++ b/primitives/allocator/Cargo.toml
@@ -21,7 +21,8 @@ log = { version = "0.4.11", optional = true }
 thiserror = { version = "1.0.21", optional = true }
 
 [features]
-default = [ "std" ]
+default = [ "std", "track-maximum" ]
+track-maximum = []
 std = [
 	"sp-std/std",
 	"sp-core/std",
diff --git a/primitives/allocator/src/freeing_bump.rs b/primitives/allocator/src/freeing_bump.rs
index e1afe7cec..8494b8167 100644
--- a/primitives/allocator/src/freeing_bump.rs
+++ b/primitives/allocator/src/freeing_bump.rs
@@ -309,6 +309,17 @@ pub struct FreeingBumpHeapAllocator {
 	free_lists: FreeLists,
 	total_size: u32,
 	poisoned: bool,
+	#[cfg(feature = "track-maximum")]
+	maximum_total_size: u32,
+}
+
+sp_std::if_std! {
+	#[cfg(feature = "track-maximum")]
+	impl Drop for FreeingBumpHeapAllocator {
+		fn drop(&mut self) {
+			log::debug!(target: "wasm-heap", "dropping allocator, maximum allocated amount {} bytes.", self.maximum_total_size);
+		}
+	}
 }
 
 impl FreeingBumpHeapAllocator {
@@ -318,12 +329,14 @@ impl FreeingBumpHeapAllocator {
 	///
 	/// - `heap_base` - the offset from the beginning of the linear memory where the heap starts.
 	pub fn new(heap_base: u32) -> Self {
-		let aligned_heap_base = (dbg!(heap_base) + ALIGNMENT - 1) / ALIGNMENT * ALIGNMENT;
+		let aligned_heap_base = (heap_base + ALIGNMENT - 1) / ALIGNMENT * ALIGNMENT;
 
 		FreeingBumpHeapAllocator {
 			bumper: aligned_heap_base,
 			free_lists: FreeLists::new(),
 			total_size: 0,
+			#[cfg(feature = "track-maximum")]
+			maximum_total_size: 0,
 			poisoned: false,
 		}
 	}
@@ -384,6 +397,11 @@ impl FreeingBumpHeapAllocator {
 		self.total_size += order.size() + HEADER_SIZE;
 		trace!("Heap size is {} bytes after allocation", self.total_size);
 
+		#[cfg(feature = "track-maximum")]
+		if self.total_size > self.maximum_total_size {
+			self.maximum_total_size = self.total_size
+		}
+
 		bomb.disarm();
 		Ok(Pointer::new(header_ptr + HEADER_SIZE))
 	}
@@ -432,7 +450,7 @@ impl FreeingBumpHeapAllocator {
 	/// Returns an `Error::AllocatorOutOfSpace` if the operation
 	/// would exhaust the heap.
 	fn bump(bumper: &mut u32, size: u32, heap_end: u32) -> Result<u32, Error> {
-		if dbg!(*bumper + size) > dbg!(heap_end) {
+		if *bumper + size > heap_end {
 			return Err(Error::AllocatorOutOfSpace);
 		}
 
diff --git a/primitives/npos-elections/src/pjr.rs b/primitives/npos-elections/src/pjr.rs
index 290110b14..843c0e79f 100644
--- a/primitives/npos-elections/src/pjr.rs
+++ b/primitives/npos-elections/src/pjr.rs
@@ -600,7 +600,6 @@ mod tests {
 				unexpected_failures.push(t);
 			}
 		}
-		dbg!(&unexpected_successes, &unexpected_failures);
 		assert!(unexpected_failures.is_empty() && unexpected_successes.is_empty());
 
 		high_bound

but it might work. The result was just a bit odd. executed the same command that got OOM-ed with 64MB heap pages, and then I ran it with ^^ this path + 128MB heap pages, and then it said that the max total size was 30MB 🤔

[bkchr]

This number is configurable, currently from the client side and the runtime, and bumping it is not generally frowned upon.

1. Allocator limit: this number is currently hardcoded to 16MiB, and it means that **no single allocation** can be larger than this amount. Of course, what is an allocation depends on the data type, and how often rustc allocates it, and how you interact with it (e.g. do you grow it dynamically or use `::with_capacity` from the get go). But as a rule of thumb, you can assume that for a single `Vec<u8>`, it can never contain more than `16 * 1024 * 1024` elements, and inserting the `16 * 1024 * 1024 + 1` will almost certainly fail.

This is something that would already be detected by the benchmarks anyway, because it doesn't change with the maximum heap size.

[bkchr]

Regarding checking that no transaction ever consumes all the memory, I already thought about this last week.

IMHO the simple solution to that is:

1. Collect all transactions being constructed by the benchmark that are at the maximum of the input.
2. Create a block, attach these transactions and try to import this. This should be done by the normal import workflow.

In this way we can check that any transaction never eats up all the memory.

[shawntabrizi]

@coriolinus

[coriolinus]

It's not particularly hard to wrap the global allocator to emit events or collect statistics about allocations and deallocations. There's an example here. The hard part will be doing the rest of the work to integrate it into the benchmarks collection.

[kianenigma]

I tried something like this, it seems to be inaccurate:

diff --git a/primitives/allocator/Cargo.toml b/primitives/allocator/Cargo.toml
index 1c38cbbb9..39f2a077e 100644
--- a/primitives/allocator/Cargo.toml
+++ b/primitives/allocator/Cargo.toml
@@ -21,7 +21,8 @@ log = { version = "0.4.11", optional = true }
 thiserror = { version = "1.0.21", optional = true }
 
 [features]
-default = [ "std" ]
+default = [ "std", "track-maximum" ]
+track-maximum = []
 std = [
 	"sp-std/std",
 	"sp-core/std",
diff --git a/primitives/allocator/src/freeing_bump.rs b/primitives/allocator/src/freeing_bump.rs
index e1afe7cec..8494b8167 100644
--- a/primitives/allocator/src/freeing_bump.rs
+++ b/primitives/allocator/src/freeing_bump.rs
@@ -309,6 +309,17 @@ pub struct FreeingBumpHeapAllocator {
 	free_lists: FreeLists,
 	total_size: u32,
 	poisoned: bool,
+	#[cfg(feature = "track-maximum")]
+	maximum_total_size: u32,
+}
+
+sp_std::if_std! {
+	#[cfg(feature = "track-maximum")]
+	impl Drop for FreeingBumpHeapAllocator {
+		fn drop(&mut self) {
+			log::debug!(target: "wasm-heap", "dropping allocator, maximum allocated amount {} bytes.", self.maximum_total_size);
+		}
+	}
 }
 
 impl FreeingBumpHeapAllocator {
@@ -318,12 +329,14 @@ impl FreeingBumpHeapAllocator {
 	///
 	/// - `heap_base` - the offset from the beginning of the linear memory where the heap starts.
 	pub fn new(heap_base: u32) -> Self {
-		let aligned_heap_base = (dbg!(heap_base) + ALIGNMENT - 1) / ALIGNMENT * ALIGNMENT;
+		let aligned_heap_base = (heap_base + ALIGNMENT - 1) / ALIGNMENT * ALIGNMENT;
 
 		FreeingBumpHeapAllocator {
 			bumper: aligned_heap_base,
 			free_lists: FreeLists::new(),
 			total_size: 0,
+			#[cfg(feature = "track-maximum")]
+			maximum_total_size: 0,
 			poisoned: false,
 		}
 	}
@@ -384,6 +397,11 @@ impl FreeingBumpHeapAllocator {
 		self.total_size += order.size() + HEADER_SIZE;
 		trace!("Heap size is {} bytes after allocation", self.total_size);
 
+		#[cfg(feature = "track-maximum")]
+		if self.total_size > self.maximum_total_size {
+			self.maximum_total_size = self.total_size
+		}
+
 		bomb.disarm();
 		Ok(Pointer::new(header_ptr + HEADER_SIZE))
 	}
@@ -432,7 +450,7 @@ impl FreeingBumpHeapAllocator {
 	/// Returns an `Error::AllocatorOutOfSpace` if the operation
 	/// would exhaust the heap.
 	fn bump(bumper: &mut u32, size: u32, heap_end: u32) -> Result<u32, Error> {
-		if dbg!(*bumper + size) > dbg!(heap_end) {
+		if *bumper + size > heap_end {
 			return Err(Error::AllocatorOutOfSpace);
 		}
 
diff --git a/primitives/npos-elections/src/pjr.rs b/primitives/npos-elections/src/pjr.rs
index 290110b14..843c0e79f 100644
--- a/primitives/npos-elections/src/pjr.rs
+++ b/primitives/npos-elections/src/pjr.rs
@@ -600,7 +600,6 @@ mod tests {
 				unexpected_failures.push(t);
 			}
 		}
-		dbg!(&unexpected_successes, &unexpected_failures);
 		assert!(unexpected_failures.is_empty() && unexpected_successes.is_empty());
 
 		high_bound

but it might work. The result was just a bit odd. executed the same command that got OOM-ed with 64MB heap pages, and then I ran it with ^^ this path + 128MB heap pages, and then it said that the max total size was 30MB 🤔

I implemented this here paritytech/substrate#9291

The issue was the I was confusing total_size and bumper. The latter is the more important variable to monitor.