Migrate ProfilingLayer to tracing registry API (#8943)

* Migrate ProfilingLayer to tracing registry API

* Remove the `current_span` field from `BlockSubscriber`.

* Bump the `tracing-subscriber` version

* Fix Gitlab CI

substrate/Cargo.lock

@@ -10519,9 +10519,9 @@ dependencies = [
 
 [[package]]
 name = "tracing-subscriber"
-version = "0.2.16"
+version = "0.2.18"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "8ab8966ac3ca27126141f7999361cc97dd6fb4b71da04c02044fa9045d98bb96"
+checksum = "aa5553bf0883ba7c9cbe493b085c29926bd41b66afc31ff72cf17ff4fb60dcd5"
 dependencies = [
  "ansi_term 0.12.1",
  "chrono",

substrate/client/executor/Cargo.toml

@@ -48,7 +48,7 @@ sp-runtime = { version = "3.0.0", path = "../../primitives/runtime" }
 sp-tracing = { version = "3.0.0", path = "../../primitives/tracing" }
 sc-tracing = { version = "3.0.0", path = "../tracing" }
 tracing = "0.1.25"
-tracing-subscriber = "0.2.15"
+tracing-subscriber = "0.2.18"
 paste = "1.0"
 
 [features]

substrate/client/tracing/Cargo.toml

@@ -26,8 +26,8 @@ serde = "1.0.101"
 serde_json = "1.0.41"
 thiserror = "1.0.21"
 tracing = "0.1.25"
-tracing-log = "0.1.1"
+tracing-log = "0.1.2"
-tracing-subscriber = "0.2.15"
+tracing-subscriber = "0.2.18"
 sp-tracing = { version = "3.0.0", path = "../../primitives/tracing" }
 sp-rpc = { version = "3.0.0", path = "../../primitives/rpc" }
 sp-block-builder = { version = "3.0.0", path = "../../primitives/block-builder" }

substrate/client/tracing/src/block/mod.rs

@@ -20,7 +20,6 @@ use std::{collections::HashMap, sync::{Arc, atomic::{AtomicU64, Ordering}}, time
 
 use parking_lot::Mutex;
 use tracing::{Dispatch, dispatcher, Subscriber, Level, span::{Attributes, Record, Id}};
-use tracing_subscriber::CurrentSpan;
 
 use sc_client_api::BlockBackend;
 use sc_rpc_server::MAX_PAYLOAD;
@@ -75,7 +74,6 @@ pub enum Error {
 struct BlockSubscriber {
 	targets: Vec<(String, Level)>,
 	next_id: AtomicU64,
-	current_span: CurrentSpan,
 	spans: Mutex<HashMap<Id, SpanDatum>>,
 	events: Mutex<Vec<TraceEvent>>,
 }
@@ -93,7 +91,6 @@ impl BlockSubscriber {
 		BlockSubscriber {
 			targets,
 			next_id,
-			current_span: CurrentSpan::default(),
 			spans: Mutex::new(HashMap::new()),
 			events: Mutex::new(Vec::new()),
 		}
@@ -117,8 +114,7 @@ impl Subscriber for BlockSubscriber {
 		let id = Id::from_u64(self.next_id.fetch_add(1, Ordering::Relaxed));
 		let mut values = Values::default();
 		attrs.record(&mut values);
-		let parent_id = attrs.parent().cloned()
+		let parent_id = attrs.parent().cloned();
-			.or_else(|| self.current_span.id());
 		let span = SpanDatum {
 			id: id.clone(),
 			parent_id,
@@ -150,8 +146,7 @@ impl Subscriber for BlockSubscriber {
 	fn event(&self, event: &tracing::Event<'_>) {
 		let mut values = crate::Values::default();
 		event.record(&mut values);
-		let parent_id = event.parent().cloned()
+		let parent_id = event.parent().cloned();
-			.or_else(|| self.current_span.id());
 		let trace_event = TraceEvent {
 			name: event.metadata().name().to_owned(),
 			target: event.metadata().target().to_owned(),
@@ -162,14 +157,10 @@ impl Subscriber for BlockSubscriber {
 		self.events.lock().push(trace_event);
 	}
 
-	fn enter(&self, id: &Id) {
+	fn enter(&self, _id: &Id) {
-		self.current_span.enter(id.clone());
 	}
 
-	fn exit(&self, span: &Id) {
+	fn exit(&self, _span: &Id) {
-		if self.spans.lock().contains_key(span) {
-			self.current_span.exit();
-		}
 	}
 }
 

substrate/client/tracing/src/lib.rs

@@ -28,26 +28,23 @@
 
 #![warn(missing_docs)]
 
-pub mod logging;
 pub mod block;
+pub mod logging;
 
 use rustc_hash::FxHashMap;
+use serde::ser::{Serialize, SerializeMap, Serializer};
+use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
 use std::fmt;
 use std::time::{Duration, Instant};
-use parking_lot::Mutex;
-use serde::ser::{Serialize, Serializer, SerializeMap};
 use tracing::{
 	event::Event,
-	field::{Visit, Field},
+	field::{Field, Visit},
-	Level,
 	span::{Attributes, Id, Record},
 	subscriber::Subscriber,
+	Level,
 };
-use tracing_subscriber::{
+use tracing_subscriber::layer::{Context, Layer};
-	CurrentSpan,
+use tracing_subscriber::registry::LookupSpan;
-	layer::{Layer, Context},
-};
-use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
 
 #[doc(hidden)]
 pub use tracing;
@@ -58,8 +55,6 @@ const ZERO_DURATION: Duration = Duration::from_nanos(0);
 pub struct ProfilingLayer {
 	targets: Vec<(String, Level)>,
 	trace_handler: Box<dyn TraceHandler>,
-	span_data: Mutex<FxHashMap<Id, SpanDatum>>,
-	current_span: CurrentSpan,
 }
 
 /// Used to configure how to receive the metrics
@@ -142,10 +137,10 @@ impl Values {
 
 	/// Checks if all individual collections are empty
 	pub fn is_empty(&self) -> bool {
-		self.bool_values.is_empty() &&
+		self.bool_values.is_empty()
-			self.i64_values.is_empty() &&
+			&& self.i64_values.is_empty()
-			self.u64_values.is_empty() &&
+			&& self.u64_values.is_empty()
-			self.string_values.is_empty()
+			&& self.string_values.is_empty()
 	}
 }
 
@@ -225,8 +220,6 @@ impl ProfilingLayer {
 		Self {
 			targets,
 			trace_handler,
-			span_data: Mutex::new(FxHashMap::default()),
-			current_span: Default::default(),
 		}
 	}
 
@@ -257,32 +250,56 @@ fn parse_target(s: &str) -> (String, Level) {
 	}
 }
 
-impl<S: Subscriber> Layer<S> for ProfilingLayer {
+impl<S> Layer<S> for ProfilingLayer
-	fn new_span(&self, attrs: &Attributes<'_>, id: &Id, _ctx: Context<S>) {
+where
-		let mut values = Values::default();
+	S: Subscriber + for<'span> LookupSpan<'span>,
-		attrs.record(&mut values);
+{
-		let span_datum = SpanDatum {
+	fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<S>) {
-			id: id.clone(),
+		if let Some(span) = ctx.span(id) {
-			parent_id: attrs.parent().cloned().or_else(|| self.current_span.id()),
+			let mut extension = span.extensions_mut();
-			name: attrs.metadata().name().to_owned(),
+			let parent_id = attrs.parent().cloned().or_else(|| {
-			target: attrs.metadata().target().to_owned(),
+				if attrs.is_contextual() {
-			level: *attrs.metadata().level(),
+					ctx.lookup_current().map(|span| span.id())
-			line: attrs.metadata().line().unwrap_or(0),
+				} else {
-			start_time: Instant::now(),
+					None
-			overall_time: ZERO_DURATION,
+				}
-			values,
+			});
-		};
-		self.span_data.lock().insert(id.clone(), span_datum);
-	}
 
-	fn on_record(&self, span: &Id, values: &Record<'_>, _ctx: Context<S>) {
+			let mut values = Values::default();
-		let mut span_data = self.span_data.lock();
+			attrs.record(&mut values);
-		if let Some(s) = span_data.get_mut(span) {
+			let span_datum = SpanDatum {
-			values.record(&mut s.values);
+				id: id.clone(),
+				parent_id,
+				name: attrs.metadata().name().to_owned(),
+				target: attrs.metadata().target().to_owned(),
+				level: *attrs.metadata().level(),
+				line: attrs.metadata().line().unwrap_or(0),
+				start_time: Instant::now(),
+				overall_time: ZERO_DURATION,
+				values,
+			};
+			extension.insert(span_datum);
 		}
 	}
 
-	fn on_event(&self, event: &Event<'_>, _ctx: Context<S>) {
+	fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<S>) {
+		if let Some(span) = ctx.span(id) {
+			let mut extensions = span.extensions_mut();
+			if let Some(s) = extensions.get_mut::<SpanDatum>() {
+				values.record(&mut s.values);
+			}
+		}
+	}
+
+	fn on_event(&self, event: &Event<'_>, ctx: Context<S>) {
+		let parent_id = event.parent().cloned().or_else(|| {
+			if event.is_contextual() {
+				ctx.lookup_current().map(|span| span.id())
+			} else {
+				None
+			}
+		});
+
 		let mut values = Values::default();
 		event.record(&mut values);
 		let trace_event = TraceEvent {
@@ -290,46 +307,46 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 			target: event.metadata().target().to_owned(),
 			level: *event.metadata().level(),
 			values,
-			parent_id: event.parent().cloned().or_else(|| self.current_span.id()),
+			parent_id,
 		};
 		self.trace_handler.handle_event(trace_event);
 	}
 
-	fn on_enter(&self, span: &Id, _ctx: Context<S>) {
+	fn on_enter(&self, span: &Id, ctx: Context<S>) {
-		self.current_span.enter(span.clone());
+		if let Some(span) = ctx.span(span) {
-		let mut span_data = self.span_data.lock();
+			let mut extensions = span.extensions_mut();
-		let start_time = Instant::now();
+			if let Some(s) = extensions.get_mut::<SpanDatum>() {
-		if let Some(mut s) = span_data.get_mut(&span) {
+				let start_time = Instant::now();
-			s.start_time = start_time;
+				s.start_time = start_time;
+			}
 		}
 	}
 
-	fn on_exit(&self, span: &Id, _ctx: Context<S>) {
+	fn on_exit(&self, span: &Id, ctx: Context<S>) {
-		let end_time = Instant::now();
+		if let Some(span) = ctx.span(span) {
-		let span_datum = {
+			let end_time = Instant::now();
-			let mut span_data = self.span_data.lock();
+			let mut extensions = span.extensions_mut();
-			span_data.remove(&span)
+			if let Some(mut span_datum) = extensions.remove::<SpanDatum>() {
-		};
+				span_datum.overall_time += end_time - span_datum.start_time;
-
+				if span_datum.name == WASM_TRACE_IDENTIFIER {
-		if let Some(mut span_datum) = span_datum {
+					span_datum
-			// If `span_datum` is `None` we don't exit (we'd be exiting the parent span)
+						.values
-			self.current_span.exit();
+						.bool_values
-			span_datum.overall_time += end_time - span_datum.start_time;
+						.insert("wasm".to_owned(), true);
-			if span_datum.name == WASM_TRACE_IDENTIFIER {
+					if let Some(n) = span_datum.values.string_values.remove(WASM_NAME_KEY) {
-				span_datum.values.bool_values.insert("wasm".to_owned(), true);
+						span_datum.name = n;
-				if let Some(n) = span_datum.values.string_values.remove(WASM_NAME_KEY) {
+					}
-					span_datum.name = n;
+					if let Some(t) = span_datum.values.string_values.remove(WASM_TARGET_KEY) {
-				}
+						span_datum.target = t;
-				if let Some(t) = span_datum.values.string_values.remove(WASM_TARGET_KEY) {
+					}
-					span_datum.target = t;
+					if self.check_target(&span_datum.target, &span_datum.level) {
-				}
+						self.trace_handler.handle_span(span_datum);
-				if self.check_target(&span_datum.target, &span_datum.level) {
+					}
+				} else {
 					self.trace_handler.handle_span(span_datum);
 				}
-			} else {
-				self.trace_handler.handle_span(span_datum);
 			}
-		};
+		}
 	}
 
 	fn on_close(&self, _span: Id, _ctx: Context<S>) {}
@@ -414,6 +431,7 @@ impl From<SpanDatum> for sp_rpc::tracing::Span {
 #[cfg(test)]
 mod tests {
 	use super::*;
+	use parking_lot::Mutex;
 	use std::sync::Arc;
 	use tracing_subscriber::layer::SubscriberExt;
 

substrate/client/tracing/src/logging/mod.rs

@@ -398,7 +398,7 @@ mod tests {
 	#[test]
 	fn prefix_in_log_lines() {
 		let re = regex::Regex::new(&format!(
-			r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}}  \[{}\] {}$",
+			r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} \[{}\] {}$",
 			EXPECTED_NODE_NAME, EXPECTED_LOG_MESSAGE,
 		))
 		.unwrap();
@@ -448,7 +448,7 @@ mod tests {
 	#[test]
 	fn do_not_write_with_colors_on_tty() {
 		let re = regex::Regex::new(&format!(
-			r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}}  {}$",
+			r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} {}$",
 			EXPECTED_LOG_MESSAGE,
 		))
 		.unwrap();

substrate/primitives/tracing/Cargo.toml

@@ -23,7 +23,7 @@ codec = { version = "2.0.0", package = "parity-scale-codec", default-features =
 tracing = { version = "0.1.25", default-features = false }
 tracing-core = { version = "0.1.17", default-features = false }
 log = { version = "0.4.8", optional = true }
-tracing-subscriber = { version = "0.2.15", optional = true, features = ["tracing-log"] }
+tracing-subscriber = { version = "0.2.18", optional = true, features = ["tracing-log"] }
 parking_lot = { version = "0.10.0", optional = true }
 erased-serde = { version = "0.3.9", optional = true }
 serde = { version = "1.0.101", optional = true }