pvf: Log memory metrics from preparation

node/core/pvf/Cargo.toml

@@ -14,13 +14,14 @@ assert_matches = "1.4.0"
 cpu-time = "1.0.0"
 futures = "0.3.21"
 futures-timer = "3.0.2"
-slotmap = "1.0"
 gum = { package = "tracing-gum", path = "../../gum" }
 pin-project = "1.0.9"
 rand = "0.8.5"
+rayon = "1.5.1"
+slotmap = "1.0"
 tempfile = "3.3.0"
+tikv-jemalloc-ctl = "0.5.0"
 tokio = { version = "1.22.0", features = ["fs", "process"] }
-rayon = "1.5.1"
 
 parity-scale-codec = { version = "3.1.5", default-features = false, features = ["derive"] }
 
@@ -38,6 +39,9 @@ sp-wasm-interface = { git = "https://github.com/paritytech/substrate", branch =
 sp-maybe-compressed-blob = { git = "https://github.com/paritytech/substrate", branch = "master" }
 sp-tracing = { git = "https://github.com/paritytech/substrate", branch = "master" }
 
+[target.'cfg(target_os = "linux")'.dependencies]
+libc = "0.2.139"
+
 [dev-dependencies]
 adder = { package = "test-parachain-adder", path = "../../../parachain/test-parachains/adder" }
 halt = { package = "test-parachain-halt", path = "../../../parachain/test-parachains/halt" }

node/core/pvf/src/host.rs

@@ -25,7 +25,8 @@ use crate::{
 	error::PrepareError,
 	execute,
 	metrics::Metrics,
-	prepare, PrepareResult, Priority, Pvf, ValidationError, LOG_TARGET,
+	prepare::{self, PreparationKind},
+	PrepareResult, Priority, Pvf, ValidationError, LOG_TARGET,
 };
 use always_assert::never;
 use futures::{
@@ -476,6 +477,7 @@ async fn handle_precheck_pvf(
 				priority: Priority::Normal,
 				pvf,
 				preparation_timeout: PRECHECK_PREPARATION_TIMEOUT,
+				preparation_kind: PreparationKind::PreCheck,
 			},
 		)
 		.await?;
@@ -547,6 +549,7 @@ async fn handle_execute_pvf(
 							priority,
 							pvf,
 							preparation_timeout: LENIENT_PREPARATION_TIMEOUT,
+							preparation_kind: PreparationKind::FromExecutionRequest,
 						},
 					)
 					.await?;
@@ -569,6 +572,7 @@ async fn handle_execute_pvf(
 				priority,
 				pvf,
 				preparation_timeout: LENIENT_PREPARATION_TIMEOUT,
+				preparation_kind: PreparationKind::FromExecutionRequest,
 			},
 		)
 		.await?;
@@ -621,6 +625,7 @@ async fn handle_heads_up(
 								priority: Priority::Normal,
 								pvf: active_pvf,
 								preparation_timeout: LENIENT_PREPARATION_TIMEOUT,
+								preparation_kind: PreparationKind::FromHeadsUpRequest,
 							},
 						)
 						.await?;
@@ -637,6 +642,7 @@ async fn handle_heads_up(
 					priority: Priority::Normal,
 					pvf: active_pvf,
 					preparation_timeout: LENIENT_PREPARATION_TIMEOUT,
+					preparation_kind: PreparationKind::FromHeadsUpRequest,
 				},
 			)
 			.await?;
@@ -845,7 +851,7 @@ mod tests {
 		let pulse = pulse_every(Duration::from_millis(100));
 		futures::pin_mut!(pulse);
 
-		for _ in 0usize..5usize {
+		for _ in 0..5 {
 			let start = std::time::Instant::now();
 			let _ = pulse.next().await.unwrap();
 

node/core/pvf/src/metrics.rs

@@ -72,6 +72,27 @@ impl Metrics {
 	pub(crate) fn time_execution(&self) -> Option<metrics::prometheus::prometheus::HistogramTimer> {
 		self.0.as_ref().map(|metrics| metrics.execution_time.start_timer())
 	}
+
+	/// Observe max_rss for precheck preparation.
+	pub(crate) fn observe_precheck_max_rss(&self, max_rss: f64) {
+		if let Some(metrics) = &self.0 {
+			metrics.precheck_max_rss.observe(max_rss);
+		}
+	}
+
+	/// Observe max resident memory for precheck preparation.
+	pub(crate) fn observe_precheck_max_resident(&self, max_resident_kb: f64) {
+		if let Some(metrics) = &self.0 {
+			metrics.precheck_max_resident.observe(max_resident_kb);
+		}
+	}
+
+	/// Observe max allocated memory for precheck preparation.
+	pub(crate) fn observe_precheck_max_allocated(&self, max_allocated_kb: f64) {
+		if let Some(metrics) = &self.0 {
+			metrics.precheck_max_allocated.observe(max_allocated_kb);
+		}
+	}
 }
 
 #[derive(Clone)]
@@ -85,6 +106,9 @@ struct MetricsInner {
 	execute_finished: prometheus::Counter<prometheus::U64>,
 	preparation_time: prometheus::Histogram,
 	execution_time: prometheus::Histogram,
+	precheck_max_rss: prometheus::Histogram,
+	precheck_max_allocated: prometheus::Histogram,
+	precheck_max_resident: prometheus::Histogram,
 }
 
 impl metrics::Metrics for Metrics {
@@ -202,6 +226,33 @@ impl metrics::Metrics for Metrics {
 				)?,
 				registry,
 			)?,
+			precheck_max_rss: prometheus::register(
+				prometheus::Histogram::with_opts(
+					prometheus::HistogramOpts::new(
+						"polkadot_pvf_precheck_max_rss",
+						"max_rss (maximum resident set size) observed for precheck preparation (in kilobytes)",
+					)
+				)?,
+				registry,
+			)?,
+			precheck_max_resident: prometheus::register(
+				prometheus::Histogram::with_opts(
+					prometheus::HistogramOpts::new(
+						"polkadot_pvf_precheck_max_resident",
+						"max resident memory observed for precheck preparation (in kilobytes)",
+					)
+				)?,
+				registry,
+			)?,
+			precheck_max_allocated: prometheus::register(
+				prometheus::Histogram::with_opts(
+					prometheus::HistogramOpts::new(
+						"polkadot_pvf_precheck_max_allocated",
+						"max allocated memory observed for precheck preparation (in kilobytes)",
+					)
+				)?,
+				registry,
+			)?,
 		};
 		Ok(Metrics(Some(inner)))
 	}