Add support for wasm runtime metrics try #2 (#4483)

* Add runtime metrics provider Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Runner changes Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Some sample metrics in paras_inherent Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * update cargo toml Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fmt Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * bug Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * more fmt after merge Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Refactor metric prefix override Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fmt Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * remove bug comment Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Add runtime metric primitives Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Impl trace event parsing Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Update metrics Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * cargo lock Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fmt Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Fix target check Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Runtime metrics primitives Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Review feedback Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Runtime metrics crate Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Node side runtime metric changes Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * use runtime CounterVec instead of macro Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fmt nice Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * remove dead code Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * base58 decoding Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * base58 encoding Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fix warn Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * typo Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Review feedback Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Finish label support Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fmt Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * please compile Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * add feature gate Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fmt Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Comment cargo toml Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Fix cargo toml description Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Update doc. Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * switch to `runtime-metrics` feature Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fmt Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * cargo toml Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fix tests Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fixes Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * better ux Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * from_utf8_unchecked is safe Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fmt Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Add Counter and refactor Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Fixes Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * review fixes Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * more fixes Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * add integration test Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * dev deps Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * gitlab script update Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * review fixes Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * fix merge damage Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Run tests twice Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * small fix Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * typo Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * cargo lock Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * tests Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * spellcheck happy ? Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * more fixes Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * Guard tracing init Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * missing copyright Signed-off-by: Andrei Sandu <andrei-mihail@parity.io> * update lockfile for substrate Co-authored-by: parity-processbot <>
2026-06-19 18:11:03 +00:00 · 2021-12-16 13:56:25 +02:00
parent 6f2f9fe381
commit e75ad88ae8
23 changed files with 1014 additions and 185 deletions
@@ -30,6 +30,17 @@ pub use metered_channel as metered;
 pub mod metronome;
 pub use self::metronome::Metronome;

+#[cfg(feature = "runtime-metrics")]
+pub mod runtime;
+#[cfg(feature = "runtime-metrics")]
+pub use self::runtime::logger_hook;
+
+/// Export a dummy logger hook when `wasm tracing` is not enabled.
+#[cfg(not(feature = "runtime-metrics"))]
+pub fn logger_hook() -> impl FnOnce(&mut sc_cli::LoggerBuilder, &sc_service::Configuration) -> () {
+	|_logger_builder, _config| {}
+}
+
 /// This module reexports Prometheus types and defines the [`Metrics`] trait.
 pub mod metrics {
 	/// Reexport Substrate Prometheus types.
@@ -69,3 +80,6 @@ pub mod metrics {
 		}
 	}
 }
