diff --git a/Cargo.toml b/Cargo.toml index 5edc2f9..137100c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -23,7 +23,7 @@ std = [] [dependencies] cfg-if = "1" -log = "0.4.11" +tracing = { version = "0.1.37", default-features = false } [target.'cfg(any(unix, target_os = "fuchsia", target_os = "vxworks"))'.dependencies] libc = "0.2.77" diff --git a/src/epoll.rs b/src/epoll.rs index 6a9d623..91931e2 100644 --- a/src/epoll.rs +++ b/src/epoll.rs @@ -65,11 +65,11 @@ impl Poller { PollMode::Oneshot, )?; - log::trace!( - "new: epoll_fd={}, event_fd={}, timer_fd={:?}", - poller.epoll_fd.as_raw_fd(), - poller.event_fd.as_raw_fd(), - poller.timer_fd + tracing::trace!( + epoll_fd = ?poller.epoll_fd.as_raw_fd(), + event_fd = ?poller.event_fd.as_raw_fd(), + timer_fd = ?poller.timer_fd, + "new", ); Ok(poller) } @@ -86,12 +86,13 @@ impl Poller { /// Adds a new file descriptor. pub fn add(&self, fd: RawFd, ev: Event, mode: PollMode) -> io::Result<()> { - log::trace!( - "add: epoll_fd={}, fd={}, ev={:?}", - self.epoll_fd.as_raw_fd(), - fd, - ev + let span = tracing::trace_span!( + "add", + epoll_fd = ?self.epoll_fd.as_raw_fd(), + ?fd, + ?ev, ); + let _enter = span.enter(); epoll::epoll_add( &self.epoll_fd, @@ -105,12 +106,13 @@ impl Poller { /// Modifies an existing file descriptor. pub fn modify(&self, fd: RawFd, ev: Event, mode: PollMode) -> io::Result<()> { - log::trace!( - "modify: epoll_fd={}, fd={}, ev={:?}", - self.epoll_fd.as_raw_fd(), - fd, - ev + let span = tracing::trace_span!( + "modify", + epoll_fd = ?self.epoll_fd.as_raw_fd(), + ?fd, + ?ev, ); + let _enter = span.enter(); epoll::epoll_mod( &self.epoll_fd, @@ -124,7 +126,12 @@ impl Poller { /// Deletes a file descriptor. pub fn delete(&self, fd: RawFd) -> io::Result<()> { - log::trace!("remove: epoll_fd={}, fd={}", self.epoll_fd.as_raw_fd(), fd); + let span = tracing::trace_span!( + "delete", + epoll_fd = ?self.epoll_fd.as_raw_fd(), + ?fd, + ); + let _enter = span.enter(); epoll::epoll_del(&self.epoll_fd, unsafe { rustix::fd::BorrowedFd::borrow_raw(fd) @@ -136,11 +143,12 @@ impl Poller { /// Waits for I/O events with an optional timeout. #[allow(clippy::needless_update)] pub fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { - log::trace!( - "wait: epoll_fd={}, timeout={:?}", - self.epoll_fd.as_raw_fd(), - timeout + let span = tracing::trace_span!( + "wait", + epoll_fd = ?self.epoll_fd.as_raw_fd(), + ?timeout, ); + let _enter = span.enter(); if let Some(ref timer_fd) = self.timer_fd { // Configure the timeout using timerfd. @@ -188,10 +196,10 @@ impl Poller { // Wait for I/O events. epoll::epoll_wait(&self.epoll_fd, &mut events.list, timeout_ms)?; - log::trace!( - "new events: epoll_fd={}, res={}", - self.epoll_fd.as_raw_fd(), - events.list.len() + tracing::trace!( + epoll_fd = ?self.epoll_fd.as_raw_fd(), + res = ?events.list.len(), + "new events", ); // Clear the notification (if received) and re-register interest in it. @@ -211,11 +219,12 @@ impl Poller { /// Sends a notification to wake up the current or next `wait()` call. pub fn notify(&self) -> io::Result<()> { - log::trace!( - "notify: epoll_fd={}, event_fd={}", - self.epoll_fd.as_raw_fd(), - self.event_fd.as_raw_fd() + let span = tracing::trace_span!( + "notify", + epoll_fd = ?self.epoll_fd.as_raw_fd(), + event_fd = ?self.event_fd.as_raw_fd(), ); + let _enter = span.enter(); let buf: [u8; 8] = 1u64.to_ne_bytes(); let _ = write(&self.event_fd, &buf); @@ -237,12 +246,13 @@ impl AsFd for Poller { impl Drop for Poller { fn drop(&mut self) { - log::trace!( - "drop: epoll_fd={}, event_fd={}, timer_fd={:?}", - self.epoll_fd.as_raw_fd(), - self.event_fd.as_raw_fd(), - self.timer_fd + let span = tracing::trace_span!( + "drop", + epoll_fd = ?self.epoll_fd.as_raw_fd(), + event_fd = ?self.event_fd.as_raw_fd(), + timer_fd = ?self.timer_fd ); + let _enter = span.enter(); if let Some(timer_fd) = self.timer_fd.take() { let _ = self.delete(timer_fd.as_raw_fd()); diff --git a/src/iocp/afd.rs b/src/iocp/afd.rs index a254509..c666251 100644 --- a/src/iocp/afd.rs +++ b/src/iocp/afd.rs @@ -6,7 +6,7 @@ use std::cell::UnsafeCell; use std::fmt; use std::io; use std::marker::{PhantomData, PhantomPinned}; -use std::mem::{size_of, transmute, MaybeUninit}; +use std::mem::{self, size_of, transmute, MaybeUninit}; use std::os::windows::prelude::{AsRawHandle, RawHandle, RawSocket}; use std::pin::Pin; use std::ptr; @@ -111,7 +111,7 @@ macro_rules! define_ntdll_import { let addr = match addr { Some(addr) => addr, None => { - log::error!("Failed to load ntdll function {}", NAME); + tracing::error!("Failed to load ntdll function {}", NAME); return Err(io::Error::last_os_error()); }, }; @@ -212,7 +212,7 @@ impl NtdllImports { let ntdll = GetModuleHandleW(NTDLL_NAME.as_ptr() as *const _); if ntdll == 0 { - log::error!("Failed to load ntdll.dll"); + tracing::error!("Failed to load ntdll.dll"); return Err(io::Error::last_os_error()); } @@ -302,8 +302,8 @@ where // Set up device attributes. let mut device_name = UNICODE_STRING { - Length: (AFD_NAME.len() * size_of::()) as u16, - MaximumLength: (AFD_NAME.len() * size_of::()) as u16, + Length: mem::size_of_val(AFD_NAME) as u16, + MaximumLength: mem::size_of_val(AFD_NAME) as u16, Buffer: AFD_NAME.as_ptr() as *mut _, }; let mut device_attributes = OBJECT_ATTRIBUTES { diff --git a/src/iocp/mod.rs b/src/iocp/mod.rs index 77f0525..a20e7ad 100644 --- a/src/iocp/mod.rs +++ b/src/iocp/mod.rs @@ -105,7 +105,7 @@ impl Poller { let port = IoCompletionPort::new(0)?; - log::trace!("new: handle={:?}", &port); + tracing::trace!(handle = ?port, "new"); Ok(Poller { port, @@ -135,12 +135,13 @@ impl Poller { /// Add a new source to the poller. pub(super) fn add(&self, socket: RawSocket, interest: Event, mode: PollMode) -> io::Result<()> { - log::trace!( - "add: handle={:?}, sock={}, ev={:?}", - self.port, - socket, - interest + let span = tracing::trace_span!( + "add", + handle = ?self.port, + sock = ?socket, + ev = ?interest, ); + let _enter = span.enter(); // We don't support edge-triggered events. if matches!(mode, PollMode::Edge | PollMode::EdgeOneshot) { @@ -195,12 +196,13 @@ impl Poller { interest: Event, mode: PollMode, ) -> io::Result<()> { - log::trace!( - "modify: handle={:?}, sock={}, ev={:?}", - self.port, - socket, - interest + let span = tracing::trace_span!( + "modify", + handle = ?self.port, + sock = ?socket, + ev = ?interest, ); + let _enter = span.enter(); // We don't support edge-triggered events. if matches!(mode, PollMode::Edge | PollMode::EdgeOneshot) { @@ -230,7 +232,12 @@ impl Poller { /// Delete a source from the poller. pub(super) fn delete(&self, socket: RawSocket) -> io::Result<()> { - log::trace!("remove: handle={:?}, sock={}", self.port, socket); + let span = tracing::trace_span!( + "remove", + handle = ?self.port, + sock = ?socket, + ); + let _enter = span.enter(); // Get a reference to the source. let source = { @@ -252,7 +259,12 @@ impl Poller { /// Wait for events. pub(super) fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { - log::trace!("wait: handle={:?}, timeout={:?}", self.port, timeout); + let span = tracing::trace_span!( + "wait", + handle = ?self.port, + ?timeout, + ); + let _enter = span.enter(); let deadline = timeout.and_then(|timeout| Instant::now().checked_add(timeout)); let mut packets = lock!(self.packets.lock()); @@ -279,7 +291,10 @@ impl Poller { // Wait for I/O events. let len = self.port.wait(&mut packets, timeout)?; - log::trace!("new events: handle={:?}, len={}", self.port, len); + tracing::trace!( + handle = ?self.port, + res = ?len, + "new events"); // We are no longer polling. drop(guard); @@ -308,7 +323,7 @@ impl Poller { break; } - log::trace!("wait: no events found, re-entering polling loop"); + tracing::trace!("wait: no events found, re-entering polling loop"); } Ok(()) diff --git a/src/kqueue.rs b/src/kqueue.rs index f6c1893..85ec04f 100644 --- a/src/kqueue.rs +++ b/src/kqueue.rs @@ -37,7 +37,10 @@ impl Poller { // Register the notification pipe. poller.notify.register(&poller)?; - log::trace!("new: kqueue_fd={:?}", poller.kqueue_fd); + tracing::trace!( + kqueue_fd = ?poller.kqueue_fd.as_raw_fd(), + "new" + ); Ok(poller) } @@ -59,14 +62,18 @@ impl Poller { /// Modifies an existing file descriptor. pub fn modify(&self, fd: RawFd, ev: Event, mode: PollMode) -> io::Result<()> { - if !self.notify.has_fd(fd) { - log::trace!( - "add: kqueue_fd={:?}, fd={}, ev={:?}", - self.kqueue_fd, - fd, - ev + let span = if !self.notify.has_fd(fd) { + let span = tracing::trace_span!( + "add", + kqueue_fd = ?self.kqueue_fd.as_raw_fd(), + ?fd, + ?ev, ); - } + Some(span) + } else { + None + }; + let _enter = span.as_ref().map(|s| s.enter()); let mode_flags = mode_to_flags(mode); @@ -141,18 +148,23 @@ impl Poller { /// Waits for I/O events with an optional timeout. pub fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { - log::trace!( - "wait: kqueue_fd={:?}, timeout={:?}", - self.kqueue_fd, - timeout + let span = tracing::trace_span!( + "wait", + kqueue_fd = ?self.kqueue_fd.as_raw_fd(), + ?timeout, ); + let _enter = span.enter(); // Wait for I/O events. let changelist = []; let eventlist = &mut events.list; let res = unsafe { kqueue::kevent(&self.kqueue_fd, &changelist, eventlist, timeout)? }; - log::trace!("new events: kqueue_fd={:?}, res={}", self.kqueue_fd, res); + tracing::trace!( + kqueue_fd = ?self.kqueue_fd.as_raw_fd(), + ?res, + "new events", + ); // Clear the notification (if received) and re-register interest in it. self.notify.reregister(self)?; @@ -162,7 +174,12 @@ impl Poller { /// Sends a notification to wake up the current or next `wait()` call. pub fn notify(&self) -> io::Result<()> { - log::trace!("notify: kqueue_fd={:?}", self.kqueue_fd); + let span = tracing::trace_span!( + "notify", + kqueue_fd = ?self.kqueue_fd.as_raw_fd(), + ); + let _enter = span.enter(); + self.notify.notify(self).ok(); Ok(()) } @@ -182,7 +199,12 @@ impl AsFd for Poller { impl Drop for Poller { fn drop(&mut self) { - log::trace!("drop: kqueue_fd={:?}", self.kqueue_fd); + let span = tracing::trace_span!( + "drop", + kqueue_fd = ?self.kqueue_fd.as_raw_fd(), + ); + let _enter = span.enter(); + let _ = self.notify.deregister(self); } } diff --git a/src/lib.rs b/src/lib.rs index f1219b7..815ee1b 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -483,7 +483,8 @@ impl Poller { /// # std::io::Result::Ok(()) /// ``` pub fn wait(&self, events: &mut Vec, timeout: Option) -> io::Result { - log::trace!("Poller::wait(_, {:?})", timeout); + let span = tracing::trace_span!("Poller::wait", ?timeout); + let _enter = span.enter(); if let Ok(mut lock) = self.events.try_lock() { // Wait for I/O events. @@ -497,7 +498,7 @@ impl Poller { events.extend(lock.iter().filter(|ev| ev.key != usize::MAX)); Ok(events.len() - len) } else { - log::trace!("wait: skipping because another thread is already waiting on I/O"); + tracing::trace!("wait: skipping because another thread is already waiting on I/O"); Ok(0) } } @@ -525,7 +526,9 @@ impl Poller { /// # std::io::Result::Ok(()) /// ``` pub fn notify(&self) -> io::Result<()> { - log::trace!("Poller::notify()"); + let span = tracing::trace_span!("Poller::notify"); + let _enter = span.enter(); + if self .notified .compare_exchange(false, true, Ordering::SeqCst, Ordering::SeqCst) diff --git a/src/poll.rs b/src/poll.rs index 7f51ac4..846de80 100644 --- a/src/poll.rs +++ b/src/poll.rs @@ -89,11 +89,7 @@ impl Poller { // Put the reading side into non-blocking mode. fcntl_setfl(¬ify_read, fcntl_getfl(¬ify_read)? | OFlags::NONBLOCK)?; - log::trace!( - "new: notify_read={:?}, notify_write={:?}", - notify_read, - notify_write, - ); + tracing::trace!(?notify_read, ?notify_write, "new"); Ok(Self { fds: Mutex::new(Fds { @@ -128,12 +124,13 @@ impl Poller { return Err(io::Error::from(io::ErrorKind::InvalidInput)); } - log::trace!( - "add: notify_read={:?}, fd={}, ev={:?}", - self.notify_read, - fd, - ev + let span = tracing::trace_span!( + "add", + notify_read = ?self.notify_read, + ?fd, + ?ev, ); + let _enter = span.enter(); self.modify_fds(|fds| { if fds.fd_data.contains_key(&fd) { @@ -162,12 +159,13 @@ impl Poller { /// Modifies an existing file descriptor. pub fn modify(&self, fd: RawFd, ev: Event, mode: PollMode) -> io::Result<()> { - log::trace!( - "modify: notify_read={:?}, fd={}, ev={:?}", - self.notify_read, - fd, - ev + let span = tracing::trace_span!( + "modify", + notify_read = ?self.notify_read, + ?fd, + ?ev, ); + let _enter = span.enter(); self.modify_fds(|fds| { let data = fds.fd_data.get_mut(&fd).ok_or(io::ErrorKind::NotFound)?; @@ -183,7 +181,12 @@ impl Poller { /// Deletes a file descriptor. pub fn delete(&self, fd: RawFd) -> io::Result<()> { - log::trace!("delete: notify_read={:?}, fd={}", self.notify_read, fd); + let span = tracing::trace_span!( + "delete", + notify_read = ?self.notify_read, + ?fd, + ); + let _enter = span.enter(); self.modify_fds(|fds| { let data = fds.fd_data.remove(&fd).ok_or(io::ErrorKind::NotFound)?; @@ -201,11 +204,12 @@ impl Poller { /// Waits for I/O events with an optional timeout. pub fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { - log::trace!( - "wait: notify_read={:?}, timeout={:?}", - self.notify_read, - timeout + let span = tracing::trace_span!( + "wait", + notify_read = ?self.notify_read, + ?timeout, ); + let _enter = span.enter(); let deadline = timeout.and_then(|t| Instant::now().checked_add(t)); @@ -245,11 +249,7 @@ impl Poller { let num_events = poll(&mut fds.poll_fds, timeout_ms)?; let notified = !fds.poll_fds[0].revents().is_empty(); let num_fd_events = if notified { num_events - 1 } else { num_events }; - log::trace!( - "new events: notify_read={:?}, num={}", - self.notify_read, - num_events - ); + tracing::trace!(?num_events, ?notified, ?num_fd_events, "new events",); // Read all notifications. if notified { @@ -300,7 +300,11 @@ impl Poller { /// Sends a notification to wake up the current or next `wait()` call. pub fn notify(&self) -> io::Result<()> { - log::trace!("notify: notify_read={:?}", self.notify_read); + let span = tracing::trace_span!( + "notify", + notify_read = ?self.notify_read, + ); + let _enter = span.enter(); if !self.notified.swap(true, Ordering::SeqCst) { self.notify_inner()?; @@ -346,12 +350,6 @@ impl Poller { } } -impl Drop for Poller { - fn drop(&mut self) { - log::trace!("drop: notify_read={:?}", self.notify_read); - } -} - /// Get the input poll events for the given event. fn poll_events(ev: Event) -> PollFlags { (if ev.readable { diff --git a/src/port.rs b/src/port.rs index 3b14c28..1149bfb 100644 --- a/src/port.rs +++ b/src/port.rs @@ -23,6 +23,11 @@ impl Poller { let flags = fcntl_getfd(&port_fd)?; fcntl_setfd(&port_fd, flags | FdFlags::CLOEXEC)?; + tracing::trace!( + port_fd = ?port_fd.as_raw_fd(), + "new", + ); + Ok(Poller { port_fd }) } @@ -44,6 +49,14 @@ impl Poller { /// Modifies an existing file descriptor. pub fn modify(&self, fd: RawFd, ev: Event, mode: PollMode) -> io::Result<()> { + let span = tracing::trace_span!( + "modify", + port_fd = ?self.port_fd.as_raw_fd(), + ?fd, + ?ev, + ); + let _enter = span.enter(); + let mut flags = PollFlags::empty(); if ev.readable { flags |= read_flags(); @@ -67,6 +80,13 @@ impl Poller { /// Deletes a file descriptor. pub fn delete(&self, fd: RawFd) -> io::Result<()> { + let span = tracing::trace_span!( + "delete", + port_fd = ?self.port_fd.as_raw_fd(), + ?fd, + ); + let _enter = span.enter(); + let result = unsafe { port::port_dissociate_fd(&self.port_fd, fd) }; if let Err(e) = result { match e { @@ -80,8 +100,20 @@ impl Poller { /// Waits for I/O events with an optional timeout. pub fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { + let span = tracing::trace_span!( + "wait", + port_fd = ?self.port_fd.as_raw_fd(), + ?timeout, + ); + let _enter = span.enter(); + // Wait for I/O events. let res = port::port_getn(&self.port_fd, &mut events.list, 1, timeout); + tracing::trace!( + port_fd = ?self.port_fd, + res = ?events.list.len(), + "new events" + ); // Event ports sets the return value to -1 and returns ETIME on timer expire. The number of // returned events is stored in nget, but in our case it should always be 0 since we set @@ -100,6 +132,12 @@ impl Poller { pub fn notify(&self) -> io::Result<()> { const PORT_SOURCE_USER: i32 = 3; + let span = tracing::trace_span!( + "notify", + port_fd = ?self.port_fd.as_raw_fd(), + ); + let _enter = span.enter(); + // Use port_send to send a notification to the port. port::port_send(&self.port_fd, PORT_SOURCE_USER, crate::NOTIFY_KEY as _)?;