Tracing speedup

Added a callsite filter for the simple event layer.  This allows us to avoid the
lock + map lookup for non-app-services crates.

I think this is about as good as we can do performance-wise:
* Non app-services crates are statically disabled, no lock/map lookup needed
* App-services crates are dynamically handled.  We need to do the lock/map lookup each time, since we don't know when outside crates will call `register_event_sink`.

Author: bendk

components/support/rust-log-forwarder/src/lib.rs

@@ -96,7 +96,7 @@ pub fn set_logger(logger: Option<Box<dyn AppServicesLogger>>) {
     GLOBAL_SUBSCRIBER.call_once(|| {
         use tracing_subscriber::prelude::*;
         tracing_subscriber::registry()
-            .with(tracing_support::SimpleEventLayer)
+            .with(tracing_support::simple_event_layer())
             .init();
     });
 
@@ -182,8 +182,8 @@ mod test {
         let sink = Arc::new(ForwarderEventSink {});
         tracing_support::register_event_sink("rust_log_forwarder", Level::Debug.into(), sink);
 
-        tracing::event!(tracing::Level::INFO, "Test message");
-        tracing::event!(tracing::Level::WARN, "Test message2");
+        tracing_support::info!("Test message");
+        tracing_support::warn!("Test message2");
         logger.check_records(vec![
             Record {
                 level: Level::Info,

components/support/tracing/src/layer.rs

@@ -5,7 +5,11 @@
 use parking_lot::RwLock;
 use std::collections::{BTreeMap, HashMap};
 use std::sync::{Arc, LazyLock};
-use tracing_subscriber::Layer;
+use tracing::{subscriber::Interest, Metadata};
+use tracing_subscriber::{
+    layer::{Context, Filter},
+    Layer,
+};
 
 use crate::EventSink;
 use tracing::field::{Field, Visit};
@@ -42,6 +46,13 @@ pub fn unregister_event_sink(target: &str) {
     SINKS_BY_TARGET.write().remove(target);
 }
 
+pub fn simple_event_layer<S>() -> impl Layer<S>
+where
+    S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>,
+{
+    SimpleEventLayer.with_filter(SimpleEventFilter)
+}
+
 pub struct SimpleEventLayer;
 
 impl<S> Layer<S> for SimpleEventLayer
@@ -78,6 +89,33 @@ where
     }
 }
 
+struct SimpleEventFilter;
+
+impl<S> Filter<S> for SimpleEventFilter
+where
+    S: tracing::Subscriber,
+{
+    fn callsite_enabled(&self, meta: &Metadata<'_>) -> Interest {
+        if meta.fields().field("tracing_support").is_some() {
+            // Event came from `tracing_support`'s logging macros.
+            // Enable the layer for this callsite.
+            // Whether we actually do anything for an event is controlled by `SimpleEventLayer.on_event()`
+            Interest::always()
+        } else {
+            // Event came from a crate not using `tracing_support`, we don't want to handle it.
+            // By returning `Interest::never`, tracing_subscriber will ensure that this callsite is
+            // permanently filtered and we avoid the lock + map lookup.
+            // In fact, `callsite_enabled` won't even be called again.
+            Interest::never()
+        }
+    }
+
+    fn enabled(&self, _meta: &Metadata<'_>, _cx: &Context<'_, S>) -> bool {
+        // callsite_enabled() does the real filtering, we just return `true` here.
+        true
+    }
+}
+
 // from https://burgers.io/custom-logging-in-rust-using-tracing
 struct JsonVisitor<'a>(&'a mut String, &'a mut BTreeMap<String, serde_json::Value>);
 

components/support/tracing/src/lib.rs

@@ -6,8 +6,91 @@ mod testing;
 #[cfg(feature = "testing")]
 pub use testing::{init_for_tests, init_for_tests_with_level};
 
-pub use layer::{register_event_sink, unregister_event_sink, SimpleEventLayer};
-pub use tracing::{debug, error, info, trace, warn};
+pub use layer::{register_event_sink, simple_event_layer, unregister_event_sink};
+// Re-export tracing so that our dependencies can use it.
+pub use tracing;
+
+// Define standard logging macros.
+//
+// These all add `tracing_support = true`, which we use as an event filter in our layer.
+// This will statically disable the layer for events from outside crates that use tracing.
+// This way we don't pay a performance penalty for those events.
+// See `SimpleEventFilter` for details.
+
+#[macro_export]
+macro_rules! trace {
+    (target: $target:expr, $($tt:tt)*) => {
+        $crate::tracing::trace!(
+        target: $target,
+        tracing_support = true,
+        $($tt)*)
+    };
+    ($($tt:tt)*) => {
+        $crate::tracing::trace!(
+        tracing_support = true,
+        $($tt)*)
+    };
+}
+
+#[macro_export]
+macro_rules! debug {
+    (target: $target:expr, $($tt:tt)*) => {
+        $crate::tracing::debug!(
+        target: $target,
+        tracing_support = true,
+        $($tt)*)
+    };
+    ($($tt:tt)*) => {
+        $crate::tracing::debug!(
+        tracing_support = true,
+        $($tt)*)
+    };
+}
+
+#[macro_export]
+macro_rules! info {
+    (target: $target:expr, $($tt:tt)*) => {
+        $crate::tracing::info!(
+        target: $target,
+        tracing_support = true,
+        $($tt)*)
+    };
+    ($($tt:tt)*) => {
+        $crate::tracing::info!(
+        tracing_support = true,
+        $($tt)*)
+    };
+}
+
+#[macro_export]
+macro_rules! warn {
+    (target: $target:expr, $($tt:tt)*) => {
+        $crate::tracing::warn!(
+        target: $target,
+        tracing_support = true,
+        $($tt)*)
+    };
+    ($($tt:tt)*) => {
+        $crate::tracing::warn!(
+        tracing_support = true,
+        $($tt)*)
+    };
+}
+
+#[macro_export]
+macro_rules! error {
+    (target: $target:expr, $($tt:tt)*) => {
+        $crate::tracing::error!(
+        target: $target,
+        tracing_support = true,
+        $($tt)*)
+    };
+    ($($tt:tt)*) => {
+        $crate::tracing::error!(
+        tracing_support = true,
+        $($tt)*)
+    };
+}
 
 // grr - swift has name collision with `Level`? Can uniifi help make this cleaner?
 pub type Level = TracingLevel;
@@ -97,7 +180,7 @@ mod tests {
     fn test_app() {
         use tracing_subscriber::prelude::*;
         tracing_subscriber::registry()
-            .with(layer::SimpleEventLayer)
+            .with(layer::simple_event_layer())
             .init();
 
         struct Sink {
@@ -120,15 +203,24 @@ mod tests {
         let sink = Arc::new(Sink::new());
 
         crate::layer::register_event_sink("first_target", Level::Info, sink.clone());
-        crate::layer::register_event_sink("second_target", Level::Info, sink.clone());
+        crate::layer::register_event_sink("second_target", Level::Debug, sink.clone());
 
-        tracing::event!(target: "first_target", tracing::Level::INFO, extra = -1, "event message");
+        info!(target: "first_target", extra=-1, "event message");
+        debug!(target: "first_target", extra=-2, "event message (should be filtered)");
+        debug!(target: "second_target", extra=-3, "event message2");
+        info!(target: "third_target", extra=-4, "event message (should be filtered)");
 
-        assert_eq!(sink.events.read().len(), 1);
+        assert_eq!(sink.events.read().len(), 2);
         let event = &sink.events.read()[0];
         assert_eq!(event.target, "first_target");
         assert_eq!(event.level, Level::Info);
         assert_eq!(event.message, "event message");
         assert_eq!(event.fields.get("extra").unwrap().as_i64(), Some(-1));
+
+        let event2 = &sink.events.read()[1];
+        assert_eq!(event2.target, "second_target");
+        assert_eq!(event2.level, Level::Debug);
+        assert_eq!(event2.message, "event message2");
+        assert_eq!(event2.fields.get("extra").unwrap().as_i64(), Some(-3));
     }
 }