Skip to content
This repository has been archived by the owner on Nov 15, 2023. It is now read-only.

Migrate ProfilingLayer to tracing registry API #8943

Merged
4 commits merged into from
Jun 10, 2021
Merged

Migrate ProfilingLayer to tracing registry API #8943

Changes from 1 commit
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
714a530
Migrate ProfilingLayer to tracing registry API
Folyd May 29, 2021
9ed5cd4
Remove the `current_span` field from `BlockSubscriber`.
Folyd May 31, 2021
19b90ab
Bump the `tracing-subscriber` version
Folyd May 31, 2021
6b76353
Fix Gitlab CI
Folyd Jun 5, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
156 changes: 87 additions & 69 deletions client/tracing/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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},
Level,
field::{Field, Visit},
span::{Attributes, Id, Record},
subscriber::Subscriber,
Level,
};
use tracing_subscriber::{
CurrentSpan,
layer::{Layer, Context},
};
use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
use tracing_subscriber::layer::{Context, Layer};
use tracing_subscriber::registry::LookupSpan;

#[doc(hidden)]
pub use tracing;
Expand All @@ -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
Expand Down Expand Up @@ -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.i64_values.is_empty() &&
self.u64_values.is_empty() &&
self.string_values.is_empty()
self.bool_values.is_empty()
&& self.i64_values.is_empty()
&& self.u64_values.is_empty()
&& self.string_values.is_empty()
}
}

Expand Down Expand Up @@ -225,8 +220,6 @@ impl ProfilingLayer {
Self {
targets,
trace_handler,
span_data: Mutex::new(FxHashMap::default()),
current_span: Default::default(),
}
}

Expand Down Expand Up @@ -257,79 +250,103 @@ fn parse_target(s: &str) -> (String, Level) {
}
}

impl<S: Subscriber> Layer<S> for ProfilingLayer {
fn new_span(&self, attrs: &Attributes<'_>, id: &Id, _ctx: Context<S>) {
let mut values = Values::default();
attrs.record(&mut values);
let span_datum = SpanDatum {
id: id.clone(),
parent_id: attrs.parent().cloned().or_else(|| self.current_span.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,
};
self.span_data.lock().insert(id.clone(), span_datum);
impl<S> Layer<S> for ProfilingLayer
where
S: Subscriber + for<'span> LookupSpan<'span>,
{
fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<S>) {
if let Some(span) = ctx.span(id) {
let mut extension = span.extensions_mut();
let parent_id = attrs.parent().cloned().or_else(|| {
if attrs.is_contextual() {
ctx.lookup_current().map(|span| span.id())
} else {
None
}
});

let mut values = Values::default();
attrs.record(&mut values);
let span_datum = SpanDatum {
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_record(&self, span: &Id, values: &Record<'_>, _ctx: Context<S>) {
let mut span_data = self.span_data.lock();
if let Some(s) = span_data.get_mut(span) {
values.record(&mut s.values);
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>) {
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 {
name: event.metadata().name().to_owned(),
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>) {
self.current_span.enter(span.clone());
let mut span_data = self.span_data.lock();
let start_time = Instant::now();
if let Some(mut s) = span_data.get_mut(&span) {
s.start_time = start_time;
fn on_enter(&self, span: &Id, ctx: Context<S>) {
if let Some(span) = ctx.span(span) {
let mut extensions = span.extensions_mut();
if let Some(s) = extensions.get_mut::<SpanDatum>() {
let start_time = Instant::now();
s.start_time = start_time;
}
}
}

fn on_exit(&self, span: &Id, _ctx: Context<S>) {
let end_time = Instant::now();
let span_datum = {
let mut span_data = self.span_data.lock();
span_data.remove(&span)
};

if let Some(mut span_datum) = span_datum {
// If `span_datum` is `None` we don't exit (we'd be exiting the parent span)
self.current_span.exit();
span_datum.overall_time += end_time - span_datum.start_time;
if span_datum.name == WASM_TRACE_IDENTIFIER {
span_datum.values.bool_values.insert("wasm".to_owned(), true);
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 self.check_target(&span_datum.target, &span_datum.level) {
fn on_exit(&self, span: &Id, ctx: Context<S>) {
if let Some(span) = ctx.span(span) {
let end_time = Instant::now();
let mut extensions = span.extensions_mut();
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 {
span_datum
.values
.bool_values
.insert("wasm".to_owned(), true);
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 self.check_target(&span_datum.target, &span_datum.level) {
self.trace_handler.handle_span(span_datum);
}
} 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>) {}
Expand Down Expand Up @@ -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;

Expand Down