profile: Add initial trace event (#44443)

Adds a profiling event at the startup of servoshell, right after
initializing the tracing subsystem. To support this, add macro
abstractions for tracing events.
The existing span (macros) have a start and an end, but for one-off
events, we don't need a span and hence it make sense to also add the
event macros.

The new event at startup is useful when measuring / optimizing general
startup time. Adding a timestamp as field, allows us to ground the
measurement and compare it against time measured outside of servo,
regardless of how the profiling backend (tracing-perfetto,
tracing-hitrace, future backends) save timestamps.

Testing: Build-testing: the HarmonyOS build enables the tracing feature.
On other platforms this is not the case in CI.

---------

Signed-off-by: Jonathan Schwender <schwenderjonathan@gmail.com>

components/servo/lib.rs

@@ -48,6 +48,10 @@ pub use paint::WebRenderDebugOption;
 pub use paint_api::rendering_context::{
     OffscreenRenderingContext, RenderingContext, SoftwareRenderingContext, WindowRenderingContext,
 };
+// Expose our profile traits for servoshell, so we can instrument code there, but don't
+// add it as an official API.
+#[doc(hidden)]
+pub use profile_traits;
 // This should be replaced with an API on ServoBuilder.
 // See <https://github.com/servo/servo/issues/40950>.
 pub use resources;

components/shared/profile/lib.rs

@@ -52,6 +52,19 @@ macro_rules! __profiling_span {
     }};
 }
 
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __profiling_event {
+    ($backend_macro:ident, $event_name:literal $(, $($fields:tt)+)?) => {{
+        #[cfg(feature = "tracing")]
+        $crate::servo_tracing::$backend_macro!(
+            name: $event_name,
+            servo_profiling = true
+            $(, $($fields)+)?
+        );
+    }};
+}
+
 /// Provides API compatible dummies for the tracing-rs APIs we use
 /// if tracing is disabled. Hence, nothing will be traced
 pub mod dummy_tracing {
@@ -172,5 +185,56 @@ macro_rules! info_span {
     };
 }
 
+/// Emit an event at the trace level
+///
+/// This macro creates an Event for the purpose of instrumenting code to measure
+/// the execution time between events.
+///
+/// If the `tracing` feature (of the crate using this macro) is disabled, this
+/// macro expands to nothing.
+///
+/// Attention: This macro requires the user crate to have a `tracing` feature,
+/// which can be used to disable the effects of this macro.
+#[macro_export]
+macro_rules! trace_event {
+    ($event_name:literal $(, $($fields:tt)+)?) => {
+        $crate::__profiling_event!(trace, $event_name $(, $($fields)+)?)
+    };
+}
+
+/// Emit an event at the debug level
+///
+/// This macro creates an Event for the purpose of instrumenting code to measure
+/// the execution time between events.
+///
+/// If the `tracing` feature (of the crate using this macro) is disabled, this
+/// macro expands to nothing.
+///
+/// Attention: This macro requires the user crate to have a `tracing` feature,
+/// which can be used to disable the effects of this macro.
+#[macro_export]
+macro_rules! debug_event {
+    ($event_name:literal $(, $($fields:tt)+)?) => {
+        $crate::__profiling_event!(debug, $event_name $(, $($fields)+)?)
+    };
+}
+
+/// Emit an event at the info level
+///
+/// This macro creates an Event for the purpose of instrumenting code to measure
+/// the execution time between events.
+///
+/// If the `tracing` feature (of the crate using this macro) is disabled, this
+/// macro expands to nothing.
+///
+/// Attention: This macro requires the user crate to have a `tracing` feature,
+/// which can be used to disable the effects of this macro.
+#[macro_export]
+macro_rules! info_event {
+    ($event_name:literal $(, $($fields:tt)+)?) => {
+        $crate::__profiling_event!(info, $event_name $(, $($fields)+)?)
+    };
+}
+
 #[cfg(feature = "tracing")]
 pub use tracing as servo_tracing;

ports/servoshell/egl/ohos/mod.rs

@@ -260,6 +260,8 @@ fn init_app(
             ArgumentParsingResult::ErrorParsing => std::process::exit(1),
         };
 
+    crate::init_tracing(servoshell_preferences.tracing_filter.as_deref());
+
     if native_values.device_type == ohos_deviceinfo::OhosDeviceType::Phone {
         preferences.set_value("viewport_meta_enabled", PrefValue::Bool(true));
     }
@@ -272,7 +274,6 @@ fn init_app(
         }
     }
 
-    crate::init_tracing(servoshell_preferences.tracing_filter.as_deref());
     #[cfg(target_env = "ohos")]
     crate::egl::ohos::set_log_filter(servoshell_preferences.log_filter.as_deref());
 

ports/servoshell/lib.rs

@@ -96,6 +96,20 @@ pub fn init_tracing(filter_directives: Option<&str>) {
         // <https://docs.rs/tracing/0.1.40/tracing/#consuming-log-records>
         tracing::subscriber::set_global_default(subscriber)
             .expect("Failed to set tracing subscriber");
+
+        // Capture a first event, including the explicit wallclock time.
+        // The event itself is useful when investigating startup time.
+        // `wallclock_ns` allows us to ground the time, so we can compare
+        // against an external timestamp from before starting servoshell.
+        // In practice, the perfetto timestamp seems to be the same, but
+        // we shouldn't assume this, since different backends may behave differently.
+        servo::profile_traits::info_event!(
+            "servoshell::startup_tracing_initialized",
+            wallclock_ns = std::time::SystemTime::now()
+                .duration_since(std::time::UNIX_EPOCH)
+                .map(|duration| duration.as_nanos() as u64)
+                .unwrap_or(0)
+        );
     }
 }