Add a packet timer

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 {
+        .level(match std::env::var("PROTOMASK_TRACE") {
-            true => log::LevelFilter::Debug,
+            Ok(_) => log::LevelFilter::Trace,
-            false => log::LevelFilter::Info,
+            Err(_) => match verbose {
+                true => log::LevelFilter::Debug,
+                false => log::LevelFilter::Info,
+            },
         })
         // Output to STDOUT
         .chain(std::io::stdout())

src/lib.rs

@@ -10,3 +10,4 @@
 pub mod metrics;
 pub mod nat;
 mod packet;
+mod profiling;

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<Vec<u8>> = 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<Vec<u8>> = 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();
                                 }
                             });

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<RawBytes>,
     new_source: Ipv6Addr,
     new_destination: Ipv6Addr,
+    timer: &mut PacketTimer
 ) -> Result<Icmpv6Packet<RawBytes>, 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<u8> = 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<RawBytes>,
     new_source: Ipv4Addr,
     new_destination: Ipv4Addr,
+    timer: &mut PacketTimer
 ) -> Result<IcmpPacket<RawBytes>, 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<u8> = 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))
 }

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<Vec<u8>>,
     new_source: Ipv6Addr,
     new_destination: Ipv6Addr,
+    timer: &mut PacketTimer
 ) -> Result<Ipv6Packet<Vec<u8>>, 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<RawBytes> = 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<RawBytes> = 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<RawBytes> = 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<Vec<u8>>,
     new_source: Ipv4Addr,
     new_destination: Ipv4Addr,
+    timer: &mut PacketTimer
 ) -> Result<Ipv4Packet<Vec<u8>>, 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<RawBytes> = 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<RawBytes> = 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)
 }

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<RawBytes>,
     new_source_addr: Ipv6Addr,
     new_destination_addr: Ipv6Addr,
+    timer: &mut PacketTimer
 ) -> Result<TcpPacket<RawBytes>, 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<RawBytes>,
     new_source_addr: Ipv4Addr,
     new_destination_addr: Ipv4Addr,
+    timer: &mut PacketTimer
 ) -> Result<TcpPacket<RawBytes>, 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();
 

src/packet/xlat/udp.rs

@@ -1,8 +1,11 @@
 use std::net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr};
 
-use crate::packet::{
+use crate::{
-    error::PacketError,
+    packet::{
-    protocols::{raw::RawBytes, udp::UdpPacket},
+        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<RawBytes>,
     new_source_addr: Ipv6Addr,
     new_destination_addr: Ipv6Addr,
+    timer: &mut PacketTimer,
 ) -> Result<UdpPacket<RawBytes>, 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<RawBytes>,
     new_source_addr: Ipv4Addr,
     new_destination_addr: Ipv4Addr,
+    timer: &mut PacketTimer,
 ) -> Result<UdpPacket<RawBytes>, 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();
 

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<TimerScope, TimerState>,
+}
+
+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),
+        );
+    }
+}