+
+#[cfg(test)]
+mod tests;
@@ -0,0 +1,210 @@
+// Copyright 2021 Parity Technologies (UK) Ltd.
+// This file is part of Polkadot.
+
+// Polkadot is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// Polkadot is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with Polkadot.  If not, see <http://www.gnu.org/licenses/>.
+
+//! Runtime Metrics helpers.
+//!
+//! A runtime metric provider implementation that builds on top of Substrate wasm
+//! tracing support. This requires that the custom profiler (`TraceHandler`) to be
+//! registered in substrate via a `logger_hook()`. Events emitted from runtime are
+//! then captured/processed by the `TraceHandler` implementation.
+#![cfg(feature = "runtime-metrics")]
+
+use codec::Decode;
+use primitives::v1::{
+	RuntimeMetricLabelValues, RuntimeMetricOp, RuntimeMetricRegisterParams, RuntimeMetricUpdate,
+};
+use std::{
+	collections::hash_map::HashMap,
+	sync::{Arc, Mutex, MutexGuard},
+};
+use substrate_prometheus_endpoint::{
+	register, Counter, CounterVec, Opts, PrometheusError, Registry, U64,
+};
+
+const LOG_TARGET: &'static str = "metrics::runtime";
+const METRIC_PREFIX: &'static str = "polkadot";
+
+/// Holds the registered Prometheus metric collections.
+#[derive(Clone, Default)]
+pub struct Metrics {
+	counter_vecs: Arc<Mutex<HashMap<String, CounterVec<U64>>>>,
+	counters: Arc<Mutex<HashMap<String, Counter<U64>>>>,
+}
+
+/// Runtime metrics wrapper.
+#[derive(Clone)]
+pub struct RuntimeMetricsProvider(Registry, Metrics);
+
+impl RuntimeMetricsProvider {
+	/// Creates new instance.
+	pub fn new(metrics_registry: Registry) -> Self {
+		Self(metrics_registry, Metrics::default())
+	}
+
+	/// Register a counter vec metric.
+	pub fn register_countervec(&self, metric_name: &str, params: &RuntimeMetricRegisterParams) {
+		self.with_counter_vecs_lock_held(|mut hashmap| {
+			hashmap.entry(metric_name.to_owned()).or_insert(register(
+				CounterVec::new(
+					Opts::new(metric_name, params.description()),
+					&params.labels().unwrap_or_default(),
+				)?,
+				&self.0,
+			)?);
+			Ok(())
+		})
+	}
+
+	/// Register a counter metric.
+	pub fn register_counter(&self, metric_name: &str, params: &RuntimeMetricRegisterParams) {
+		self.with_counters_lock_held(|mut hashmap| {
+			hashmap
+				.entry(metric_name.to_owned())
+				.or_insert(register(Counter::new(metric_name, params.description())?, &self.0)?);
+			return Ok(())
+		})
+	}
+
+	/// Increment a counter with labels by a value.
+	pub fn inc_counter_vec_by(&self, name: &str, value: u64, labels: &RuntimeMetricLabelValues) {
+		self.with_counter_vecs_lock_held(|mut hashmap| {
+			hashmap.entry(name.to_owned()).and_modify(|counter_vec| {
+				counter_vec.with_label_values(&labels.as_str_vec()).inc_by(value)
+			});
+
+			Ok(())
+		});
+	}
+
+	/// Increment a counter by a value.
+	pub fn inc_counter_by(&self, name: &str, value: u64) {
+		self.with_counters_lock_held(|mut hashmap| {
+			hashmap
+				.entry(name.to_owned())
+				.and_modify(|counter_vec| counter_vec.inc_by(value));
+			Ok(())
+		})
+	}
+
+	fn with_counters_lock_held<F>(&self, do_something: F)
+	where
+		F: FnOnce(MutexGuard<'_, HashMap<String, Counter<U64>>>) -> Result<(), PrometheusError>,
+	{
+		let _ = self.1.counters.lock().map(do_something).or_else(|error| {
+			tracing::error!(
+				target: LOG_TARGET,
+				"Cannot acquire the counter hashmap lock: {:?}",
+				error
+			);
+			Err(error)
+		});
+	}
+
+	fn with_counter_vecs_lock_held<F>(&self, do_something: F)
+	where
+		F: FnOnce(MutexGuard<'_, HashMap<String, CounterVec<U64>>>) -> Result<(), PrometheusError>,
+	{
+		let _ = self.1.counter_vecs.lock().map(do_something).or_else(|error| {
+			tracing::error!(
+				target: LOG_TARGET,
+				"Cannot acquire the countervec hashmap lock: {:?}",
+				error
+			);
+			Err(error)
+		});
+	}
+}
+
+impl sc_tracing::TraceHandler for RuntimeMetricsProvider {
+	fn handle_span(&self, _span: &sc_tracing::SpanDatum) {}
+	fn handle_event(&self, event: &sc_tracing::TraceEvent) {
+		if event
+			.values
+			.string_values
+			.get("target")
+			.unwrap_or(&String::default())
+			.ne("metrics")
+		{
+			return
+		}
+
+		if let Some(update_op_bs58) = event.values.string_values.get("params") {
+			// Deserialize the metric update struct.
+			match RuntimeMetricUpdate::decode(
+				&mut RuntimeMetricsProvider::parse_event_params(&update_op_bs58)
+					.unwrap_or_default()
+					.as_slice(),
+			) {
+				Ok(update_op) => {
+					self.parse_metric_update(update_op);
+				},
+				Err(e) => {
+					tracing::error!(target: LOG_TARGET, "TraceEvent decode failed: {:?}", e);
+				},
+			}
+		}
+	}
+}
+
+impl RuntimeMetricsProvider {
+	// Parse end execute the update operation.
+	fn parse_metric_update(&self, update: RuntimeMetricUpdate) {
+		let metric_name = &format!("{}_{}", METRIC_PREFIX, update.metric_name());
+
+		match update.op {
+			RuntimeMetricOp::Register(ref params) =>
+				if params.labels.is_none() {
+					self.register_counter(metric_name, &params);
+				} else {
+					self.register_countervec(metric_name, &params);
+				},
+			RuntimeMetricOp::IncrementCounterVec(value, ref labels) =>
+				self.inc_counter_vec_by(metric_name, value, labels),
+			RuntimeMetricOp::IncrementCounter(value) => self.inc_counter_by(metric_name, value),
+		}
+	}
+
+	// Returns the `bs58` encoded metric update operation.
+	fn parse_event_params(event_params: &str) -> Option<Vec<u8>> {
+		// Shave " }" suffix.
+		let new_len = event_params.len().saturating_sub(2);
+		let event_params = &event_params[..new_len];
+
+		// Shave " { update_op: " prefix.
+		const SKIP_CHARS: &'static str = " { update_op: ";
+		if SKIP_CHARS.len() < event_params.len() {
+			if SKIP_CHARS.eq_ignore_ascii_case(&event_params[..SKIP_CHARS.len()]) {
+				return bs58::decode(&event_params[SKIP_CHARS.len()..].as_bytes()).into_vec().ok()
+			}
+		}
+
+		// No event was parsed
+		None
+	}
+}
+
+/// Returns the custom profiling closure that we'll apply to the `LoggerBuilder`.
+pub fn logger_hook() -> impl FnOnce(&mut sc_cli::LoggerBuilder, &sc_service::Configuration) -> () {
+	|logger_builder, config| {
+		if config.prometheus_registry().is_none() {
+			tracing::debug!(target: LOG_TARGET, "Prometheus registry is not configured.",);
+			return
+		}
+		let registry = config.prometheus_registry().cloned().unwrap();
+		let metrics_provider = RuntimeMetricsProvider::new(registry);
+		logger_builder.with_custom_profiling(Box::new(metrics_provider));
+	}
+}
@@ -0,0 +1,70 @@
+// Copyright 2021 Parity Technologies (UK) Ltd.
+// This file is part of Substrate.
+
+// Substrate is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// Substrate is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with Substrate.  If not, see <http://www.gnu.org/licenses/>.
+#![cfg(feature = "runtime-metrics")]
+use assert_cmd::cargo::cargo_bin;
+use std::{convert::TryInto, process::Command, thread, time::Duration};
+use tempfile::tempdir;
+
+#[test]
+#[cfg(unix)]
+fn runtime_can_publish_metrics() {
+	use hyper::{Client, Uri};
+	use nix::{
+		sys::signal::{kill, Signal::SIGINT},
+		unistd::Pid,
+	};
+	use std::convert::TryFrom;
+
+	const RUNTIME_METRIC_NAME: &str = "polkadot_parachain_inherent_data_bitfields_processed";
+	const DEFAULT_PROMETHEUS_PORT: u16 = 9615;
+	let metrics_uri = format!("http://localhost:{}/metrics", DEFAULT_PROMETHEUS_PORT);
+
+	// Start the node with tracing enabled and forced wasm runtime execution.
+	let cmd = Command::new(cargo_bin("polkadot"))
+		// Runtime metrics require this trace target.
+		.args(&["--tracing-targets", "wasm_tracing=trace"])
+		.args(&["--execution", "wasm"])
+		.args(&["--dev", "-d"])
+		.arg(tempdir().expect("failed to create temp dir.").path())
+		.spawn()
+		.expect("failed to start the node process");
+
+	// Enough time to author one block.
+	thread::sleep(Duration::from_secs(10));
+
+	let runtime = tokio::runtime::Runtime::new().expect("failed to create tokio runtime");
+
+	runtime.block_on(async {
+		let client = Client::new();
+
+		let res = client
+			.get(Uri::try_from(&metrics_uri).expect("bad URI"))
+			.await
+			.expect("get request failed");
+
+		let body = String::from_utf8(
+			hyper::body::to_bytes(res).await.expect("can't get body as bytes").to_vec(),
+		)
+		.expect("body is not an UTF8 string");
+
+		// Time to die.
+		kill(Pid::from_raw(cmd.id().try_into().unwrap()), SIGINT)
+			.expect("failed to kill the node process");
+
+		// If the node has authored at least 1 block this should pass.
+		assert!(body.contains(&RUNTIME_METRIC_NAME));
+	});
+}