From c795ed15fce16567969370422a372546e1d120cc Mon Sep 17 00:00:00 2001 From: Evan Pratten Date: Thu, 27 Jul 2023 17:02:21 -0400 Subject: [PATCH] Add a packet timer --- src/cli/logging.rs | 9 ++- src/lib.rs | 1 + src/nat/mod.rs | 20 +++++- src/packet/xlat/icmp/mod.rs | 12 +++- src/packet/xlat/ip.rs | 28 ++++++--- src/packet/xlat/tcp.rs | 22 +++++-- src/packet/xlat/udp.rs | 27 ++++++--- src/profiling.rs | 117 ++++++++++++++++++++++++++++++++++++ 8 files changed, 209 insertions(+), 27 deletions(-) create mode 100644 src/profiling.rs diff --git a/src/cli/logging.rs b/src/cli/logging.rs index 72ac3b7..6d81046 100644 --- a/src/cli/logging.rs +++ b/src/cli/logging.rs @@ -40,9 +40,12 @@ pub fn enable_logger(verbose: bool) { )) }) // Set the correct log level based on CLI flags - .level(match verbose { - true => log::LevelFilter::Debug, - false => log::LevelFilter::Info, + .level(match std::env::var("PROTOMASK_TRACE") { + Ok(_) => log::LevelFilter::Trace, + Err(_) => match verbose { + true => log::LevelFilter::Debug, + false => log::LevelFilter::Info, + }, }) // Output to STDOUT .chain(std::io::stdout()) diff --git a/src/lib.rs b/src/lib.rs index 14f189f..a9d7f54 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -10,3 +10,4 @@ pub mod metrics; pub mod nat; mod packet; +mod profiling; diff --git a/src/nat/mod.rs b/src/nat/mod.rs index 930b363..02977f5 100644 --- a/src/nat/mod.rs +++ b/src/nat/mod.rs @@ -3,7 +3,7 @@ use crate::{ packet::{ protocols::{ipv4::Ipv4Packet, ipv6::Ipv6Packet}, xlat::ip::{translate_ipv4_to_ipv6, translate_ipv6_to_ipv4}, - }, + }, profiling::PacketTimer, }; use self::{ @@ -66,6 +66,9 @@ impl Nat64 { // Get an rx/tx pair for the interface let (tx, mut rx) = self.interface.spawn_worker().await; + // Only test if we should be printing profiling data once. This won't change mid-execution + let should_print_profiling = std::env::var("PROTOMASK_TRACE").is_ok(); + // Process packets in a loop loop { // Try to read a packet @@ -74,9 +77,15 @@ impl Nat64 { // Clone the TX so the worker can respond with data let tx = tx.clone(); + // Build a profiling object. + // This will be used by various functions to keep rough track of + // how long each major operation takes in the lifecycle of this Packet + let mut timer = PacketTimer::new(packet[0] >> 4); + // Separate logic is needed for handling IPv4 vs IPv6 packets, so a check must be done here match packet[0] >> 4 { 4 => { + // Parse the packet let packet: Ipv4Packet> = packet.try_into()?; @@ -103,13 +112,18 @@ impl Nat64 { packet, new_source, new_destination, + &mut timer, )) { tx.send(output.into()).await.unwrap(); + if should_print_profiling { + timer.log(); + } PACKET_COUNTER.with_label_values(&["ipv6", "sent"]).inc(); } }); } 6 => { + // Parse the packet let packet: Ipv6Packet> = packet.try_into()?; @@ -152,8 +166,12 @@ impl Nat64 { &packet, new_source, new_destination, + &mut timer, )) { tx.send(output.into()).await.unwrap(); + if should_print_profiling { + timer.log(); + } PACKET_COUNTER.with_label_values(&["ipv4", "sent"]).inc(); } }); diff --git a/src/packet/xlat/icmp/mod.rs b/src/packet/xlat/icmp/mod.rs index f0479b0..dd40034 100644 --- a/src/packet/xlat/icmp/mod.rs +++ b/src/packet/xlat/icmp/mod.rs @@ -9,7 +9,7 @@ use crate::{ packet::{ error::PacketError, protocols::{icmp::IcmpPacket, icmpv6::Icmpv6Packet, raw::RawBytes}, - }, + }, profiling::{PacketTimer, TimerScope}, }; use super::ip::{translate_ipv4_to_ipv6, translate_ipv6_to_ipv4}; @@ -21,6 +21,7 @@ pub fn translate_icmp_to_icmpv6( input: IcmpPacket, new_source: Ipv6Addr, new_destination: Ipv6Addr, + timer: &mut PacketTimer ) -> Result, PacketError> { ICMP_COUNTER .with_label_values(&[ @@ -29,6 +30,7 @@ pub fn translate_icmp_to_icmpv6( &input.icmp_code.0.to_string(), ]) .inc(); + timer.start(TimerScope::IcmpToIcmpv6); // Translate the type and code let (icmpv6_type, icmpv6_code) = @@ -43,7 +45,7 @@ pub fn translate_icmp_to_icmpv6( // Translate let inner_payload = - translate_ipv4_to_ipv6(inner_payload.try_into()?, new_source, new_destination)?; + translate_ipv4_to_ipv6(inner_payload.try_into()?, new_source, new_destination, timer)?; let inner_payload: Vec = inner_payload.into(); // Build the new payload @@ -58,6 +60,7 @@ pub fn translate_icmp_to_icmpv6( }; // Build output packet + timer.end(TimerScope::IcmpToIcmpv6); Ok(Icmpv6Packet::new( new_source, new_destination, @@ -72,6 +75,7 @@ pub fn translate_icmpv6_to_icmp( input: Icmpv6Packet, new_source: Ipv4Addr, new_destination: Ipv4Addr, + timer: &mut PacketTimer ) -> Result, PacketError> { ICMP_COUNTER .with_label_values(&[ @@ -80,6 +84,7 @@ pub fn translate_icmpv6_to_icmp( &input.icmp_code.0.to_string(), ]) .inc(); + timer.start(TimerScope::Icmpv6ToIcmp); // Translate the type and code let (icmp_type, icmp_code) = @@ -94,7 +99,7 @@ pub fn translate_icmpv6_to_icmp( // Translate let inner_payload = - translate_ipv6_to_ipv4(&inner_payload.try_into()?, new_source, new_destination)?; + translate_ipv6_to_ipv4(&inner_payload.try_into()?, new_source, new_destination, timer)?; let inner_payload: Vec = inner_payload.into(); // Build the new payload @@ -109,5 +114,6 @@ pub fn translate_icmpv6_to_icmp( }; // Build output packet + timer.end(TimerScope::Icmpv6ToIcmp); Ok(IcmpPacket::new(icmp_type, icmp_code, payload)) } diff --git a/src/packet/xlat/ip.rs b/src/packet/xlat/ip.rs index ae9804f..be4040f 100644 --- a/src/packet/xlat/ip.rs +++ b/src/packet/xlat/ip.rs @@ -7,7 +7,7 @@ use crate::{ packet::{ error::PacketError, protocols::{icmpv6::Icmpv6Packet, ipv4::Ipv4Packet, ipv6::Ipv6Packet, raw::RawBytes}, - }, + }, profiling::{PacketTimer, TimerScope}, }; use super::{ @@ -21,12 +21,16 @@ pub fn translate_ipv4_to_ipv6( input: Ipv4Packet>, new_source: Ipv6Addr, new_destination: Ipv6Addr, + timer: &mut PacketTimer ) -> Result>, PacketError> { + // Start profiling this function + timer.start(TimerScope::Ipv4ToIpv6); + // Perform recursive translation to determine the new payload let new_payload = match input.protocol { IpNextHeaderProtocols::Icmp => { let icmp_input: IcmpPacket = input.payload.try_into()?; - translate_icmp_to_icmpv6(icmp_input, new_source, new_destination)?.into() + translate_icmp_to_icmpv6(icmp_input, new_source, new_destination, timer)?.into() } IpNextHeaderProtocols::Udp => { let udp_input: UdpPacket = UdpPacket::new_from_bytes_raw_payload( @@ -34,7 +38,7 @@ pub fn translate_ipv4_to_ipv6( IpAddr::V4(input.source_address), IpAddr::V4(input.destination_address), )?; - translate_udp4_to_udp6(udp_input, new_source, new_destination)?.into() + translate_udp4_to_udp6(udp_input, new_source, new_destination, timer)?.into() } IpNextHeaderProtocols::Tcp => { let tcp_input: TcpPacket = TcpPacket::new_from_bytes_raw_payload( @@ -42,7 +46,7 @@ pub fn translate_ipv4_to_ipv6( IpAddr::V4(input.source_address), IpAddr::V4(input.destination_address), )?; - translate_tcp4_to_tcp6(tcp_input, new_source, new_destination)?.into() + translate_tcp4_to_tcp6(tcp_input, new_source, new_destination, timer)?.into() } _ => { log::warn!("Unsupported next level protocol: {}", input.protocol); @@ -64,6 +68,9 @@ pub fn translate_ipv4_to_ipv6( new_payload, ); + // End the timer + timer.end(TimerScope::Ipv4ToIpv6); + // Return the output Ok(output) } @@ -73,7 +80,11 @@ pub fn translate_ipv6_to_ipv4( input: &Ipv6Packet>, new_source: Ipv4Addr, new_destination: Ipv4Addr, + timer: &mut PacketTimer ) -> Result>, PacketError> { + // Start profiling this function + timer.start(TimerScope::Ipv6ToIpv4); + // Perform recursive translation to determine the new payload let new_payload = match input.next_header { IpNextHeaderProtocols::Icmpv6 => { @@ -82,7 +93,7 @@ pub fn translate_ipv6_to_ipv4( input.source_address, input.destination_address, )?; - Some(translate_icmpv6_to_icmp(icmpv6_input, new_source, new_destination)?.into()) + Some(translate_icmpv6_to_icmp(icmpv6_input, new_source, new_destination, timer)?.into()) } IpNextHeaderProtocols::Udp => { let udp_input: UdpPacket = UdpPacket::new_from_bytes_raw_payload( @@ -90,7 +101,7 @@ pub fn translate_ipv6_to_ipv4( IpAddr::V6(input.source_address), IpAddr::V6(input.destination_address), )?; - Some(translate_udp6_to_udp4(udp_input, new_source, new_destination)?.into()) + Some(translate_udp6_to_udp4(udp_input, new_source, new_destination, timer)?.into()) } IpNextHeaderProtocols::Tcp => { let tcp_input: TcpPacket = TcpPacket::new_from_bytes_raw_payload( @@ -98,7 +109,7 @@ pub fn translate_ipv6_to_ipv4( IpAddr::V6(input.source_address), IpAddr::V6(input.destination_address), )?; - Some(translate_tcp6_to_tcp4(tcp_input, new_source, new_destination)?.into()) + Some(translate_tcp6_to_tcp4(tcp_input, new_source, new_destination, timer)?.into()) } _ => { log::warn!("Unsupported next level protocol: {}", input.next_header); @@ -124,6 +135,9 @@ pub fn translate_ipv6_to_ipv4( new_payload.unwrap_or_default(), ); + // End the timer + timer.end(TimerScope::Ipv6ToIpv4); + // Return the output Ok(output) } diff --git a/src/packet/xlat/tcp.rs b/src/packet/xlat/tcp.rs index 2b456c3..5a21bc6 100644 --- a/src/packet/xlat/tcp.rs +++ b/src/packet/xlat/tcp.rs @@ -1,18 +1,20 @@ use std::net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr}; -use crate::packet::{ +use crate::{packet::{ error::PacketError, protocols::{raw::RawBytes, tcp::TcpPacket}, -}; +}, profiling::{PacketTimer, TimerScope}}; /// Translates an IPv4 TCP packet to an IPv6 TCP packet pub fn translate_tcp4_to_tcp6( input: TcpPacket, new_source_addr: Ipv6Addr, new_destination_addr: Ipv6Addr, + timer: &mut PacketTimer ) -> Result, PacketError> { // Build the packet - TcpPacket::new( + timer.start(TimerScope::Tcp); + let output = TcpPacket::new( SocketAddr::new(IpAddr::V6(new_source_addr), input.source().port()), SocketAddr::new(IpAddr::V6(new_destination_addr), input.destination().port()), input.sequence, @@ -22,7 +24,9 @@ pub fn translate_tcp4_to_tcp6( input.urgent_pointer, input.options, input.payload, - ) + ); + timer.end(TimerScope::Tcp); + output } /// Translates an IPv6 TCP packet to an IPv4 TCP packet @@ -30,9 +34,11 @@ pub fn translate_tcp6_to_tcp4( input: TcpPacket, new_source_addr: Ipv4Addr, new_destination_addr: Ipv4Addr, + timer: &mut PacketTimer ) -> Result, PacketError> { // Build the packet - TcpPacket::new( + timer.start(TimerScope::Tcp); + let output = TcpPacket::new( SocketAddr::new(IpAddr::V4(new_source_addr), input.source().port()), SocketAddr::new(IpAddr::V4(new_destination_addr), input.destination().port()), input.sequence, @@ -42,7 +48,9 @@ pub fn translate_tcp6_to_tcp4( input.urgent_pointer, input.options, input.payload, - ) + ); + timer.end(TimerScope::Tcp); + output } #[cfg(test)] @@ -68,6 +76,7 @@ mod tests { input, "2001:db8::1".parse().unwrap(), "2001:db8::2".parse().unwrap(), + &mut PacketTimer::new(4), ) .unwrap(); @@ -104,6 +113,7 @@ mod tests { input, "192.0.2.1".parse().unwrap(), "192.0.2.2".parse().unwrap(), + &mut PacketTimer::new(6), ) .unwrap(); diff --git a/src/packet/xlat/udp.rs b/src/packet/xlat/udp.rs index df2a74b..0498696 100644 --- a/src/packet/xlat/udp.rs +++ b/src/packet/xlat/udp.rs @@ -1,8 +1,11 @@ use std::net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr}; -use crate::packet::{ - error::PacketError, - protocols::{raw::RawBytes, udp::UdpPacket}, +use crate::{ + packet::{ + error::PacketError, + protocols::{raw::RawBytes, udp::UdpPacket}, + }, + profiling::{PacketTimer, TimerScope}, }; /// Translates an IPv4 UDP packet to an IPv6 UDP packet @@ -10,13 +13,17 @@ pub fn translate_udp4_to_udp6( input: UdpPacket, new_source_addr: Ipv6Addr, new_destination_addr: Ipv6Addr, + timer: &mut PacketTimer, ) -> Result, PacketError> { // Build the packet - UdpPacket::new( + timer.start(TimerScope::Udp); + let output = UdpPacket::new( SocketAddr::new(IpAddr::V6(new_source_addr), input.source().port()), SocketAddr::new(IpAddr::V6(new_destination_addr), input.destination().port()), input.payload, - ) + ); + timer.end(TimerScope::Udp); + output } /// Translates an IPv6 UDP packet to an IPv4 UDP packet @@ -24,13 +31,17 @@ pub fn translate_udp6_to_udp4( input: UdpPacket, new_source_addr: Ipv4Addr, new_destination_addr: Ipv4Addr, + timer: &mut PacketTimer, ) -> Result, PacketError> { // Build the packet - UdpPacket::new( + timer.start(TimerScope::Udp); + let output = UdpPacket::new( SocketAddr::new(IpAddr::V4(new_source_addr), input.source().port()), SocketAddr::new(IpAddr::V4(new_destination_addr), input.destination().port()), input.payload, - ) + ); + timer.end(TimerScope::Udp); + output } #[cfg(test)] @@ -53,6 +64,7 @@ mod tests { ipv4_packet, "2001:db8::1".parse().unwrap(), "2001:db8::2".parse().unwrap(), + &mut PacketTimer::new(4) ) .unwrap(); @@ -83,6 +95,7 @@ mod tests { ipv6_packet, "192.0.2.1".parse().unwrap(), "192.0.2.2".parse().unwrap(), + &mut PacketTimer::new(6) ) .unwrap(); diff --git a/src/profiling.rs b/src/profiling.rs new file mode 100644 index 0000000..d76c3de --- /dev/null +++ b/src/profiling.rs @@ -0,0 +1,117 @@ +use std::{ + collections::HashMap, + time::{Duration, Instant}, +}; + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub enum TimerScope { + Ipv4ToIpv6, + Ipv6ToIpv4, + IcmpToIcmpv6, + Icmpv6ToIcmp, + Udp, + Tcp, +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +enum TimerState { + Started(Instant, u8), + Ended(Duration, u8), +} + +pub struct PacketTimer { + protocol: u8, + creation_time: Instant, + states: HashMap, +} + +impl PacketTimer { + /// Construct a new `PacketTimer` + pub fn new(protocol: u8) -> Self { + Self { + protocol, + creation_time: Instant::now(), + states: HashMap::new(), + } + } + + pub fn start(&mut self, scope: TimerScope) { + match self.states.get(&scope) { + // If we have already started a timer for this scope, just increment the counter for "number of times started" + Some(TimerState::Started(instant, start_count)) => { + self.states + .insert(scope, TimerState::Started(*instant, start_count + 1)); + } + // This should never happen + Some(TimerState::Ended(_, _)) => { + unreachable!( + "Timer already ended for scope {:?}. Not starting again.", + scope + ); + } + // If the timer hasn't been started yet, start it + None => { + self.states + .insert(scope, TimerState::Started(Instant::now(), 0)); + } + } + } + + pub fn end(&mut self, scope: TimerScope) { + match self.states.get(&scope) { + // If the timer is currently "started", either decrement the counter or end the timer + Some(TimerState::Started(instant, start_count)) => { + if *start_count == 0 { + self.states + .insert(scope, TimerState::Ended(instant.elapsed(), *start_count)); + } else { + self.states + .insert(scope, TimerState::Started(*instant, start_count - 1)); + } + } + // Ending an already ended timer does nothing + Some(TimerState::Ended(_, _)) => { + log::error!( + "Timer already ended for scope {:?}. Not ending again.", + scope + ); + } + // Ending a timer that never started should be impossible + None => { + unreachable!("Timer not started for scope {:?}. Not ending.", scope); + } + } + } + + pub fn log(&self) { + log::trace!( + "[Timer report] proto: {}, total: {:05}µs, ipv4_to_ipv6: {:05}µs, ipv6_to_ipv4: {:05}µs, icmp_to_icmpv6: {:05}µs, icmpv6_to_icmp: {:05}µs, udp: {:05}µs, tcp: {:05}µs", + self.protocol, + self.creation_time.elapsed().as_micros(), + self.states.get(&TimerScope::Ipv4ToIpv6).map(|val| match val { + TimerState::Ended(duration, _) => duration.as_micros(), + _=>0 + }).unwrap_or(0), + self.states.get(&TimerScope::Ipv6ToIpv4).map(|val| match val { + TimerState::Ended(duration, _) => duration.as_micros(), + _=>0 + }).unwrap_or(0), + self.states.get(&TimerScope::IcmpToIcmpv6).map(|val| match val { + TimerState::Ended(duration, _) => duration.as_micros(), + _=>0 + }).unwrap_or(0), + self.states.get(&TimerScope::Icmpv6ToIcmp).map(|val| match val { + TimerState::Ended(duration, _) => duration.as_micros(), + _=>0 + }).unwrap_or(0), + self.states.get(&TimerScope::Udp).map(|val| match val { + TimerState::Ended(duration, _) => duration.as_micros(), + _=>0 + }).unwrap_or(0), + self.states.get(&TimerScope::Tcp).map(|val| match val { + TimerState::Ended(duration, _) => duration.as_micros(), + _=>0 + }).unwrap_or(0), + ); + } +}