From 45bf82870cefa5d140bd0a80ef07197d5b05b166 Mon Sep 17 00:00:00 2001 From: Thibault Saunier Date: Fri, 30 Jun 2023 11:10:21 -0400 Subject: [PATCH 1/4] Add pad name in traces --- src/tracer.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/tracer.rs b/src/tracer.rs index ccb8638..c377f13 100644 --- a/src/tracer.rs +++ b/src/tracer.rs @@ -51,7 +51,7 @@ impl TracingTracerPriv { None, None, GstCallsiteKind::Span, - &["gstpad.state", "gstpad.parent.name"], + &["gstpad.state", "gstpad.name", "gstpad.parent.name"], ); let interest = callsite.interest(); if interest.is_never() { @@ -65,6 +65,8 @@ impl TracingTracerPriv { let gstpad_flags_value = Some(tracing_core::field::display(crate::PadFlags( pad.pad_flags().bits(), ))); + let name = pad.name(); + let name_value = Some(name.as_str()); let gstpad_parent = pad.parent_element(); let gstpad_parent_name_value = gstpad_parent.map(|p| p.name()); let gstpad_parent_name_value = gstpad_parent_name_value.as_ref().map(|n| n.as_str()); @@ -73,6 +75,7 @@ impl TracingTracerPriv { let values = field_values![fields_iter => // /!\ /!\ /!\ Must be in the same order as the field list above /!\ /!\ /!\ "gstpad.flags" = gstpad_flags_value; + "gstpad.name" = name_value; "gstpad.parent.name" = gstpad_parent_name_value; ]; let valueset = fields.value_set(&values); From 6e02435c1af8111f12dce83259efbdfbb27d1eb8 Mon Sep 17 00:00:00 2001 From: Thibault Saunier Date: Fri, 30 Jun 2023 11:13:39 -0400 Subject: [PATCH 2/4] Add pad chain infos --- Cargo.toml | 3 +++ src/tracer.rs | 16 ++++++++++++++++ 2 files changed, 19 insertions(+) diff --git a/Cargo.toml b/Cargo.toml index 7fb0df5..82df630 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -31,3 +31,6 @@ tracing-tracy = "0.10" [package.metadata.docs.rs] rustdoc-args = ["--cfg", "tracing_gstreamer_docs"] + +[features] +v1_22 = ["gstreamer/v1_22"] diff --git a/src/tracer.rs b/src/tracer.rs index c377f13..f8f1534 100644 --- a/src/tracer.rs +++ b/src/tracer.rs @@ -118,12 +118,23 @@ impl ObjectImpl for TracingTracerPriv { self.register_hook(TracerHook::PadPushEventPre); self.register_hook(TracerHook::PadPullRangePost); self.register_hook(TracerHook::PadPullRangePre); + + #[cfg(feature = "v1_22")] + { + self.register_hook(TracerHook::PadChainPre); + self.register_hook(TracerHook::PadChainPost); + } } } impl GstObjectImpl for TracingTracerPriv {} impl TracerImpl for TracingTracerPriv { + #[cfg(feature = "v1_22")] + fn pad_chain_pre(&self, _: u64, pad: &Pad, _: &Buffer) { + self.pad_pre("pad_chain", pad); + } + fn pad_push_pre(&self, _: u64, pad: &Pad, _: &Buffer) { self.pad_pre("pad_push", pad); } @@ -160,6 +171,11 @@ impl TracerImpl for TracingTracerPriv { self.pop_span(); } + #[cfg(feature = "v1_22")] + fn pad_chain_post(&self, _: u64, _: &Pad, _: Result) { + self.pop_span(); + } + fn pad_query_post(&self, _: u64, _: &Pad, _: &gstreamer::QueryRef, _: bool) { self.pop_span(); } From 0c3cb3a3f7b9c6f5797ed2e8f9e9eeb00c1397c9 Mon Sep 17 00:00:00 2001 From: Thibault Saunier Date: Sat, 1 Jul 2023 09:23:33 -0400 Subject: [PATCH 3/4] tracer: Factor out a SpanBuilder struct to log different objects It is useful in the logs to know the query/message/event that are being handled so we log them. --- src/lib.rs | 8 ++++ src/tracer.rs | 123 ++++++++++++++++++++++++++++++++++++++------------ 2 files changed, 101 insertions(+), 30 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index b29cde3..0bdd147 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -91,6 +91,14 @@ fn state_desc(state: gstreamer::ffi::GstState) -> &'static str { } } +fn query_name(query: &gstreamer::QueryRef) -> &'static str { + use gstreamer::ffi as gffi; + unsafe { + let type_ = gffi::gst_query_type_get_name((*query.as_ptr()).type_); + std::ffi::CStr::from_ptr(type_).to_str().unwrap() + } +} + /// Enable the integration between GStreamer logging system and the `tracing` library. /// /// Once enabled the default [`tracing::Subscriber`][tracing_core::subscriber::Subscriber] will diff --git a/src/tracer.rs b/src/tracer.rs index f8f1534..aa72cb8 100644 --- a/src/tracer.rs +++ b/src/tracer.rs @@ -3,6 +3,7 @@ use glib::subclass::basic; use gstreamer::{ glib, prelude::PadExtManual, + prelude::*, subclass::prelude::*, traits::{GstObjectExt, PadExt}, Buffer, FlowError, FlowSuccess, Object, Pad, Tracer, @@ -19,39 +20,59 @@ pub struct TracingTracerPriv { span_stack: thread_local::ThreadLocal>>, } -impl TracingTracerPriv { - fn push_span(&self, dispatch: Dispatch, attributes: Attributes) { - let span_id = dispatch.new_span(&attributes); - dispatch.enter(&span_id); - self.span_stack - .get_or(|| RefCell::new(Vec::new())) - .borrow_mut() - .push(EnteredSpan { - id: span_id, - dispatch, - }) +struct SpanBuilder<'a> { + name: &'static str, + pad: Option<&'a Pad>, + event: Option<&'a gstreamer::Event>, + query: Option<&'a gstreamer::QueryRef>, +} + +impl<'a> SpanBuilder<'a> { + fn new_pad(name: &'static str, pad: &'a Pad) -> Self { + Self { + name, + pad: Some(pad), + event: None, + query: None, + } } - fn pop_span(&self) -> Option<()> { - self.span_stack - .get_or(|| RefCell::new(Vec::new())) - .borrow_mut() - .pop() - .map(|span| { - span.dispatch.exit(&span.id); - span.dispatch.try_close(span.id); - }) + + fn event(self, event: &'a gstreamer::Event) -> Self { + Self { + event: Some(event), + ..self + } } - fn pad_pre(&self, name: &'static str, pad: &Pad) { + fn query(self, query: &'a gstreamer::QueryRef) -> Self { + Self { + query: Some(query), + ..self + } + } + + fn build(self, tracer: &TracingTracerPriv) { let callsite = crate::callsite::DynamicCallsites::get().callsite_for( tracing::Level::ERROR, - name, - name, + self.name, + self.name, None, None, None, GstCallsiteKind::Span, - &["gstpad.state", "gstpad.name", "gstpad.parent.name"], + self.pad.as_ref().map_or( + unreachable!(), + |_| { + // List of fields for pad traces + &[ + "gstpad.flags", + "gstpad.name", + "gstpad.parent.name", + "gstpad.event.type", + "gstpad.query.type", + ] + }, + ), ); let interest = callsite.interest(); if interest.is_never() { @@ -62,6 +83,7 @@ impl TracingTracerPriv { if !dispatch.enabled(meta) { return; } + let pad = self.pad.unwrap(); let gstpad_flags_value = Some(tracing_core::field::display(crate::PadFlags( pad.pad_flags().bits(), ))); @@ -72,15 +94,52 @@ impl TracingTracerPriv { let gstpad_parent_name_value = gstpad_parent_name_value.as_ref().map(|n| n.as_str()); let fields = meta.fields(); let mut fields_iter = fields.into_iter(); + let event_type = self.event.map(|e| e.type_().name()); + let event_type_name = event_type.as_ref().map(|n| n.as_str()); + let query_type_name = self.query.map(|q| crate::query_name(q)); + let values = field_values![fields_iter => - // /!\ /!\ /!\ Must be in the same order as the field list above /!\ /!\ /!\ + // /!\ /!\ /!\ Must be in the same order as the list of fields for pad above /!\ /!\ /!\ "gstpad.flags" = gstpad_flags_value; "gstpad.name" = name_value; "gstpad.parent.name" = gstpad_parent_name_value; + "gstpad.event.type" = event_type_name; + "gstpad.query.type" = query_type_name; ]; + let valueset = fields.value_set(&values); let attrs = tracing::span::Attributes::new_root(meta, &valueset); - self.push_span(dispatch, attrs); + tracer.push_span(dispatch, attrs); + } +} + +impl TracingTracerPriv { + fn push_span(&self, dispatch: Dispatch, attributes: Attributes) { + let span_id = dispatch.new_span(&attributes); + dispatch.enter(&span_id); + self.span_stack + .get_or(|| RefCell::new(Vec::new())) + .borrow_mut() + .push(EnteredSpan { + id: span_id, + dispatch, + }) + } + fn pop_span(&self) -> Option<()> { + self.span_stack + .get_or(|| RefCell::new(Vec::new())) + .borrow_mut() + .pop() + .map(|span| { + span.dispatch.exit(&span.id); + span.dispatch.try_close(span.id); + }) + } + + fn pad_pre(&self, name: &'static str, pad: &Pad) { + let builder = SpanBuilder::new_pad(name, pad); + + builder.build(self); } } @@ -143,12 +202,16 @@ impl TracerImpl for TracingTracerPriv { self.pad_pre("pad_push_list", pad); } - fn pad_query_pre(&self, _: u64, pad: &Pad, _: &gstreamer::QueryRef) { - self.pad_pre("pad_query", pad); + fn pad_query_pre(&self, _: u64, pad: &Pad, query: &gstreamer::QueryRef) { + SpanBuilder::new_pad("pad_query", pad) + .query(query) + .build(self); } - fn pad_push_event_pre(&self, _: u64, pad: &Pad, _: &gstreamer::Event) { - self.pad_pre("pad_event", pad); + fn pad_push_event_pre(&self, _: u64, pad: &Pad, event: &gstreamer::Event) { + SpanBuilder::new_pad("pad_event", pad) + .event(event) + .build(self); } fn pad_pull_range_pre(&self, _: u64, pad: &Pad, _: u64, _: u32) { From 3fe70be1857e981e91981d466b3c7f6fb0107226 Mon Sep 17 00:00:00 2001 From: Thibault Saunier Date: Sat, 1 Jul 2023 09:30:15 -0400 Subject: [PATCH 4/4] tracer: Log elements state change and messages on the bus --- src/lib.rs | 8 +++ src/tracer.rs | 145 +++++++++++++++++++++++++++++++++++++++++--------- 2 files changed, 127 insertions(+), 26 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 0bdd147..6cce5e5 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -99,6 +99,14 @@ fn query_name(query: &gstreamer::QueryRef) -> &'static str { } } +fn message_name(message: &gstreamer::Message) -> &'static str { + use gstreamer::ffi as gffi; + unsafe { + let type_ = gffi::gst_message_type_get_name((*message.as_ptr()).type_); + std::ffi::CStr::from_ptr(type_).to_str().unwrap() + } +} + /// Enable the integration between GStreamer logging system and the `tracing` library. /// /// Once enabled the default [`tracing::Subscriber`][tracing_core::subscriber::Subscriber] will diff --git a/src/tracer.rs b/src/tracer.rs index aa72cb8..efba1c2 100644 --- a/src/tracer.rs +++ b/src/tracer.rs @@ -23,17 +23,32 @@ pub struct TracingTracerPriv { struct SpanBuilder<'a> { name: &'static str, pad: Option<&'a Pad>, + element: Option<&'a gstreamer::Element>, event: Option<&'a gstreamer::Event>, query: Option<&'a gstreamer::QueryRef>, + message: Option<&'a gstreamer::Message>, } impl<'a> SpanBuilder<'a> { + fn new_element(name: &'static str, element: &'a gstreamer::Element) -> Self { + Self { + name, + pad: None, + event: None, + query: None, + element: Some(element), + message: None, + } + } + fn new_pad(name: &'static str, pad: &'a Pad) -> Self { Self { name, pad: Some(pad), event: None, query: None, + element: None, + message: None, } } @@ -51,6 +66,13 @@ impl<'a> SpanBuilder<'a> { } } + fn message(self, message: &'a gstreamer::Message) -> Self { + Self { + message: Some(message), + ..self + } + } + fn build(self, tracer: &TracingTracerPriv) { let callsite = crate::callsite::DynamicCallsites::get().callsite_for( tracing::Level::ERROR, @@ -61,7 +83,13 @@ impl<'a> SpanBuilder<'a> { None, GstCallsiteKind::Span, self.pad.as_ref().map_or( - unreachable!(), + // List of fields for element traces + &[ + "gstelement.name", + "gstelement.state", + "gstelement.next_state", + "gstelement.message.type", + ], |_| { // List of fields for pad traces &[ @@ -83,33 +111,59 @@ impl<'a> SpanBuilder<'a> { if !dispatch.enabled(meta) { return; } - let pad = self.pad.unwrap(); - let gstpad_flags_value = Some(tracing_core::field::display(crate::PadFlags( - pad.pad_flags().bits(), - ))); - let name = pad.name(); - let name_value = Some(name.as_str()); - let gstpad_parent = pad.parent_element(); - let gstpad_parent_name_value = gstpad_parent.map(|p| p.name()); - let gstpad_parent_name_value = gstpad_parent_name_value.as_ref().map(|n| n.as_str()); let fields = meta.fields(); + let mut fields_iter = fields.into_iter(); - let event_type = self.event.map(|e| e.type_().name()); - let event_type_name = event_type.as_ref().map(|n| n.as_str()); - let query_type_name = self.query.map(|q| crate::query_name(q)); - - let values = field_values![fields_iter => - // /!\ /!\ /!\ Must be in the same order as the list of fields for pad above /!\ /!\ /!\ - "gstpad.flags" = gstpad_flags_value; - "gstpad.name" = name_value; - "gstpad.parent.name" = gstpad_parent_name_value; - "gstpad.event.type" = event_type_name; - "gstpad.query.type" = query_type_name; - ]; - - let valueset = fields.value_set(&values); - let attrs = tracing::span::Attributes::new_root(meta, &valueset); - tracer.push_span(dispatch, attrs); + if let Some(element) = self.element { + let (_, state, next_state) = + element.state(Some(gstreamer::ClockTime::from_mseconds(0))); + let state_value = Some(crate::state_desc(state as i32)); + let next_state_value = Some(crate::state_desc(next_state as i32)); + let name = element.name(); + let name_value = Some(name.as_str()); + let message_type_name = self.message.map(crate::message_name); + + // /!\ /!\ /!\ Must be in the same order as the list of fields for element above /!\ /!\ /!\ + let values = field_values![fields_iter => + "gstelement.name" = name_value; + "gstelement.state" = state_value; + "gstelement.next_state" = next_state_value; + "gstelement.message.type" = message_type_name; + ]; + + let valueset = fields.value_set(&values); + let attrs = tracing::span::Attributes::new_root(meta, &valueset); + + tracer.push_span(dispatch, attrs); + } else { + let pad = self.pad.unwrap(); + + let gstpad_flags_value = Some(tracing_core::field::display(crate::PadFlags( + pad.pad_flags().bits(), + ))); + let name = pad.name(); + let name_value = Some(name.as_str()); + let gstpad_parent = pad.parent_element(); + let gstpad_parent_name_value = gstpad_parent.map(|p| p.name()); + let gstpad_parent_name_value = gstpad_parent_name_value.as_ref().map(|n| n.as_str()); + let event_type = self.event.map(|e| e.type_().name()); + let event_type_name = event_type.as_ref().map(|n| n.as_str()); + let query_type_name = self.query.map(crate::query_name); + + let values = field_values![fields_iter => + // /!\ /!\ /!\ Must be in the same order as the list of fields for pad above /!\ /!\ /!\ + "gstpad.flags" = gstpad_flags_value; + "gstpad.name" = name_value; + "gstpad.parent.name" = gstpad_parent_name_value; + "gstpad.event.type" = event_type_name; + "gstpad.query.type" = query_type_name; + ]; + + let valueset = fields.value_set(&values); + let attrs = tracing::span::Attributes::new_root(meta, &valueset); + + tracer.push_span(dispatch, attrs); + } } } @@ -177,6 +231,11 @@ impl ObjectImpl for TracingTracerPriv { self.register_hook(TracerHook::PadPushEventPre); self.register_hook(TracerHook::PadPullRangePost); self.register_hook(TracerHook::PadPullRangePre); + self.register_hook(TracerHook::ElementChangeStatePre); + self.register_hook(TracerHook::ElementChangeStatePost); + + self.register_hook(TracerHook::ElementPostMessagePre); + self.register_hook(TracerHook::ElementPostMessagePost); #[cfg(feature = "v1_22")] { @@ -189,6 +248,26 @@ impl ObjectImpl for TracingTracerPriv { impl GstObjectImpl for TracingTracerPriv {} impl TracerImpl for TracingTracerPriv { + fn element_post_message_pre( + &self, + _ts: u64, + element: &gstreamer::Element, + message: &gstreamer::Message, + ) { + SpanBuilder::new_element("message", element) + .message(message) + .build(self); + } + + fn element_change_state_pre( + &self, + _ts: u64, + element: &gstreamer::Element, + _change: gstreamer::StateChange, + ) { + SpanBuilder::new_element("element_state", element).build(self); + } + #[cfg(feature = "v1_22")] fn pad_chain_pre(&self, _: u64, pad: &Pad, _: &Buffer) { self.pad_pre("pad_chain", pad); @@ -242,4 +321,18 @@ impl TracerImpl for TracingTracerPriv { fn pad_query_post(&self, _: u64, _: &Pad, _: &gstreamer::QueryRef, _: bool) { self.pop_span(); } + + fn element_change_state_post( + &self, + _: u64, + _: &gstreamer::Element, + _: gstreamer::StateChange, + _: Result, + ) { + self.pop_span(); + } + + fn element_post_message_post(&self, _ts: u64, _element: &gstreamer::Element, _success: bool) { + self.pop_span(); + } }