diff --git a/Cargo.lock b/Cargo.lock index cad36a7e49ee3..f981d8190e6a3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2765,6 +2765,9 @@ name = "gecko_tracing" version = "0.1.0" dependencies = [ "error-support", + "gecko-profiler", + "gecko_logger", + "log", "tracing", "tracing-subscriber", "tracing-support", @@ -5496,7 +5499,6 @@ version = "0.1.0" dependencies = [ "firefox-on-glean", "libc", - "log", "neqo-common", "neqo-http3", "neqo-qpack", @@ -5510,6 +5512,7 @@ dependencies = [ "static_assertions", "static_prefs", "thin-vec", + "tracing", "uuid", "winapi", "xpcom", diff --git a/netwerk/socket/neqo_glue/Cargo.toml b/netwerk/socket/neqo_glue/Cargo.toml index 1fb68b1010e3f..40752be186f53 100644 --- a/netwerk/socket/neqo_glue/Cargo.toml +++ b/netwerk/socket/neqo_glue/Cargo.toml @@ -19,7 +19,7 @@ nserror = { path = "../../../xpcom/rust/nserror" } nsstring = { path = "../../../xpcom/rust/nsstring" } xpcom = { path = "../../../xpcom/rust/xpcom" } thin-vec = { version = "0.2.1", features = ["gecko-ffi"] } -log = "0.4.0" +tracing = "0.1" qlog = "0.16" libc = "0.2.0" rustix = { version = "1.1", default-features = false, features = ["fs", "net"] } diff --git a/netwerk/socket/neqo_glue/src/lib.rs b/netwerk/socket/neqo_glue/src/lib.rs index 93fa297da41c4..88b8b44550455 100644 --- a/netwerk/socket/neqo_glue/src/lib.rs +++ b/netwerk/socket/neqo_glue/src/lib.rs @@ -27,11 +27,10 @@ use firefox_on_glean::{ #[cfg(not(windows))] use libc::{c_int, AF_INET, AF_INET6}; use libc::{c_uchar, size_t}; -use log::debug; use neqo_common::{ - datagram, event::Provider as _, qdebug, qerror, qlog::Qlog, qwarn, Datagram, Decoder, Encoder, - Header, Role, Tos, + datagram, event::Provider as _, qlog::Qlog, Datagram, Decoder, Encoder, Header, Role, Tos, }; +use tracing::{debug, error, warn}; use neqo_http3::{ features::extended_connect::session, ConnectUdpEvent, Error as Http3Error, Http3Client, Http3ClientEvent, Http3Parameters, Http3State, Priority, WebTransportEvent, @@ -241,12 +240,12 @@ fn enable_zstd_decoder(c: &mut Connection) -> neqo_transport::Res<()> { // ZSTD_isError return 1 if error, 0 otherwise if unsafe { ZSTD_isError(output_len) != 0 } { - qdebug!("zstd compression failed with {output_len}"); + debug!("zstd compression failed with {output_len}"); return Err(nss_rs::Error::CertificateDecoding); } if output.len() != output_len { - qdebug!("zstd compression `output_len` {output_len} doesn't match expected `output.len()` {}", output.len()); + debug!("zstd compression `output_len` {output_len} doesn't match expected `output.len()` {}", output.len()); return Err(nss_rs::Error::CertificateDecoding); } @@ -370,11 +369,11 @@ impl NeqoHttp3Conn { let borrowed = { use std::os::fd::{BorrowedFd, RawFd}; if socket == -1 { - qerror!("got invalid socked {}", socket); + error!("got invalid socked {}", socket); return Err(NS_ERROR_INVALID_ARG); } let raw: RawFd = socket.try_into().map_err(|e| { - qerror!("got invalid socked {}: {}", socket, e); + error!("got invalid socked {}: {}", socket, e); NS_ERROR_INVALID_ARG })?; unsafe { BorrowedFd::borrow_raw(raw) } @@ -383,17 +382,17 @@ impl NeqoHttp3Conn { let borrowed = { use std::os::windows::io::{BorrowedSocket, RawSocket}; if socket as usize == winapi::um::winsock2::INVALID_SOCKET { - qerror!("got invalid socked {}", socket); + error!("got invalid socked {}", socket); return Err(NS_ERROR_INVALID_ARG); } let raw: RawSocket = socket.try_into().map_err(|e| { - qerror!("got invalid socked {}: {}", socket, e); + error!("got invalid socked {}: {}", socket, e); NS_ERROR_INVALID_ARG })?; unsafe { BorrowedSocket::borrow_raw(raw) } }; let s = neqo_udp::Socket::new(borrowed).map_err(|e| { - qerror!("failed to initialize socket {}: {}", socket, e); + error!("failed to initialize socket {}: {}", socket, e); into_nsresult(&e) })?; // Called after Socket::new (which sets up IP_RECVTOS etc.) since @@ -580,7 +579,7 @@ impl NeqoHttp3Conn { Err(e) => { // Emit warnings but to not return an error if qlog initialization // fails. - qwarn!("failed to create Qlog at {}: {}", qlog_path.display(), e); + warn!("failed to create Qlog at {}: {}", qlog_path.display(), e); } } } @@ -683,7 +682,7 @@ impl NeqoHttp3Conn { glean::http_3_ecn_ce_ect0_ratio_received.accumulate_single_sample_signed(ratio); } else { let msg = "Failed to convert ratio to i64 for use with glean"; - qwarn!("{msg}"); + warn!("{msg}"); debug_assert!(false, "{msg}"); } } @@ -699,14 +698,14 @@ impl NeqoHttp3Conn { glean::http_3_ecn_ce_ect0_ratio_sent.accumulate_single_sample_signed(ratio); } else { let msg = "Failed to convert ratio to i64 for use with glean"; - qwarn!("{msg}"); + warn!("{msg}"); debug_assert!(false, "{msg}"); } } for (outcome, value) in stats.ecn_path_validation.into_iter() { let Ok(value) = i32::try_from(value) else { let msg = format!("Failed to convert {value} to i32 for use with glean"); - qwarn!("{msg}"); + warn!("{msg}"); debug_assert!(false, "{msg}"); continue; }; @@ -743,7 +742,7 @@ impl NeqoHttp3Conn { Some(v) } Err(e) => { - qwarn!("Failed to convert ratio to i64 for use with glean: {e}"); + warn!("Failed to convert ratio to i64 for use with glean: {e}"); debug_assert!( false, "Failed to convert ratio to i64 for use with glean: {e}" @@ -931,7 +930,7 @@ impl NeqoHttp3Conn { .accumulate_single_sample_signed(spurious); } else { let msg = "Failed to convert ratio to i64 for use with glean"; - qwarn!("{msg}"); + warn!("{msg}"); debug_assert!(false, "{msg}"); } } @@ -943,7 +942,7 @@ impl NeqoHttp3Conn { .add(ce_loss); } else { let msg = "Failed to convert to i32 for use with glean"; - qwarn!("{msg}"); + warn!("{msg}"); debug_assert!(false, "{msg}"); } if let Ok(ce_ecn) = i32::try_from(stats.cc.congestion_events.ecn) { @@ -952,7 +951,7 @@ impl NeqoHttp3Conn { .add(ce_ecn); } else { let msg = "Failed to convert to i32 for use with glean"; - qwarn!("{msg}"); + warn!("{msg}"); debug_assert!(false, "{msg}"); } } @@ -1141,7 +1140,19 @@ pub struct ProcessInputResult { pub unsafe extern "C" fn neqo_http3conn_process_input( conn: &mut NeqoHttp3Conn, ) -> ProcessInputResult { + // Holding this span open for the whole call records an interval (duration) + // marker in the profiler, rather than a point-in-time event. `bytes_received` + // is filled in below once known, and shows up in the marker. + let span = + tracing::debug_span!( + "neqo_http3conn_process_input", + bytes_received = tracing::field::Empty, + segments_received = tracing::field::Empty + ) + .entered(); + let mut bytes_read = 0; + let mut segments_received: u64 = 0; RECV_BUF.with_borrow_mut(|recv_buf| { loop { @@ -1157,7 +1168,7 @@ pub unsafe extern "C" fn neqo_http3conn_process_input( break; } Err(e) => { - qwarn!("failed to receive datagrams: {}", e); + warn!("failed to receive datagrams: {}", e); return ProcessInputResult { result: into_nsresult(&e), bytes_read: 0, @@ -1189,8 +1200,11 @@ pub unsafe extern "C" fn neqo_http3conn_process_input( conn.datagram_size_received.accumulate(sum as u64); conn.datagram_segments_received.accumulate(segment_count); bytes_read += sum; + segments_received += segment_count; } + span.record("bytes_received", bytes_read); + span.record("segments_received", segments_received); ProcessInputResult { result: NS_OK, bytes_read: bytes_read.try_into().unwrap_or(u32::MAX), @@ -1270,7 +1284,15 @@ pub extern "C" fn neqo_http3conn_process_output_and_send( context: *mut c_void, set_timer_func: SetTimerFunc, ) -> ProcessOutputAndSendResult { + let span = tracing::debug_span!( + "neqo_http3conn_process_output_and_send", + bytes_sent = tracing::field::Empty, + segments_sent = tracing::field::Empty + ) + .entered(); + let mut bytes_written: usize = 0; + let mut segments_sent: u64 = 0; loop { let Ok(max_gso_segments) = min( static_prefs::pref!("network.http.http3.max_gso_segments") @@ -1282,7 +1304,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send( .max_gso_segments(), ) .try_into() else { - qerror!("Socket return GSO size of 0"); + error!("Socket return GSO size of 0"); return ProcessOutputAndSendResult { result: NS_ERROR_UNEXPECTED, bytes_written: 0, @@ -1306,7 +1328,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send( if static_prefs::pref!("network.http.http3.block_loopback_ipv6_addr") && matches!(dg.destination(), SocketAddr::V6(addr) if addr.ip().is_loopback()) { - qdebug!("network.http.http3.block_loopback_ipv6_addr is set, returning NS_ERROR_CONNECTION_REFUSED for localhost IPv6"); + debug!("network.http.http3.block_loopback_ipv6_addr is set, returning NS_ERROR_CONNECTION_REFUSED for localhost IPv6"); return ProcessOutputAndSendResult { result: NS_ERROR_CONNECTION_REFUSED, bytes_written: 0, @@ -1318,7 +1340,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send( Err(e) if e.kind() == io::ErrorKind::WouldBlock => { conn.increment_would_block_tx(); if static_prefs::pref!("network.http.http3.pr_poll_write") { - qdebug!("Buffer outbound datagram to be sent once UDP socket has write-availability."); + debug!("Buffer outbound datagram to be sent once UDP socket has write-availability."); conn.buffered_outbound_datagram = Some(dg); return ProcessOutputAndSendResult { // Propagate WouldBlock error, thus indicating that @@ -1328,7 +1350,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send( bytes_written: bytes_written.try_into().unwrap_or(u32::MAX), }; } else { - qwarn!("dropping datagram as socket would block"); + warn!("dropping datagram as socket would block"); break; } } @@ -1346,18 +1368,18 @@ pub extern "C" fn neqo_http3conn_process_output_and_send( // // Long term this fallback belongs in quinn-udp, see // . - qdebug!("Failed to send datagram batch size {} with error {e}. Missing GSO support? Resending as individual datagrams.", dg.num_datagrams()); + debug!("Failed to send datagram batch size {} with error {e}. Missing GSO support? Resending as individual datagrams.", dg.num_datagrams()); let socket = conn.socket.as_mut().expect("non NSPR IO"); for single in dg.iter() { let single = datagram::Batch::from(single.to_owned()); if let Err(e) = socket.send(&single) { - qwarn!("failed to resend datagram without GSO: {e}"); + warn!("failed to resend datagram without GSO: {e}"); break; } } } Err(e) => { - qwarn!("failed to send datagram: {}", e); + warn!("failed to send datagram: {}", e); return ProcessOutputAndSendResult { result: into_nsresult(&e), bytes_written: 0, @@ -1365,6 +1387,7 @@ pub extern "C" fn neqo_http3conn_process_output_and_send( } } bytes_written += dg.data().len(); + segments_sent += dg.num_datagrams() as u64; // Glean metrics conn.datagram_size_sent.accumulate(dg.data().len() as u64); @@ -1403,6 +1426,8 @@ pub extern "C" fn neqo_http3conn_process_output_and_send( } } + span.record("bytes_sent", bytes_written); + span.record("segments_sent", segments_sent); ProcessOutputAndSendResult { result: NS_OK, bytes_written: bytes_written.try_into().unwrap_or(u32::MAX), diff --git a/xpcom/rust/gecko_logger/src/lib.rs b/xpcom/rust/gecko_logger/src/lib.rs index 8d97b660d1140..dc92a1e556648 100644 --- a/xpcom/rust/gecko_logger/src/lib.rs +++ b/xpcom/rust/gecko_logger/src/lib.rs @@ -58,6 +58,19 @@ fn get_level_for_module<'a>( return (key, false, LevelFilter::Off); } +/// Returns whether `target` is enabled at `level` according to the MOZ_LOG +/// module levels. This is the Rust-visible equivalent of `MOZ_LOG_TEST`, for +/// callers (such as the tracing layer) that need to gate work without going +/// through a `log::Record`. +pub fn log_enabled(target: &str, level: Level) -> bool { + if !LOGGING_ACTIVE.load(Ordering::Relaxed) { + return false; + } + let map = LOG_MODULE_MAP.read().unwrap(); + let (_, _, filter) = get_level_for_module(&map, target); + filter >= level +} + /// This function takes a record to maybe log to Gecko. /// It returns true if the record was handled by Gecko's logging, and false /// otherwise. diff --git a/xpcom/rust/gecko_tracing/Cargo.toml b/xpcom/rust/gecko_tracing/Cargo.toml index 73213f9e626bc..95f795df78568 100644 --- a/xpcom/rust/gecko_tracing/Cargo.toml +++ b/xpcom/rust/gecko_tracing/Cargo.toml @@ -5,6 +5,9 @@ edition = "2021" license = "MPL-2.0" [dependencies] +gecko-profiler = { path = "../../../tools/profiler/rust-api" } +gecko_logger = { path = "../gecko_logger" } +log = "0.4" tracing = "0.1" tracing-subscriber = { version = "0.3", default-features = false, features = ["fmt", "std"] } # app-services crates, overridden in the `[patch.crates-io]` section of the top-level Cargo.toml diff --git a/xpcom/rust/gecko_tracing/src/layer.rs b/xpcom/rust/gecko_tracing/src/layer.rs new file mode 100644 index 0000000000000..1077bf7bcdff4 --- /dev/null +++ b/xpcom/rust/gecko_tracing/src/layer.rs @@ -0,0 +1,156 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at https://mozilla.org/MPL/2.0/. */ + +//! A `tracing` layer that mirrors the C++ MOZ_LOG fan-out for Rust `tracing`. +//! +//! - Events are forwarded to the `log` crate, where `GeckoLogger` turns them +//! into the same stderr/MOZ_LOG_FILE output and `LOGS`-category profiler +//! markers that a C++ `MOZ_LOG` call produces. They therefore obey MOZ_LOG +//! (and RUST_LOG) levels for free. +//! - Spans are recorded as interval (duration) markers in the profiler only, +//! gated by the same MOZ_LOG levels. + +use std::fmt::Write as _; + +use gecko_profiler::{add_text_marker, gecko_profiler_category, MarkerOptions, MarkerTiming, + ProfilerTime}; +use tracing::{ + field::{Field, Visit}, + span, Event, Level, Subscriber, +}; +use tracing_subscriber::{layer::Context, registry::LookupSpan, Layer}; + +/// Collects an event's or span's message and fields into a single string. +struct MessageVisitor<'a> { + text: &'a mut String, +} + +impl Visit for MessageVisitor<'_> { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + if !self.text.is_empty() { + self.text.push(' '); + } + if field.name() == "message" { + let _ = write!(self.text, "{value:?}"); + } else { + let _ = write!(self.text, "{}={value:?}", field.name()); + } + } +} + +fn to_log_level(level: &Level) -> log::Level { + match *level { + Level::ERROR => log::Level::Error, + Level::WARN => log::Level::Warn, + Level::INFO => log::Level::Info, + Level::DEBUG => log::Level::Debug, + Level::TRACE => log::Level::Trace, + } +} + +/// Stored in a span's extensions so that, when the span closes, the resulting +/// marker can cover the span's whole lifetime as an interval (duration) marker. +struct SpanTiming { + start: ProfilerTime, + fields: String, +} + +struct GeckoLayer; + +impl Layer for GeckoLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { + let metadata = event.metadata(); + let level = to_log_level(metadata.level()); + if log::max_level() < level { + return; + } + + // TODO(perf): needs profiling. `log::max_level()` is only a global + // ceiling, so once any rust module is verbose this runs for every + // event in the process, allocating `text` and formatting all fields + // before we know whether this specific target is enabled. C++ MOZ_LOG + // gates per-module first (MOZ_LOG_TEST). Consider gating on + // `gecko_logger::log_enabled` (or `register_callsite`/`enabled` + // returning `Interest::never` for disabled targets) and reusing a + // thread-local buffer to avoid the per-event allocation. Note also that + // GeckoLogger re-formats `record.args()`, so the message is built twice. + let mut text = String::new(); + event.record(&mut MessageVisitor { text: &mut text }); + + // Forwarding to the `log` crate reuses GeckoLogger, which applies the + // MOZ_LOG/RUST_LOG levels and produces both the stderr line and the + // LOGS profiler marker, exactly like a C++ MOZ_LOG call. + log::logger().log( + &log::Record::builder() + .args(format_args!("{text}")) + .level(level) + .target(metadata.target()) + .module_path(Some(metadata.target())) + .file(metadata.file()) + .line(metadata.line()) + .build(), + ); + } + + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + let metadata = attrs.metadata(); + if !gecko_logger::log_enabled(metadata.target(), to_log_level(metadata.level())) { + return; + } + let Some(span) = ctx.span(id) else { + return; + }; + // TODO(perf): needs profiling. `ProfilerTime::now()` runs for every + // span on hot paths (e.g. neqo_glue's per-call process_input/ + // process_output_and_send). + span.extensions_mut().insert(SpanTiming { + start: ProfilerTime::now(), + // Only fields added later via `Span::record` (see `on_record`) are + // captured; the current spans fill their values that way. + fields: String::new(), + }); + } + + fn on_record(&self, id: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { + let Some(span) = ctx.span(id) else { + return; + }; + let mut extensions = span.extensions_mut(); + if let Some(timing) = extensions.get_mut::() { + values.record(&mut MessageVisitor { + text: &mut timing.fields, + }); + } + } + + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + let Some(span) = ctx.span(&id) else { + return; + }; + let Some(timing) = span.extensions_mut().remove::() else { + return; + }; + add_text_marker( + span.metadata().name(), + gecko_profiler_category!(Logs), + MarkerOptions { + timing: MarkerTiming::interval_until_now_from(timing.start), + ..Default::default() + }, + &timing.fields, + ); + } +} + +/// Returns the layer that forwards tracing events to the Gecko logging and +/// profiler infrastructure. +pub fn layer() -> impl Layer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + GeckoLayer +} diff --git a/xpcom/rust/gecko_tracing/src/lib.rs b/xpcom/rust/gecko_tracing/src/lib.rs index 38e1ca3ba208a..1329d041c2ff9 100644 --- a/xpcom/rust/gecko_tracing/src/lib.rs +++ b/xpcom/rust/gecko_tracing/src/lib.rs @@ -3,14 +3,19 @@ * file, You can obtain one at https://mozilla.org/MPL/2.0/. */ //! This provides a way to set up rust tracing "layers". +mod layer; + pub fn initialize_tracing() { use tracing_subscriber::prelude::*; tracing_subscriber::registry() // The application-services tracing-support library, which directs tracing from some crates // back into the application for logging or other diagnostic purposes. .with(tracing_support::simple_event_layer()) + // Route tracing events through Gecko's logging (stderr/MOZ_LOG plus + // profiler markers, like a C++ MOZ_LOG call) and record tracing spans + // as profiler duration markers. See + // https://bugzilla.mozilla.org/show_bug.cgi?id=1652558. + .with(layer::layer()) // More layers can be added by additional `.with(...)` statements. - // For inspiration, see https://bugzilla.mozilla.org/show_bug.cgi?id=1652558, which never - // landed but does have a good example of what a more sophisticated subscriber needs. .init(); }