From 79bfca3958e5eb2c2cafd50b8b19cd0f7ce0e561 Mon Sep 17 00:00:00 2001 From: jtnunley Date: Fri, 30 Dec 2022 10:14:04 -0800 Subject: [PATCH] int: Use tracing instead of log --- Cargo.toml | 2 +- src/epoll.rs | 16 ++++++++-------- src/kqueue.rs | 12 ++++++------ src/lib.rs | 9 ++++++--- src/poll.rs | 18 +++++++++--------- src/port.rs | 18 ++++++++++++++++++ src/wepoll.rs | 16 ++++++++-------- 7 files changed, 56 insertions(+), 35 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 0694854..241a6e6 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 } [build-dependencies] autocfg = "1" diff --git a/src/epoll.rs b/src/epoll.rs index bf94b01..6239960 100644 --- a/src/epoll.rs +++ b/src/epoll.rs @@ -79,7 +79,7 @@ impl Poller { }, )?; - log::trace!( + tracing::trace!( "new: epoll_fd={}, event_fd={}, timer_fd={:?}", epoll_fd, event_fd, @@ -90,25 +90,25 @@ impl Poller { /// Adds a new file descriptor. pub fn add(&self, fd: RawFd, ev: Event) -> io::Result<()> { - log::trace!("add: epoll_fd={}, fd={}, ev={:?}", self.epoll_fd, fd, ev); + tracing::trace!("add: epoll_fd={}, fd={}, ev={:?}", self.epoll_fd, fd, ev); self.ctl(libc::EPOLL_CTL_ADD, fd, Some(ev)) } /// Modifies an existing file descriptor. pub fn modify(&self, fd: RawFd, ev: Event) -> io::Result<()> { - log::trace!("modify: epoll_fd={}, fd={}, ev={:?}", self.epoll_fd, fd, ev); + tracing::trace!("modify: epoll_fd={}, fd={}, ev={:?}", self.epoll_fd, fd, ev); self.ctl(libc::EPOLL_CTL_MOD, fd, Some(ev)) } /// Deletes a file descriptor. pub fn delete(&self, fd: RawFd) -> io::Result<()> { - log::trace!("remove: epoll_fd={}, fd={}", self.epoll_fd, fd); + tracing::trace!("remove: epoll_fd={}, fd={}", self.epoll_fd, fd); self.ctl(libc::EPOLL_CTL_DEL, fd, None) } /// Waits for I/O events with an optional timeout. pub fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { - log::trace!("wait: epoll_fd={}, timeout={:?}", self.epoll_fd, timeout); + tracing::trace!("wait: epoll_fd={}, timeout={:?}", self.epoll_fd, timeout); if let Some(timer_fd) = self.timer_fd { // Configure the timeout using timerfd. @@ -165,7 +165,7 @@ impl Poller { timeout_ms as libc::c_int, ))?; events.len = res as usize; - log::trace!("new events: epoll_fd={}, res={}", self.epoll_fd, res); + tracing::trace!("new events: epoll_fd={}, res={}", self.epoll_fd, res); // Clear the notification (if received) and re-register interest in it. let mut buf = [0u8; 8]; @@ -187,7 +187,7 @@ impl Poller { /// Sends a notification to wake up the current or next `wait()` call. pub fn notify(&self) -> io::Result<()> { - log::trace!( + tracing::trace!( "notify: epoll_fd={}, event_fd={}", self.epoll_fd, self.event_fd @@ -245,7 +245,7 @@ impl AsFd for Poller { impl Drop for Poller { fn drop(&mut self) { - log::trace!( + tracing::trace!( "drop: epoll_fd={}, event_fd={}, timer_fd={:?}", self.epoll_fd, self.event_fd, diff --git a/src/kqueue.rs b/src/kqueue.rs index 67e7167..7ed43a8 100644 --- a/src/kqueue.rs +++ b/src/kqueue.rs @@ -49,7 +49,7 @@ impl Poller { }, )?; - log::trace!( + tracing::trace!( "new: kqueue_fd={}, read_stream={:?}", kqueue_fd, poller.read_stream @@ -66,7 +66,7 @@ impl Poller { /// Modifies an existing file descriptor. pub fn modify(&self, fd: RawFd, ev: Event) -> io::Result<()> { if fd != self.read_stream.as_raw_fd() { - log::trace!("add: kqueue_fd={}, fd={}, ev={:?}", self.kqueue_fd, fd, ev); + tracing::trace!("add: kqueue_fd={}, fd={}, ev={:?}", self.kqueue_fd, fd, ev); } let read_flags = if ev.readable { @@ -132,7 +132,7 @@ 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); + tracing::trace!("wait: kqueue_fd={}, timeout={:?}", self.kqueue_fd, timeout); // Convert the `Duration` to `libc::timespec`. let timeout = timeout.map(|t| libc::timespec { @@ -155,7 +155,7 @@ impl Poller { } ))?; events.len = res as usize; - log::trace!("new events: kqueue_fd={}, res={}", self.kqueue_fd, res); + tracing::trace!("new events: kqueue_fd={}, res={}", self.kqueue_fd, res); // Clear the notification (if received) and re-register interest in it. while (&self.read_stream).read(&mut [0; 64]).is_ok() {} @@ -173,7 +173,7 @@ 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); + tracing::trace!("notify: kqueue_fd={}", self.kqueue_fd); let _ = (&self.write_stream).write(&[1]); Ok(()) } @@ -195,7 +195,7 @@ impl AsFd for Poller { impl Drop for Poller { fn drop(&mut self) { - log::trace!("drop: kqueue_fd={}", self.kqueue_fd); + tracing::trace!("drop: kqueue_fd={}", self.kqueue_fd); let _ = self.delete(self.read_stream.as_raw_fd()); let _ = syscall!(close(self.kqueue_fd)); } diff --git a/src/lib.rs b/src/lib.rs index 2ca3f7b..5cf7e41 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -396,7 +396,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 = ?timeout); + let _enter = span.enter(); if let Ok(mut lock) = self.events.try_lock() { // Wait for I/O events. @@ -410,7 +411,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) } } @@ -438,7 +439,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 63fee66..5288d84 100644 --- a/src/poll.rs +++ b/src/poll.rs @@ -94,7 +94,7 @@ impl Poller { notify_read_flags | libc::O_NONBLOCK ))?; - log::trace!( + tracing::trace!( "new: notify_read={}, notify_write={}", notify_pipe[0], notify_pipe[1] @@ -123,7 +123,7 @@ impl Poller { return Err(io::Error::from(io::ErrorKind::InvalidInput)); } - log::trace!( + tracing::trace!( "add: notify_read={}, fd={}, ev={:?}", self.notify_read, fd, @@ -156,7 +156,7 @@ impl Poller { /// Modifies an existing file descriptor. pub fn modify(&self, fd: RawFd, ev: Event) -> io::Result<()> { - log::trace!( + tracing::trace!( "modify: notify_read={}, fd={}, ev={:?}", self.notify_read, fd, @@ -175,7 +175,7 @@ impl Poller { /// Deletes a file descriptor. pub fn delete(&self, fd: RawFd) -> io::Result<()> { - log::trace!("delete: notify_read={}, fd={}", self.notify_read, fd); + tracing::trace!("delete: notify_read={}, fd={}", self.notify_read, fd); self.modify_fds(|fds| { let data = fds.fd_data.remove(&fd).ok_or(io::ErrorKind::NotFound)?; @@ -193,7 +193,7 @@ impl Poller { /// Waits for I/O events with an optional timeout. pub fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { - log::trace!( + tracing::trace!( "wait: notify_read={}, timeout={:?}", self.notify_read, timeout @@ -223,7 +223,7 @@ impl Poller { let num_events = poll(&mut fds.poll_fds, deadline)?; let notified = fds.poll_fds[0].0.revents != 0; let num_fd_events = if notified { num_events - 1 } else { num_events }; - log::trace!( + tracing::trace!( "new events: notify_read={}, num={}", self.notify_read, num_events @@ -275,7 +275,7 @@ 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); + tracing::trace!("notify: notify_read={}", self.notify_read); if !self.notified.swap(true, Ordering::SeqCst) { self.notify_inner()?; @@ -299,7 +299,7 @@ impl Poller { let _ = self.pop_notification(); } - let res = f(&mut *fds); + let res = f(&mut fds); if self.waiting_operations.fetch_sub(1, Ordering::SeqCst) == 1 { self.operations_complete.notify_one(); @@ -323,7 +323,7 @@ impl Poller { impl Drop for Poller { fn drop(&mut self) { - log::trace!("drop: notify_read={}", self.notify_read); + tracing::trace!("drop: notify_read={}", self.notify_read); let _ = syscall!(close(self.notify_read)); let _ = syscall!(close(self.notify_write)); } diff --git a/src/port.rs b/src/port.rs index feee300..9856f75 100644 --- a/src/port.rs +++ b/src/port.rs @@ -48,6 +48,11 @@ impl Poller { }, )?; + tracing::trace!( + "new: port_fd={}, read_stream={:?}", + port_fd, + poller.read_stream + ); Ok(poller) } @@ -59,6 +64,10 @@ impl Poller { /// Modifies an existing file descriptor. pub fn modify(&self, fd: RawFd, ev: Event) -> io::Result<()> { + if fd != self.read_stream.as_raw_fd() { + tracing::trace!("modify: port_fd={}, fd={}, ev={:?}", self.port_fd, fd, ev); + } + let mut flags = 0; if ev.readable { flags |= libc::POLLIN; @@ -79,6 +88,10 @@ impl Poller { /// Deletes a file descriptor. pub fn delete(&self, fd: RawFd) -> io::Result<()> { + if fd != self.read_stream.as_raw_fd() { + tracing::trace!("delete: port_fd={}, fd={}", self.port_fd, fd); + } + if let Err(e) = syscall!(port_dissociate( self.port_fd, libc::PORT_SOURCE_FD, @@ -95,6 +108,8 @@ impl Poller { /// Waits for I/O events with an optional timeout. pub fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { + tracing::trace!("wait: port_fd={}, timeout={:?}", self.port_fd, timeout); + let mut timeout = timeout.map(|t| libc::timespec { tv_sec: t.as_secs() as libc::time_t, tv_nsec: t.subsec_nanos() as libc::c_long, @@ -123,6 +138,7 @@ impl Poller { }, Ok(_) => nget as usize, }; + tracing::trace!("new events: port_fd={}, nevents={}", self.port_fd, nevents); events.len = nevents; // Clear the notification (if received) and re-register interest in it. @@ -141,6 +157,7 @@ impl Poller { /// Sends a notification to wake up the current or next `wait()` call. pub fn notify(&self) -> io::Result<()> { + tracing::trace!("notify: port_fd={}", self.port_fd); let _ = (&self.write_stream).write(&[1]); Ok(()) } @@ -162,6 +179,7 @@ impl AsFd for Poller { impl Drop for Poller { fn drop(&mut self) { + tracing::trace!("drop: port_fd={}", self.port_fd); let _ = self.delete(self.read_stream.as_raw_fd()); let _ = syscall!(close(self.port_fd)); } diff --git a/src/wepoll.rs b/src/wepoll.rs index f33d55e..70a68cb 100644 --- a/src/wepoll.rs +++ b/src/wepoll.rs @@ -54,19 +54,19 @@ impl Poller { )); } let notified = AtomicBool::new(false); - log::trace!("new: handle={:?}", handle); + tracing::trace!("new: handle={:?}", handle); Ok(Poller { handle, notified }) } /// Adds a socket. pub fn add(&self, sock: RawSocket, ev: Event) -> io::Result<()> { - log::trace!("add: handle={:?}, sock={}, ev={:?}", self.handle, sock, ev); + tracing::trace!("add: handle={:?}, sock={}, ev={:?}", self.handle, sock, ev); self.ctl(we::EPOLL_CTL_ADD, sock, Some(ev)) } /// Modifies a socket. pub fn modify(&self, sock: RawSocket, ev: Event) -> io::Result<()> { - log::trace!( + tracing::trace!( "modify: handle={:?}, sock={}, ev={:?}", self.handle, sock, @@ -77,7 +77,7 @@ impl Poller { /// Deletes a socket. pub fn delete(&self, sock: RawSocket) -> io::Result<()> { - log::trace!("remove: handle={:?}, sock={}", self.handle, sock); + tracing::trace!("remove: handle={:?}, sock={}", self.handle, sock); self.ctl(we::EPOLL_CTL_DEL, sock, None) } @@ -88,7 +88,7 @@ impl Poller { /// If a notification occurs, this method will return but the notification event will not be /// included in the `events` list nor contribute to the returned count. pub fn wait(&self, events: &mut Events, timeout: Option) -> io::Result<()> { - log::trace!("wait: handle={:?}, timeout={:?}", self.handle, timeout); + tracing::trace!("wait: handle={:?}, timeout={:?}", self.handle, timeout); let deadline = timeout.map(|t| Instant::now() + t); loop { @@ -112,7 +112,7 @@ impl Poller { events.list.len() as c_int, timeout_ms, ))? as usize; - log::trace!("new events: handle={:?}, len={}", self.handle, events.len); + tracing::trace!("new events: handle={:?}, len={}", self.handle, events.len); // Break if there was a notification or at least one event, or if deadline is reached. if self.notified.swap(false, Ordering::SeqCst) || events.len > 0 || timeout_ms == 0 { @@ -125,7 +125,7 @@ impl Poller { /// Sends a notification to wake up the current or next `wait()` call. pub fn notify(&self) -> io::Result<()> { - log::trace!("notify: handle={:?}", self.handle); + tracing::trace!("notify: handle={:?}", self.handle); if self .notified @@ -194,7 +194,7 @@ impl AsHandle for Poller { impl Drop for Poller { fn drop(&mut self) { - log::trace!("drop: handle={:?}", self.handle); + tracing::trace!("drop: handle={:?}", self.handle); unsafe { we::epoll_close(self.handle); }