libatrace_rust/src/tracing_subscriber.rs - platform/system/extras - Git at Google

 // Copyright (C) 2023 The Android Open Source Project
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
 // You may obtain a copy of the License at
 //
 //     http://www.apache.org/licenses/LICENSE-2.0
 //
 // Unless required by applicable law or agreed to in writing, software
 // distributed under the License is distributed on an "AS IS" BASIS,
 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 // See the License for the specific language governing permissions and
 // limitations under the License.

 //! Tracing-subscriber layer for libatrace_rust.

 use ::atrace::AtraceTag;
 use std::fmt::Write;
 use tracing::span::Attributes;
 use tracing::span::Record;
 use tracing::{Event, Id, Subscriber};
 use tracing_subscriber::field::Visit;
 use tracing_subscriber::layer::{Context, Layer};
 use tracing_subscriber::registry::LookupSpan;

 /// Subscriber layer that forwards events to ATrace.
 pub struct AtraceSubscriber {
     tag: AtraceTag,
     should_record_fields: bool,
     should_filter: bool,
 }

 impl Default for AtraceSubscriber {
     fn default() -> Self {
         Self::new(AtraceTag::App)
     }
 }

 impl AtraceSubscriber {
     /// Makes a new subscriber with tag.
     pub fn new(tag: AtraceTag) -> AtraceSubscriber {
         AtraceSubscriber { tag, should_filter: false, should_record_fields: true }
     }

     /// Enables event and span filtering. With filtering enabled, this layer would filter events for
     /// all the layers of the subscriber.
     /// Use this to speed up the subscriber if it's the only layer. Do not enable if you need other
     /// layers to receive events when ATrace is disabled.
     pub fn with_filter(self) -> AtraceSubscriber {
         AtraceSubscriber { should_filter: true, ..self }
     }

     /// Disables recording of field values.
     pub fn without_fields(self) -> AtraceSubscriber {
         AtraceSubscriber { should_record_fields: false, ..self }
     }
 }

 // Internal methods.
 impl AtraceSubscriber {
     /// Checks that events and spans should be recorded in the span/event notification.
     fn should_process_event(&self) -> bool {
         // If `should_filter == true` we don't need to check the tag - it was already checked by
         // the layer filter in the `Layer::enabled()` method.
         // The checks are done in this order:
         //  * `Layer::register_callsite()` - once per callsite, the result is cached.
         //  * `Layer::enabled()` - once per span or event construction if the callsite is enabled.
         //  * `should_process_event()` - on every notification like new span, span enter/exit/record, event.
         // The first two checks are global, i.e. affect other layers, and only enabled with `should_filter`.
         // Read more:
         // https://docs.rs/tracing-subscriber/latest/tracing_subscriber/layer/index.html#filtering-with-layers
         self.should_filter || atrace::atrace_is_tag_enabled(self.tag)
     }
 }

 impl<S: Subscriber + for<'lookup> LookupSpan<'lookup>> Layer<S> for AtraceSubscriber {
     fn register_callsite(
         &self,
         _metadata: &'static tracing::Metadata<'static>,
     ) -> tracing::subscriber::Interest {
         if self.should_filter {
             // When we return `Interest::sometimes()`, the `enabled()` method would get checked
             // every time.
             // We can't use callsite caching (`Interest::never()`) because there's no callback
             // for when tracing gets enabled - we need to check it every time.
             tracing::subscriber::Interest::sometimes()
         } else {
             // If we do not disable events in the layer, we always receive the notifications.
             tracing::subscriber::Interest::always()
         }
     }

     // When filtering in this layer is enabled, this method would get called on every event and span.
     // This filter affects all layers, so if this method returns false, it would disable the event
     // for others as well.
     fn enabled(&self, _metadata: &tracing::Metadata<'_>, _ctx: Context<'_, S>) -> bool {
         !self.should_filter || atrace::atrace_is_tag_enabled(self.tag)
     }

     fn on_new_span(&self, attrs: &Attributes, id: &Id, ctx: Context<S>) {
         if !self.should_record_fields || attrs.fields().is_empty() || !self.should_process_event() {
             return;
         }

         let span = ctx.span(id).unwrap();
         let mut formatter = FieldFormatter::for_span(span.metadata().name());
         attrs.record(&mut formatter);
         span.extensions_mut().insert(formatter);
     }

     fn on_record(&self, span: &Id, values: &Record, ctx: Context<S>) {
         if !self.should_record_fields || !self.should_process_event() {
             return;
         }

         values
             .record(ctx.span(span).unwrap().extensions_mut().get_mut::<FieldFormatter>().unwrap());
     }

     fn on_enter(&self, id: &Id, ctx: Context<S>) {
         if !self.should_process_event() {
             return;
         }

         let span = ctx.span(id).unwrap();
         if span.fields().is_empty() || !self.should_record_fields {
             atrace::atrace_begin(self.tag, span.metadata().name());
         } else {
             let span_extensions = span.extensions();
             let formatter = span_extensions.get::<FieldFormatter>().unwrap();
             atrace::atrace_begin(self.tag, formatter.as_str());
         }
     }

     fn on_exit(&self, _id: &Id, _ctx: Context<S>) {
         if !self.should_process_event() {
             return;
         }

         atrace::atrace_end(self.tag);
     }

     fn on_event(&self, event: &Event, _ctx: Context<S>) {
         if !self.should_process_event() {
             return;
         }

         if self.should_record_fields {
             let mut formatter = FieldFormatter::for_event();
             event.record(&mut formatter);
             atrace::atrace_instant(self.tag, formatter.as_str());
         } else if let Some(field) = event.metadata().fields().field("message") {
             struct MessageVisitor<'a> {
                 tag: AtraceTag,
                 field: &'a tracing::field::Field,
             }
             impl Visit for MessageVisitor<'_> {
                 fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
                     if field == self.field {
                         atrace::atrace_instant(self.tag, value);
                     }
                 }
                 fn record_debug(
                     &mut self,
                     field: &tracing::field::Field,
                     value: &dyn std::fmt::Debug,
                 ) {
                     if field == self.field {
                         atrace::atrace_instant(self.tag, &format!("{:?}", value));
                     }
                 }
             }
             event.record(&mut MessageVisitor { tag: self.tag, field: &field });
         } else {
             atrace::atrace_instant(
                 self.tag,
                 &format!("{} event", event.metadata().level().as_str()),
             );
         }
     }
 }

 struct FieldFormatter {
     is_event: bool,
     s: String,
 }

 impl FieldFormatter {
     fn new() -> FieldFormatter {
         const DEFAULT_STR_CAPACITY: usize = 128; // Should fit most events without realloc.
         FieldFormatter { is_event: true, s: String::with_capacity(DEFAULT_STR_CAPACITY) }
     }

     fn for_event() -> FieldFormatter {
         FieldFormatter { is_event: true, ..FieldFormatter::new() }
     }
     fn for_span(span_name: &str) -> FieldFormatter {
         let mut formatter = FieldFormatter { is_event: false, ..FieldFormatter::new() };
         formatter.s.push_str(span_name);
         formatter
     }

     fn as_str(&self) -> &str {
         &self.s
     }
     fn add_delimeter_if_needed(&mut self) {
         if !self.s.is_empty() {
             self.s.push_str(", ");
         }
     }
 }

 impl Visit for FieldFormatter {
     fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
         self.add_delimeter_if_needed();
         if self.is_event && field.name() == "message" {
             self.s.push_str(value);
         } else {
             write!(&mut self.s, "{} = \"{}\"", field.name(), value).unwrap();
         }
     }
     fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
         self.add_delimeter_if_needed();
         if self.is_event && field.name() == "message" {
             write!(&mut self.s, "{:?}", value).unwrap();
         } else {
             write!(&mut self.s, "{} = {:?}", field.name(), value).unwrap();
         }
     }
 }

 #[cfg(test)]
 use self::tests::mock_atrace as atrace;

 #[cfg(test)]
 mod tests {
     use super::*;
     use tracing::Level;
     use tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt;

     pub mod mock_atrace {
         use atrace::AtraceTag;
         use std::cell::RefCell;

         /// Contains logic to check binding calls.
         /// Implement this trait in the test with mocking logic and checks in implemented functions.
         /// Default implementations panic.
         pub trait ATraceMocker {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 panic!("Unexpected call");
             }

             fn atrace_begin(&mut self, _tag: AtraceTag, _name: &str) {
                 panic!("Unexpected call");
             }

             fn atrace_end(&mut self, _tag: AtraceTag) {
                 panic!("Unexpected call");
             }

             fn atrace_instant(&mut self, _tag: AtraceTag, _name: &str) {
                 panic!("Unexpected call");
             }

             /// This method should contain checks to be performed at the end of the test.
             fn finish(&self) {}
         }

         struct DefaultMocker;
         impl ATraceMocker for DefaultMocker {}

         // Global mock object is thread-local, so that the tests can run safely in parallel.
         thread_local!(static MOCKER: RefCell<Box<dyn ATraceMocker>> = RefCell::new(Box::new(DefaultMocker{})));

         /// Sets the global mock object.
         fn set_mocker(mocker: Box<dyn ATraceMocker>) {
             MOCKER.with(|m| *m.borrow_mut() = mocker)
         }

         /// Calls the passed method `f` with a mutable reference to the global mock object.
         /// Example:
         /// ```
         /// with_mocker(|mocker| mocker.atrace_begin(tag, name))
         /// ```
         fn with_mocker<F, R>(f: F) -> R
         where
             F: FnOnce(&mut dyn ATraceMocker) -> R,
         {
             MOCKER.with(|m| f(m.borrow_mut().as_mut()))
         }

         /// Finish the test and perform final checks in the mocker.
         /// Calls `finish()` on the global mocker.
         ///
         /// Needs to be called manually at the end of each test that uses mocks.
         ///
         /// May panic, so it can not be called in `drop()` methods,
         /// since it may result in double panic.
         pub fn mocker_finish() {
             with_mocker(|m| m.finish())
         }

         /// RAII guard that resets the mock to the default implementation.
         pub struct MockerGuard;
         impl Drop for MockerGuard {
             fn drop(&mut self) {
                 set_mocker(Box::new(DefaultMocker {}));
             }
         }

         /// Sets the mock object for the duration of the scope.
         ///
         /// Returns a RAII guard that resets the mock back to default on destruction.
         pub fn set_scoped_mocker<T: ATraceMocker + 'static>(m: T) -> MockerGuard {
             set_mocker(Box::new(m));
             MockerGuard {}
         }

         // Wrapped functions that forward calls into mocker.

         pub fn atrace_is_tag_enabled(tag: AtraceTag) -> bool {
             with_mocker(|m| m.atrace_is_tag_enabled(tag))
         }
         pub fn atrace_begin(tag: AtraceTag, name: &str) {
             with_mocker(|m| m.atrace_begin(tag, name))
         }

         pub fn atrace_end(tag: AtraceTag) {
             with_mocker(|m| m.atrace_end(tag))
         }

         pub fn atrace_instant(tag: AtraceTag, name: &str) {
             with_mocker(|m| m.atrace_instant(tag, name))
         }
     }

     #[test]
     fn emits_span_begin() {
         #[derive(Default)]
         struct CallCheck {
             begin_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_begin(&mut self, tag: AtraceTag, name: &str) {
                 self.begin_count += 1;
                 assert!(self.begin_count < 2);
                 assert_eq!(tag, AtraceTag::App);
                 assert_eq!(name, "test span");
             }
             fn atrace_end(&mut self, _tag: AtraceTag) {}

             fn finish(&self) {
                 assert_eq!(self.begin_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default()),
         );

         let _span = tracing::info_span!("test span").entered();

         mock_atrace::mocker_finish();
     }

     #[test]
     fn emits_span_end() {
         #[derive(Default)]
         struct CallCheck {
             end_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_begin(&mut self, _tag: AtraceTag, _name: &str) {}
             fn atrace_end(&mut self, tag: AtraceTag) {
                 self.end_count += 1;
                 assert!(self.end_count < 2);
                 assert_eq!(tag, AtraceTag::App);
             }

             fn finish(&self) {
                 assert_eq!(self.end_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default()),
         );

         {
             let _span = tracing::info_span!("test span").entered();
         }

         mock_atrace::mocker_finish();
     }

     #[test]
     fn span_begin_end_is_ordered() {
         #[derive(Default)]
         struct CallCheck {
             begin_count: u32,
             instant_count: u32,
             end_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_begin(&mut self, _tag: AtraceTag, _name: &str) {
                 assert_eq!(self.end_count, 0);
                 assert_eq!(self.instant_count, 0);

                 self.begin_count += 1;
                 assert!(self.begin_count < 2);
             }
             fn atrace_instant(&mut self, _tag: AtraceTag, _name: &str) {
                 assert_eq!(self.begin_count, 1);
                 assert_eq!(self.end_count, 0);

                 self.instant_count += 1;
                 assert!(self.instant_count < 2);
             }
             fn atrace_end(&mut self, _tag: AtraceTag) {
                 assert_eq!(self.begin_count, 1);
                 assert_eq!(self.instant_count, 1);

                 self.end_count += 1;
                 assert!(self.end_count < 2);
             }

             fn finish(&self) {
                 assert_eq!(self.begin_count, 1);
                 assert_eq!(self.end_count, 1);
                 assert_eq!(self.instant_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default()),
         );

         {
             let _span = tracing::info_span!("span").entered();
             tracing::info!("test info");
         }

         mock_atrace::mocker_finish();
     }

     #[test]
     fn emits_instant_event() {
         #[derive(Default)]
         struct CallCheck {
             instant_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_instant(&mut self, tag: AtraceTag, name: &str) {
                 self.instant_count += 1;
                 assert!(self.instant_count < 2);
                 assert_eq!(tag, AtraceTag::App);
                 assert_eq!(name, "test info");
             }

             fn finish(&self) {
                 assert_eq!(self.instant_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default()),
         );

         tracing::info!("test info");

         mock_atrace::mocker_finish();
     }

     #[test]
     fn formats_event_without_message_with_fields_disabled() {
         #[derive(Default)]
         struct CallCheck {
             instant_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_instant(&mut self, _tag: AtraceTag, name: &str) {
                 self.instant_count += 1;
                 assert!(self.instant_count < 2);
                 assert_eq!(name, "DEBUG event");
             }

             fn finish(&self) {
                 assert_eq!(self.instant_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default().without_fields()),
         );

         tracing::debug!(foo = 1);

         mock_atrace::mocker_finish();
     }

     #[test]
     fn formats_event_without_message_with_fields_enabled() {
         #[derive(Default)]
         struct CallCheck {
             instant_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_instant(&mut self, _tag: AtraceTag, name: &str) {
                 self.instant_count += 1;
                 assert!(self.instant_count < 2);
                 assert_eq!(name, "foo = 1");
             }

             fn finish(&self) {
                 assert_eq!(self.instant_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default()),
         );

         tracing::debug!(foo = 1);

         mock_atrace::mocker_finish();
     }

     #[test]
     fn can_set_tag() {
         #[derive(Default)]
         struct CallCheck {
             begin_count: u32,
             instant_count: u32,
             end_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_begin(&mut self, tag: AtraceTag, _name: &str) {
                 self.begin_count += 1;
                 assert!(self.begin_count < 2);
                 assert_eq!(tag, AtraceTag::WindowManager);
             }
             fn atrace_instant(&mut self, tag: AtraceTag, _name: &str) {
                 self.instant_count += 1;
                 assert!(self.instant_count < 2);
                 assert_eq!(tag, AtraceTag::WindowManager);
             }
             fn atrace_end(&mut self, tag: AtraceTag) {
                 self.end_count += 1;
                 assert!(self.end_count < 2);
                 assert_eq!(tag, AtraceTag::WindowManager);
             }

             fn finish(&self) {
                 assert_eq!(self.begin_count, 1);
                 assert_eq!(self.end_count, 1);
                 assert_eq!(self.instant_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::new(AtraceTag::WindowManager)),
         );

         {
             let _span = tracing::info_span!("span").entered();
             tracing::info!("test info");
         }

         mock_atrace::mocker_finish();
     }

     #[test]
     fn fields_ignored_when_disabled() {
         #[derive(Default)]
         struct CallCheck {
             begin_count: u32,
             instant_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_begin(&mut self, _tag: AtraceTag, name: &str) {
                 self.begin_count += 1;
                 assert!(self.begin_count < 2);
                 assert_eq!(name, "test span");
             }
             fn atrace_instant(&mut self, _tag: AtraceTag, name: &str) {
                 self.instant_count += 1;
                 assert!(self.instant_count < 2);
                 assert_eq!(name, "test info");
             }
             fn atrace_end(&mut self, _tag: AtraceTag) {}
             fn finish(&self) {
                 assert_eq!(self.begin_count, 1);
                 assert_eq!(self.instant_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default().without_fields()),
         );

         let _span = tracing::info_span!("test span", bar = "foo").entered();
         tracing::event!(Level::INFO, foo = "bar", "test info");

         mock_atrace::mocker_finish();
     }

     #[test]
     fn formats_instant_event_fields() {
         #[derive(Default)]
         struct CallCheck {
             instant_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_instant(&mut self, _tag: AtraceTag, name: &str) {
                 self.instant_count += 1;
                 assert!(self.instant_count < 2);
                 assert_eq!(name, "test info, foo = \"bar\", baz = 5");
             }
             fn finish(&self) {
                 assert_eq!(self.instant_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default()),
         );

         tracing::event!(Level::INFO, foo = "bar", baz = 5, "test info");

         mock_atrace::mocker_finish();
     }

     #[test]
     fn formats_span_fields() {
         #[derive(Default)]
         struct CallCheck {
             begin_count: u32,
         }
         impl mock_atrace::ATraceMocker for CallCheck {
             fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
                 true
             }
             fn atrace_begin(&mut self, _tag: AtraceTag, name: &str) {
                 self.begin_count += 1;
                 assert!(self.begin_count < 2);
                 assert_eq!(name, "test span, foo = \"bar\", baz = 5");
             }
             fn atrace_end(&mut self, _tag: AtraceTag) {}
             fn finish(&self) {
                 assert_eq!(self.begin_count, 1);
             }
         }
         let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

         let _subscriber_guard = tracing::subscriber::set_default(
             tracing_subscriber::registry().with(AtraceSubscriber::default()),
         );

         let _span = tracing::info_span!("test span", foo = "bar", baz = 5).entered();

         mock_atrace::mocker_finish();
     }
 }
	// Copyright (C) 2023 The Android Open Source Project
	//
	// Licensed under the Apache License, Version 2.0 (the "License");
	// you may not use this file except in compliance with the License.
	// You may obtain a copy of the License at
	//
	// http://www.apache.org/licenses/LICENSE-2.0
	//
	// Unless required by applicable law or agreed to in writing, software
	// distributed under the License is distributed on an "AS IS" BASIS,
	// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
	// See the License for the specific language governing permissions and
	// limitations under the License.

	//! Tracing-subscriber layer for libatrace_rust.

	use ::atrace::AtraceTag;
	use std::fmt::Write;
	use tracing::span::Attributes;
	use tracing::span::Record;
	use tracing::{Event, Id, Subscriber};
	use tracing_subscriber::field::Visit;
	use tracing_subscriber::layer::{Context, Layer};
	use tracing_subscriber::registry::LookupSpan;

	/// Subscriber layer that forwards events to ATrace.
	pub struct AtraceSubscriber {
	tag: AtraceTag,
	should_record_fields: bool,
	should_filter: bool,
	}

	impl Default for AtraceSubscriber {
	fn default() -> Self {
	Self::new(AtraceTag::App)
	}
	}

	impl AtraceSubscriber {
	/// Makes a new subscriber with tag.
	pub fn new(tag: AtraceTag) -> AtraceSubscriber {
	AtraceSubscriber { tag, should_filter: false, should_record_fields: true }
	}

	/// Enables event and span filtering. With filtering enabled, this layer would filter events for
	/// all the layers of the subscriber.
	/// Use this to speed up the subscriber if it's the only layer. Do not enable if you need other
	/// layers to receive events when ATrace is disabled.
	pub fn with_filter(self) -> AtraceSubscriber {
	AtraceSubscriber { should_filter: true, ..self }
	}

	/// Disables recording of field values.
	pub fn without_fields(self) -> AtraceSubscriber {
	AtraceSubscriber { should_record_fields: false, ..self }
	}
	}

	// Internal methods.
	impl AtraceSubscriber {
	/// Checks that events and spans should be recorded in the span/event notification.
	fn should_process_event(&self) -> bool {
	// If `should_filter == true` we don't need to check the tag - it was already checked by
	// the layer filter in the `Layer::enabled()` method.
	// The checks are done in this order:
	// * `Layer::register_callsite()` - once per callsite, the result is cached.
	// * `Layer::enabled()` - once per span or event construction if the callsite is enabled.
	// * `should_process_event()` - on every notification like new span, span enter/exit/record, event.
	// The first two checks are global, i.e. affect other layers, and only enabled with `should_filter`.
	// Read more:
	// https://docs.rs/tracing-subscriber/latest/tracing_subscriber/layer/index.html#filtering-with-layers
	self.should_filter \|\| atrace::atrace_is_tag_enabled(self.tag)
	}
	}

	impl<S: Subscriber + for<'lookup> LookupSpan<'lookup>> Layer<S> for AtraceSubscriber {
	fn register_callsite(
	&self,
	_metadata: &'static tracing::Metadata<'static>,
	) -> tracing::subscriber::Interest {
	if self.should_filter {
	// When we return `Interest::sometimes()`, the `enabled()` method would get checked
	// every time.
	// We can't use callsite caching (`Interest::never()`) because there's no callback
	// for when tracing gets enabled - we need to check it every time.
	tracing::subscriber::Interest::sometimes()
	} else {
	// If we do not disable events in the layer, we always receive the notifications.
	tracing::subscriber::Interest::always()
	}
	}

	// When filtering in this layer is enabled, this method would get called on every event and span.
	// This filter affects all layers, so if this method returns false, it would disable the event
	// for others as well.
	fn enabled(&self, _metadata: &tracing::Metadata<'_>, _ctx: Context<'_, S>) -> bool {
	!self.should_filter \|\| atrace::atrace_is_tag_enabled(self.tag)
	}

	fn on_new_span(&self, attrs: &Attributes, id: &Id, ctx: Context<S>) {
	if !self.should_record_fields \|\| attrs.fields().is_empty() \|\| !self.should_process_event() {
	return;
	}

	let span = ctx.span(id).unwrap();
	let mut formatter = FieldFormatter::for_span(span.metadata().name());
	attrs.record(&mut formatter);
	span.extensions_mut().insert(formatter);
	}

	fn on_record(&self, span: &Id, values: &Record, ctx: Context<S>) {
	if !self.should_record_fields \|\| !self.should_process_event() {
	return;
	}

	values
	.record(ctx.span(span).unwrap().extensions_mut().get_mut::<FieldFormatter>().unwrap());
	}

	fn on_enter(&self, id: &Id, ctx: Context<S>) {
	if !self.should_process_event() {
	return;
	}

	let span = ctx.span(id).unwrap();
	if span.fields().is_empty() \|\| !self.should_record_fields {
	atrace::atrace_begin(self.tag, span.metadata().name());
	} else {
	let span_extensions = span.extensions();
	let formatter = span_extensions.get::<FieldFormatter>().unwrap();
	atrace::atrace_begin(self.tag, formatter.as_str());
	}
	}

	fn on_exit(&self, _id: &Id, _ctx: Context<S>) {
	if !self.should_process_event() {
	return;
	}

	atrace::atrace_end(self.tag);
	}

	fn on_event(&self, event: &Event, _ctx: Context<S>) {
	if !self.should_process_event() {
	return;
	}

	if self.should_record_fields {
	let mut formatter = FieldFormatter::for_event();
	event.record(&mut formatter);
	atrace::atrace_instant(self.tag, formatter.as_str());
	} else if let Some(field) = event.metadata().fields().field("message") {
	struct MessageVisitor<'a> {
	tag: AtraceTag,
	field: &'a tracing::field::Field,
	}
	impl Visit for MessageVisitor<'_> {
	fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
	if field == self.field {
	atrace::atrace_instant(self.tag, value);
	}
	}
	fn record_debug(
	&mut self,
	field: &tracing::field::Field,
	value: &dyn std::fmt::Debug,
	) {
	if field == self.field {
	atrace::atrace_instant(self.tag, &format!("{:?}", value));
	}
	}
	}
	event.record(&mut MessageVisitor { tag: self.tag, field: &field });
	} else {
	atrace::atrace_instant(
	self.tag,
	&format!("{} event", event.metadata().level().as_str()),
	);
	}
	}
	}

	struct FieldFormatter {
	is_event: bool,
	s: String,
	}

	impl FieldFormatter {
	fn new() -> FieldFormatter {
	const DEFAULT_STR_CAPACITY: usize = 128; // Should fit most events without realloc.
	FieldFormatter { is_event: true, s: String::with_capacity(DEFAULT_STR_CAPACITY) }
	}

	fn for_event() -> FieldFormatter {
	FieldFormatter { is_event: true, ..FieldFormatter::new() }
	}
	fn for_span(span_name: &str) -> FieldFormatter {
	let mut formatter = FieldFormatter { is_event: false, ..FieldFormatter::new() };
	formatter.s.push_str(span_name);
	formatter
	}

	fn as_str(&self) -> &str {
	&self.s
	}
	fn add_delimeter_if_needed(&mut self) {
	if !self.s.is_empty() {
	self.s.push_str(", ");
	}
	}
	}

	impl Visit for FieldFormatter {
	fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
	self.add_delimeter_if_needed();
	if self.is_event && field.name() == "message" {
	self.s.push_str(value);
	} else {
	write!(&mut self.s, "{} = \"{}\"", field.name(), value).unwrap();
	}
	}
	fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
	self.add_delimeter_if_needed();
	if self.is_event && field.name() == "message" {
	write!(&mut self.s, "{:?}", value).unwrap();
	} else {
	write!(&mut self.s, "{} = {:?}", field.name(), value).unwrap();
	}
	}
	}

	#[cfg(test)]
	use self::tests::mock_atrace as atrace;

	#[cfg(test)]
	mod tests {
	use super::*;
	use tracing::Level;
	use tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt;

	pub mod mock_atrace {
	use atrace::AtraceTag;
	use std::cell::RefCell;

	/// Contains logic to check binding calls.
	/// Implement this trait in the test with mocking logic and checks in implemented functions.
	/// Default implementations panic.
	pub trait ATraceMocker {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	panic!("Unexpected call");
	}

	fn atrace_begin(&mut self, _tag: AtraceTag, _name: &str) {
	panic!("Unexpected call");
	}

	fn atrace_end(&mut self, _tag: AtraceTag) {
	panic!("Unexpected call");
	}

	fn atrace_instant(&mut self, _tag: AtraceTag, _name: &str) {
	panic!("Unexpected call");
	}

	/// This method should contain checks to be performed at the end of the test.
	fn finish(&self) {}
	}

	struct DefaultMocker;
	impl ATraceMocker for DefaultMocker {}

	// Global mock object is thread-local, so that the tests can run safely in parallel.
	thread_local!(static MOCKER: RefCell<Box<dyn ATraceMocker>> = RefCell::new(Box::new(DefaultMocker{})));

	/// Sets the global mock object.
	fn set_mocker(mocker: Box<dyn ATraceMocker>) {
	MOCKER.with(\|m\| *m.borrow_mut() = mocker)
	}

	/// Calls the passed method `f` with a mutable reference to the global mock object.
	/// Example:
	/// ```
	/// with_mocker(\|mocker\| mocker.atrace_begin(tag, name))
	/// ```
	fn with_mocker<F, R>(f: F) -> R
	where
	F: FnOnce(&mut dyn ATraceMocker) -> R,
	{
	MOCKER.with(\|m\| f(m.borrow_mut().as_mut()))
	}

	/// Finish the test and perform final checks in the mocker.
	/// Calls `finish()` on the global mocker.
	///
	/// Needs to be called manually at the end of each test that uses mocks.
	///
	/// May panic, so it can not be called in `drop()` methods,
	/// since it may result in double panic.
	pub fn mocker_finish() {
	with_mocker(\|m\| m.finish())
	}

	/// RAII guard that resets the mock to the default implementation.
	pub struct MockerGuard;
	impl Drop for MockerGuard {
	fn drop(&mut self) {
	set_mocker(Box::new(DefaultMocker {}));
	}
	}

	/// Sets the mock object for the duration of the scope.
	///
	/// Returns a RAII guard that resets the mock back to default on destruction.
	pub fn set_scoped_mocker<T: ATraceMocker + 'static>(m: T) -> MockerGuard {
	set_mocker(Box::new(m));
	MockerGuard {}
	}

	// Wrapped functions that forward calls into mocker.

	pub fn atrace_is_tag_enabled(tag: AtraceTag) -> bool {
	with_mocker(\|m\| m.atrace_is_tag_enabled(tag))
	}
	pub fn atrace_begin(tag: AtraceTag, name: &str) {
	with_mocker(\|m\| m.atrace_begin(tag, name))
	}

	pub fn atrace_end(tag: AtraceTag) {
	with_mocker(\|m\| m.atrace_end(tag))
	}

	pub fn atrace_instant(tag: AtraceTag, name: &str) {
	with_mocker(\|m\| m.atrace_instant(tag, name))
	}
	}

	#[test]
	fn emits_span_begin() {
	#[derive(Default)]
	struct CallCheck {
	begin_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_begin(&mut self, tag: AtraceTag, name: &str) {
	self.begin_count += 1;
	assert!(self.begin_count < 2);
	assert_eq!(tag, AtraceTag::App);
	assert_eq!(name, "test span");
	}
	fn atrace_end(&mut self, _tag: AtraceTag) {}

	fn finish(&self) {
	assert_eq!(self.begin_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default()),
	);

	let _span = tracing::info_span!("test span").entered();

	mock_atrace::mocker_finish();
	}

	#[test]
	fn emits_span_end() {
	#[derive(Default)]
	struct CallCheck {
	end_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_begin(&mut self, _tag: AtraceTag, _name: &str) {}
	fn atrace_end(&mut self, tag: AtraceTag) {
	self.end_count += 1;
	assert!(self.end_count < 2);
	assert_eq!(tag, AtraceTag::App);
	}

	fn finish(&self) {
	assert_eq!(self.end_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default()),
	);

	{
	let _span = tracing::info_span!("test span").entered();
	}

	mock_atrace::mocker_finish();
	}

	#[test]
	fn span_begin_end_is_ordered() {
	#[derive(Default)]
	struct CallCheck {
	begin_count: u32,
	instant_count: u32,
	end_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_begin(&mut self, _tag: AtraceTag, _name: &str) {
	assert_eq!(self.end_count, 0);
	assert_eq!(self.instant_count, 0);

	self.begin_count += 1;
	assert!(self.begin_count < 2);
	}
	fn atrace_instant(&mut self, _tag: AtraceTag, _name: &str) {
	assert_eq!(self.begin_count, 1);
	assert_eq!(self.end_count, 0);

	self.instant_count += 1;
	assert!(self.instant_count < 2);
	}
	fn atrace_end(&mut self, _tag: AtraceTag) {
	assert_eq!(self.begin_count, 1);
	assert_eq!(self.instant_count, 1);

	self.end_count += 1;
	assert!(self.end_count < 2);
	}

	fn finish(&self) {
	assert_eq!(self.begin_count, 1);
	assert_eq!(self.end_count, 1);
	assert_eq!(self.instant_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default()),
	);

	{
	let _span = tracing::info_span!("span").entered();
	tracing::info!("test info");
	}

	mock_atrace::mocker_finish();
	}

	#[test]
	fn emits_instant_event() {
	#[derive(Default)]
	struct CallCheck {
	instant_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_instant(&mut self, tag: AtraceTag, name: &str) {
	self.instant_count += 1;
	assert!(self.instant_count < 2);
	assert_eq!(tag, AtraceTag::App);
	assert_eq!(name, "test info");
	}

	fn finish(&self) {
	assert_eq!(self.instant_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default()),
	);

	tracing::info!("test info");

	mock_atrace::mocker_finish();
	}

	#[test]
	fn formats_event_without_message_with_fields_disabled() {
	#[derive(Default)]
	struct CallCheck {
	instant_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_instant(&mut self, _tag: AtraceTag, name: &str) {
	self.instant_count += 1;
	assert!(self.instant_count < 2);
	assert_eq!(name, "DEBUG event");
	}

	fn finish(&self) {
	assert_eq!(self.instant_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default().without_fields()),
	);

	tracing::debug!(foo = 1);

	mock_atrace::mocker_finish();
	}

	#[test]
	fn formats_event_without_message_with_fields_enabled() {
	#[derive(Default)]
	struct CallCheck {
	instant_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_instant(&mut self, _tag: AtraceTag, name: &str) {
	self.instant_count += 1;
	assert!(self.instant_count < 2);
	assert_eq!(name, "foo = 1");
	}

	fn finish(&self) {
	assert_eq!(self.instant_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default()),
	);

	tracing::debug!(foo = 1);

	mock_atrace::mocker_finish();
	}

	#[test]
	fn can_set_tag() {
	#[derive(Default)]
	struct CallCheck {
	begin_count: u32,
	instant_count: u32,
	end_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_begin(&mut self, tag: AtraceTag, _name: &str) {
	self.begin_count += 1;
	assert!(self.begin_count < 2);
	assert_eq!(tag, AtraceTag::WindowManager);
	}
	fn atrace_instant(&mut self, tag: AtraceTag, _name: &str) {
	self.instant_count += 1;
	assert!(self.instant_count < 2);
	assert_eq!(tag, AtraceTag::WindowManager);
	}
	fn atrace_end(&mut self, tag: AtraceTag) {
	self.end_count += 1;
	assert!(self.end_count < 2);
	assert_eq!(tag, AtraceTag::WindowManager);
	}

	fn finish(&self) {
	assert_eq!(self.begin_count, 1);
	assert_eq!(self.end_count, 1);
	assert_eq!(self.instant_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::new(AtraceTag::WindowManager)),
	);

	{
	let _span = tracing::info_span!("span").entered();
	tracing::info!("test info");
	}

	mock_atrace::mocker_finish();
	}

	#[test]
	fn fields_ignored_when_disabled() {
	#[derive(Default)]
	struct CallCheck {
	begin_count: u32,
	instant_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_begin(&mut self, _tag: AtraceTag, name: &str) {
	self.begin_count += 1;
	assert!(self.begin_count < 2);
	assert_eq!(name, "test span");
	}
	fn atrace_instant(&mut self, _tag: AtraceTag, name: &str) {
	self.instant_count += 1;
	assert!(self.instant_count < 2);
	assert_eq!(name, "test info");
	}
	fn atrace_end(&mut self, _tag: AtraceTag) {}
	fn finish(&self) {
	assert_eq!(self.begin_count, 1);
	assert_eq!(self.instant_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default().without_fields()),
	);

	let _span = tracing::info_span!("test span", bar = "foo").entered();
	tracing::event!(Level::INFO, foo = "bar", "test info");

	mock_atrace::mocker_finish();
	}

	#[test]
	fn formats_instant_event_fields() {
	#[derive(Default)]
	struct CallCheck {
	instant_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_instant(&mut self, _tag: AtraceTag, name: &str) {
	self.instant_count += 1;
	assert!(self.instant_count < 2);
	assert_eq!(name, "test info, foo = \"bar\", baz = 5");
	}
	fn finish(&self) {
	assert_eq!(self.instant_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default()),
	);

	tracing::event!(Level::INFO, foo = "bar", baz = 5, "test info");

	mock_atrace::mocker_finish();
	}

	#[test]
	fn formats_span_fields() {
	#[derive(Default)]
	struct CallCheck {
	begin_count: u32,
	}
	impl mock_atrace::ATraceMocker for CallCheck {
	fn atrace_is_tag_enabled(&mut self, _tag: AtraceTag) -> bool {
	true
	}
	fn atrace_begin(&mut self, _tag: AtraceTag, name: &str) {
	self.begin_count += 1;
	assert!(self.begin_count < 2);
	assert_eq!(name, "test span, foo = \"bar\", baz = 5");
	}
	fn atrace_end(&mut self, _tag: AtraceTag) {}
	fn finish(&self) {
	assert_eq!(self.begin_count, 1);
	}
	}
	let _mock_guard = mock_atrace::set_scoped_mocker(CallCheck::default());

	let _subscriber_guard = tracing::subscriber::set_default(
	tracing_subscriber::registry().with(AtraceSubscriber::default()),
	);

	let _span = tracing::info_span!("test span", foo = "bar", baz = 5).entered();

	mock_atrace::mocker_finish();
	}
	}