From 6c3a719f88a74451c14326b7cb1de2240a2febd3 Mon Sep 17 00:00:00 2001 From: Martin Thomson Date: Thu, 15 Feb 2024 23:26:58 +1100 Subject: [PATCH 01/30] Track sent packets in a Vec --- neqo-transport/src/cc/classic_cc.rs | 4 +- neqo-transport/src/cc/mod.rs | 2 +- neqo-transport/src/cc/tests/cubic.rs | 2 +- neqo-transport/src/cc/tests/new_reno.rs | 2 +- neqo-transport/src/connection/mod.rs | 8 +- neqo-transport/src/path.rs | 4 +- neqo-transport/src/qlog.rs | 2 +- .../src/{recovery.rs => recovery/mod.rs} | 180 +++------ neqo-transport/src/recovery/sent.rs | 361 ++++++++++++++++++ neqo-transport/src/recovery/token.rs | 63 +++ neqo-transport/src/sender.rs | 2 +- neqo-transport/src/tracking.rs | 108 ------ 12 files changed, 484 insertions(+), 254 deletions(-) rename neqo-transport/src/{recovery.rs => recovery/mod.rs} (91%) create mode 100644 neqo-transport/src/recovery/sent.rs create mode 100644 neqo-transport/src/recovery/token.rs diff --git a/neqo-transport/src/cc/classic_cc.rs b/neqo-transport/src/cc/classic_cc.rs index 6f4a01d795..baf98cca46 100644 --- a/neqo-transport/src/cc/classic_cc.rs +++ b/neqo-transport/src/cc/classic_cc.rs @@ -18,9 +18,9 @@ use crate::{ cc::MAX_DATAGRAM_SIZE, packet::PacketNumber, qlog::{self, QlogMetric}, + recovery::SentPacket, rtt::RttEstimate, sender::PACING_BURST_SIZE, - tracking::SentPacket, }; #[rustfmt::skip] // to keep `::` and thus prevent conflict with `crate::qlog` use ::qlog::events::{quic::CongestionStateUpdated, EventData}; @@ -555,8 +555,8 @@ mod tests { CongestionControl, CongestionControlAlgorithm, CWND_INITIAL_PKTS, MAX_DATAGRAM_SIZE, }, packet::{PacketNumber, PacketType}, + recovery::SentPacket, rtt::RttEstimate, - tracking::SentPacket, }; const PTO: Duration = Duration::from_millis(100); diff --git a/neqo-transport/src/cc/mod.rs b/neqo-transport/src/cc/mod.rs index a1a43bd157..9d3989b6bc 100644 --- a/neqo-transport/src/cc/mod.rs +++ b/neqo-transport/src/cc/mod.rs @@ -15,7 +15,7 @@ use std::{ use neqo_common::qlog::NeqoQlog; -use crate::{path::PATH_MTU_V6, rtt::RttEstimate, tracking::SentPacket, Error}; +use crate::{path::PATH_MTU_V6, recovery::SentPacket, rtt::RttEstimate, Error}; mod classic_cc; mod cubic; diff --git a/neqo-transport/src/cc/tests/cubic.rs b/neqo-transport/src/cc/tests/cubic.rs index 0c82e47817..1861cdff46 100644 --- a/neqo-transport/src/cc/tests/cubic.rs +++ b/neqo-transport/src/cc/tests/cubic.rs @@ -25,8 +25,8 @@ use crate::{ CongestionControl, MAX_DATAGRAM_SIZE, MAX_DATAGRAM_SIZE_F64, }, packet::PacketType, + recovery::SentPacket, rtt::RttEstimate, - tracking::SentPacket, }; const RTT: Duration = Duration::from_millis(100); diff --git a/neqo-transport/src/cc/tests/new_reno.rs b/neqo-transport/src/cc/tests/new_reno.rs index a73844a755..0736f398fb 100644 --- a/neqo-transport/src/cc/tests/new_reno.rs +++ b/neqo-transport/src/cc/tests/new_reno.rs @@ -17,8 +17,8 @@ use crate::{ MAX_DATAGRAM_SIZE, }, packet::PacketType, + recovery::SentPacket, rtt::RttEstimate, - tracking::SentPacket, }; const PTO: Duration = Duration::from_millis(100); diff --git a/neqo-transport/src/connection/mod.rs b/neqo-transport/src/connection/mod.rs index 749cf315d3..1e53447007 100644 --- a/neqo-transport/src/connection/mod.rs +++ b/neqo-transport/src/connection/mod.rs @@ -45,7 +45,7 @@ use crate::{ path::{Path, PathRef, Paths}, qlog, quic_datagrams::{DatagramTracking, QuicDatagrams}, - recovery::{LossRecovery, RecoveryToken, SendProfile}, + recovery::{LossRecovery, RecoveryToken, SendProfile, SentPacket}, recv_stream::RecvStreamStats, rtt::GRANULARITY, send_stream::SendStream, @@ -56,7 +56,7 @@ use crate::{ self, TransportParameter, TransportParameterId, TransportParameters, TransportParametersHandler, }, - tracking::{AckTracker, PacketNumberSpace, SentPacket}, + tracking::{AckTracker, PacketNumberSpace}, version::{Version, WireVersion}, AppError, ConnectionError, Error, Res, StreamId, }; @@ -2884,12 +2884,12 @@ impl Connection { fn handle_ack( &mut self, space: PacketNumberSpace, - largest_acknowledged: u64, + largest_acknowledged: PacketNumber, ack_ranges: R, ack_delay: u64, now: Instant, ) where - R: IntoIterator> + Debug, + R: IntoIterator> + Debug, R::IntoIter: ExactSizeIterator, { qinfo!([self], "Rx ACK space={}, ranges={:?}", space, ack_ranges); diff --git a/neqo-transport/src/path.rs b/neqo-transport/src/path.rs index 897763d7de..782fe896c0 100644 --- a/neqo-transport/src/path.rs +++ b/neqo-transport/src/path.rs @@ -26,11 +26,11 @@ use crate::{ cid::{ConnectionId, ConnectionIdRef, ConnectionIdStore, RemoteConnectionIdEntry}, frame::{FRAME_TYPE_PATH_CHALLENGE, FRAME_TYPE_PATH_RESPONSE, FRAME_TYPE_RETIRE_CONNECTION_ID}, packet::PacketBuilder, - recovery::RecoveryToken, + recovery::{RecoveryToken, SentPacket}, rtt::RttEstimate, sender::PacketSender, stats::FrameStats, - tracking::{PacketNumberSpace, SentPacket}, + tracking::PacketNumberSpace, Stats, }; diff --git a/neqo-transport/src/qlog.rs b/neqo-transport/src/qlog.rs index f6d3f4e1e2..b59df0e37c 100644 --- a/neqo-transport/src/qlog.rs +++ b/neqo-transport/src/qlog.rs @@ -29,9 +29,9 @@ use crate::{ frame::{CloseError, Frame}, packet::{DecryptedPacket, PacketNumber, PacketType, PublicPacket}, path::PathRef, + recovery::SentPacket, stream_id::StreamType as NeqoStreamType, tparams::{self, TransportParametersHandler}, - tracking::SentPacket, version::{Version, VersionConfig, WireVersion}, }; diff --git a/neqo-transport/src/recovery.rs b/neqo-transport/src/recovery/mod.rs similarity index 91% rename from neqo-transport/src/recovery.rs rename to neqo-transport/src/recovery/mod.rs index ec1d7e4a3d..7f362e4104 100644 --- a/neqo-transport/src/recovery.rs +++ b/neqo-transport/src/recovery/mod.rs @@ -6,33 +6,29 @@ // Tracking of sent packets and detecting their loss. -#![deny(clippy::pedantic)] +mod sent; +mod token; use std::{ cmp::{max, min}, - collections::BTreeMap, convert::TryFrom, - mem, ops::RangeInclusive, time::{Duration, Instant}, }; use neqo_common::{qdebug, qinfo, qlog::NeqoQlog, qtrace, qwarn}; +pub use sent::SentPacket; +use sent::SentPackets; use smallvec::{smallvec, SmallVec}; +pub use token::{RecoveryToken, StreamRecoveryToken}; use crate::{ - ackrate::AckRate, - cid::ConnectionIdEntry, - crypto::CryptoRecoveryToken, packet::PacketNumber, path::{Path, PathRef}, qlog::{self, QlogMetric}, - quic_datagrams::DatagramTracking, rtt::RttEstimate, - send_stream::SendStreamRecoveryToken, stats::{Stats, StatsCell}, - stream_id::{StreamId, StreamType}, - tracking::{AckToken, PacketNumberSpace, PacketNumberSpaceSet, SentPacket}, + tracking::{PacketNumberSpace, PacketNumberSpaceSet}, }; pub(crate) const PACKET_THRESHOLD: u64 = 3; @@ -51,54 +47,6 @@ pub(crate) const MIN_OUTSTANDING_UNACK: usize = 16; /// The scale we use for the fast PTO feature. pub const FAST_PTO_SCALE: u8 = 100; -#[derive(Debug, Clone)] -#[allow(clippy::module_name_repetitions)] -pub enum StreamRecoveryToken { - Stream(SendStreamRecoveryToken), - ResetStream { - stream_id: StreamId, - }, - StopSending { - stream_id: StreamId, - }, - - MaxData(u64), - DataBlocked(u64), - - MaxStreamData { - stream_id: StreamId, - max_data: u64, - }, - StreamDataBlocked { - stream_id: StreamId, - limit: u64, - }, - - MaxStreams { - stream_type: StreamType, - max_streams: u64, - }, - StreamsBlocked { - stream_type: StreamType, - limit: u64, - }, -} - -#[derive(Debug, Clone)] -#[allow(clippy::module_name_repetitions)] -pub enum RecoveryToken { - Stream(StreamRecoveryToken), - Ack(AckToken), - Crypto(CryptoRecoveryToken), - HandshakeDone, - KeepAlive, // Special PING. - NewToken(usize), - NewConnectionId(ConnectionIdEntry<[u8; 16]>), - RetireConnectionId(u64), - AckFrequency(AckRate), - Datagram(DatagramTracking), -} - /// `SendProfile` tells a sender how to send packets. #[derive(Debug)] pub struct SendProfile { @@ -183,7 +131,8 @@ pub(crate) struct LossRecoverySpace { /// This might be less than the number of ACK-eliciting packets, /// because PTO packets don't count. in_flight_outstanding: usize, - sent_packets: BTreeMap, + /// The packets that we have sent and are tracking. + sent_packets: SentPackets, /// The time that the first out-of-order packet was sent. /// This is `None` if there were no out-of-order packets detected. /// When set to `Some(T)`, time-based loss detection should be enabled. @@ -198,7 +147,7 @@ impl LossRecoverySpace { largest_acked_sent_time: None, last_ack_eliciting: None, in_flight_outstanding: 0, - sent_packets: BTreeMap::default(), + sent_packets: SentPackets::default(), first_ooo_time: None, } } @@ -223,9 +172,9 @@ impl LossRecoverySpace { pub fn pto_packets(&mut self, count: usize) -> impl Iterator { self.sent_packets .iter_mut() - .filter_map(|(pn, sent)| { + .filter_map(|sent| { if sent.pto() { - qtrace!("PTO: marking packet {} lost ", pn); + qtrace!("PTO: marking packet {} lost ", sent.pn); Some(&*sent) } else { None @@ -267,7 +216,7 @@ impl LossRecoverySpace { // always. See `LossRecoverySpace::pto_base_time()` for details. self.last_ack_eliciting = Some(sent_packet.time_sent); } - self.sent_packets.insert(sent_packet.pn, sent_packet); + self.sent_packets.track(sent_packet); } /// If we are only sending ACK frames, send a PING frame after 2 PTOs so that @@ -297,46 +246,31 @@ impl LossRecoverySpace { } } - /// Remove all acknowledged packets. + /// Remove all newly acknowledged packets. /// Returns all the acknowledged packets, with the largest packet number first. /// ...and a boolean indicating if any of those packets were ack-eliciting. /// This operates more efficiently because it assumes that the input is sorted /// in the order that an ACK frame is (from the top). fn remove_acked(&mut self, acked_ranges: R, stats: &mut Stats) -> (Vec, bool) where - R: IntoIterator>, + R: IntoIterator>, R::IntoIter: ExactSizeIterator, { - let acked_ranges = acked_ranges.into_iter(); - let mut keep = Vec::with_capacity(acked_ranges.len()); - - let mut acked = Vec::new(); let mut eliciting = false; + let mut acked = Vec::new(); for range in acked_ranges { - let first_keep = *range.end() + 1; - if let Some((&first, _)) = self.sent_packets.range(range).next() { - let mut tail = self.sent_packets.split_off(&first); - if let Some((&next, _)) = tail.range(first_keep..).next() { - keep.push(tail.split_off(&next)); - } - for (_, p) in tail.into_iter().rev() { - self.remove_packet(&p); - eliciting |= p.ack_eliciting(); - if p.lost() { - stats.late_ack += 1; - } - if p.pto_fired() { - stats.pto_ack += 1; - } - acked.push(p); - } - } + acked.extend(self.sent_packets.take_range(range)); } - - for mut k in keep.into_iter().rev() { - self.sent_packets.append(&mut k); + for p in &acked { + self.remove_packet(p); + eliciting |= p.ack_eliciting(); + if p.lost() { + stats.late_ack += 1; + } + if p.pto_fired() { + stats.pto_ack += 1; + } } - (acked, eliciting) } @@ -345,12 +279,12 @@ impl LossRecoverySpace { /// and when keys are dropped. fn remove_ignored(&mut self) -> impl Iterator { self.in_flight_outstanding = 0; - mem::take(&mut self.sent_packets).into_values() + std::mem::take(&mut self.sent_packets).drain_all() } /// Remove the primary path marking on any packets this is tracking. fn migrate(&mut self) { - for pkt in self.sent_packets.values_mut() { + for pkt in self.sent_packets.iter_mut() { pkt.clear_primary_path(); } } @@ -361,23 +295,8 @@ impl LossRecoverySpace { /// might remove all in-flight packets and stop sending probes. #[allow(clippy::option_if_let_else)] // Hard enough to read as-is. fn remove_old_lost(&mut self, now: Instant, cd: Duration) { - let mut it = self.sent_packets.iter(); - // If the first item is not expired, do nothing. - if it.next().map_or(false, |(_, p)| p.expired(now, cd)) { - // Find the index of the first unexpired packet. - let to_remove = if let Some(first_keep) = - it.find_map(|(i, p)| if p.expired(now, cd) { None } else { Some(*i) }) - { - // Some packets haven't expired, so keep those. - let keep = self.sent_packets.split_off(&first_keep); - mem::replace(&mut self.sent_packets, keep) - } else { - // All packets are expired. - mem::take(&mut self.sent_packets) - }; - for (_, p) in to_remove { - self.remove_packet(&p); - } + for p in self.sent_packets.remove_expired(now, cd) { + self.remove_packet(&p); } } @@ -404,27 +323,24 @@ impl LossRecoverySpace { let largest_acked = self.largest_acked; - // Lost for retrans/CC purposes - let mut lost_pns = SmallVec::<[_; 8]>::new(); - - for (pn, packet) in self + for packet in self .sent_packets .iter_mut() // BTreeMap iterates in order of ascending PN - .take_while(|(&k, _)| k < largest_acked.unwrap_or(PacketNumber::MAX)) + .take_while(|p| p.pn < largest_acked.unwrap_or(PacketNumber::MAX)) { // Packets sent before now - loss_delay are deemed lost. if packet.time_sent + loss_delay <= now { qtrace!( "lost={}, time sent {:?} is before lost_delay {:?}", - pn, + packet.pn, packet.time_sent, loss_delay ); - } else if largest_acked >= Some(*pn + PACKET_THRESHOLD) { + } else if largest_acked >= Some(packet.pn + PACKET_THRESHOLD) { qtrace!( "lost={}, is >= {} from largest acked {:?}", - pn, + packet.pn, PACKET_THRESHOLD, largest_acked ); @@ -437,11 +353,9 @@ impl LossRecoverySpace { }; if packet.declare_lost(now) { - lost_pns.push(*pn); + lost_packets.push(packet.clone()); } } - - lost_packets.extend(lost_pns.iter().map(|pn| self.sent_packets[pn].clone())); } } @@ -672,13 +586,13 @@ impl LossRecovery { &mut self, primary_path: &PathRef, pn_space: PacketNumberSpace, - largest_acked: u64, + largest_acked: PacketNumber, acked_ranges: R, ack_delay: Duration, now: Instant, ) -> (Vec, Vec) where - R: IntoIterator>, + R: IntoIterator>, R::IntoIter: ExactSizeIterator, { qdebug!( @@ -1035,7 +949,7 @@ mod tests { use crate::{ cc::CongestionControlAlgorithm, cid::{ConnectionId, ConnectionIdEntry}, - packet::PacketType, + packet::{PacketNumber, PacketType}, path::{Path, PathRef}, rtt::RttEstimate, stats::{Stats, StatsCell}, @@ -1062,8 +976,8 @@ mod tests { pub fn on_ack_received( &mut self, pn_space: PacketNumberSpace, - largest_acked: u64, - acked_ranges: Vec>, + largest_acked: PacketNumber, + acked_ranges: Vec>, ack_delay: Duration, now: Instant, ) -> (Vec, Vec) { @@ -1232,8 +1146,8 @@ mod tests { ); } - fn add_sent(lrs: &mut LossRecoverySpace, packet_numbers: &[u64]) { - for &pn in packet_numbers { + fn add_sent(lrs: &mut LossRecoverySpace, max_pn: PacketNumber) { + for pn in 0..=max_pn { lrs.on_packet_sent(SentPacket::new( PacketType::Short, pn, @@ -1245,15 +1159,15 @@ mod tests { } } - fn match_acked(acked: &[SentPacket], expected: &[u64]) { - assert!(acked.iter().map(|p| &p.pn).eq(expected)); + fn match_acked(acked: &[SentPacket], expected: &[PacketNumber]) { + assert_eq!(acked.iter().map(|p| p.pn).collect::>(), expected); } #[test] fn remove_acked() { let mut lrs = LossRecoverySpace::new(PacketNumberSpace::ApplicationData); let mut stats = Stats::default(); - add_sent(&mut lrs, &[1, 2, 3, 4, 5, 6, 7, 8, 9, 10]); + add_sent(&mut lrs, 10); let (acked, _) = lrs.remove_acked(vec![], &mut stats); assert!(acked.is_empty()); let (acked, _) = lrs.remove_acked(vec![7..=8, 2..=4], &mut stats); @@ -1261,7 +1175,7 @@ mod tests { let (acked, _) = lrs.remove_acked(vec![8..=11], &mut stats); match_acked(&acked, &[10, 9]); let (acked, _) = lrs.remove_acked(vec![0..=2], &mut stats); - match_acked(&acked, &[1]); + match_acked(&acked, &[1, 0]); let (acked, _) = lrs.remove_acked(vec![5..=6], &mut stats); match_acked(&acked, &[6, 5]); } @@ -1597,7 +1511,7 @@ mod tests { lr.on_packet_sent(SentPacket::new( PacketType::Initial, - 1, + 0, now(), true, Vec::new(), diff --git a/neqo-transport/src/recovery/sent.rs b/neqo-transport/src/recovery/sent.rs new file mode 100644 index 0000000000..0da4bfdc0e --- /dev/null +++ b/neqo-transport/src/recovery/sent.rs @@ -0,0 +1,361 @@ +// Licensed under the Apache License, Version 2.0 or the MIT license +// , at your +// option. This file may not be copied, modified, or distributed +// except according to those terms. + +// A collection for sent packets. + +use std::{ + cmp::min, + convert::TryFrom, + ops::RangeInclusive, + time::{Duration, Instant}, +}; + +use crate::{ + packet::{PacketNumber, PacketType}, + recovery::RecoveryToken, +}; + +#[derive(Debug, Clone)] +pub struct SentPacket { + pub pt: PacketType, + pub pn: PacketNumber, + ack_eliciting: bool, + pub time_sent: Instant, + primary_path: bool, + pub tokens: Vec, + + time_declared_lost: Option, + /// After a PTO, this is true when the packet has been released. + pto: bool, + + pub size: usize, +} + +impl SentPacket { + pub fn new( + pt: PacketType, + pn: PacketNumber, + time_sent: Instant, + ack_eliciting: bool, + tokens: Vec, + size: usize, + ) -> Self { + Self { + pt, + pn, + time_sent, + ack_eliciting, + primary_path: true, + tokens, + time_declared_lost: None, + pto: false, + size, + } + } + + /// Returns `true` if the packet will elicit an ACK. + pub fn ack_eliciting(&self) -> bool { + self.ack_eliciting + } + + /// Returns `true` if the packet was sent on the primary path. + pub fn on_primary_path(&self) -> bool { + self.primary_path + } + + /// Clears the flag that had this packet on the primary path. + /// Used when migrating to clear out state. + pub fn clear_primary_path(&mut self) { + self.primary_path = false; + } + + /// Whether the packet has been declared lost. + pub fn lost(&self) -> bool { + self.time_declared_lost.is_some() + } + + /// Whether accounting for the loss or acknowledgement in the + /// congestion controller is pending. + /// Returns `true` if the packet counts as being "in flight", + /// and has not previously been declared lost. + /// Note that this should count packets that contain only ACK and PADDING, + /// but we don't send PADDING, so we don't track that. + pub fn cc_outstanding(&self) -> bool { + self.ack_eliciting() && self.on_primary_path() && !self.lost() + } + + /// Whether the packet should be tracked as in-flight. + pub fn cc_in_flight(&self) -> bool { + self.ack_eliciting() && self.on_primary_path() + } + + /// Declare the packet as lost. Returns `true` if this is the first time. + pub fn declare_lost(&mut self, now: Instant) -> bool { + if self.lost() { + false + } else { + self.time_declared_lost = Some(now); + true + } + } + + /// Ask whether this tracked packet has been declared lost for long enough + /// that it can be expired and no longer tracked. + pub fn expired(&self, now: Instant, expiration_period: Duration) -> bool { + self.time_declared_lost + .map_or(false, |loss_time| (loss_time + expiration_period) <= now) + } + + /// Whether the packet contents were cleared out after a PTO. + pub fn pto_fired(&self) -> bool { + self.pto + } + + /// On PTO, we need to get the recovery tokens so that we can ensure that + /// the frames we sent can be sent again in the PTO packet(s). Do that just once. + pub fn pto(&mut self) -> bool { + if self.pto || self.lost() { + false + } else { + self.pto = true; + true + } + } +} + +/// A collection for packets that we have sent that haven't been acknowledged. +#[derive(Debug, Default)] +pub struct SentPackets { + /// The collection. + packets: Vec>, + /// The packet number of the first item in the collection. + offset: PacketNumber, + /// The number of `Some` values in the packet. This is cached to keep things squeaky-fast. + len: usize, +} + +impl SentPackets { + pub fn len(&self) -> usize { + self.len + } + + pub fn track(&mut self, packet: SentPacket) { + if self.offset + PacketNumber::try_from(self.packets.len()).unwrap() != packet.pn { + assert_eq!( + self.len, 0, + "packet number skipping only supported for the first packet in a space" + ); + self.offset = packet.pn; + } + self.len += 1; + self.packets.push(Some(packet)); + } + + pub fn iter_mut(&mut self) -> impl Iterator { + self.packets.iter_mut().filter_map(Option::as_mut) + } + + /// Take values from a specified range of packet numbers. + /// Note that this will not remove values unless the iterator is consumed. + /// The values returned will be reversed, so that the most recent packet appears first. + /// This is because ACK frames arrive with ranges starting from the largest acknowledged + /// and we want to match that. + pub fn take_range( + &mut self, + r: RangeInclusive, + ) -> impl Iterator + '_ { + let start = usize::try_from((*r.start()).saturating_sub(self.offset)).unwrap(); + let end = min( + usize::try_from((*r.end() + 1).saturating_sub(self.offset)).unwrap(), + self.packets.len(), + ); + + let len_ref = &mut self.len; + self.packets[start..end] + .iter_mut() + .rev() + .filter_map(Option::take) + .inspect(move |_| { + // Decrement the length for any values that are taken. + *len_ref -= 1; + }) + } + + /// Empty out the packets, but keep the offset. + pub fn drain_all(&mut self) -> impl Iterator { + self.len = 0; + self.offset += u64::try_from(self.packets.len()).unwrap(); + std::mem::take(&mut self.packets).into_iter().flatten() + } + + /// See `LossRecoverySpace::remove_old_lost` for details on `now` and `cd`. + pub fn remove_expired( + &mut self, + now: Instant, + cd: Duration, + ) -> impl Iterator { + let mut count = 0; + // Find the first unexpired packet and only keep from that one onwards. + for (i, p) in self.packets.iter().enumerate() { + if p.as_ref().map_or(false, |p| !p.expired(now, cd)) { + let mut other = self.packets.split_off(i); + self.len -= count; + self.offset += u64::try_from(i).unwrap(); + std::mem::swap(&mut self.packets, &mut other); + return other.into_iter().flatten(); + } + // Count `Some` values that we are removing. + count += usize::from(p.is_some()); + } + + self.len = 0; + self.offset += u64::try_from(self.packets.len()).unwrap(); + std::mem::take(&mut self.packets).into_iter().flatten() + } +} + +#[cfg(test)] +mod tests { + use std::{ + cell::OnceCell, + convert::TryFrom, + time::{Duration, Instant}, + }; + + use super::{SentPacket, SentPackets}; + use crate::packet::{PacketNumber, PacketType}; + + const PACKET_GAP: Duration = Duration::from_secs(1); + fn start_time() -> Instant { + thread_local!(static STARTING_TIME: OnceCell = OnceCell::new()); + STARTING_TIME.with(|t| *t.get_or_init(Instant::now)) + } + + fn pkt(n: u32) -> SentPacket { + SentPacket::new( + PacketType::Short, + PacketNumber::from(n), + start_time() + (PACKET_GAP * n), + true, + Vec::new(), + 100, + ) + } + + fn pkts() -> SentPackets { + let mut pkts = SentPackets::default(); + pkts.track(pkt(0)); + pkts.track(pkt(1)); + pkts.track(pkt(2)); + assert_eq!(pkts.len(), 3); + pkts + } + + trait HasPacketNumber { + fn pn(&self) -> PacketNumber; + } + impl HasPacketNumber for SentPacket { + fn pn(&self) -> PacketNumber { + self.pn + } + } + impl HasPacketNumber for &'_ SentPacket { + fn pn(&self) -> PacketNumber { + self.pn + } + } + impl HasPacketNumber for &'_ mut SentPacket { + fn pn(&self) -> PacketNumber { + self.pn + } + } + + fn remove_one(pkts: &mut SentPackets, idx: PacketNumber) { + assert_eq!(pkts.len(), 3); + let mut it = pkts.take_range(idx..=idx); + assert_eq!(idx, it.next().unwrap().pn()); + assert!(it.next().is_none()); + std::mem::drop(it); + assert_eq!(pkts.len(), 2); + } + + fn assert_zero_and_two<'a, 'b: 'a>( + mut it: impl Iterator + 'a, + ) { + assert_eq!(it.next().unwrap().pn(), 0); + assert_eq!(it.next().unwrap().pn(), 2); + assert!(it.next().is_none()); + } + + #[test] + fn iterate_skipped() { + let mut pkts = pkts(); + for (i, p) in pkts.packets.iter().enumerate() { + assert_eq!(i, usize::try_from(p.as_ref().unwrap().pn).unwrap()); + } + remove_one(&mut pkts, 1); + + // Validate the merged result multiple ways. + assert_zero_and_two(pkts.iter_mut()); + + { + // Reverse the expectations here as this iterator reverses its output. + let mut it = pkts.take_range(0..=2); + assert_eq!(it.next().unwrap().pn(), 2); + assert_eq!(it.next().unwrap().pn(), 0); + assert!(it.next().is_none()); + }; + + // The None values are still there in this case, so offset is 0. + assert_eq!(pkts.offset, 0); + assert_eq!(pkts.packets.len(), 3); + assert_eq!(pkts.len(), 0); + } + + #[test] + fn drain() { + let mut pkts = pkts(); + remove_one(&mut pkts, 1); + + assert_zero_and_two(pkts.drain_all()); + assert_eq!(pkts.offset, 3); + assert_eq!(pkts.len(), 0); + } + + #[test] + fn remove_expired() { + let mut pkts = pkts(); + remove_one(&mut pkts, 0); + + for p in pkts.iter_mut() { + p.declare_lost(p.time_sent); // just to keep things simple. + } + + // Expire up to pkt(1). + let mut it = pkts.remove_expired(start_time() + PACKET_GAP, Duration::new(0, 0)); + assert_eq!(it.next().unwrap().pn(), 1); + assert!(it.next().is_none()); + std::mem::drop(it); + + assert_eq!(pkts.offset, 2); + assert_eq!(pkts.len(), 1); + } + + #[test] + #[should_panic(expected = "packet number skipping only supported for the first packet")] + fn skipped_not_ok() { + let mut pkts = pkts(); + pkts.track(pkt(4)); + } + + #[test] + fn first_skipped_ok() { + let mut pkts = SentPackets::default(); + pkts.track(pkt(4)); // This is fine. + assert_eq!(pkts.offset, 4); + assert_eq!(pkts.len(), 1); + } +} diff --git a/neqo-transport/src/recovery/token.rs b/neqo-transport/src/recovery/token.rs new file mode 100644 index 0000000000..93f84268cd --- /dev/null +++ b/neqo-transport/src/recovery/token.rs @@ -0,0 +1,63 @@ +// Licensed under the Apache License, Version 2.0 or the MIT license +// , at your +// option. This file may not be copied, modified, or distributed +// except according to those terms. + +use crate::{ + ackrate::AckRate, + cid::ConnectionIdEntry, + crypto::CryptoRecoveryToken, + quic_datagrams::DatagramTracking, + send_stream::SendStreamRecoveryToken, + stream_id::{StreamId, StreamType}, + tracking::AckToken, +}; + +#[derive(Debug, Clone)] +#[allow(clippy::module_name_repetitions)] +pub enum StreamRecoveryToken { + Stream(SendStreamRecoveryToken), + ResetStream { + stream_id: StreamId, + }, + StopSending { + stream_id: StreamId, + }, + + MaxData(u64), + DataBlocked(u64), + + MaxStreamData { + stream_id: StreamId, + max_data: u64, + }, + StreamDataBlocked { + stream_id: StreamId, + limit: u64, + }, + + MaxStreams { + stream_type: StreamType, + max_streams: u64, + }, + StreamsBlocked { + stream_type: StreamType, + limit: u64, + }, +} + +#[derive(Debug, Clone)] +#[allow(clippy::module_name_repetitions)] +pub enum RecoveryToken { + Stream(StreamRecoveryToken), + Ack(AckToken), + Crypto(CryptoRecoveryToken), + HandshakeDone, + KeepAlive, // Special PING. + NewToken(usize), + NewConnectionId(ConnectionIdEntry<[u8; 16]>), + RetireConnectionId(u64), + AckFrequency(AckRate), + Datagram(DatagramTracking), +} diff --git a/neqo-transport/src/sender.rs b/neqo-transport/src/sender.rs index 9a00dfc7a7..0f75f5543a 100644 --- a/neqo-transport/src/sender.rs +++ b/neqo-transport/src/sender.rs @@ -18,8 +18,8 @@ use neqo_common::qlog::NeqoQlog; use crate::{ cc::{ClassicCongestionControl, CongestionControl, CongestionControlAlgorithm, Cubic, NewReno}, pace::Pacer, + recovery::SentPacket, rtt::RttEstimate, - tracking::SentPacket, }; /// The number of packets we allow to burst from the pacer. diff --git a/neqo-transport/src/tracking.rs b/neqo-transport/src/tracking.rs index 012c895a18..81dda30154 100644 --- a/neqo-transport/src/tracking.rs +++ b/neqo-transport/src/tracking.rs @@ -133,114 +133,6 @@ impl std::fmt::Debug for PacketNumberSpaceSet { } } -#[derive(Debug, Clone)] -pub struct SentPacket { - pub pt: PacketType, - pub pn: PacketNumber, - ack_eliciting: bool, - pub time_sent: Instant, - primary_path: bool, - pub tokens: Vec, - - time_declared_lost: Option, - /// After a PTO, this is true when the packet has been released. - pto: bool, - - pub size: usize, -} - -impl SentPacket { - pub fn new( - pt: PacketType, - pn: PacketNumber, - time_sent: Instant, - ack_eliciting: bool, - tokens: Vec, - size: usize, - ) -> Self { - Self { - pt, - pn, - time_sent, - ack_eliciting, - primary_path: true, - tokens, - time_declared_lost: None, - pto: false, - size, - } - } - - /// Returns `true` if the packet will elicit an ACK. - pub fn ack_eliciting(&self) -> bool { - self.ack_eliciting - } - - /// Returns `true` if the packet was sent on the primary path. - pub fn on_primary_path(&self) -> bool { - self.primary_path - } - - /// Clears the flag that had this packet on the primary path. - /// Used when migrating to clear out state. - pub fn clear_primary_path(&mut self) { - self.primary_path = false; - } - - /// Whether the packet has been declared lost. - pub fn lost(&self) -> bool { - self.time_declared_lost.is_some() - } - - /// Whether accounting for the loss or acknowledgement in the - /// congestion controller is pending. - /// Returns `true` if the packet counts as being "in flight", - /// and has not previously been declared lost. - /// Note that this should count packets that contain only ACK and PADDING, - /// but we don't send PADDING, so we don't track that. - pub fn cc_outstanding(&self) -> bool { - self.ack_eliciting() && self.on_primary_path() && !self.lost() - } - - /// Whether the packet should be tracked as in-flight. - pub fn cc_in_flight(&self) -> bool { - self.ack_eliciting() && self.on_primary_path() - } - - /// Declare the packet as lost. Returns `true` if this is the first time. - pub fn declare_lost(&mut self, now: Instant) -> bool { - if self.lost() { - false - } else { - self.time_declared_lost = Some(now); - true - } - } - - /// Ask whether this tracked packet has been declared lost for long enough - /// that it can be expired and no longer tracked. - pub fn expired(&self, now: Instant, expiration_period: Duration) -> bool { - self.time_declared_lost - .map_or(false, |loss_time| (loss_time + expiration_period) <= now) - } - - /// Whether the packet contents were cleared out after a PTO. - pub fn pto_fired(&self) -> bool { - self.pto - } - - /// On PTO, we need to get the recovery tokens so that we can ensure that - /// the frames we sent can be sent again in the PTO packet(s). Do that just once. - pub fn pto(&mut self) -> bool { - if self.pto || self.lost() { - false - } else { - self.pto = true; - true - } - } -} - impl std::fmt::Display for PacketNumberSpace { fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { f.write_str(match self { From 5e24ead002c754ebcf6a1b32dbe52f75ce05e5e3 Mon Sep 17 00:00:00 2001 From: Martin Thomson Date: Fri, 16 Feb 2024 00:09:30 +1100 Subject: [PATCH 02/30] Try a bit harder --- neqo-transport/src/recovery/mod.rs | 21 +++++----- neqo-transport/src/recovery/sent.rs | 60 ++++++++++++++++++++--------- 2 files changed, 54 insertions(+), 27 deletions(-) diff --git a/neqo-transport/src/recovery/mod.rs b/neqo-transport/src/recovery/mod.rs index 7f362e4104..41f3995f07 100644 --- a/neqo-transport/src/recovery/mod.rs +++ b/neqo-transport/src/recovery/mod.rs @@ -174,7 +174,7 @@ impl LossRecoverySpace { .iter_mut() .filter_map(|sent| { if sent.pto() { - qtrace!("PTO: marking packet {} lost ", sent.pn); + qtrace!("PTO: marking packet {} lost ", sent.pn()); Some(&*sent) } else { None @@ -259,7 +259,7 @@ impl LossRecoverySpace { let mut eliciting = false; let mut acked = Vec::new(); for range in acked_ranges { - acked.extend(self.sent_packets.take_range(range)); + self.sent_packets.take_range(range, &mut acked); } for p in &acked { self.remove_packet(p); @@ -327,20 +327,20 @@ impl LossRecoverySpace { .sent_packets .iter_mut() // BTreeMap iterates in order of ascending PN - .take_while(|p| p.pn < largest_acked.unwrap_or(PacketNumber::MAX)) + .take_while(|p| p.pn() < largest_acked.unwrap_or(PacketNumber::MAX)) { // Packets sent before now - loss_delay are deemed lost. if packet.time_sent + loss_delay <= now { qtrace!( "lost={}, time sent {:?} is before lost_delay {:?}", - packet.pn, + packet.pn(), packet.time_sent, loss_delay ); - } else if largest_acked >= Some(packet.pn + PACKET_THRESHOLD) { + } else if largest_acked >= Some(packet.pn() + PACKET_THRESHOLD) { qtrace!( "lost={}, is >= {} from largest acked {:?}", - packet.pn, + packet.pn(), PACKET_THRESHOLD, largest_acked ); @@ -546,7 +546,7 @@ impl LossRecovery { pub fn on_packet_sent(&mut self, path: &PathRef, mut sent_packet: SentPacket) { let pn_space = PacketNumberSpace::from(sent_packet.pt); - qdebug!([self], "packet {}-{} sent", pn_space, sent_packet.pn); + qdebug!([self], "packet {}-{} sent", pn_space, sent_packet.pn()); if let Some(space) = self.spaces.get_mut(pn_space) { path.borrow_mut().packet_sent(&mut sent_packet); space.on_packet_sent(sent_packet); @@ -555,7 +555,7 @@ impl LossRecovery { [self], "ignoring {}-{} from dropped space", pn_space, - sent_packet.pn + sent_packet.pn() ); } } @@ -1160,7 +1160,10 @@ mod tests { } fn match_acked(acked: &[SentPacket], expected: &[PacketNumber]) { - assert_eq!(acked.iter().map(|p| p.pn).collect::>(), expected); + assert_eq!( + acked.iter().map(SentPacket::pn).collect::>(), + expected + ); } #[test] diff --git a/neqo-transport/src/recovery/sent.rs b/neqo-transport/src/recovery/sent.rs index 0da4bfdc0e..4c1d811b12 100644 --- a/neqo-transport/src/recovery/sent.rs +++ b/neqo-transport/src/recovery/sent.rs @@ -56,6 +56,11 @@ impl SentPacket { } } + /// The number of the packet. + pub fn pn(&self) -> PacketNumber { + self.pn + } + /// Returns `true` if the packet will elicit an ACK. pub fn ack_eliciting(&self) -> bool { self.ack_eliciting @@ -155,7 +160,7 @@ impl SentPackets { } pub fn iter_mut(&mut self) -> impl Iterator { - self.packets.iter_mut().filter_map(Option::as_mut) + self.packets.iter_mut().flatten() } /// Take values from a specified range of packet numbers. @@ -163,25 +168,40 @@ impl SentPackets { /// The values returned will be reversed, so that the most recent packet appears first. /// This is because ACK frames arrive with ranges starting from the largest acknowledged /// and we want to match that. - pub fn take_range( - &mut self, - r: RangeInclusive, - ) -> impl Iterator + '_ { + pub fn take_range(&mut self, r: RangeInclusive, store: &mut Vec) { let start = usize::try_from((*r.start()).saturating_sub(self.offset)).unwrap(); let end = min( usize::try_from((*r.end() + 1).saturating_sub(self.offset)).unwrap(), self.packets.len(), ); - let len_ref = &mut self.len; - self.packets[start..end] - .iter_mut() - .rev() - .filter_map(Option::take) - .inspect(move |_| { - // Decrement the length for any values that are taken. - *len_ref -= 1; - }) + let before = store.len(); + if self.packets[..start].iter().all(Option::is_none) { + // If there are extra empty slots, split those off too. + let extra = self.packets[end..] + .iter() + .take_while(|&p| p.is_none()) + .count(); + self.offset += u64::try_from(end + extra).unwrap(); + let mut other = self.packets.split_off(end + extra); + std::mem::swap(&mut self.packets, &mut other); + store.extend( + other + .into_iter() + .rev() + .skip(extra) + .take(end - start) + .flatten(), + ); + } else { + store.extend( + self.packets[start..end] + .iter_mut() + .rev() + .filter_map(Option::take), + ); + } + self.len -= store.len() - before; } /// Empty out the packets, but keep the offset. @@ -275,7 +295,9 @@ mod tests { fn remove_one(pkts: &mut SentPackets, idx: PacketNumber) { assert_eq!(pkts.len(), 3); - let mut it = pkts.take_range(idx..=idx); + let mut store = Vec::new(); + pkts.take_range(idx..=idx, &mut store); + let mut it = store.into_iter(); assert_eq!(idx, it.next().unwrap().pn()); assert!(it.next().is_none()); std::mem::drop(it); @@ -303,15 +325,17 @@ mod tests { { // Reverse the expectations here as this iterator reverses its output. - let mut it = pkts.take_range(0..=2); + let mut store = Vec::new(); + pkts.take_range(0..=2, &mut store); + let mut it = store.into_iter(); assert_eq!(it.next().unwrap().pn(), 2); assert_eq!(it.next().unwrap().pn(), 0); assert!(it.next().is_none()); }; // The None values are still there in this case, so offset is 0. - assert_eq!(pkts.offset, 0); - assert_eq!(pkts.packets.len(), 3); + assert_eq!(pkts.offset, 3); + assert_eq!(pkts.packets.len(), 0); assert_eq!(pkts.len(), 0); } From 4f91c07ac7aa6dc8a5cf12c6a7b6386333a634a3 Mon Sep 17 00:00:00 2001 From: Martin Thomson Date: Fri, 16 Feb 2024 09:05:50 +1100 Subject: [PATCH 03/30] VecDeque might be faster --- neqo-transport/src/recovery/sent.rs | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/neqo-transport/src/recovery/sent.rs b/neqo-transport/src/recovery/sent.rs index 4c1d811b12..320acf1c16 100644 --- a/neqo-transport/src/recovery/sent.rs +++ b/neqo-transport/src/recovery/sent.rs @@ -8,6 +8,7 @@ use std::{ cmp::min, + collections::VecDeque, convert::TryFrom, ops::RangeInclusive, time::{Duration, Instant}, @@ -135,7 +136,7 @@ impl SentPacket { #[derive(Debug, Default)] pub struct SentPackets { /// The collection. - packets: Vec>, + packets: VecDeque>, /// The packet number of the first item in the collection. offset: PacketNumber, /// The number of `Some` values in the packet. This is cached to keep things squeaky-fast. @@ -156,7 +157,7 @@ impl SentPackets { self.offset = packet.pn; } self.len += 1; - self.packets.push(Some(packet)); + self.packets.push_back(Some(packet)); } pub fn iter_mut(&mut self) -> impl Iterator { @@ -176,10 +177,11 @@ impl SentPackets { ); let before = store.len(); - if self.packets[..start].iter().all(Option::is_none) { + if self.packets.range(..start).all(Option::is_none) { // If there are extra empty slots, split those off too. - let extra = self.packets[end..] - .iter() + let extra = self + .packets + .range(end..) .take_while(|&p| p.is_none()) .count(); self.offset += u64::try_from(end + extra).unwrap(); @@ -195,8 +197,8 @@ impl SentPackets { ); } else { store.extend( - self.packets[start..end] - .iter_mut() + self.packets + .range_mut(start..end) .rev() .filter_map(Option::take), ); From e4e45be543640e29f10bde670ba77626d49324a4 Mon Sep 17 00:00:00 2001 From: Martin Thomson Date: Mon, 19 Feb 2024 17:55:33 +1100 Subject: [PATCH 04/30] Double down on making SentPacket fields private --- neqo-transport/src/cc/classic_cc.rs | 56 ++++++++++++------------- neqo-transport/src/cc/tests/new_reno.rs | 4 +- neqo-transport/src/connection/mod.rs | 6 +-- neqo-transport/src/path.rs | 4 +- neqo-transport/src/qlog.rs | 9 +++- neqo-transport/src/recovery/mod.rs | 18 ++++---- neqo-transport/src/recovery/sent.rs | 40 ++++++++++++++---- neqo-transport/src/sender.rs | 2 +- 8 files changed, 85 insertions(+), 54 deletions(-) diff --git a/neqo-transport/src/cc/classic_cc.rs b/neqo-transport/src/cc/classic_cc.rs index baf98cca46..01849a5643 100644 --- a/neqo-transport/src/cc/classic_cc.rs +++ b/neqo-transport/src/cc/classic_cc.rs @@ -168,8 +168,8 @@ impl CongestionControl for ClassicCongestionControl { qinfo!( "packet_acked this={:p}, pn={}, ps={}, ignored={}, lost={}, rtt_est={:?}", self, - pkt.pn, - pkt.size, + pkt.pn(), + pkt.len(), i32::from(!pkt.cc_outstanding()), i32::from(pkt.lost()), rtt_est, @@ -177,11 +177,11 @@ impl CongestionControl for ClassicCongestionControl { if !pkt.cc_outstanding() { continue; } - if pkt.pn < self.first_app_limited { + if pkt.pn() < self.first_app_limited { is_app_limited = false; } - assert!(self.bytes_in_flight >= pkt.size); - self.bytes_in_flight -= pkt.size; + assert!(self.bytes_in_flight >= pkt.len()); + self.bytes_in_flight -= pkt.len(); if !self.after_recovery_start(pkt) { // Do not increase congestion window for packets sent before @@ -194,7 +194,7 @@ impl CongestionControl for ClassicCongestionControl { qlog::metrics_updated(&mut self.qlog, &[QlogMetric::InRecovery(false)]); } - new_acked += pkt.size; + new_acked += pkt.len(); } if is_app_limited { @@ -269,11 +269,11 @@ impl CongestionControl for ClassicCongestionControl { qinfo!( "packet_lost this={:p}, pn={}, ps={}", self, - pkt.pn, - pkt.size + pkt.pn(), + pkt.len() ); - assert!(self.bytes_in_flight >= pkt.size); - self.bytes_in_flight -= pkt.size; + assert!(self.bytes_in_flight >= pkt.len()); + self.bytes_in_flight -= pkt.len(); } qlog::metrics_updated( &mut self.qlog, @@ -299,13 +299,13 @@ impl CongestionControl for ClassicCongestionControl { fn discard(&mut self, pkt: &SentPacket) { if pkt.cc_outstanding() { - assert!(self.bytes_in_flight >= pkt.size); - self.bytes_in_flight -= pkt.size; + assert!(self.bytes_in_flight >= pkt.len()); + self.bytes_in_flight -= pkt.len(); qlog::metrics_updated( &mut self.qlog, &[QlogMetric::BytesInFlight(self.bytes_in_flight)], ); - qtrace!([self], "Ignore pkt with size {}", pkt.size); + qtrace!([self], "Ignore pkt with size {}", pkt.len()); } } @@ -320,7 +320,7 @@ impl CongestionControl for ClassicCongestionControl { fn on_packet_sent(&mut self, pkt: &SentPacket) { // Record the recovery time and exit any transient state. if self.state.transient() { - self.recovery_start = Some(pkt.pn); + self.recovery_start = Some(pkt.pn()); self.state.update(); } @@ -332,15 +332,15 @@ impl CongestionControl for ClassicCongestionControl { // window. Assume that all in-flight packets up to this one are NOT app-limited. // However, subsequent packets might be app-limited. Set `first_app_limited` to the // next packet number. - self.first_app_limited = pkt.pn + 1; + self.first_app_limited = pkt.pn() + 1; } - self.bytes_in_flight += pkt.size; + self.bytes_in_flight += pkt.len(); qinfo!( "packet_sent this={:p}, pn={}, ps={}", self, - pkt.pn, - pkt.size + pkt.pn(), + pkt.len() ); qlog::metrics_updated( &mut self.qlog, @@ -439,20 +439,20 @@ impl ClassicCongestionControl { let cutoff = max(first_rtt_sample_time, prev_largest_acked_sent); for p in lost_packets .iter() - .skip_while(|p| Some(p.time_sent) < cutoff) + .skip_while(|p| Some(p.time_sent()) < cutoff) { - if p.pn != last_pn + 1 { + if p.pn() != last_pn + 1 { // Not a contiguous range of lost packets, start over. start = None; } - last_pn = p.pn; + last_pn = p.pn(); if !p.cc_in_flight() { // Not interesting, keep looking. continue; } if let Some(t) = start { let elapsed = p - .time_sent + .time_sent() .checked_duration_since(t) .expect("time is monotonic"); if elapsed > pc_period { @@ -467,7 +467,7 @@ impl ClassicCongestionControl { return true; } } else { - start = Some(p.time_sent); + start = Some(p.time_sent()); } } false @@ -481,7 +481,7 @@ impl ClassicCongestionControl { // state and update the variable `self.recovery_start`. Before the // first recovery, all packets were sent after the recovery event, // allowing to reduce the cwnd on congestion events. - !self.state.transient() && self.recovery_start.map_or(true, |pn| packet.pn >= pn) + !self.state.transient() && self.recovery_start.map_or(true, |pn| packet.pn() >= pn) } /// Handle a congestion event. @@ -916,12 +916,12 @@ mod tests { fn persistent_congestion_ack_eliciting() { let mut lost = make_lost(&[1, PERSISTENT_CONG_THRESH + 2]); lost[0] = SentPacket::new( - lost[0].pt, - lost[0].pn, - lost[0].time_sent, + lost[0].packet_type(), + lost[0].pn(), + lost[0].time_sent(), false, Vec::new(), - lost[0].size, + lost[0].len(), ); assert!(!persistent_congestion_by_pto( ClassicCongestionControl::new(NewReno::default()), diff --git a/neqo-transport/src/cc/tests/new_reno.rs b/neqo-transport/src/cc/tests/new_reno.rs index 0736f398fb..3f3fdd9e07 100644 --- a/neqo-transport/src/cc/tests/new_reno.rs +++ b/neqo-transport/src/cc/tests/new_reno.rs @@ -126,14 +126,14 @@ fn issue_876() { // and ack it. cwnd increases slightly cc.on_packets_acked(&sent_packets[6..], &RTT_ESTIMATE, time_now); - assert_eq!(cc.acked_bytes(), sent_packets[6].size); + assert_eq!(cc.acked_bytes(), sent_packets[6].len()); cwnd_is_halved(&cc); assert_eq!(cc.bytes_in_flight(), 5 * MAX_DATAGRAM_SIZE - 2); // Packet from before is lost. Should not hurt cwnd. cc.on_packets_lost(Some(time_now), None, PTO, &sent_packets[1..2]); assert!(!cc.recovery_packet()); - assert_eq!(cc.acked_bytes(), sent_packets[6].size); + assert_eq!(cc.acked_bytes(), sent_packets[6].len()); cwnd_is_halved(&cc); assert_eq!(cc.bytes_in_flight(), 4 * MAX_DATAGRAM_SIZE); } diff --git a/neqo-transport/src/connection/mod.rs b/neqo-transport/src/connection/mod.rs index 1e53447007..979c164800 100644 --- a/neqo-transport/src/connection/mod.rs +++ b/neqo-transport/src/connection/mod.rs @@ -2329,7 +2329,7 @@ impl Connection { packets.len(), mtu ); - initial.size += mtu - packets.len(); + initial.add_padding(mtu - packets.len()); packets.resize(mtu, 0); } self.loss_recovery.on_packet_sent(path, initial); @@ -2848,7 +2848,7 @@ impl Connection { /// to retransmit the frame as needed. fn handle_lost_packets(&mut self, lost_packets: &[SentPacket]) { for lost in lost_packets { - for token in &lost.tokens { + for token in lost.tokens() { qdebug!([self], "Lost: {:?}", token); match token { RecoveryToken::Ack(_) => {} @@ -2903,7 +2903,7 @@ impl Connection { now, ); for acked in acked_packets { - for token in &acked.tokens { + for token in acked.tokens() { match token { RecoveryToken::Stream(stream_token) => self.streams.acked(stream_token), RecoveryToken::Ack(at) => self.acks.acked(at), diff --git a/neqo-transport/src/path.rs b/neqo-transport/src/path.rs index 782fe896c0..06259e08c9 100644 --- a/neqo-transport/src/path.rs +++ b/neqo-transport/src/path.rs @@ -945,12 +945,12 @@ impl Path { qinfo!( [self], "discarding a packet without an RTT estimate; guessing RTT={:?}", - now - sent.time_sent + now - sent.time_sent() ); stats.rtt_init_guess = true; self.rtt.update( &mut self.qlog, - now - sent.time_sent, + now - sent.time_sent(), Duration::new(0, 0), false, now, diff --git a/neqo-transport/src/qlog.rs b/neqo-transport/src/qlog.rs index b59df0e37c..bb75dc3899 100644 --- a/neqo-transport/src/qlog.rs +++ b/neqo-transport/src/qlog.rs @@ -261,8 +261,13 @@ pub fn packet_dropped(qlog: &mut NeqoQlog, public_packet: &PublicPacket) { pub fn packets_lost(qlog: &mut NeqoQlog, pkts: &[SentPacket]) { qlog.add_event_with_stream(|stream| { for pkt in pkts { - let header = - PacketHeader::with_type(to_qlog_pkt_type(pkt.pt), Some(pkt.pn), None, None, None); + let header = PacketHeader::with_type( + to_qlog_pkt_type(pkt.packet_type()), + Some(pkt.pn()), + None, + None, + None, + ); let ev_data = EventData::PacketLost(PacketLost { header: Some(header), diff --git a/neqo-transport/src/recovery/mod.rs b/neqo-transport/src/recovery/mod.rs index 41f3995f07..2aec479b5f 100644 --- a/neqo-transport/src/recovery/mod.rs +++ b/neqo-transport/src/recovery/mod.rs @@ -207,14 +207,14 @@ impl LossRecoverySpace { pub fn on_packet_sent(&mut self, sent_packet: SentPacket) { if sent_packet.ack_eliciting() { - self.last_ack_eliciting = Some(sent_packet.time_sent); + self.last_ack_eliciting = Some(sent_packet.time_sent()); self.in_flight_outstanding += 1; } else if self.space != PacketNumberSpace::ApplicationData && self.last_ack_eliciting.is_none() { // For Initial and Handshake spaces, make sure that we have a PTO baseline // always. See `LossRecoverySpace::pto_base_time()` for details. - self.last_ack_eliciting = Some(sent_packet.time_sent); + self.last_ack_eliciting = Some(sent_packet.time_sent()); } self.sent_packets.track(sent_packet); } @@ -330,11 +330,11 @@ impl LossRecoverySpace { .take_while(|p| p.pn() < largest_acked.unwrap_or(PacketNumber::MAX)) { // Packets sent before now - loss_delay are deemed lost. - if packet.time_sent + loss_delay <= now { + if packet.time_sent() + loss_delay <= now { qtrace!( "lost={}, time sent {:?} is before lost_delay {:?}", packet.pn(), - packet.time_sent, + packet.time_sent(), loss_delay ); } else if largest_acked >= Some(packet.pn() + PACKET_THRESHOLD) { @@ -346,7 +346,7 @@ impl LossRecoverySpace { ); } else { if largest_acked.is_some() { - self.first_ooo_time = Some(packet.time_sent); + self.first_ooo_time = Some(packet.time_sent()); } // No more packets can be declared lost after this one. break; @@ -545,7 +545,7 @@ impl LossRecovery { } pub fn on_packet_sent(&mut self, path: &PathRef, mut sent_packet: SentPacket) { - let pn_space = PacketNumberSpace::from(sent_packet.pt); + let pn_space = PacketNumberSpace::from(sent_packet.packet_type()); qdebug!([self], "packet {}-{} sent", pn_space, sent_packet.pn()); if let Some(space) = self.spaces.get_mut(pn_space) { path.borrow_mut().packet_sent(&mut sent_packet); @@ -622,11 +622,11 @@ impl LossRecovery { // If the largest acknowledged is newly acked and any newly acked // packet was ack-eliciting, update the RTT. (-recovery 5.1) let largest_acked_pkt = acked_packets.first().expect("must be there"); - space.largest_acked_sent_time = Some(largest_acked_pkt.time_sent); + space.largest_acked_sent_time = Some(largest_acked_pkt.time_sent()); if any_ack_eliciting && largest_acked_pkt.on_primary_path() { self.rtt_sample( primary_path.borrow_mut().rtt_mut(), - largest_acked_pkt.time_sent, + largest_acked_pkt.time_sent(), now, ack_delay, ); @@ -1413,7 +1413,7 @@ mod tests { PacketType::Short, ] { let sent_pkt = SentPacket::new(*sp, 1, pn_time(3), true, Vec::new(), ON_SENT_SIZE); - let pn_space = PacketNumberSpace::from(sent_pkt.pt); + let pn_space = PacketNumberSpace::from(sent_pkt.packet_type()); lr.on_packet_sent(sent_pkt); lr.on_ack_received(pn_space, 1, vec![1..=1], Duration::from_secs(0), pn_time(3)); let mut lost = Vec::new(); diff --git a/neqo-transport/src/recovery/sent.rs b/neqo-transport/src/recovery/sent.rs index 320acf1c16..33d77b0ff7 100644 --- a/neqo-transport/src/recovery/sent.rs +++ b/neqo-transport/src/recovery/sent.rs @@ -21,18 +21,18 @@ use crate::{ #[derive(Debug, Clone)] pub struct SentPacket { - pub pt: PacketType, - pub pn: PacketNumber, + pt: PacketType, + pn: PacketNumber, ack_eliciting: bool, - pub time_sent: Instant, + time_sent: Instant, primary_path: bool, - pub tokens: Vec, + tokens: Vec, time_declared_lost: Option, /// After a PTO, this is true when the packet has been released. pto: bool, - pub size: usize, + len: usize, } impl SentPacket { @@ -42,7 +42,7 @@ impl SentPacket { time_sent: Instant, ack_eliciting: bool, tokens: Vec, - size: usize, + len: usize, ) -> Self { Self { pt, @@ -53,15 +53,25 @@ impl SentPacket { tokens, time_declared_lost: None, pto: false, - size, + len, } } + /// The type of this packet. + pub fn packet_type(&self) -> PacketType { + self.pt + } + /// The number of the packet. pub fn pn(&self) -> PacketNumber { self.pn } + /// The time that this packet was sent. + pub fn time_sent(&self) -> Instant { + self.time_sent + } + /// Returns `true` if the packet will elicit an ACK. pub fn ack_eliciting(&self) -> bool { self.ack_eliciting @@ -72,12 +82,28 @@ impl SentPacket { self.primary_path } + /// The length of the packet that was sent. + pub fn len(&self) -> usize { + self.len + } + + /// Access the recovery tokens that this holds. + pub fn tokens(&self) -> &[RecoveryToken] { + &self.tokens + } + /// Clears the flag that had this packet on the primary path. /// Used when migrating to clear out state. pub fn clear_primary_path(&mut self) { self.primary_path = false; } + /// For Initial packets, it is possible that the packet builder needs to amend the length. + pub fn add_padding(&mut self, padding: usize) { + debug_assert_eq!(self.pt, PacketType::Initial); + self.len += padding; + } + /// Whether the packet has been declared lost. pub fn lost(&self) -> bool { self.time_declared_lost.is_some() diff --git a/neqo-transport/src/sender.rs b/neqo-transport/src/sender.rs index 0f75f5543a..0ea18e5279 100644 --- a/neqo-transport/src/sender.rs +++ b/neqo-transport/src/sender.rs @@ -109,7 +109,7 @@ impl PacketSender { pub fn on_packet_sent(&mut self, pkt: &SentPacket, rtt: Duration) { self.pacer - .spend(pkt.time_sent, rtt, self.cc.cwnd(), pkt.size); + .spend(pkt.time_sent(), rtt, self.cc.cwnd(), pkt.len()); self.cc.on_packet_sent(pkt); } From cffa720e5fdb043019a3343f1faca772c3f7a275 Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Fri, 15 Mar 2024 05:19:55 +0200 Subject: [PATCH 05/30] ci: Do full mutants run twice a week (#1745) And when dispatched manually. --- .github/workflows/mutants.yml | 26 ++++++++++++++++++++------ 1 file changed, 20 insertions(+), 6 deletions(-) diff --git a/.github/workflows/mutants.yml b/.github/workflows/mutants.yml index 7903f3f5e4..a32068ce17 100644 --- a/.github/workflows/mutants.yml +++ b/.github/workflows/mutants.yml @@ -1,8 +1,12 @@ name: Find mutants on: + schedule: + - cron: '42 3 * * 2,5' # Runs at 03:42 UTC (m and h chosen arbitrarily) twice a week. + workflow_dispatch: pull_request: branches: ["main"] paths-ignore: ["*.md", "*.png", "*.svg", "LICENSE-*"] + merge_group: concurrency: group: ${{ github.workflow }}-${{ github.ref_name }} @@ -16,9 +20,6 @@ jobs: with: fetch-depth: 0 - - name: Relative diff - run: git diff origin/${{ github.base_ref }}.. > pr.diff - - name: Install dependencies env: DEBIAN_FRONTEND: noninteractive @@ -34,13 +35,26 @@ jobs: with: version: stable - - name: Mutants + - name: Find incremental mutants + if: github.event_name == 'pull_request' || github.event_name == 'merge_group' run: | - # Don't fail the build if mutants fail, for now. + git diff origin/${{ github.base_ref }}.. > pr.diff set -o pipefail cargo mutants --test-tool=nextest --no-shuffle -j 2 -vV --in-diff pr.diff | tee results.txt || true + echo 'TITLE="Incremental Mutants"' >> "$GITHUB_ENV" + + - name: Find mutants + if: github.event_name == 'schedule' || github.event_name == 'workflow_dispatch' + run: | + set -o pipefail + cargo mutants --test-tool=nextest -vV --in-place | tee results.txt || true + echo 'TITLE="All Mutants"' >> "$GITHUB_ENV" + + - name: Post step summary + if: always() + run: | { - echo "### Mutants" + echo "### $TITLE" echo "See https://mutants.rs/using-results.html for more information." echo '```' cat results.txt From f2733e4e89dc20294054d4840d51ed9cd9c8889e Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Fri, 15 Mar 2024 05:23:12 +0200 Subject: [PATCH 06/30] chore: Add some things, remove some things (#1746) --- .gitignore | 13 +++++-------- 1 file changed, 5 insertions(+), 8 deletions(-) diff --git a/.gitignore b/.gitignore index 41867fa4e8..542ed5205d 100644 --- a/.gitignore +++ b/.gitignore @@ -1,10 +1,7 @@ -/target/ -**/*.rs.bk -Cargo.lock -/db +.DS_Store +*.qlog *~ /.vscode/ -.idea -*.qlog -*.swp -/qns/.last-update-* +/lcov.info +/target/ +Cargo.lock From 177385e02466115755a815edb334bbe5fee144a4 Mon Sep 17 00:00:00 2001 From: Max Inden Date: Fri, 15 Mar 2024 13:21:32 +0100 Subject: [PATCH 07/30] refactor(udp): move udp mod from neqo-common to neqo-bin (#1736) The `udp` module is only used in the `neqo_bin` crate, more specifically by the Neqo client and server implementation. This commit moves the `udp` module to `neqo-bin`. Co-authored-by: Lars Eggert --- neqo-bin/Cargo.toml | 3 ++- neqo-bin/src/bin/client/main.rs | 3 ++- neqo-bin/src/bin/server/main.rs | 3 ++- neqo-bin/src/lib.rs | 2 ++ {neqo-common => neqo-bin}/src/udp.rs | 8 ++++---- neqo-common/Cargo.toml | 3 --- neqo-common/src/datagram.rs | 12 ++++++------ neqo-common/src/lib.rs | 2 -- 8 files changed, 18 insertions(+), 18 deletions(-) rename {neqo-common => neqo-bin}/src/udp.rs (98%) diff --git a/neqo-bin/Cargo.toml b/neqo-bin/Cargo.toml index 2beafa7e42..d36d2ecdca 100644 --- a/neqo-bin/Cargo.toml +++ b/neqo-bin/Cargo.toml @@ -28,12 +28,13 @@ clap = { version = "4.4", default-features = false, features = ["std", "color", futures = { version = "0.3", default-features = false, features = ["alloc"] } hex = { version = "0.4", default-features = false, features = ["std"] } log = { version = "0.4", default-features = false } -neqo-common = { path = "./../neqo-common", features = ["udp"] } +neqo-common = { path = "./../neqo-common" } neqo-crypto = { path = "./../neqo-crypto" } neqo-http3 = { path = "./../neqo-http3" } neqo-qpack = { path = "./../neqo-qpack" } neqo-transport = { path = "./../neqo-transport" } qlog = { version = "0.12", default-features = false } +quinn-udp = { git = "https://github.com/quinn-rs/quinn/", rev = "a947962131aba8a6521253d03cc948b20098a2d6" } regex = { version = "1.9", default-features = false, features = ["unicode-perl"] } tokio = { version = "1", default-features = false, features = ["net", "time", "macros", "rt", "rt-multi-thread"] } url = { version = "2.5", default-features = false } diff --git a/neqo-bin/src/bin/client/main.rs b/neqo-bin/src/bin/client/main.rs index 4710f8b222..d472dfb2bc 100644 --- a/neqo-bin/src/bin/client/main.rs +++ b/neqo-bin/src/bin/client/main.rs @@ -21,7 +21,8 @@ use futures::{ future::{select, Either}, FutureExt, TryFutureExt, }; -use neqo_common::{self as common, qdebug, qinfo, qlog::NeqoQlog, udp, Datagram, Role}; +use neqo_bin::udp; +use neqo_common::{self as common, qdebug, qinfo, qlog::NeqoQlog, Datagram, Role}; use neqo_crypto::{ constants::{TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256}, init, Cipher, ResumptionToken, diff --git a/neqo-bin/src/bin/server/main.rs b/neqo-bin/src/bin/server/main.rs index da8de3831c..f694cf98c1 100644 --- a/neqo-bin/src/bin/server/main.rs +++ b/neqo-bin/src/bin/server/main.rs @@ -24,7 +24,8 @@ use futures::{ future::{select, select_all, Either}, FutureExt, }; -use neqo_common::{hex, qinfo, qwarn, udp, Datagram, Header}; +use neqo_bin::udp; +use neqo_common::{hex, qinfo, qwarn, Datagram, Header}; use neqo_crypto::{ constants::{TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256}, generate_ech_keys, init_db, random, AntiReplay, Cipher, diff --git a/neqo-bin/src/lib.rs b/neqo-bin/src/lib.rs index 4fe47d5cbf..8a7ff69b69 100644 --- a/neqo-bin/src/lib.rs +++ b/neqo-bin/src/lib.rs @@ -17,6 +17,8 @@ use neqo_transport::{ Version, }; +pub mod udp; + #[derive(Debug, Parser)] pub struct SharedArgs { #[arg(short = 'a', long, default_value = "h3")] diff --git a/neqo-common/src/udp.rs b/neqo-bin/src/udp.rs similarity index 98% rename from neqo-common/src/udp.rs rename to neqo-bin/src/udp.rs index c27b0632ff..632a1293d7 100644 --- a/neqo-common/src/udp.rs +++ b/neqo-bin/src/udp.rs @@ -13,11 +13,10 @@ use std::{ slice, }; +use neqo_common::{Datagram, IpTos}; use quinn_udp::{EcnCodepoint, RecvMeta, Transmit, UdpSocketState}; use tokio::io::Interest; -use crate::{Datagram, IpTos}; - /// Socket receive buffer size. /// /// Allows reading multiple datagrams in a single [`Socket::recv`] call. @@ -61,7 +60,7 @@ impl Socket { let transmit = Transmit { destination: d.destination(), ecn: EcnCodepoint::from_bits(Into::::into(d.tos())), - contents: d.into_data().into(), + contents: Vec::from(d).into(), segment_size: None, src_ip: None, }; @@ -129,8 +128,9 @@ impl Socket { #[cfg(test)] mod tests { + use neqo_common::{IpTosDscp, IpTosEcn}; + use super::*; - use crate::{IpTosDscp, IpTosEcn}; #[tokio::test] async fn datagram_tos() -> Result<(), io::Error> { diff --git a/neqo-common/Cargo.toml b/neqo-common/Cargo.toml index dae8362bfd..89eaa53890 100644 --- a/neqo-common/Cargo.toml +++ b/neqo-common/Cargo.toml @@ -18,16 +18,13 @@ enum-map = { version = "2.7", default-features = false } env_logger = { version = "0.10", default-features = false } log = { version = "0.4", default-features = false } qlog = { version = "0.12", default-features = false } -quinn-udp = { git = "https://github.com/quinn-rs/quinn/", rev = "a947962131aba8a6521253d03cc948b20098a2d6", optional = true } time = { version = "0.3", default-features = false, features = ["formatting"] } -tokio = { version = "1", default-features = false, features = ["net", "time", "macros", "rt", "rt-multi-thread"], optional = true } [dev-dependencies] test-fixture = { path = "../test-fixture" } [features] ci = [] -udp = ["dep:quinn-udp", "dep:tokio"] [target."cfg(windows)".dependencies.winapi] version = "0.3" diff --git a/neqo-common/src/datagram.rs b/neqo-common/src/datagram.rs index 04ba1a45a1..9cebb64ea5 100644 --- a/neqo-common/src/datagram.rs +++ b/neqo-common/src/datagram.rs @@ -53,12 +53,6 @@ impl Datagram { pub fn ttl(&self) -> Option { self.ttl } - - #[cfg(feature = "udp")] - #[must_use] - pub(crate) fn into_data(self) -> Vec { - self.d - } } impl Deref for Datagram { @@ -83,6 +77,12 @@ impl std::fmt::Debug for Datagram { } } +impl From for Vec { + fn from(datagram: Datagram) -> Self { + datagram.d + } +} + #[cfg(test)] use test_fixture::datagram; diff --git a/neqo-common/src/lib.rs b/neqo-common/src/lib.rs index fe88097983..e988c6071d 100644 --- a/neqo-common/src/lib.rs +++ b/neqo-common/src/lib.rs @@ -16,8 +16,6 @@ pub mod log; pub mod qlog; pub mod timer; pub mod tos; -#[cfg(feature = "udp")] -pub mod udp; use std::fmt::Write; From d2c7cbb49319052e48ea4f28f76ac1a06df3746c Mon Sep 17 00:00:00 2001 From: Max Inden Date: Fri, 15 Mar 2024 22:19:40 +0100 Subject: [PATCH 08/30] refactor(udp): remove useless Socket::send return value (#1749) `Socket::send` returns the number of `Datagram`s sent. Given that it only accepts a single `Datagram` to be send, this return value is at best useless and in the worst case confusing. --- neqo-bin/src/udp.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/neqo-bin/src/udp.rs b/neqo-bin/src/udp.rs index 632a1293d7..f4ede0b5c2 100644 --- a/neqo-bin/src/udp.rs +++ b/neqo-bin/src/udp.rs @@ -56,7 +56,7 @@ impl Socket { } /// Send the UDP datagram on the specified socket. - pub fn send(&self, d: Datagram) -> io::Result { + pub fn send(&self, d: Datagram) -> io::Result<()> { let transmit = Transmit { destination: d.destination(), ecn: EcnCodepoint::from_bits(Into::::into(d.tos())), @@ -72,7 +72,7 @@ impl Socket { assert_eq!(n, 1, "only passed one slice"); - Ok(n) + Ok(()) } /// Receive a UDP datagram on the specified socket. From aed423eafc5b8cb8382c694e73a64fb8722611ac Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Sat, 16 Mar 2024 07:36:30 +1000 Subject: [PATCH 09/30] ci: Don't trigger on `merge_group` --- .github/workflows/mutants.yml | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/.github/workflows/mutants.yml b/.github/workflows/mutants.yml index a32068ce17..90001bd8b7 100644 --- a/.github/workflows/mutants.yml +++ b/.github/workflows/mutants.yml @@ -6,7 +6,6 @@ on: pull_request: branches: ["main"] paths-ignore: ["*.md", "*.png", "*.svg", "LICENSE-*"] - merge_group: concurrency: group: ${{ github.workflow }}-${{ github.ref_name }} @@ -36,7 +35,7 @@ jobs: version: stable - name: Find incremental mutants - if: github.event_name == 'pull_request' || github.event_name == 'merge_group' + if: github.event_name == 'pull_request' run: | git diff origin/${{ github.base_ref }}.. > pr.diff set -o pipefail From fe2241eaf1215a1537c4b66d6eea12f94121eef6 Mon Sep 17 00:00:00 2001 From: Max Inden Date: Fri, 15 Mar 2024 22:23:37 +0100 Subject: [PATCH 10/30] refactor(transport/tests): remove unused IdEntry (#1748) --- neqo-transport/src/connection/tests/stream.rs | 6 ------ 1 file changed, 6 deletions(-) diff --git a/neqo-transport/src/connection/tests/stream.rs b/neqo-transport/src/connection/tests/stream.rs index f469866d50..66d3bf32f3 100644 --- a/neqo-transport/src/connection/tests/stream.rs +++ b/neqo-transport/src/connection/tests/stream.rs @@ -116,12 +116,6 @@ fn transfer() { assert!(fin3); } -#[derive(PartialEq, Eq, PartialOrd, Ord)] -struct IdEntry { - sendorder: StreamOrder, - stream_id: StreamId, -} - // tests stream sendorder priorization fn sendorder_test(order_of_sendorder: &[Option]) { let mut client = default_client(); From a68dd1c2a1aead9117b808dc22329ca928d86cd8 Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Sat, 16 Mar 2024 05:57:12 +0200 Subject: [PATCH 11/30] test: Make `criterion` calculate transfer benchmark throughputs (#1738) * test: Make `criterion` calculate transfer benchmark throughputs Like: ``` transfer/Run multiple transfers with varying seeds time: [213.61 ms 224.95 ms 235.29 ms] thrpt: [17.000 MiB/s 17.782 MiB/s 18.726 MiB/s] change: time: [-17.204% -6.9690% +1.8324%] (p = 0.21 > 0.05) thrpt: [-1.7994% +7.4910% +20.778%] No change in performance detected. Found 5 outliers among 100 measurements (5.00%) 5 (5.00%) low mild transfer/Run multiple transfers with the same seed time: [175.41 ms 188.40 ms 201.32 ms] thrpt: [19.869 MiB/s 21.231 MiB/s 22.803 MiB/s] change: time: [-5.9393% +5.5417% +18.399%] (p = 0.35 > 0.05) thrpt: [-15.540% -5.2507% +6.3144%] No change in performance detected. Found 14 outliers among 100 measurements (14.00%) 8 (8.00%) low mild 5 (5.00%) high mild 1 (1.00%) high severe ``` * This doesn't actually run `cargo bench`, it runs `cargo flamegraph` --- .github/workflows/bench.yml | 7 ------- neqo-transport/benches/transfer.rs | 7 +++++-- 2 files changed, 5 insertions(+), 9 deletions(-) diff --git a/.github/workflows/bench.yml b/.github/workflows/bench.yml index 72b835f843..81ef297a9e 100644 --- a/.github/workflows/bench.yml +++ b/.github/workflows/bench.yml @@ -62,16 +62,9 @@ jobs: # Work around https://github.com/flamegraph-rs/flamegraph/issues/248 by passing explicit perf arguments. - name: Profile cargo bench transfer run: | - # This re-runs part of the previous step, and would hence overwrite part of the criterion results. - # Avoid that by shuffling the directories around so this run uses its own results directory. - mv target/criterion target/criterion-bench - mv target/criterion-transfer-profile target/criterion || true taskset -c 0 nice -n -20 \ cargo "+$TOOLCHAIN" flamegraph -v -c "$PERF_CMD" --features bench --bench transfer -- \ --bench --exact "Run multiple transfers with varying seeds" --noplot - # And now restore the directories. - mv target/criterion target/criterion-transfer-profile - mv target/criterion-bench target/criterion - name: Profile client/server transfer run: | diff --git a/neqo-transport/benches/transfer.rs b/neqo-transport/benches/transfer.rs index 444f738f9c..b13075a4ff 100644 --- a/neqo-transport/benches/transfer.rs +++ b/neqo-transport/benches/transfer.rs @@ -6,7 +6,7 @@ use std::time::Duration; -use criterion::{criterion_group, criterion_main, BatchSize::SmallInput, Criterion}; +use criterion::{criterion_group, criterion_main, BatchSize::SmallInput, Criterion, Throughput}; use test_fixture::{ boxed, sim::{ @@ -21,7 +21,9 @@ const JITTER: Duration = Duration::from_millis(10); const TRANSFER_AMOUNT: usize = 1 << 22; // 4Mbyte fn benchmark_transfer(c: &mut Criterion, label: &str, seed: Option>) { - c.bench_function(label, |b| { + let mut group = c.benchmark_group("transfer"); + group.throughput(Throughput::Bytes(u64::try_from(TRANSFER_AMOUNT).unwrap())); + group.bench_function(label, |b| { b.iter_batched( || { let nodes = boxed![ @@ -44,6 +46,7 @@ fn benchmark_transfer(c: &mut Criterion, label: &str, seed: Option Date: Sat, 16 Mar 2024 14:17:48 +1000 Subject: [PATCH 12/30] Strip ANSI escapes from Markdown output --- .github/workflows/mutants.yml | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/.github/workflows/mutants.yml b/.github/workflows/mutants.yml index 90001bd8b7..cd28cfe604 100644 --- a/.github/workflows/mutants.yml +++ b/.github/workflows/mutants.yml @@ -12,7 +12,7 @@ concurrency: cancel-in-progress: true jobs: - incremental-mutants: + mutants: runs-on: ubuntu-latest steps: - uses: actions/checkout@v4 @@ -40,14 +40,14 @@ jobs: git diff origin/${{ github.base_ref }}.. > pr.diff set -o pipefail cargo mutants --test-tool=nextest --no-shuffle -j 2 -vV --in-diff pr.diff | tee results.txt || true - echo 'TITLE="Incremental Mutants"' >> "$GITHUB_ENV" + echo 'TITLE=Incremental Mutants' >> "$GITHUB_ENV" - name: Find mutants if: github.event_name == 'schedule' || github.event_name == 'workflow_dispatch' run: | set -o pipefail cargo mutants --test-tool=nextest -vV --in-place | tee results.txt || true - echo 'TITLE="All Mutants"' >> "$GITHUB_ENV" + echo 'TITLE=All Mutants' >> "$GITHUB_ENV" - name: Post step summary if: always() @@ -56,7 +56,7 @@ jobs: echo "### $TITLE" echo "See https://mutants.rs/using-results.html for more information." echo '```' - cat results.txt + cat results.txt | sed 's/[^[:print:]]//g' echo '```' } > "$GITHUB_STEP_SUMMARY" From 83e673335875d426faed91fc6e095ef521565f1d Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Sat, 16 Mar 2024 14:19:01 +1000 Subject: [PATCH 13/30] Fix `actionlint` issue --- .github/workflows/mutants.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/mutants.yml b/.github/workflows/mutants.yml index cd28cfe604..e11eb96f21 100644 --- a/.github/workflows/mutants.yml +++ b/.github/workflows/mutants.yml @@ -56,7 +56,7 @@ jobs: echo "### $TITLE" echo "See https://mutants.rs/using-results.html for more information." echo '```' - cat results.txt | sed 's/[^[:print:]]//g' + sed 's/[^[:print:]]//g' results.txt echo '```' } > "$GITHUB_STEP_SUMMARY" From 9ff375129b9a84b9589a5dbecc87117e0c92337b Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Sat, 16 Mar 2024 06:44:49 +0200 Subject: [PATCH 14/30] build: Enable "fat" LTO for release builds (#1751) Because that's what Firefox does: https://searchfox.org/mozilla-central/source/config/makefiles/rust.mk#95 --- Cargo.toml | 3 +++ 1 file changed, 3 insertions(+) diff --git a/Cargo.toml b/Cargo.toml index 35916da5b1..e5bec00796 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -25,6 +25,9 @@ rust-version = "1.74.0" [workspace.lints.clippy] pedantic = { level = "warn", priority = -1 } +[profile.release] +lto = "fat" + [profile.bench] # Inherits from the "release" profile, so just provide overrides here: # https://doc.rust-lang.org/cargo/reference/profiles.html#release From ec4ec8e3019a55f6cf1bb11709a76b40205c5b0e Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Sat, 16 Mar 2024 21:35:06 +1000 Subject: [PATCH 15/30] Properly strip ANSI sequences from Markdown --- .github/workflows/mutants.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/mutants.yml b/.github/workflows/mutants.yml index e11eb96f21..4db2e4b925 100644 --- a/.github/workflows/mutants.yml +++ b/.github/workflows/mutants.yml @@ -56,7 +56,7 @@ jobs: echo "### $TITLE" echo "See https://mutants.rs/using-results.html for more information." echo '```' - sed 's/[^[:print:]]//g' results.txt + sed 's/\x1b\[[0-9;]*[mGKHF]//g' results.txt echo '```' } > "$GITHUB_STEP_SUMMARY" From ef5caeb46b510f89cd6f8668a3bf31a2d597cbd2 Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Sun, 17 Mar 2024 02:56:20 +0200 Subject: [PATCH 16/30] ci: Ignore coverage in `neqo-bin` (#1754) Should have been part of #1724 --- .codecov.yml | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/.codecov.yml b/.codecov.yml index 12facb68da..3ecf204940 100644 --- a/.codecov.yml +++ b/.codecov.yml @@ -1,8 +1,6 @@ -# neqo has no test coverage for its example client, server and interop test +# neqo has no test coverage for its example client and server ignore: - - "neqo-client" - - "neqo-interop" - - "neqo-server" + - "neqo-bin" # Do not notify until at least three results have been uploaded from the CI pipeline. # (This corresponds to the three main platforms we support: Linux, macOS, and Windows.) From 29fdbc0f6990760e71dd13bd33c0ee81c4c81040 Mon Sep 17 00:00:00 2001 From: Max Inden Date: Sun, 17 Mar 2024 21:47:38 +0100 Subject: [PATCH 17/30] feat(bin/client): use BufWriter when writing to file (#1756) * feat: Use `std::io::BufWriter` with a 64KB buffer for dumping data Let's see if this makes things faster. * Flush `BufWriter` on FIN * Update neqo-bin/src/bin/client/http3.rs Co-authored-by: Max Inden Signed-off-by: Lars Eggert * Fix * Also for h09 * Move BufWriter construction into get_output_file --------- Signed-off-by: Lars Eggert Co-authored-by: Lars Eggert --- neqo-bin/src/bin/client/http09.rs | 13 +++++++------ neqo-bin/src/bin/client/http3.rs | 12 ++++++++---- neqo-bin/src/bin/client/main.rs | 8 +++++--- 3 files changed, 20 insertions(+), 13 deletions(-) diff --git a/neqo-bin/src/bin/client/http09.rs b/neqo-bin/src/bin/client/http09.rs index a7dc2c21c7..6d9a26fec2 100644 --- a/neqo-bin/src/bin/client/http09.rs +++ b/neqo-bin/src/bin/client/http09.rs @@ -10,7 +10,7 @@ use std::{ cell::RefCell, collections::{HashMap, VecDeque}, fs::File, - io::Write, + io::{BufWriter, Write}, net::SocketAddr, path::PathBuf, rc::Rc, @@ -29,7 +29,7 @@ use super::{get_output_file, Args, KeyUpdateState, Res}; use crate::qlog_new; pub struct Handler<'a> { - streams: HashMap>, + streams: HashMap>>, url_queue: VecDeque, all_paths: Vec, args: &'a Args, @@ -219,7 +219,7 @@ impl<'b> Handler<'b> { client: &mut Connection, stream_id: StreamId, output_read_data: bool, - maybe_out_file: &mut Option, + maybe_out_file: &mut Option>, ) -> Res { let mut data = vec![0; 4096]; loop { @@ -246,8 +246,7 @@ impl<'b> Handler<'b> { } fn read(&mut self, client: &mut Connection, stream_id: StreamId) -> Res<()> { - let mut maybe_maybe_out_file = self.streams.get_mut(&stream_id); - match &mut maybe_maybe_out_file { + match self.streams.get_mut(&stream_id) { None => { println!("Data on unexpected stream: {stream_id}"); return Ok(()); @@ -261,7 +260,9 @@ impl<'b> Handler<'b> { )?; if fin_recvd { - if maybe_out_file.is_none() { + if let Some(mut out_file) = maybe_out_file.take() { + out_file.flush()?; + } else { println!(""); } self.streams.remove(&stream_id); diff --git a/neqo-bin/src/bin/client/http3.rs b/neqo-bin/src/bin/client/http3.rs index 754de9cb16..07cc0e4cde 100644 --- a/neqo-bin/src/bin/client/http3.rs +++ b/neqo-bin/src/bin/client/http3.rs @@ -11,7 +11,7 @@ use std::{ collections::{HashMap, VecDeque}, fmt::Display, fs::File, - io::Write, + io::{BufWriter, Write}, net::SocketAddr, path::PathBuf, rc::Rc, @@ -269,7 +269,7 @@ impl StreamHandlerType { } struct DownloadStreamHandler { - out_file: Option, + out_file: Option>, } impl StreamHandler for DownloadStreamHandler { @@ -300,8 +300,12 @@ impl StreamHandler for DownloadStreamHandler { println!("READ[{}]: 0x{}", stream_id, hex(&data)); } - if fin && self.out_file.is_none() { - println!(""); + if fin { + if let Some(mut out_file) = self.out_file.take() { + out_file.flush()?; + } else { + println!(""); + } } Ok(true) diff --git a/neqo-bin/src/bin/client/main.rs b/neqo-bin/src/bin/client/main.rs index d472dfb2bc..7b1a5928a6 100644 --- a/neqo-bin/src/bin/client/main.rs +++ b/neqo-bin/src/bin/client/main.rs @@ -8,7 +8,7 @@ use std::{ collections::{HashMap, VecDeque}, fmt::{self, Display}, fs::{create_dir_all, File, OpenOptions}, - io, + io::{self, BufWriter}, net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr, ToSocketAddrs}, path::PathBuf, pin::Pin, @@ -36,6 +36,8 @@ use url::{Origin, Url}; mod http09; mod http3; +const BUFWRITER_BUFFER_SIZE: usize = 64 * 1024; + #[derive(Debug)] pub enum ClientError { ArgumentError(&'static str), @@ -252,7 +254,7 @@ fn get_output_file( url: &Url, output_dir: &Option, all_paths: &mut Vec, -) -> Option { +) -> Option> { if let Some(ref dir) = output_dir { let mut out_path = dir.clone(); @@ -284,7 +286,7 @@ fn get_output_file( .ok()?; all_paths.push(out_path); - Some(f) + Some(BufWriter::with_capacity(BUFWRITER_BUFFER_SIZE, f)) } else { None } From 32ef2c3cb2f0f13c6b46222d98c3316a69d7b411 Mon Sep 17 00:00:00 2001 From: Max Inden Date: Sun, 17 Mar 2024 21:48:18 +0100 Subject: [PATCH 18/30] fix(bin): enable pacing on client & server by default (#1753) * fix(bin): enable pacing on server by default Before https://github.com/mozilla/neqo/pull/1724 `neqo-server` would always run with `ConnectionParameters::pacing` `true`. `neqo-client` would provide a command line flag `--pacing` which defaulted to `false`. https://github.com/mozilla/neqo/pull/1724 consolidated the `QuicParameters` `struct` from `neqo-client` and `neqo-server`. Since both `neqo-client` and `neqo-server` default to `pacing` `false`. This commit restores the pre-#1724 behavior, i.e. `neqo-server` defaulting to `pacing=true` and `neqo-client` defaulting to `pacing=false`. (Note that you will have to provide a value to `--pacing` from now on. I.e. `--pacing=true` or `--pacing=false` instead of just `--pacing`.) * fix(bin): enable pacing by default and add optional --no-pacing Before https://github.com/mozilla/neqo/pull/1724 `neqo-server` would always run with `ConnectionParameters::pacing` `true`. `neqo-client` would provide a command line flag `--pacing` which defaulted to `false`. https://github.com/mozilla/neqo/pull/1724 consolidated the `QuicParameters` `struct` from `neqo-client` and `neqo-server`. Since both `neqo-client` and `neqo-server` default to `pacing` `false`. This commit replaces the `--pacing` flag with `--no-pacing`. Pacing is enabled by default on both `neqo-server` and `neqo-client`. * Update test/upload_test.sh * Update comment --- neqo-bin/src/lib.rs | 8 ++++---- test/upload_test.sh | 7 ++++--- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/neqo-bin/src/lib.rs b/neqo-bin/src/lib.rs index 8a7ff69b69..b7bc158245 100644 --- a/neqo-bin/src/lib.rs +++ b/neqo-bin/src/lib.rs @@ -89,9 +89,9 @@ pub struct QuicParameters { /// The congestion controller to use. pub congestion_control: CongestionControlAlgorithm, - #[arg(long = "pacing")] - /// Whether pacing is enabled. - pub pacing: bool, + #[arg(long = "no-pacing")] + /// Whether to disable pacing. + pub no_pacing: bool, #[arg(name = "preferred-address-v4", long)] /// An IPv4 address for the server preferred address. @@ -162,7 +162,7 @@ impl QuicParameters { .max_streams(StreamType::UniDi, self.max_streams_uni) .idle_timeout(Duration::from_secs(self.idle_timeout)) .cc_algorithm(self.congestion_control) - .pacing(self.pacing); + .pacing(!self.no_pacing); if let Some(&first) = self.quic_version.first() { let all = if self.quic_version[1..].contains(&first) { diff --git a/test/upload_test.sh b/test/upload_test.sh index 40c3aaaeb9..685a6a926c 100755 --- a/test/upload_test.sh +++ b/test/upload_test.sh @@ -9,9 +9,10 @@ cc=cubic client="cargo run --release --bin neqo-client -- http://$server_address:$server_port/ --test upload --upload-size $upload_size --cc $cc" server="cargo run --release --bin neqo-server -- --db ../test-fixture/db $server_address:$server_port" server_pid=0 -pacing=true -if [ "$pacing" = true ]; then - client="$client --pacing" +no_pacing=false +if [ "$no_pacing" = true ]; then + client="$client --no-pacing" + server="$server --no-pacing" fi # Define two indexed arrays to store network conditions From 7028479a4bc0e652f97295c5c57bfafd42c7dd92 Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Tue, 19 Mar 2024 16:17:50 +1000 Subject: [PATCH 19/30] Revert "Merge branch 'sent-packets-vec' of github.com:martinthomson/neqo" This reverts commit 8e8972c13bd3d511b5d2c7e1de8478fcc54d1478, reversing changes made to 32ef2c3cb2f0f13c6b46222d98c3316a69d7b411. --- neqo-transport/src/cc/classic_cc.rs | 60 +-- neqo-transport/src/cc/mod.rs | 2 +- neqo-transport/src/cc/tests/cubic.rs | 2 +- neqo-transport/src/cc/tests/new_reno.rs | 6 +- neqo-transport/src/connection/mod.rs | 14 +- neqo-transport/src/path.rs | 8 +- neqo-transport/src/qlog.rs | 11 +- .../src/{recovery/mod.rs => recovery.rs} | 207 ++++++--- neqo-transport/src/recovery/sent.rs | 413 ------------------ neqo-transport/src/recovery/token.rs | 63 --- neqo-transport/src/sender.rs | 4 +- neqo-transport/src/tracking.rs | 108 +++++ 12 files changed, 302 insertions(+), 596 deletions(-) rename neqo-transport/src/{recovery/mod.rs => recovery.rs} (91%) delete mode 100644 neqo-transport/src/recovery/sent.rs delete mode 100644 neqo-transport/src/recovery/token.rs diff --git a/neqo-transport/src/cc/classic_cc.rs b/neqo-transport/src/cc/classic_cc.rs index 0e26d39cbd..89be6c4b0f 100644 --- a/neqo-transport/src/cc/classic_cc.rs +++ b/neqo-transport/src/cc/classic_cc.rs @@ -17,9 +17,9 @@ use crate::{ cc::MAX_DATAGRAM_SIZE, packet::PacketNumber, qlog::{self, QlogMetric}, - recovery::SentPacket, rtt::RttEstimate, sender::PACING_BURST_SIZE, + tracking::SentPacket, }; #[rustfmt::skip] // to keep `::` and thus prevent conflict with `crate::qlog` use ::qlog::events::{quic::CongestionStateUpdated, EventData}; @@ -167,8 +167,8 @@ impl CongestionControl for ClassicCongestionControl { qinfo!( "packet_acked this={:p}, pn={}, ps={}, ignored={}, lost={}, rtt_est={:?}", self, - pkt.pn(), - pkt.len(), + pkt.pn, + pkt.size, i32::from(!pkt.cc_outstanding()), i32::from(pkt.lost()), rtt_est, @@ -176,11 +176,11 @@ impl CongestionControl for ClassicCongestionControl { if !pkt.cc_outstanding() { continue; } - if pkt.pn() < self.first_app_limited { + if pkt.pn < self.first_app_limited { is_app_limited = false; } - assert!(self.bytes_in_flight >= pkt.len()); - self.bytes_in_flight -= pkt.len(); + assert!(self.bytes_in_flight >= pkt.size); + self.bytes_in_flight -= pkt.size; if !self.after_recovery_start(pkt) { // Do not increase congestion window for packets sent before @@ -193,7 +193,7 @@ impl CongestionControl for ClassicCongestionControl { qlog::metrics_updated(&mut self.qlog, &[QlogMetric::InRecovery(false)]); } - new_acked += pkt.len(); + new_acked += pkt.size; } if is_app_limited { @@ -268,11 +268,11 @@ impl CongestionControl for ClassicCongestionControl { qinfo!( "packet_lost this={:p}, pn={}, ps={}", self, - pkt.pn(), - pkt.len() + pkt.pn, + pkt.size ); - assert!(self.bytes_in_flight >= pkt.len()); - self.bytes_in_flight -= pkt.len(); + assert!(self.bytes_in_flight >= pkt.size); + self.bytes_in_flight -= pkt.size; } qlog::metrics_updated( &mut self.qlog, @@ -298,13 +298,13 @@ impl CongestionControl for ClassicCongestionControl { fn discard(&mut self, pkt: &SentPacket) { if pkt.cc_outstanding() { - assert!(self.bytes_in_flight >= pkt.len()); - self.bytes_in_flight -= pkt.len(); + assert!(self.bytes_in_flight >= pkt.size); + self.bytes_in_flight -= pkt.size; qlog::metrics_updated( &mut self.qlog, &[QlogMetric::BytesInFlight(self.bytes_in_flight)], ); - qtrace!([self], "Ignore pkt with size {}", pkt.len()); + qtrace!([self], "Ignore pkt with size {}", pkt.size); } } @@ -319,7 +319,7 @@ impl CongestionControl for ClassicCongestionControl { fn on_packet_sent(&mut self, pkt: &SentPacket) { // Record the recovery time and exit any transient state. if self.state.transient() { - self.recovery_start = Some(pkt.pn()); + self.recovery_start = Some(pkt.pn); self.state.update(); } @@ -331,15 +331,15 @@ impl CongestionControl for ClassicCongestionControl { // window. Assume that all in-flight packets up to this one are NOT app-limited. // However, subsequent packets might be app-limited. Set `first_app_limited` to the // next packet number. - self.first_app_limited = pkt.pn() + 1; + self.first_app_limited = pkt.pn + 1; } - self.bytes_in_flight += pkt.len(); + self.bytes_in_flight += pkt.size; qinfo!( "packet_sent this={:p}, pn={}, ps={}", self, - pkt.pn(), - pkt.len() + pkt.pn, + pkt.size ); qlog::metrics_updated( &mut self.qlog, @@ -438,20 +438,20 @@ impl ClassicCongestionControl { let cutoff = max(first_rtt_sample_time, prev_largest_acked_sent); for p in lost_packets .iter() - .skip_while(|p| Some(p.time_sent()) < cutoff) + .skip_while(|p| Some(p.time_sent) < cutoff) { - if p.pn() != last_pn + 1 { + if p.pn != last_pn + 1 { // Not a contiguous range of lost packets, start over. start = None; } - last_pn = p.pn(); + last_pn = p.pn; if !p.cc_in_flight() { // Not interesting, keep looking. continue; } if let Some(t) = start { let elapsed = p - .time_sent() + .time_sent .checked_duration_since(t) .expect("time is monotonic"); if elapsed > pc_period { @@ -466,7 +466,7 @@ impl ClassicCongestionControl { return true; } } else { - start = Some(p.time_sent()); + start = Some(p.time_sent); } } false @@ -480,7 +480,7 @@ impl ClassicCongestionControl { // state and update the variable `self.recovery_start`. Before the // first recovery, all packets were sent after the recovery event, // allowing to reduce the cwnd on congestion events. - !self.state.transient() && self.recovery_start.map_or(true, |pn| packet.pn() >= pn) + !self.state.transient() && self.recovery_start.map_or(true, |pn| packet.pn >= pn) } /// Handle a congestion event. @@ -551,8 +551,8 @@ mod tests { CongestionControl, CongestionControlAlgorithm, CWND_INITIAL_PKTS, MAX_DATAGRAM_SIZE, }, packet::{PacketNumber, PacketType}, - recovery::SentPacket, rtt::RttEstimate, + tracking::SentPacket, }; const PTO: Duration = Duration::from_millis(100); @@ -912,12 +912,12 @@ mod tests { fn persistent_congestion_ack_eliciting() { let mut lost = make_lost(&[1, PERSISTENT_CONG_THRESH + 2]); lost[0] = SentPacket::new( - lost[0].packet_type(), - lost[0].pn(), - lost[0].time_sent(), + lost[0].pt, + lost[0].pn, + lost[0].time_sent, false, Vec::new(), - lost[0].len(), + lost[0].size, ); assert!(!persistent_congestion_by_pto( ClassicCongestionControl::new(NewReno::default()), diff --git a/neqo-transport/src/cc/mod.rs b/neqo-transport/src/cc/mod.rs index 965b3e5558..486d15e67e 100644 --- a/neqo-transport/src/cc/mod.rs +++ b/neqo-transport/src/cc/mod.rs @@ -14,7 +14,7 @@ use std::{ use neqo_common::qlog::NeqoQlog; -use crate::{path::PATH_MTU_V6, recovery::SentPacket, rtt::RttEstimate, Error}; +use crate::{path::PATH_MTU_V6, rtt::RttEstimate, tracking::SentPacket, Error}; mod classic_cc; mod cubic; diff --git a/neqo-transport/src/cc/tests/cubic.rs b/neqo-transport/src/cc/tests/cubic.rs index 1d933790e1..2e0200fd6d 100644 --- a/neqo-transport/src/cc/tests/cubic.rs +++ b/neqo-transport/src/cc/tests/cubic.rs @@ -24,8 +24,8 @@ use crate::{ CongestionControl, MAX_DATAGRAM_SIZE, MAX_DATAGRAM_SIZE_F64, }, packet::PacketType, - recovery::SentPacket, rtt::RttEstimate, + tracking::SentPacket, }; const RTT: Duration = Duration::from_millis(100); diff --git a/neqo-transport/src/cc/tests/new_reno.rs b/neqo-transport/src/cc/tests/new_reno.rs index 863c15c260..4cc20de5a7 100644 --- a/neqo-transport/src/cc/tests/new_reno.rs +++ b/neqo-transport/src/cc/tests/new_reno.rs @@ -16,8 +16,8 @@ use crate::{ MAX_DATAGRAM_SIZE, }, packet::PacketType, - recovery::SentPacket, rtt::RttEstimate, + tracking::SentPacket, }; const PTO: Duration = Duration::from_millis(100); @@ -125,14 +125,14 @@ fn issue_876() { // and ack it. cwnd increases slightly cc.on_packets_acked(&sent_packets[6..], &RTT_ESTIMATE, time_now); - assert_eq!(cc.acked_bytes(), sent_packets[6].len()); + assert_eq!(cc.acked_bytes(), sent_packets[6].size); cwnd_is_halved(&cc); assert_eq!(cc.bytes_in_flight(), 5 * MAX_DATAGRAM_SIZE - 2); // Packet from before is lost. Should not hurt cwnd. cc.on_packets_lost(Some(time_now), None, PTO, &sent_packets[1..2]); assert!(!cc.recovery_packet()); - assert_eq!(cc.acked_bytes(), sent_packets[6].len()); + assert_eq!(cc.acked_bytes(), sent_packets[6].size); cwnd_is_halved(&cc); assert_eq!(cc.bytes_in_flight(), 4 * MAX_DATAGRAM_SIZE); } diff --git a/neqo-transport/src/connection/mod.rs b/neqo-transport/src/connection/mod.rs index 03f05aad06..c81a3727c6 100644 --- a/neqo-transport/src/connection/mod.rs +++ b/neqo-transport/src/connection/mod.rs @@ -44,7 +44,7 @@ use crate::{ path::{Path, PathRef, Paths}, qlog, quic_datagrams::{DatagramTracking, QuicDatagrams}, - recovery::{LossRecovery, RecoveryToken, SendProfile, SentPacket}, + recovery::{LossRecovery, RecoveryToken, SendProfile}, recv_stream::RecvStreamStats, rtt::GRANULARITY, send_stream::SendStream, @@ -55,7 +55,7 @@ use crate::{ self, TransportParameter, TransportParameterId, TransportParameters, TransportParametersHandler, }, - tracking::{AckTracker, PacketNumberSpace}, + tracking::{AckTracker, PacketNumberSpace, SentPacket}, version::{Version, WireVersion}, AppError, ConnectionError, Error, Res, StreamId, }; @@ -2336,7 +2336,7 @@ impl Connection { packets.len(), mtu ); - initial.add_padding(mtu - packets.len()); + initial.size += mtu - packets.len(); packets.resize(mtu, 0); } self.loss_recovery.on_packet_sent(path, initial); @@ -2855,7 +2855,7 @@ impl Connection { /// to retransmit the frame as needed. fn handle_lost_packets(&mut self, lost_packets: &[SentPacket]) { for lost in lost_packets { - for token in lost.tokens() { + for token in &lost.tokens { qdebug!([self], "Lost: {:?}", token); match token { RecoveryToken::Ack(_) => {} @@ -2891,12 +2891,12 @@ impl Connection { fn handle_ack( &mut self, space: PacketNumberSpace, - largest_acknowledged: PacketNumber, + largest_acknowledged: u64, ack_ranges: R, ack_delay: u64, now: Instant, ) where - R: IntoIterator> + Debug, + R: IntoIterator> + Debug, R::IntoIter: ExactSizeIterator, { qinfo!([self], "Rx ACK space={}, ranges={:?}", space, ack_ranges); @@ -2910,7 +2910,7 @@ impl Connection { now, ); for acked in acked_packets { - for token in acked.tokens() { + for token in &acked.tokens { match token { RecoveryToken::Stream(stream_token) => self.streams.acked(stream_token), RecoveryToken::Ack(at) => self.acks.acked(at), diff --git a/neqo-transport/src/path.rs b/neqo-transport/src/path.rs index 59bb871b3d..4e8d9958ab 100644 --- a/neqo-transport/src/path.rs +++ b/neqo-transport/src/path.rs @@ -24,11 +24,11 @@ use crate::{ cid::{ConnectionId, ConnectionIdRef, ConnectionIdStore, RemoteConnectionIdEntry}, frame::{FRAME_TYPE_PATH_CHALLENGE, FRAME_TYPE_PATH_RESPONSE, FRAME_TYPE_RETIRE_CONNECTION_ID}, packet::PacketBuilder, - recovery::{RecoveryToken, SentPacket}, + recovery::RecoveryToken, rtt::RttEstimate, sender::PacketSender, stats::FrameStats, - tracking::PacketNumberSpace, + tracking::{PacketNumberSpace, SentPacket}, Stats, }; @@ -943,12 +943,12 @@ impl Path { qinfo!( [self], "discarding a packet without an RTT estimate; guessing RTT={:?}", - now - sent.time_sent() + now - sent.time_sent ); stats.rtt_init_guess = true; self.rtt.update( &mut self.qlog, - now - sent.time_sent(), + now - sent.time_sent, Duration::new(0, 0), false, now, diff --git a/neqo-transport/src/qlog.rs b/neqo-transport/src/qlog.rs index 7732974136..2572966104 100644 --- a/neqo-transport/src/qlog.rs +++ b/neqo-transport/src/qlog.rs @@ -27,9 +27,9 @@ use crate::{ frame::{CloseError, Frame}, packet::{DecryptedPacket, PacketNumber, PacketType, PublicPacket}, path::PathRef, - recovery::SentPacket, stream_id::StreamType as NeqoStreamType, tparams::{self, TransportParametersHandler}, + tracking::SentPacket, version::{Version, VersionConfig, WireVersion}, }; @@ -259,13 +259,8 @@ pub fn packet_dropped(qlog: &mut NeqoQlog, public_packet: &PublicPacket) { pub fn packets_lost(qlog: &mut NeqoQlog, pkts: &[SentPacket]) { qlog.add_event_with_stream(|stream| { for pkt in pkts { - let header = PacketHeader::with_type( - to_qlog_pkt_type(pkt.packet_type()), - Some(pkt.pn()), - None, - None, - None, - ); + let header = + PacketHeader::with_type(to_qlog_pkt_type(pkt.pt), Some(pkt.pn), None, None, None); let ev_data = EventData::PacketLost(PacketLost { header: Some(header), diff --git a/neqo-transport/src/recovery/mod.rs b/neqo-transport/src/recovery.rs similarity index 91% rename from neqo-transport/src/recovery/mod.rs rename to neqo-transport/src/recovery.rs index 2aec479b5f..dbea3aaf57 100644 --- a/neqo-transport/src/recovery/mod.rs +++ b/neqo-transport/src/recovery.rs @@ -6,29 +6,30 @@ // Tracking of sent packets and detecting their loss. -mod sent; -mod token; - use std::{ cmp::{max, min}, - convert::TryFrom, + collections::BTreeMap, + mem, ops::RangeInclusive, time::{Duration, Instant}, }; use neqo_common::{qdebug, qinfo, qlog::NeqoQlog, qtrace, qwarn}; -pub use sent::SentPacket; -use sent::SentPackets; use smallvec::{smallvec, SmallVec}; -pub use token::{RecoveryToken, StreamRecoveryToken}; use crate::{ + ackrate::AckRate, + cid::ConnectionIdEntry, + crypto::CryptoRecoveryToken, packet::PacketNumber, path::{Path, PathRef}, qlog::{self, QlogMetric}, + quic_datagrams::DatagramTracking, rtt::RttEstimate, + send_stream::SendStreamRecoveryToken, stats::{Stats, StatsCell}, - tracking::{PacketNumberSpace, PacketNumberSpaceSet}, + stream_id::{StreamId, StreamType}, + tracking::{AckToken, PacketNumberSpace, PacketNumberSpaceSet, SentPacket}, }; pub(crate) const PACKET_THRESHOLD: u64 = 3; @@ -47,6 +48,54 @@ pub(crate) const MIN_OUTSTANDING_UNACK: usize = 16; /// The scale we use for the fast PTO feature. pub const FAST_PTO_SCALE: u8 = 100; +#[derive(Debug, Clone)] +#[allow(clippy::module_name_repetitions)] +pub enum StreamRecoveryToken { + Stream(SendStreamRecoveryToken), + ResetStream { + stream_id: StreamId, + }, + StopSending { + stream_id: StreamId, + }, + + MaxData(u64), + DataBlocked(u64), + + MaxStreamData { + stream_id: StreamId, + max_data: u64, + }, + StreamDataBlocked { + stream_id: StreamId, + limit: u64, + }, + + MaxStreams { + stream_type: StreamType, + max_streams: u64, + }, + StreamsBlocked { + stream_type: StreamType, + limit: u64, + }, +} + +#[derive(Debug, Clone)] +#[allow(clippy::module_name_repetitions)] +pub enum RecoveryToken { + Stream(StreamRecoveryToken), + Ack(AckToken), + Crypto(CryptoRecoveryToken), + HandshakeDone, + KeepAlive, // Special PING. + NewToken(usize), + NewConnectionId(ConnectionIdEntry<[u8; 16]>), + RetireConnectionId(u64), + AckFrequency(AckRate), + Datagram(DatagramTracking), +} + /// `SendProfile` tells a sender how to send packets. #[derive(Debug)] pub struct SendProfile { @@ -131,8 +180,7 @@ pub(crate) struct LossRecoverySpace { /// This might be less than the number of ACK-eliciting packets, /// because PTO packets don't count. in_flight_outstanding: usize, - /// The packets that we have sent and are tracking. - sent_packets: SentPackets, + sent_packets: BTreeMap, /// The time that the first out-of-order packet was sent. /// This is `None` if there were no out-of-order packets detected. /// When set to `Some(T)`, time-based loss detection should be enabled. @@ -147,7 +195,7 @@ impl LossRecoverySpace { largest_acked_sent_time: None, last_ack_eliciting: None, in_flight_outstanding: 0, - sent_packets: SentPackets::default(), + sent_packets: BTreeMap::default(), first_ooo_time: None, } } @@ -172,9 +220,9 @@ impl LossRecoverySpace { pub fn pto_packets(&mut self, count: usize) -> impl Iterator { self.sent_packets .iter_mut() - .filter_map(|sent| { + .filter_map(|(pn, sent)| { if sent.pto() { - qtrace!("PTO: marking packet {} lost ", sent.pn()); + qtrace!("PTO: marking packet {} lost ", pn); Some(&*sent) } else { None @@ -207,16 +255,16 @@ impl LossRecoverySpace { pub fn on_packet_sent(&mut self, sent_packet: SentPacket) { if sent_packet.ack_eliciting() { - self.last_ack_eliciting = Some(sent_packet.time_sent()); + self.last_ack_eliciting = Some(sent_packet.time_sent); self.in_flight_outstanding += 1; } else if self.space != PacketNumberSpace::ApplicationData && self.last_ack_eliciting.is_none() { // For Initial and Handshake spaces, make sure that we have a PTO baseline // always. See `LossRecoverySpace::pto_base_time()` for details. - self.last_ack_eliciting = Some(sent_packet.time_sent()); + self.last_ack_eliciting = Some(sent_packet.time_sent); } - self.sent_packets.track(sent_packet); + self.sent_packets.insert(sent_packet.pn, sent_packet); } /// If we are only sending ACK frames, send a PING frame after 2 PTOs so that @@ -246,31 +294,46 @@ impl LossRecoverySpace { } } - /// Remove all newly acknowledged packets. + /// Remove all acknowledged packets. /// Returns all the acknowledged packets, with the largest packet number first. /// ...and a boolean indicating if any of those packets were ack-eliciting. /// This operates more efficiently because it assumes that the input is sorted /// in the order that an ACK frame is (from the top). fn remove_acked(&mut self, acked_ranges: R, stats: &mut Stats) -> (Vec, bool) where - R: IntoIterator>, + R: IntoIterator>, R::IntoIter: ExactSizeIterator, { - let mut eliciting = false; + let acked_ranges = acked_ranges.into_iter(); + let mut keep = Vec::with_capacity(acked_ranges.len()); + let mut acked = Vec::new(); + let mut eliciting = false; for range in acked_ranges { - self.sent_packets.take_range(range, &mut acked); - } - for p in &acked { - self.remove_packet(p); - eliciting |= p.ack_eliciting(); - if p.lost() { - stats.late_ack += 1; - } - if p.pto_fired() { - stats.pto_ack += 1; + let first_keep = *range.end() + 1; + if let Some((&first, _)) = self.sent_packets.range(range).next() { + let mut tail = self.sent_packets.split_off(&first); + if let Some((&next, _)) = tail.range(first_keep..).next() { + keep.push(tail.split_off(&next)); + } + for (_, p) in tail.into_iter().rev() { + self.remove_packet(&p); + eliciting |= p.ack_eliciting(); + if p.lost() { + stats.late_ack += 1; + } + if p.pto_fired() { + stats.pto_ack += 1; + } + acked.push(p); + } } } + + for mut k in keep.into_iter().rev() { + self.sent_packets.append(&mut k); + } + (acked, eliciting) } @@ -279,12 +342,12 @@ impl LossRecoverySpace { /// and when keys are dropped. fn remove_ignored(&mut self) -> impl Iterator { self.in_flight_outstanding = 0; - std::mem::take(&mut self.sent_packets).drain_all() + mem::take(&mut self.sent_packets).into_values() } /// Remove the primary path marking on any packets this is tracking. fn migrate(&mut self) { - for pkt in self.sent_packets.iter_mut() { + for pkt in self.sent_packets.values_mut() { pkt.clear_primary_path(); } } @@ -295,8 +358,23 @@ impl LossRecoverySpace { /// might remove all in-flight packets and stop sending probes. #[allow(clippy::option_if_let_else)] // Hard enough to read as-is. fn remove_old_lost(&mut self, now: Instant, cd: Duration) { - for p in self.sent_packets.remove_expired(now, cd) { - self.remove_packet(&p); + let mut it = self.sent_packets.iter(); + // If the first item is not expired, do nothing. + if it.next().map_or(false, |(_, p)| p.expired(now, cd)) { + // Find the index of the first unexpired packet. + let to_remove = if let Some(first_keep) = + it.find_map(|(i, p)| if p.expired(now, cd) { None } else { Some(*i) }) + { + // Some packets haven't expired, so keep those. + let keep = self.sent_packets.split_off(&first_keep); + mem::replace(&mut self.sent_packets, keep) + } else { + // All packets are expired. + mem::take(&mut self.sent_packets) + }; + for (_, p) in to_remove { + self.remove_packet(&p); + } } } @@ -323,39 +401,44 @@ impl LossRecoverySpace { let largest_acked = self.largest_acked; - for packet in self + // Lost for retrans/CC purposes + let mut lost_pns = SmallVec::<[_; 8]>::new(); + + for (pn, packet) in self .sent_packets .iter_mut() // BTreeMap iterates in order of ascending PN - .take_while(|p| p.pn() < largest_acked.unwrap_or(PacketNumber::MAX)) + .take_while(|(&k, _)| k < largest_acked.unwrap_or(PacketNumber::MAX)) { // Packets sent before now - loss_delay are deemed lost. - if packet.time_sent() + loss_delay <= now { + if packet.time_sent + loss_delay <= now { qtrace!( "lost={}, time sent {:?} is before lost_delay {:?}", - packet.pn(), - packet.time_sent(), + pn, + packet.time_sent, loss_delay ); - } else if largest_acked >= Some(packet.pn() + PACKET_THRESHOLD) { + } else if largest_acked >= Some(*pn + PACKET_THRESHOLD) { qtrace!( "lost={}, is >= {} from largest acked {:?}", - packet.pn(), + pn, PACKET_THRESHOLD, largest_acked ); } else { if largest_acked.is_some() { - self.first_ooo_time = Some(packet.time_sent()); + self.first_ooo_time = Some(packet.time_sent); } // No more packets can be declared lost after this one. break; }; if packet.declare_lost(now) { - lost_packets.push(packet.clone()); + lost_pns.push(*pn); } } + + lost_packets.extend(lost_pns.iter().map(|pn| self.sent_packets[pn].clone())); } } @@ -545,8 +628,8 @@ impl LossRecovery { } pub fn on_packet_sent(&mut self, path: &PathRef, mut sent_packet: SentPacket) { - let pn_space = PacketNumberSpace::from(sent_packet.packet_type()); - qdebug!([self], "packet {}-{} sent", pn_space, sent_packet.pn()); + let pn_space = PacketNumberSpace::from(sent_packet.pt); + qdebug!([self], "packet {}-{} sent", pn_space, sent_packet.pn); if let Some(space) = self.spaces.get_mut(pn_space) { path.borrow_mut().packet_sent(&mut sent_packet); space.on_packet_sent(sent_packet); @@ -555,7 +638,7 @@ impl LossRecovery { [self], "ignoring {}-{} from dropped space", pn_space, - sent_packet.pn() + sent_packet.pn ); } } @@ -586,13 +669,13 @@ impl LossRecovery { &mut self, primary_path: &PathRef, pn_space: PacketNumberSpace, - largest_acked: PacketNumber, + largest_acked: u64, acked_ranges: R, ack_delay: Duration, now: Instant, ) -> (Vec, Vec) where - R: IntoIterator>, + R: IntoIterator>, R::IntoIter: ExactSizeIterator, { qdebug!( @@ -622,11 +705,11 @@ impl LossRecovery { // If the largest acknowledged is newly acked and any newly acked // packet was ack-eliciting, update the RTT. (-recovery 5.1) let largest_acked_pkt = acked_packets.first().expect("must be there"); - space.largest_acked_sent_time = Some(largest_acked_pkt.time_sent()); + space.largest_acked_sent_time = Some(largest_acked_pkt.time_sent); if any_ack_eliciting && largest_acked_pkt.on_primary_path() { self.rtt_sample( primary_path.borrow_mut().rtt_mut(), - largest_acked_pkt.time_sent(), + largest_acked_pkt.time_sent, now, ack_delay, ); @@ -934,7 +1017,6 @@ impl ::std::fmt::Display for LossRecovery { mod tests { use std::{ cell::RefCell, - convert::TryInto, ops::{Deref, DerefMut, RangeInclusive}, rc::Rc, time::{Duration, Instant}, @@ -949,7 +1031,7 @@ mod tests { use crate::{ cc::CongestionControlAlgorithm, cid::{ConnectionId, ConnectionIdEntry}, - packet::{PacketNumber, PacketType}, + packet::PacketType, path::{Path, PathRef}, rtt::RttEstimate, stats::{Stats, StatsCell}, @@ -976,8 +1058,8 @@ mod tests { pub fn on_ack_received( &mut self, pn_space: PacketNumberSpace, - largest_acked: PacketNumber, - acked_ranges: Vec>, + largest_acked: u64, + acked_ranges: Vec>, ack_delay: Duration, now: Instant, ) -> (Vec, Vec) { @@ -1146,8 +1228,8 @@ mod tests { ); } - fn add_sent(lrs: &mut LossRecoverySpace, max_pn: PacketNumber) { - for pn in 0..=max_pn { + fn add_sent(lrs: &mut LossRecoverySpace, packet_numbers: &[u64]) { + for &pn in packet_numbers { lrs.on_packet_sent(SentPacket::new( PacketType::Short, pn, @@ -1159,18 +1241,15 @@ mod tests { } } - fn match_acked(acked: &[SentPacket], expected: &[PacketNumber]) { - assert_eq!( - acked.iter().map(SentPacket::pn).collect::>(), - expected - ); + fn match_acked(acked: &[SentPacket], expected: &[u64]) { + assert!(acked.iter().map(|p| &p.pn).eq(expected)); } #[test] fn remove_acked() { let mut lrs = LossRecoverySpace::new(PacketNumberSpace::ApplicationData); let mut stats = Stats::default(); - add_sent(&mut lrs, 10); + add_sent(&mut lrs, &[1, 2, 3, 4, 5, 6, 7, 8, 9, 10]); let (acked, _) = lrs.remove_acked(vec![], &mut stats); assert!(acked.is_empty()); let (acked, _) = lrs.remove_acked(vec![7..=8, 2..=4], &mut stats); @@ -1178,7 +1257,7 @@ mod tests { let (acked, _) = lrs.remove_acked(vec![8..=11], &mut stats); match_acked(&acked, &[10, 9]); let (acked, _) = lrs.remove_acked(vec![0..=2], &mut stats); - match_acked(&acked, &[1, 0]); + match_acked(&acked, &[1]); let (acked, _) = lrs.remove_acked(vec![5..=6], &mut stats); match_acked(&acked, &[6, 5]); } @@ -1413,7 +1492,7 @@ mod tests { PacketType::Short, ] { let sent_pkt = SentPacket::new(*sp, 1, pn_time(3), true, Vec::new(), ON_SENT_SIZE); - let pn_space = PacketNumberSpace::from(sent_pkt.packet_type()); + let pn_space = PacketNumberSpace::from(sent_pkt.pt); lr.on_packet_sent(sent_pkt); lr.on_ack_received(pn_space, 1, vec![1..=1], Duration::from_secs(0), pn_time(3)); let mut lost = Vec::new(); @@ -1514,7 +1593,7 @@ mod tests { lr.on_packet_sent(SentPacket::new( PacketType::Initial, - 0, + 1, now(), true, Vec::new(), diff --git a/neqo-transport/src/recovery/sent.rs b/neqo-transport/src/recovery/sent.rs deleted file mode 100644 index 33d77b0ff7..0000000000 --- a/neqo-transport/src/recovery/sent.rs +++ /dev/null @@ -1,413 +0,0 @@ -// Licensed under the Apache License, Version 2.0 or the MIT license -// , at your -// option. This file may not be copied, modified, or distributed -// except according to those terms. - -// A collection for sent packets. - -use std::{ - cmp::min, - collections::VecDeque, - convert::TryFrom, - ops::RangeInclusive, - time::{Duration, Instant}, -}; - -use crate::{ - packet::{PacketNumber, PacketType}, - recovery::RecoveryToken, -}; - -#[derive(Debug, Clone)] -pub struct SentPacket { - pt: PacketType, - pn: PacketNumber, - ack_eliciting: bool, - time_sent: Instant, - primary_path: bool, - tokens: Vec, - - time_declared_lost: Option, - /// After a PTO, this is true when the packet has been released. - pto: bool, - - len: usize, -} - -impl SentPacket { - pub fn new( - pt: PacketType, - pn: PacketNumber, - time_sent: Instant, - ack_eliciting: bool, - tokens: Vec, - len: usize, - ) -> Self { - Self { - pt, - pn, - time_sent, - ack_eliciting, - primary_path: true, - tokens, - time_declared_lost: None, - pto: false, - len, - } - } - - /// The type of this packet. - pub fn packet_type(&self) -> PacketType { - self.pt - } - - /// The number of the packet. - pub fn pn(&self) -> PacketNumber { - self.pn - } - - /// The time that this packet was sent. - pub fn time_sent(&self) -> Instant { - self.time_sent - } - - /// Returns `true` if the packet will elicit an ACK. - pub fn ack_eliciting(&self) -> bool { - self.ack_eliciting - } - - /// Returns `true` if the packet was sent on the primary path. - pub fn on_primary_path(&self) -> bool { - self.primary_path - } - - /// The length of the packet that was sent. - pub fn len(&self) -> usize { - self.len - } - - /// Access the recovery tokens that this holds. - pub fn tokens(&self) -> &[RecoveryToken] { - &self.tokens - } - - /// Clears the flag that had this packet on the primary path. - /// Used when migrating to clear out state. - pub fn clear_primary_path(&mut self) { - self.primary_path = false; - } - - /// For Initial packets, it is possible that the packet builder needs to amend the length. - pub fn add_padding(&mut self, padding: usize) { - debug_assert_eq!(self.pt, PacketType::Initial); - self.len += padding; - } - - /// Whether the packet has been declared lost. - pub fn lost(&self) -> bool { - self.time_declared_lost.is_some() - } - - /// Whether accounting for the loss or acknowledgement in the - /// congestion controller is pending. - /// Returns `true` if the packet counts as being "in flight", - /// and has not previously been declared lost. - /// Note that this should count packets that contain only ACK and PADDING, - /// but we don't send PADDING, so we don't track that. - pub fn cc_outstanding(&self) -> bool { - self.ack_eliciting() && self.on_primary_path() && !self.lost() - } - - /// Whether the packet should be tracked as in-flight. - pub fn cc_in_flight(&self) -> bool { - self.ack_eliciting() && self.on_primary_path() - } - - /// Declare the packet as lost. Returns `true` if this is the first time. - pub fn declare_lost(&mut self, now: Instant) -> bool { - if self.lost() { - false - } else { - self.time_declared_lost = Some(now); - true - } - } - - /// Ask whether this tracked packet has been declared lost for long enough - /// that it can be expired and no longer tracked. - pub fn expired(&self, now: Instant, expiration_period: Duration) -> bool { - self.time_declared_lost - .map_or(false, |loss_time| (loss_time + expiration_period) <= now) - } - - /// Whether the packet contents were cleared out after a PTO. - pub fn pto_fired(&self) -> bool { - self.pto - } - - /// On PTO, we need to get the recovery tokens so that we can ensure that - /// the frames we sent can be sent again in the PTO packet(s). Do that just once. - pub fn pto(&mut self) -> bool { - if self.pto || self.lost() { - false - } else { - self.pto = true; - true - } - } -} - -/// A collection for packets that we have sent that haven't been acknowledged. -#[derive(Debug, Default)] -pub struct SentPackets { - /// The collection. - packets: VecDeque>, - /// The packet number of the first item in the collection. - offset: PacketNumber, - /// The number of `Some` values in the packet. This is cached to keep things squeaky-fast. - len: usize, -} - -impl SentPackets { - pub fn len(&self) -> usize { - self.len - } - - pub fn track(&mut self, packet: SentPacket) { - if self.offset + PacketNumber::try_from(self.packets.len()).unwrap() != packet.pn { - assert_eq!( - self.len, 0, - "packet number skipping only supported for the first packet in a space" - ); - self.offset = packet.pn; - } - self.len += 1; - self.packets.push_back(Some(packet)); - } - - pub fn iter_mut(&mut self) -> impl Iterator { - self.packets.iter_mut().flatten() - } - - /// Take values from a specified range of packet numbers. - /// Note that this will not remove values unless the iterator is consumed. - /// The values returned will be reversed, so that the most recent packet appears first. - /// This is because ACK frames arrive with ranges starting from the largest acknowledged - /// and we want to match that. - pub fn take_range(&mut self, r: RangeInclusive, store: &mut Vec) { - let start = usize::try_from((*r.start()).saturating_sub(self.offset)).unwrap(); - let end = min( - usize::try_from((*r.end() + 1).saturating_sub(self.offset)).unwrap(), - self.packets.len(), - ); - - let before = store.len(); - if self.packets.range(..start).all(Option::is_none) { - // If there are extra empty slots, split those off too. - let extra = self - .packets - .range(end..) - .take_while(|&p| p.is_none()) - .count(); - self.offset += u64::try_from(end + extra).unwrap(); - let mut other = self.packets.split_off(end + extra); - std::mem::swap(&mut self.packets, &mut other); - store.extend( - other - .into_iter() - .rev() - .skip(extra) - .take(end - start) - .flatten(), - ); - } else { - store.extend( - self.packets - .range_mut(start..end) - .rev() - .filter_map(Option::take), - ); - } - self.len -= store.len() - before; - } - - /// Empty out the packets, but keep the offset. - pub fn drain_all(&mut self) -> impl Iterator { - self.len = 0; - self.offset += u64::try_from(self.packets.len()).unwrap(); - std::mem::take(&mut self.packets).into_iter().flatten() - } - - /// See `LossRecoverySpace::remove_old_lost` for details on `now` and `cd`. - pub fn remove_expired( - &mut self, - now: Instant, - cd: Duration, - ) -> impl Iterator { - let mut count = 0; - // Find the first unexpired packet and only keep from that one onwards. - for (i, p) in self.packets.iter().enumerate() { - if p.as_ref().map_or(false, |p| !p.expired(now, cd)) { - let mut other = self.packets.split_off(i); - self.len -= count; - self.offset += u64::try_from(i).unwrap(); - std::mem::swap(&mut self.packets, &mut other); - return other.into_iter().flatten(); - } - // Count `Some` values that we are removing. - count += usize::from(p.is_some()); - } - - self.len = 0; - self.offset += u64::try_from(self.packets.len()).unwrap(); - std::mem::take(&mut self.packets).into_iter().flatten() - } -} - -#[cfg(test)] -mod tests { - use std::{ - cell::OnceCell, - convert::TryFrom, - time::{Duration, Instant}, - }; - - use super::{SentPacket, SentPackets}; - use crate::packet::{PacketNumber, PacketType}; - - const PACKET_GAP: Duration = Duration::from_secs(1); - fn start_time() -> Instant { - thread_local!(static STARTING_TIME: OnceCell = OnceCell::new()); - STARTING_TIME.with(|t| *t.get_or_init(Instant::now)) - } - - fn pkt(n: u32) -> SentPacket { - SentPacket::new( - PacketType::Short, - PacketNumber::from(n), - start_time() + (PACKET_GAP * n), - true, - Vec::new(), - 100, - ) - } - - fn pkts() -> SentPackets { - let mut pkts = SentPackets::default(); - pkts.track(pkt(0)); - pkts.track(pkt(1)); - pkts.track(pkt(2)); - assert_eq!(pkts.len(), 3); - pkts - } - - trait HasPacketNumber { - fn pn(&self) -> PacketNumber; - } - impl HasPacketNumber for SentPacket { - fn pn(&self) -> PacketNumber { - self.pn - } - } - impl HasPacketNumber for &'_ SentPacket { - fn pn(&self) -> PacketNumber { - self.pn - } - } - impl HasPacketNumber for &'_ mut SentPacket { - fn pn(&self) -> PacketNumber { - self.pn - } - } - - fn remove_one(pkts: &mut SentPackets, idx: PacketNumber) { - assert_eq!(pkts.len(), 3); - let mut store = Vec::new(); - pkts.take_range(idx..=idx, &mut store); - let mut it = store.into_iter(); - assert_eq!(idx, it.next().unwrap().pn()); - assert!(it.next().is_none()); - std::mem::drop(it); - assert_eq!(pkts.len(), 2); - } - - fn assert_zero_and_two<'a, 'b: 'a>( - mut it: impl Iterator + 'a, - ) { - assert_eq!(it.next().unwrap().pn(), 0); - assert_eq!(it.next().unwrap().pn(), 2); - assert!(it.next().is_none()); - } - - #[test] - fn iterate_skipped() { - let mut pkts = pkts(); - for (i, p) in pkts.packets.iter().enumerate() { - assert_eq!(i, usize::try_from(p.as_ref().unwrap().pn).unwrap()); - } - remove_one(&mut pkts, 1); - - // Validate the merged result multiple ways. - assert_zero_and_two(pkts.iter_mut()); - - { - // Reverse the expectations here as this iterator reverses its output. - let mut store = Vec::new(); - pkts.take_range(0..=2, &mut store); - let mut it = store.into_iter(); - assert_eq!(it.next().unwrap().pn(), 2); - assert_eq!(it.next().unwrap().pn(), 0); - assert!(it.next().is_none()); - }; - - // The None values are still there in this case, so offset is 0. - assert_eq!(pkts.offset, 3); - assert_eq!(pkts.packets.len(), 0); - assert_eq!(pkts.len(), 0); - } - - #[test] - fn drain() { - let mut pkts = pkts(); - remove_one(&mut pkts, 1); - - assert_zero_and_two(pkts.drain_all()); - assert_eq!(pkts.offset, 3); - assert_eq!(pkts.len(), 0); - } - - #[test] - fn remove_expired() { - let mut pkts = pkts(); - remove_one(&mut pkts, 0); - - for p in pkts.iter_mut() { - p.declare_lost(p.time_sent); // just to keep things simple. - } - - // Expire up to pkt(1). - let mut it = pkts.remove_expired(start_time() + PACKET_GAP, Duration::new(0, 0)); - assert_eq!(it.next().unwrap().pn(), 1); - assert!(it.next().is_none()); - std::mem::drop(it); - - assert_eq!(pkts.offset, 2); - assert_eq!(pkts.len(), 1); - } - - #[test] - #[should_panic(expected = "packet number skipping only supported for the first packet")] - fn skipped_not_ok() { - let mut pkts = pkts(); - pkts.track(pkt(4)); - } - - #[test] - fn first_skipped_ok() { - let mut pkts = SentPackets::default(); - pkts.track(pkt(4)); // This is fine. - assert_eq!(pkts.offset, 4); - assert_eq!(pkts.len(), 1); - } -} diff --git a/neqo-transport/src/recovery/token.rs b/neqo-transport/src/recovery/token.rs deleted file mode 100644 index 93f84268cd..0000000000 --- a/neqo-transport/src/recovery/token.rs +++ /dev/null @@ -1,63 +0,0 @@ -// Licensed under the Apache License, Version 2.0 or the MIT license -// , at your -// option. This file may not be copied, modified, or distributed -// except according to those terms. - -use crate::{ - ackrate::AckRate, - cid::ConnectionIdEntry, - crypto::CryptoRecoveryToken, - quic_datagrams::DatagramTracking, - send_stream::SendStreamRecoveryToken, - stream_id::{StreamId, StreamType}, - tracking::AckToken, -}; - -#[derive(Debug, Clone)] -#[allow(clippy::module_name_repetitions)] -pub enum StreamRecoveryToken { - Stream(SendStreamRecoveryToken), - ResetStream { - stream_id: StreamId, - }, - StopSending { - stream_id: StreamId, - }, - - MaxData(u64), - DataBlocked(u64), - - MaxStreamData { - stream_id: StreamId, - max_data: u64, - }, - StreamDataBlocked { - stream_id: StreamId, - limit: u64, - }, - - MaxStreams { - stream_type: StreamType, - max_streams: u64, - }, - StreamsBlocked { - stream_type: StreamType, - limit: u64, - }, -} - -#[derive(Debug, Clone)] -#[allow(clippy::module_name_repetitions)] -pub enum RecoveryToken { - Stream(StreamRecoveryToken), - Ack(AckToken), - Crypto(CryptoRecoveryToken), - HandshakeDone, - KeepAlive, // Special PING. - NewToken(usize), - NewConnectionId(ConnectionIdEntry<[u8; 16]>), - RetireConnectionId(u64), - AckFrequency(AckRate), - Datagram(DatagramTracking), -} diff --git a/neqo-transport/src/sender.rs b/neqo-transport/src/sender.rs index 0d3da70faa..3a54851533 100644 --- a/neqo-transport/src/sender.rs +++ b/neqo-transport/src/sender.rs @@ -18,8 +18,8 @@ use neqo_common::qlog::NeqoQlog; use crate::{ cc::{ClassicCongestionControl, CongestionControl, CongestionControlAlgorithm, Cubic, NewReno}, pace::Pacer, - recovery::SentPacket, rtt::RttEstimate, + tracking::SentPacket, }; /// The number of packets we allow to burst from the pacer. @@ -109,7 +109,7 @@ impl PacketSender { pub fn on_packet_sent(&mut self, pkt: &SentPacket, rtt: Duration) { self.pacer - .spend(pkt.time_sent(), rtt, self.cc.cwnd(), pkt.len()); + .spend(pkt.time_sent, rtt, self.cc.cwnd(), pkt.size); self.cc.on_packet_sent(pkt); } diff --git a/neqo-transport/src/tracking.rs b/neqo-transport/src/tracking.rs index 44a0bef4c8..bdd0f250c7 100644 --- a/neqo-transport/src/tracking.rs +++ b/neqo-transport/src/tracking.rs @@ -130,6 +130,114 @@ impl std::fmt::Debug for PacketNumberSpaceSet { } } +#[derive(Debug, Clone)] +pub struct SentPacket { + pub pt: PacketType, + pub pn: PacketNumber, + ack_eliciting: bool, + pub time_sent: Instant, + primary_path: bool, + pub tokens: Vec, + + time_declared_lost: Option, + /// After a PTO, this is true when the packet has been released. + pto: bool, + + pub size: usize, +} + +impl SentPacket { + pub fn new( + pt: PacketType, + pn: PacketNumber, + time_sent: Instant, + ack_eliciting: bool, + tokens: Vec, + size: usize, + ) -> Self { + Self { + pt, + pn, + time_sent, + ack_eliciting, + primary_path: true, + tokens, + time_declared_lost: None, + pto: false, + size, + } + } + + /// Returns `true` if the packet will elicit an ACK. + pub fn ack_eliciting(&self) -> bool { + self.ack_eliciting + } + + /// Returns `true` if the packet was sent on the primary path. + pub fn on_primary_path(&self) -> bool { + self.primary_path + } + + /// Clears the flag that had this packet on the primary path. + /// Used when migrating to clear out state. + pub fn clear_primary_path(&mut self) { + self.primary_path = false; + } + + /// Whether the packet has been declared lost. + pub fn lost(&self) -> bool { + self.time_declared_lost.is_some() + } + + /// Whether accounting for the loss or acknowledgement in the + /// congestion controller is pending. + /// Returns `true` if the packet counts as being "in flight", + /// and has not previously been declared lost. + /// Note that this should count packets that contain only ACK and PADDING, + /// but we don't send PADDING, so we don't track that. + pub fn cc_outstanding(&self) -> bool { + self.ack_eliciting() && self.on_primary_path() && !self.lost() + } + + /// Whether the packet should be tracked as in-flight. + pub fn cc_in_flight(&self) -> bool { + self.ack_eliciting() && self.on_primary_path() + } + + /// Declare the packet as lost. Returns `true` if this is the first time. + pub fn declare_lost(&mut self, now: Instant) -> bool { + if self.lost() { + false + } else { + self.time_declared_lost = Some(now); + true + } + } + + /// Ask whether this tracked packet has been declared lost for long enough + /// that it can be expired and no longer tracked. + pub fn expired(&self, now: Instant, expiration_period: Duration) -> bool { + self.time_declared_lost + .map_or(false, |loss_time| (loss_time + expiration_period) <= now) + } + + /// Whether the packet contents were cleared out after a PTO. + pub fn pto_fired(&self) -> bool { + self.pto + } + + /// On PTO, we need to get the recovery tokens so that we can ensure that + /// the frames we sent can be sent again in the PTO packet(s). Do that just once. + pub fn pto(&mut self) -> bool { + if self.pto || self.lost() { + false + } else { + self.pto = true; + true + } + } +} + impl std::fmt::Display for PacketNumberSpace { fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { f.write_str(match self { From e2f9369296488c6d60c778e19aa77aca6df4fbf1 Mon Sep 17 00:00:00 2001 From: Max Inden Date: Thu, 21 Mar 2024 22:53:23 +0100 Subject: [PATCH 20/30] ci(check.yml): add sleep i.e. client wait for server (#1765) Windows CI oftentimes fails with: ``` 0s 0ms INFO H3 Client connecting: [::]:65093 -> [::1]:4433 Error: IoError(Os { code: 10054, kind: ConnectionReset, message: "An existing connection was forcibly closed by the remote host." }) 0s 0ms INFO Server waiting for connection on: [::1]:4433 0s 0ms INFO Server waiting for connection on: 127.0.0.1:4433 ``` https://github.com/mozilla/neqo/actions/runs/8374577016/job/22930136500?pr=1692 This suggests that the client connects to the server before the server is ready to accept connections. This commit adds a sleep, thus giving the server time to start up. Tracked in https://github.com/mozilla/neqo/issues/1759. Sleep was previously introduced in https://github.com/mozilla/neqo/pull/1713 but later removed in https://github.com/mozilla/neqo/pull/1717 --- .github/workflows/check.yml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.github/workflows/check.yml b/.github/workflows/check.yml index 10085ffda6..a89e4859d3 100644 --- a/.github/workflows/check.yml +++ b/.github/workflows/check.yml @@ -122,6 +122,8 @@ jobs: cargo +${{ matrix.rust-toolchain }} build $BUILD_TYPE --bin neqo-client --bin neqo-server "target/$BUILD_DIR/neqo-server" "$HOST:4433" & PID=$! + # Give the server time to start. + sleep 1 "target/$BUILD_DIR/neqo-client" --output-dir . "https://$HOST:4433/$SIZE" kill $PID [ "$(wc -c <"$SIZE")" -eq "$SIZE" ] || exit 1 From 56f53bb6b3fde59cf4e7d0daa54c8c206d11d3d6 Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Thu, 21 Mar 2024 23:53:51 +0200 Subject: [PATCH 21/30] feat: Extend `Frame::Padding` with length (#1762) * feat: Extend `Frame::Padding` with a `length` field This is preparation of qlog supporting the logging of runs of padding frames via `payload_length`, instead of each one individually. * Use `dv` more * Fix test * Address code review * Add TODO --- neqo-transport/src/connection/dump.rs | 3 +- neqo-transport/src/connection/mod.rs | 25 +- .../src/connection/tests/handshake.rs | 2 +- neqo-transport/src/frame.rs | 60 +-- neqo-transport/src/packet/mod.rs | 4 +- neqo-transport/src/qlog.rs | 347 +++++++++--------- 6 files changed, 219 insertions(+), 222 deletions(-) diff --git a/neqo-transport/src/connection/dump.rs b/neqo-transport/src/connection/dump.rs index 8a4f34dbb8..34ac58f55e 100644 --- a/neqo-transport/src/connection/dump.rs +++ b/neqo-transport/src/connection/dump.rs @@ -38,7 +38,8 @@ pub fn dump_packet( s.push_str(" [broken]..."); break; }; - if let Some(x) = f.dump() { + let x = f.dump(); + if !x.is_empty() { write!(&mut s, "\n {} {}", dir, &x).unwrap(); } } diff --git a/neqo-transport/src/connection/mod.rs b/neqo-transport/src/connection/mod.rs index c81a3727c6..8d1c106358 100644 --- a/neqo-transport/src/connection/mod.rs +++ b/neqo-transport/src/connection/mod.rs @@ -461,7 +461,7 @@ impl Connection { } /// # Errors - /// When the operation fails. + /// When the operation fails. pub fn client_enable_ech(&mut self, ech_config_list: impl AsRef<[u8]>) -> Res<()> { self.crypto.client_enable_ech(ech_config_list) } @@ -1560,24 +1560,8 @@ impl Connection { let mut ack_eliciting = false; let mut probing = true; let mut d = Decoder::from(&packet[..]); - let mut consecutive_padding = 0; while d.remaining() > 0 { - let mut f = Frame::decode(&mut d)?; - - // Skip padding - while f == Frame::Padding && d.remaining() > 0 { - consecutive_padding += 1; - f = Frame::decode(&mut d)?; - } - if consecutive_padding > 0 { - qdebug!( - [self], - "PADDING frame repeated {} times", - consecutive_padding - ); - consecutive_padding = 0; - } - + let f = Frame::decode(&mut d)?; ack_eliciting |= f.ack_eliciting(); probing &= f.path_probing(); let t = f.get_type(); @@ -2694,9 +2678,8 @@ impl Connection { .input_frame(&frame, &mut self.stats.borrow_mut().frame_rx); } match frame { - Frame::Padding => { - // Note: This counts contiguous padding as a single frame. - self.stats.borrow_mut().frame_rx.padding += 1; + Frame::Padding(length) => { + self.stats.borrow_mut().frame_rx.padding += usize::from(length); } Frame::Ping => { // If we get a PING and there are outstanding CRYPTO frames, diff --git a/neqo-transport/src/connection/tests/handshake.rs b/neqo-transport/src/connection/tests/handshake.rs index af0352ce90..cfb6d99166 100644 --- a/neqo-transport/src/connection/tests/handshake.rs +++ b/neqo-transport/src/connection/tests/handshake.rs @@ -458,7 +458,7 @@ fn coalesce_05rtt() { assert_eq!(client.stats().dropped_rx, 0); // No Initial padding. assert_eq!(client.stats().packets_rx, 4); assert_eq!(client.stats().saved_datagrams, 1); - assert_eq!(client.stats().frame_rx.padding, 1); // Padding uses frames. + assert!(client.stats().frame_rx.padding > 0); // Padding uses frames. // Allow the handshake to complete. now += RTT / 2; diff --git a/neqo-transport/src/frame.rs b/neqo-transport/src/frame.rs index b3bb024a2c..5a86a07108 100644 --- a/neqo-transport/src/frame.rs +++ b/neqo-transport/src/frame.rs @@ -20,7 +20,7 @@ use crate::{ #[allow(clippy::module_name_repetitions)] pub type FrameType = u64; -const FRAME_TYPE_PADDING: FrameType = 0x0; +pub const FRAME_TYPE_PADDING: FrameType = 0x0; pub const FRAME_TYPE_PING: FrameType = 0x1; pub const FRAME_TYPE_ACK: FrameType = 0x2; const FRAME_TYPE_ACK_ECN: FrameType = 0x3; @@ -103,7 +103,7 @@ pub struct AckRange { #[derive(PartialEq, Eq, Debug, Clone)] pub enum Frame<'a> { - Padding, + Padding(u16), Ping, Ack { largest_acknowledged: u64, @@ -215,7 +215,7 @@ impl<'a> Frame<'a> { pub fn get_type(&self) -> FrameType { match self { - Self::Padding => FRAME_TYPE_PADDING, + Self::Padding { .. } => FRAME_TYPE_PADDING, Self::Ping => FRAME_TYPE_PING, Self::Ack { .. } => FRAME_TYPE_ACK, // We don't do ACK ECN. Self::ResetStream { .. } => FRAME_TYPE_RESET_STREAM, @@ -288,7 +288,7 @@ impl<'a> Frame<'a> { pub fn ack_eliciting(&self) -> bool { !matches!( self, - Self::Ack { .. } | Self::Padding | Self::ConnectionClose { .. } + Self::Ack { .. } | Self::Padding { .. } | Self::ConnectionClose { .. } ) } @@ -297,7 +297,7 @@ impl<'a> Frame<'a> { pub fn path_probing(&self) -> bool { matches!( self, - Self::Padding + Self::Padding { .. } | Self::NewConnectionId { .. } | Self::PathChallenge { .. } | Self::PathResponse { .. } @@ -347,36 +347,34 @@ impl<'a> Frame<'a> { Ok(acked_ranges) } - pub fn dump(&self) -> Option { + pub fn dump(&self) -> String { match self { - Self::Crypto { offset, data } => Some(format!( - "Crypto {{ offset: {}, len: {} }}", - offset, - data.len() - )), + Self::Crypto { offset, data } => { + format!("Crypto {{ offset: {}, len: {} }}", offset, data.len()) + } Self::Stream { stream_id, offset, fill, data, fin, - } => Some(format!( + } => format!( "Stream {{ stream_id: {}, offset: {}, len: {}{}, fin: {} }}", stream_id.as_u64(), offset, if *fill { ">>" } else { "" }, data.len(), fin, - )), - Self::Padding => None, - Self::Datagram { data, .. } => Some(format!("Datagram {{ len: {} }}", data.len())), - _ => Some(format!("{self:?}")), + ), + Self::Padding(length) => format!("Padding {{ len: {length} }}"), + Self::Datagram { data, .. } => format!("Datagram {{ len: {} }}", data.len()), + _ => format!("{self:?}"), } } pub fn is_allowed(&self, pt: PacketType) -> bool { match self { - Self::Padding | Self::Ping => true, + Self::Padding { .. } | Self::Ping => true, Self::Crypto { .. } | Self::Ack { .. } | Self::ConnectionClose { @@ -409,13 +407,23 @@ impl<'a> Frame<'a> { } // TODO(ekr@rtfm.com): check for minimal encoding - let t = d(dec.decode_varint())?; + let t = dv(dec)?; match t { - FRAME_TYPE_PADDING => Ok(Self::Padding), + FRAME_TYPE_PADDING => { + let mut length: u16 = 1; + while let Some(b) = dec.peek_byte() { + if u64::from(b) != FRAME_TYPE_PADDING { + break; + } + length += 1; + dec.skip(1); + } + Ok(Self::Padding(length)) + } FRAME_TYPE_PING => Ok(Self::Ping), FRAME_TYPE_RESET_STREAM => Ok(Self::ResetStream { stream_id: StreamId::from(dv(dec)?), - application_error_code: d(dec.decode_varint())?, + application_error_code: dv(dec)?, final_size: match dec.decode_varint() { Some(v) => v, _ => return Err(Error::NoMoreData), @@ -457,7 +465,7 @@ impl<'a> Frame<'a> { } FRAME_TYPE_STOP_SENDING => Ok(Self::StopSending { stream_id: StreamId::from(dv(dec)?), - application_error_code: d(dec.decode_varint())?, + application_error_code: dv(dec)?, }), FRAME_TYPE_CRYPTO => { let offset = dv(dec)?; @@ -563,7 +571,7 @@ impl<'a> Frame<'a> { Ok(Self::PathResponse { data: datav }) } FRAME_TYPE_CONNECTION_CLOSE_TRANSPORT | FRAME_TYPE_CONNECTION_CLOSE_APPLICATION => { - let error_code = CloseError::from_type_bit(t, d(dec.decode_varint())?); + let error_code = CloseError::from_type_bit(t, dv(dec)?); let frame_type = if t == FRAME_TYPE_CONNECTION_CLOSE_TRANSPORT { dv(dec)? } else { @@ -631,8 +639,10 @@ mod tests { #[test] fn padding() { - let f = Frame::Padding; + let f = Frame::Padding(1); just_dec(&f, "00"); + let f = Frame::Padding(2); + just_dec(&f, "0000"); } #[test] @@ -888,8 +898,8 @@ mod tests { #[test] fn test_compare() { - let f1 = Frame::Padding; - let f2 = Frame::Padding; + let f1 = Frame::Padding(1); + let f2 = Frame::Padding(1); let f3 = Frame::Crypto { offset: 0, data: &[1, 2, 3], diff --git a/neqo-transport/src/packet/mod.rs b/neqo-transport/src/packet/mod.rs index 8458f69779..d11b3423a4 100644 --- a/neqo-transport/src/packet/mod.rs +++ b/neqo-transport/src/packet/mod.rs @@ -18,6 +18,7 @@ use neqo_crypto::random; use crate::{ cid::{ConnectionId, ConnectionIdDecoder, ConnectionIdRef, MAX_CONNECTION_ID_LEN}, crypto::{CryptoDxState, CryptoSpace, CryptoStates}, + frame::FRAME_TYPE_PADDING, version::{Version, WireVersion}, Error, Res, }; @@ -257,7 +258,8 @@ impl PacketBuilder { /// Returns true if padding was added. pub fn pad(&mut self) -> bool { if self.padding && !self.is_long() { - self.encoder.pad_to(self.limit, 0); + self.encoder + .pad_to(self.limit, FRAME_TYPE_PADDING.try_into().unwrap()); true } else { false diff --git a/neqo-transport/src/qlog.rs b/neqo-transport/src/qlog.rs index 2572966104..a8ad986d2a 100644 --- a/neqo-transport/src/qlog.rs +++ b/neqo-transport/src/qlog.rs @@ -195,7 +195,7 @@ pub fn packet_sent( ) { qlog.add_event_with_stream(|stream| { let mut d = Decoder::from(body); - let header = PacketHeader::with_type(to_qlog_pkt_type(pt), Some(pn), None, None, None); + let header = PacketHeader::with_type(pt.into(), Some(pn), None, None, None); let raw = RawInfo { length: Some(plen as u64), payload_length: None, @@ -205,7 +205,7 @@ pub fn packet_sent( let mut frames = SmallVec::new(); while d.remaining() > 0 { if let Ok(f) = Frame::decode(&mut d) { - frames.push(frame_to_qlogframe(&f)); + frames.push(QuicFrame::from(&f)); } else { qinfo!("qlog: invalid frame"); break; @@ -231,13 +231,8 @@ pub fn packet_sent( pub fn packet_dropped(qlog: &mut NeqoQlog, public_packet: &PublicPacket) { qlog.add_event_data(|| { - let header = PacketHeader::with_type( - to_qlog_pkt_type(public_packet.packet_type()), - None, - None, - None, - None, - ); + let header = + PacketHeader::with_type(public_packet.packet_type().into(), None, None, None, None); let raw = RawInfo { length: Some(public_packet.len() as u64), payload_length: None, @@ -259,8 +254,7 @@ pub fn packet_dropped(qlog: &mut NeqoQlog, public_packet: &PublicPacket) { pub fn packets_lost(qlog: &mut NeqoQlog, pkts: &[SentPacket]) { qlog.add_event_with_stream(|stream| { for pkt in pkts { - let header = - PacketHeader::with_type(to_qlog_pkt_type(pkt.pt), Some(pkt.pn), None, None, None); + let header = PacketHeader::with_type(pkt.pt.into(), Some(pkt.pn), None, None, None); let ev_data = EventData::PacketLost(PacketLost { header: Some(header), @@ -283,7 +277,7 @@ pub fn packet_received( let mut d = Decoder::from(&payload[..]); let header = PacketHeader::with_type( - to_qlog_pkt_type(public_packet.packet_type()), + public_packet.packet_type().into(), Some(payload.pn()), None, None, @@ -299,7 +293,7 @@ pub fn packet_received( while d.remaining() > 0 { if let Ok(f) = Frame::decode(&mut d) { - frames.push(frame_to_qlogframe(&f)); + frames.push(QuicFrame::from(&f)); } else { qinfo!("qlog: invalid frame"); break; @@ -393,173 +387,180 @@ pub fn metrics_updated(qlog: &mut NeqoQlog, updated_metrics: &[QlogMetric]) { #[allow(clippy::too_many_lines)] // Yeah, but it's a nice match. #[allow(clippy::cast_possible_truncation, clippy::cast_precision_loss)] // No choice here. -fn frame_to_qlogframe(frame: &Frame) -> QuicFrame { - match frame { - Frame::Padding => QuicFrame::Padding, - Frame::Ping => QuicFrame::Ping, - Frame::Ack { - largest_acknowledged, - ack_delay, - first_ack_range, - ack_ranges, - } => { - let ranges = - Frame::decode_ack_frame(*largest_acknowledged, *first_ack_range, ack_ranges).ok(); - - let acked_ranges = ranges.map(|all| { - AckedRanges::Double( - all.into_iter() - .map(RangeInclusive::into_inner) - .collect::>(), - ) - }); - - QuicFrame::Ack { - ack_delay: Some(*ack_delay as f32 / 1000.0), - acked_ranges, - ect1: None, - ect0: None, - ce: None, +impl From<&Frame<'_>> for QuicFrame { + fn from(frame: &Frame) -> Self { + match frame { + // TODO: Add payload length to `QuicFrame::Padding` once + // https://github.com/cloudflare/quiche/pull/1745 is available via the qlog crate. + Frame::Padding { .. } => QuicFrame::Padding, + Frame::Ping => QuicFrame::Ping, + Frame::Ack { + largest_acknowledged, + ack_delay, + first_ack_range, + ack_ranges, + } => { + let ranges = + Frame::decode_ack_frame(*largest_acknowledged, *first_ack_range, ack_ranges) + .ok(); + + let acked_ranges = ranges.map(|all| { + AckedRanges::Double( + all.into_iter() + .map(RangeInclusive::into_inner) + .collect::>(), + ) + }); + + QuicFrame::Ack { + ack_delay: Some(*ack_delay as f32 / 1000.0), + acked_ranges, + ect1: None, + ect0: None, + ce: None, + } } - } - Frame::ResetStream { - stream_id, - application_error_code, - final_size, - } => QuicFrame::ResetStream { - stream_id: stream_id.as_u64(), - error_code: *application_error_code, - final_size: *final_size, - }, - Frame::StopSending { - stream_id, - application_error_code, - } => QuicFrame::StopSending { - stream_id: stream_id.as_u64(), - error_code: *application_error_code, - }, - Frame::Crypto { offset, data } => QuicFrame::Crypto { - offset: *offset, - length: data.len() as u64, - }, - Frame::NewToken { token } => QuicFrame::NewToken { - token: qlog::Token { - ty: Some(qlog::TokenType::Retry), - details: None, - raw: Some(RawInfo { - data: Some(hex(token)), - length: Some(token.len() as u64), - payload_length: None, - }), + Frame::ResetStream { + stream_id, + application_error_code, + final_size, + } => QuicFrame::ResetStream { + stream_id: stream_id.as_u64(), + error_code: *application_error_code, + final_size: *final_size, + }, + Frame::StopSending { + stream_id, + application_error_code, + } => QuicFrame::StopSending { + stream_id: stream_id.as_u64(), + error_code: *application_error_code, + }, + Frame::Crypto { offset, data } => QuicFrame::Crypto { + offset: *offset, + length: data.len() as u64, + }, + Frame::NewToken { token } => QuicFrame::NewToken { + token: qlog::Token { + ty: Some(qlog::TokenType::Retry), + details: None, + raw: Some(RawInfo { + data: Some(hex(token)), + length: Some(token.len() as u64), + payload_length: None, + }), + }, }, - }, - Frame::Stream { - fin, - stream_id, - offset, - data, - .. - } => QuicFrame::Stream { - stream_id: stream_id.as_u64(), - offset: *offset, - length: data.len() as u64, - fin: Some(*fin), - raw: None, - }, - Frame::MaxData { maximum_data } => QuicFrame::MaxData { - maximum: *maximum_data, - }, - Frame::MaxStreamData { - stream_id, - maximum_stream_data, - } => QuicFrame::MaxStreamData { - stream_id: stream_id.as_u64(), - maximum: *maximum_stream_data, - }, - Frame::MaxStreams { - stream_type, - maximum_streams, - } => QuicFrame::MaxStreams { - stream_type: match stream_type { - NeqoStreamType::BiDi => StreamType::Bidirectional, - NeqoStreamType::UniDi => StreamType::Unidirectional, + Frame::Stream { + fin, + stream_id, + offset, + data, + .. + } => QuicFrame::Stream { + stream_id: stream_id.as_u64(), + offset: *offset, + length: data.len() as u64, + fin: Some(*fin), + raw: None, }, - maximum: *maximum_streams, - }, - Frame::DataBlocked { data_limit } => QuicFrame::DataBlocked { limit: *data_limit }, - Frame::StreamDataBlocked { - stream_id, - stream_data_limit, - } => QuicFrame::StreamDataBlocked { - stream_id: stream_id.as_u64(), - limit: *stream_data_limit, - }, - Frame::StreamsBlocked { - stream_type, - stream_limit, - } => QuicFrame::StreamsBlocked { - stream_type: match stream_type { - NeqoStreamType::BiDi => StreamType::Bidirectional, - NeqoStreamType::UniDi => StreamType::Unidirectional, + Frame::MaxData { maximum_data } => QuicFrame::MaxData { + maximum: *maximum_data, }, - limit: *stream_limit, - }, - Frame::NewConnectionId { - sequence_number, - retire_prior, - connection_id, - stateless_reset_token, - } => QuicFrame::NewConnectionId { - sequence_number: *sequence_number as u32, - retire_prior_to: *retire_prior as u32, - connection_id_length: Some(connection_id.len() as u8), - connection_id: hex(connection_id), - stateless_reset_token: Some(hex(stateless_reset_token)), - }, - Frame::RetireConnectionId { sequence_number } => QuicFrame::RetireConnectionId { - sequence_number: *sequence_number as u32, - }, - Frame::PathChallenge { data } => QuicFrame::PathChallenge { - data: Some(hex(data)), - }, - Frame::PathResponse { data } => QuicFrame::PathResponse { - data: Some(hex(data)), - }, - Frame::ConnectionClose { - error_code, - frame_type, - reason_phrase, - } => QuicFrame::ConnectionClose { - error_space: match error_code { - CloseError::Transport(_) => Some(ErrorSpace::TransportError), - CloseError::Application(_) => Some(ErrorSpace::ApplicationError), + Frame::MaxStreamData { + stream_id, + maximum_stream_data, + } => QuicFrame::MaxStreamData { + stream_id: stream_id.as_u64(), + maximum: *maximum_stream_data, }, - error_code: Some(error_code.code()), - error_code_value: Some(0), - reason: Some(String::from_utf8_lossy(reason_phrase).to_string()), - trigger_frame_type: Some(*frame_type), - }, - Frame::HandshakeDone => QuicFrame::HandshakeDone, - Frame::AckFrequency { .. } => QuicFrame::Unknown { - frame_type_value: None, - raw_frame_type: frame.get_type(), - raw: None, - }, - Frame::Datagram { data, .. } => QuicFrame::Datagram { - length: data.len() as u64, - raw: None, - }, + Frame::MaxStreams { + stream_type, + maximum_streams, + } => QuicFrame::MaxStreams { + stream_type: match stream_type { + NeqoStreamType::BiDi => StreamType::Bidirectional, + NeqoStreamType::UniDi => StreamType::Unidirectional, + }, + maximum: *maximum_streams, + }, + Frame::DataBlocked { data_limit } => QuicFrame::DataBlocked { limit: *data_limit }, + Frame::StreamDataBlocked { + stream_id, + stream_data_limit, + } => QuicFrame::StreamDataBlocked { + stream_id: stream_id.as_u64(), + limit: *stream_data_limit, + }, + Frame::StreamsBlocked { + stream_type, + stream_limit, + } => QuicFrame::StreamsBlocked { + stream_type: match stream_type { + NeqoStreamType::BiDi => StreamType::Bidirectional, + NeqoStreamType::UniDi => StreamType::Unidirectional, + }, + limit: *stream_limit, + }, + Frame::NewConnectionId { + sequence_number, + retire_prior, + connection_id, + stateless_reset_token, + } => QuicFrame::NewConnectionId { + sequence_number: *sequence_number as u32, + retire_prior_to: *retire_prior as u32, + connection_id_length: Some(connection_id.len() as u8), + connection_id: hex(connection_id), + stateless_reset_token: Some(hex(stateless_reset_token)), + }, + Frame::RetireConnectionId { sequence_number } => QuicFrame::RetireConnectionId { + sequence_number: *sequence_number as u32, + }, + Frame::PathChallenge { data } => QuicFrame::PathChallenge { + data: Some(hex(data)), + }, + Frame::PathResponse { data } => QuicFrame::PathResponse { + data: Some(hex(data)), + }, + Frame::ConnectionClose { + error_code, + frame_type, + reason_phrase, + } => QuicFrame::ConnectionClose { + error_space: match error_code { + CloseError::Transport(_) => Some(ErrorSpace::TransportError), + CloseError::Application(_) => Some(ErrorSpace::ApplicationError), + }, + error_code: Some(error_code.code()), + error_code_value: Some(0), + reason: Some(String::from_utf8_lossy(reason_phrase).to_string()), + trigger_frame_type: Some(*frame_type), + }, + Frame::HandshakeDone => QuicFrame::HandshakeDone, + Frame::AckFrequency { .. } => QuicFrame::Unknown { + frame_type_value: None, + raw_frame_type: frame.get_type(), + raw: None, + }, + Frame::Datagram { data, .. } => QuicFrame::Datagram { + length: data.len() as u64, + raw: None, + }, + } } } -fn to_qlog_pkt_type(ptype: PacketType) -> qlog::events::quic::PacketType { - match ptype { - PacketType::Initial => qlog::events::quic::PacketType::Initial, - PacketType::Handshake => qlog::events::quic::PacketType::Handshake, - PacketType::ZeroRtt => qlog::events::quic::PacketType::ZeroRtt, - PacketType::Short => qlog::events::quic::PacketType::OneRtt, - PacketType::Retry => qlog::events::quic::PacketType::Retry, - PacketType::VersionNegotiation => qlog::events::quic::PacketType::VersionNegotiation, - PacketType::OtherVersion => qlog::events::quic::PacketType::Unknown, +impl From for qlog::events::quic::PacketType { + fn from(value: PacketType) -> Self { + match value { + PacketType::Initial => qlog::events::quic::PacketType::Initial, + PacketType::Handshake => qlog::events::quic::PacketType::Handshake, + PacketType::ZeroRtt => qlog::events::quic::PacketType::ZeroRtt, + PacketType::Short => qlog::events::quic::PacketType::OneRtt, + PacketType::Retry => qlog::events::quic::PacketType::Retry, + PacketType::VersionNegotiation => qlog::events::quic::PacketType::VersionNegotiation, + PacketType::OtherVersion => qlog::events::quic::PacketType::Unknown, + } } } From a80db4759ed63c7a314e624a35a5055b5de916f4 Mon Sep 17 00:00:00 2001 From: Max Inden Date: Thu, 21 Mar 2024 23:47:22 +0100 Subject: [PATCH 22/30] feat(bin/client): add --stats flag printing connection statistics (#1766) This commit introduces the `--stats` flag to `neqo-client`. It will print the `neqo_transport::Stats` of the `Connection` after close. ``` $ cargo run --bin neqo-client -- --stats http://127.0.0.1:12345/10000000 stats for Client ... rx: 7728 drop 1 dup 0 saved 1 tx: 819 lost 12 lateack 0 ptoack 4 resumed: false frames rx: crypto 3 done 1 token 1 close 0 ack 40 (max 805) ping 0 padding 0 stream 7704 reset 0 stop 0 max: stream 0 data 0 stream_data 0 blocked: stream 0 data 0 stream_data 19 datagram 0 ncid 7 rcid 0 pchallenge 0 presponse 0 ack_frequency 4 frames tx: crypto 2 done 0 token 0 close 0 ack 783 (max 7769) ping 5 padding 0 stream 5 reset 0 stop 0 max: stream 0 data 0 stream_data 30 blocked: stream 0 data 0 stream_data 0 datagram 0 ncid 0 rcid 0 pchallenge 0 presponse 0 ack_frequency 2 ``` Co-authored-by: Lars Eggert --- neqo-bin/src/bin/client/http09.rs | 4 ++++ neqo-bin/src/bin/client/http3.rs | 4 ++++ neqo-bin/src/bin/client/main.rs | 8 ++++++++ neqo-transport/src/stats.rs | 2 +- 4 files changed, 17 insertions(+), 1 deletion(-) diff --git a/neqo-bin/src/bin/client/http09.rs b/neqo-bin/src/bin/client/http09.rs index 6d9a26fec2..9135eb5bb8 100644 --- a/neqo-bin/src/bin/client/http09.rs +++ b/neqo-bin/src/bin/client/http09.rs @@ -153,6 +153,10 @@ impl super::Client for Connection { fn is_closed(&self) -> bool { matches!(self.state(), State::Closed(..)) } + + fn stats(&self) -> neqo_transport::Stats { + self.stats() + } } impl<'b> Handler<'b> { diff --git a/neqo-bin/src/bin/client/http3.rs b/neqo-bin/src/bin/client/http3.rs index 07cc0e4cde..21637fb3d6 100644 --- a/neqo-bin/src/bin/client/http3.rs +++ b/neqo-bin/src/bin/client/http3.rs @@ -125,6 +125,10 @@ impl super::Client for Http3Client { { self.close(now, app_error, msg); } + + fn stats(&self) -> neqo_transport::Stats { + self.transport_stats() + } } impl<'a> super::Handler for Handler<'a> { diff --git a/neqo-bin/src/bin/client/main.rs b/neqo-bin/src/bin/client/main.rs index 7b1a5928a6..3332d79438 100644 --- a/neqo-bin/src/bin/client/main.rs +++ b/neqo-bin/src/bin/client/main.rs @@ -179,6 +179,10 @@ pub struct Args { /// The request size that will be used for upload test. #[arg(name = "upload-size", long, default_value = "100")] upload_size: usize, + + /// Print connection stats after close. + #[arg(name = "stats", long)] + stats: bool, } impl Args { @@ -327,6 +331,7 @@ trait Client { where S: AsRef + Display; fn is_closed(&self) -> bool; + fn stats(&self) -> neqo_transport::Stats; } struct Runner<'a, H: Handler> { @@ -361,6 +366,9 @@ impl<'a, H: Handler> Runner<'a, H> { self.process(None).await?; if self.client.is_closed() { + if self.args.stats { + qinfo!("{:?}", self.client.stats()); + } return Ok(self.handler.take_token()); } diff --git a/neqo-transport/src/stats.rs b/neqo-transport/src/stats.rs index 9eff503dcf..cdc378d71b 100644 --- a/neqo-transport/src/stats.rs +++ b/neqo-transport/src/stats.rs @@ -206,7 +206,7 @@ impl Debug for Stats { " tx: {} lost {} lateack {} ptoack {}", self.packets_tx, self.lost, self.late_ack, self.pto_ack )?; - writeln!(f, " resumed: {} ", self.resumed)?; + writeln!(f, " resumed: {}", self.resumed)?; writeln!(f, " frames rx:")?; self.frame_rx.fmt(f)?; writeln!(f, " frames tx:")?; From e4bc0c1ed4b3075d1a5d3ebff488d4ed74d4d260 Mon Sep 17 00:00:00 2001 From: Max Inden Date: Thu, 21 Mar 2024 23:47:58 +0100 Subject: [PATCH 23/30] feat(client,server): rework logging (#1692) * feat(client,server): rework logging - In `neqo-client` and `neqo-server` use `neqo_common::log` instead of `println!` and `eprintln!`. - Add `-q`, `-v`, `-vv`, `-vvv`, `-vvvv` log level flags via `clap_verbosity_flag`. - Set default log level to INFO. Demote many `qinfo!` to `qdebug!`. * fix(upload_test.sh): set RUST_LOG debug for neqo_transport::cc Needed in order for mozlog_neqo_cwnd.py to analyze cc. * Additional level reductions * Trigger CI --------- Co-authored-by: Lars Eggert --- neqo-bin/Cargo.toml | 1 + neqo-bin/src/bin/client/http09.rs | 26 ++++++++++++------------ neqo-bin/src/bin/client/http3.rs | 26 ++++++++++++------------ neqo-bin/src/bin/client/main.rs | 30 ++++++++++++++++------------ neqo-bin/src/bin/server/main.rs | 22 +++++++++++--------- neqo-bin/src/bin/server/old_https.rs | 12 +++++------ neqo-common/src/log.rs | 21 ++++++++++--------- neqo-crypto/src/agent.rs | 4 ++-- neqo-http3/src/connection.rs | 16 +++++++-------- neqo-http3/src/connection_client.rs | 4 ++-- neqo-http3/src/connection_server.rs | 4 ++-- neqo-http3/src/recv_message.rs | 2 +- neqo-http3/src/send_message.rs | 6 +++--- neqo-http3/src/server_events.rs | 8 ++++---- neqo-transport/src/cc/classic_cc.rs | 16 +++++++-------- neqo-transport/src/connection/mod.rs | 18 ++++++++--------- neqo-transport/src/crypto.rs | 8 ++++---- neqo-transport/src/lib.rs | 4 ++-- neqo-transport/src/path.rs | 2 +- neqo-transport/src/stats.rs | 4 ++-- test/upload_test.sh | 2 ++ 21 files changed, 125 insertions(+), 111 deletions(-) diff --git a/neqo-bin/Cargo.toml b/neqo-bin/Cargo.toml index d36d2ecdca..04210e00db 100644 --- a/neqo-bin/Cargo.toml +++ b/neqo-bin/Cargo.toml @@ -25,6 +25,7 @@ workspace = true [dependencies] # neqo-bin is not used in Firefox, so we can be liberal with dependency versions clap = { version = "4.4", default-features = false, features = ["std", "color", "help", "usage", "error-context", "suggestions", "derive"] } +clap-verbosity-flag = { version = "2.2", default-features = false } futures = { version = "0.3", default-features = false, features = ["alloc"] } hex = { version = "0.4", default-features = false, features = ["std"] } log = { version = "0.4", default-features = false } diff --git a/neqo-bin/src/bin/client/http09.rs b/neqo-bin/src/bin/client/http09.rs index 9135eb5bb8..372a112853 100644 --- a/neqo-bin/src/bin/client/http09.rs +++ b/neqo-bin/src/bin/client/http09.rs @@ -17,7 +17,7 @@ use std::{ time::Instant, }; -use neqo_common::{event::Provider, Datagram}; +use neqo_common::{event::Provider, qdebug, qinfo, qwarn, Datagram}; use neqo_crypto::{AuthenticationStatus, ResumptionToken}; use neqo_transport::{ Connection, ConnectionEvent, EmptyConnectionIdGenerator, Error, Output, State, StreamId, @@ -50,13 +50,13 @@ impl<'a> super::Handler for Handler<'a> { self.read(client, stream_id)?; } ConnectionEvent::SendStreamWritable { stream_id } => { - println!("stream {stream_id} writable"); + qdebug!("stream {stream_id} writable"); } ConnectionEvent::SendStreamComplete { stream_id } => { - println!("stream {stream_id} complete"); + qdebug!("stream {stream_id} complete"); } ConnectionEvent::SendStreamCreatable { stream_type } => { - println!("stream {stream_type:?} creatable"); + qdebug!("stream {stream_type:?} creatable"); if stream_type == StreamType::BiDi { self.download_urls(client); } @@ -64,7 +64,7 @@ impl<'a> super::Handler for Handler<'a> { ConnectionEvent::StateChange( State::WaitInitial | State::Handshaking | State::Connected, ) => { - println!("{event:?}"); + qdebug!("{event:?}"); self.download_urls(client); } ConnectionEvent::StateChange(State::Confirmed) => { @@ -74,7 +74,7 @@ impl<'a> super::Handler for Handler<'a> { self.token = Some(token); } _ => { - println!("Unhandled event {event:?}"); + qwarn!("Unhandled event {event:?}"); } } } @@ -187,7 +187,7 @@ impl<'b> Handler<'b> { fn download_next(&mut self, client: &mut Connection) -> bool { if self.key_update.needed() { - println!("Deferring requests until after first key update"); + qdebug!("Deferring requests until after first key update"); return false; } let url = self @@ -196,7 +196,7 @@ impl<'b> Handler<'b> { .expect("download_next called with empty queue"); match client.stream_create(StreamType::BiDi) { Ok(client_stream_id) => { - println!("Created stream {client_stream_id} for {url}"); + qinfo!("Created stream {client_stream_id} for {url}"); let req = format!("GET {}\r\n", url.path()); _ = client .stream_send(client_stream_id, req.as_bytes()) @@ -207,7 +207,7 @@ impl<'b> Handler<'b> { true } Err(e @ (Error::StreamLimitError | Error::ConnectionState)) => { - println!("Cannot create stream {e:?}"); + qwarn!("Cannot create stream {e:?}"); self.url_queue.push_front(url); false } @@ -235,9 +235,9 @@ impl<'b> Handler<'b> { if let Some(out_file) = maybe_out_file { out_file.write_all(&data[..sz])?; } else if !output_read_data { - println!("READ[{stream_id}]: {sz} bytes"); + qdebug!("READ[{stream_id}]: {sz} bytes"); } else { - println!( + qdebug!( "READ[{}]: {}", stream_id, String::from_utf8(data.clone()).unwrap() @@ -252,7 +252,7 @@ impl<'b> Handler<'b> { fn read(&mut self, client: &mut Connection, stream_id: StreamId) -> Res<()> { match self.streams.get_mut(&stream_id) { None => { - println!("Data on unexpected stream: {stream_id}"); + qwarn!("Data on unexpected stream: {stream_id}"); return Ok(()); } Some(maybe_out_file) => { @@ -267,7 +267,7 @@ impl<'b> Handler<'b> { if let Some(mut out_file) = maybe_out_file.take() { out_file.flush()?; } else { - println!(""); + qinfo!(""); } self.streams.remove(&stream_id); self.download_urls(client); diff --git a/neqo-bin/src/bin/client/http3.rs b/neqo-bin/src/bin/client/http3.rs index 21637fb3d6..e9f5e406a5 100644 --- a/neqo-bin/src/bin/client/http3.rs +++ b/neqo-bin/src/bin/client/http3.rs @@ -18,7 +18,7 @@ use std::{ time::Instant, }; -use neqo_common::{event::Provider, hex, Datagram, Header}; +use neqo_common::{event::Provider, hex, qdebug, qinfo, qwarn, Datagram, Header}; use neqo_crypto::{AuthenticationStatus, ResumptionToken}; use neqo_http3::{Error, Http3Client, Http3ClientEvent, Http3Parameters, Http3State, Priority}; use neqo_transport::{ @@ -149,7 +149,7 @@ impl<'a> super::Handler for Handler<'a> { if let Some(handler) = self.url_handler.stream_handler(stream_id) { handler.process_header_ready(stream_id, fin, headers); } else { - println!("Data on unexpected stream: {stream_id}"); + qwarn!("Data on unexpected stream: {stream_id}"); } if fin { self.url_handler.on_stream_fin(client, stream_id); @@ -159,7 +159,7 @@ impl<'a> super::Handler for Handler<'a> { let mut stream_done = false; match self.url_handler.stream_handler(stream_id) { None => { - println!("Data on unexpected stream: {stream_id}"); + qwarn!("Data on unexpected stream: {stream_id}"); } Some(handler) => loop { let mut data = vec![0; 4096]; @@ -193,7 +193,7 @@ impl<'a> super::Handler for Handler<'a> { Http3ClientEvent::DataWritable { stream_id } => { match self.url_handler.stream_handler(stream_id) { None => { - println!("Data on unexpected stream: {stream_id}"); + qwarn!("Data on unexpected stream: {stream_id}"); } Some(handler) => { handler.process_data_writable(client, stream_id); @@ -206,7 +206,7 @@ impl<'a> super::Handler for Handler<'a> { } Http3ClientEvent::ResumptionToken(t) => self.token = Some(t), _ => { - println!("Unhandled event {event:?}"); + qwarn!("Unhandled event {event:?}"); } } } @@ -279,7 +279,7 @@ struct DownloadStreamHandler { impl StreamHandler for DownloadStreamHandler { fn process_header_ready(&mut self, stream_id: StreamId, fin: bool, headers: Vec
) { if self.out_file.is_none() { - println!("READ HEADERS[{stream_id}]: fin={fin} {headers:?}"); + qdebug!("READ HEADERS[{stream_id}]: fin={fin} {headers:?}"); } } @@ -297,18 +297,18 @@ impl StreamHandler for DownloadStreamHandler { } return Ok(true); } else if !output_read_data { - println!("READ[{stream_id}]: {sz} bytes"); + qdebug!("READ[{stream_id}]: {sz} bytes"); } else if let Ok(txt) = String::from_utf8(data.clone()) { - println!("READ[{stream_id}]: {txt}"); + qdebug!("READ[{stream_id}]: {txt}"); } else { - println!("READ[{}]: 0x{}", stream_id, hex(&data)); + qdebug!("READ[{}]: 0x{}", stream_id, hex(&data)); } if fin { if let Some(mut out_file) = self.out_file.take() { out_file.flush()?; } else { - println!(""); + qdebug!(""); } } @@ -327,7 +327,7 @@ struct UploadStreamHandler { impl StreamHandler for UploadStreamHandler { fn process_header_ready(&mut self, stream_id: StreamId, fin: bool, headers: Vec
) { - println!("READ HEADERS[{stream_id}]: fin={fin} {headers:?}"); + qdebug!("READ HEADERS[{stream_id}]: fin={fin} {headers:?}"); } fn process_data_readable( @@ -343,7 +343,7 @@ impl StreamHandler for UploadStreamHandler { let parsed: usize = trimmed_txt.parse().unwrap(); if parsed == self.data.len() { let upload_time = Instant::now().duration_since(self.start); - println!("Stream ID: {stream_id:?}, Upload time: {upload_time:?}"); + qinfo!("Stream ID: {stream_id:?}, Upload time: {upload_time:?}"); } } else { panic!("Unexpected data [{}]: 0x{}", stream_id, hex(&data)); @@ -411,7 +411,7 @@ impl<'a> UrlHandler<'a> { Priority::default(), ) { Ok(client_stream_id) => { - println!("Successfully created stream id {client_stream_id} for {url}"); + qdebug!("Successfully created stream id {client_stream_id} for {url}"); let handler: Box = StreamHandlerType::make_handler( &self.handler_type, diff --git a/neqo-bin/src/bin/client/main.rs b/neqo-bin/src/bin/client/main.rs index 3332d79438..63aa12db13 100644 --- a/neqo-bin/src/bin/client/main.rs +++ b/neqo-bin/src/bin/client/main.rs @@ -22,7 +22,7 @@ use futures::{ FutureExt, TryFutureExt, }; use neqo_bin::udp; -use neqo_common::{self as common, qdebug, qinfo, qlog::NeqoQlog, Datagram, Role}; +use neqo_common::{self as common, qdebug, qerror, qinfo, qlog::NeqoQlog, qwarn, Datagram, Role}; use neqo_crypto::{ constants::{TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256}, init, Cipher, ResumptionToken, @@ -103,7 +103,7 @@ impl KeyUpdateState { _ => return Err(e), } } else { - println!("Keys updated"); + qerror!("Keys updated"); self.0 = false; } } @@ -119,6 +119,9 @@ impl KeyUpdateState { #[command(author, version, about, long_about = None)] #[allow(clippy::struct_excessive_bools)] // Not a good use of that lint. pub struct Args { + #[command(flatten)] + verbose: clap_verbosity_flag::Verbosity, + #[command(flatten)] shared: neqo_bin::SharedArgs, @@ -211,7 +214,7 @@ impl Args { "http3" => { if let Some(testcase) = &self.test { if testcase.as_str() != "upload" { - eprintln!("Unsupported test case: {testcase}"); + qerror!("Unsupported test case: {testcase}"); exit(127) } @@ -223,7 +226,7 @@ impl Args { } "zerortt" | "resumption" => { if self.urls.len() < 2 { - eprintln!("Warning: resumption tests won't work without >1 URL"); + qerror!("Warning: resumption tests won't work without >1 URL"); exit(127); } self.shared.use_old_http = true; @@ -272,11 +275,11 @@ fn get_output_file( out_path.push(url_path); if all_paths.contains(&out_path) { - eprintln!("duplicate path {}", out_path.display()); + qerror!("duplicate path {}", out_path.display()); return None; } - eprintln!("Saving {url} to {out_path:?}"); + qinfo!("Saving {url} to {out_path:?}"); if let Some(parent) = out_path.parent() { create_dir_all(parent).ok()?; @@ -398,7 +401,7 @@ impl<'a, H: Handler> Runner<'a, H> { self.socket.send(dgram)?; } Output::Callback(new_timeout) => { - qinfo!("Setting timeout of {:?}", new_timeout); + qdebug!("Setting timeout of {:?}", new_timeout); self.timeout = Some(Box::pin(tokio::time::sleep(new_timeout))); break; } @@ -444,11 +447,12 @@ fn qlog_new(args: &Args, hostname: &str, cid: &ConnectionId) -> Res { #[tokio::main] async fn main() -> Res<()> { - init(); - let mut args = Args::parse(); + neqo_common::log::init(Some(args.verbose.log_level_filter())); args.update_for_tests(); + init(); + let urls_by_origin = args .urls .clone() @@ -461,14 +465,14 @@ async fn main() -> Res<()> { .filter_map(|(origin, urls)| match origin { Origin::Tuple(_scheme, h, p) => Some(((h, p), urls)), Origin::Opaque(x) => { - eprintln!("Opaque origin {x:?}"); + qwarn!("Opaque origin {x:?}"); None } }); for ((host, port), mut urls) in urls_by_origin { if args.resume && urls.len() < 2 { - eprintln!("Resumption to {host} cannot work without at least 2 URLs."); + qerror!("Resumption to {host} cannot work without at least 2 URLs."); exit(127); } @@ -479,7 +483,7 @@ async fn main() -> Res<()> { ) }); let Some(remote_addr) = remote_addr else { - eprintln!("No compatible address found for: {host}"); + qerror!("No compatible address found for: {host}"); exit(1); }; @@ -490,7 +494,7 @@ async fn main() -> Res<()> { let mut socket = udp::Socket::bind(local_addr)?; let real_local = socket.local_addr().unwrap(); - println!( + qinfo!( "{} Client connecting: {:?} -> {:?}", if args.shared.use_old_http { "H9" } else { "H3" }, real_local, diff --git a/neqo-bin/src/bin/server/main.rs b/neqo-bin/src/bin/server/main.rs index f694cf98c1..753794d6f6 100644 --- a/neqo-bin/src/bin/server/main.rs +++ b/neqo-bin/src/bin/server/main.rs @@ -25,7 +25,7 @@ use futures::{ FutureExt, }; use neqo_bin::udp; -use neqo_common::{hex, qinfo, qwarn, Datagram, Header}; +use neqo_common::{hex, qdebug, qerror, qinfo, qwarn, Datagram, Header}; use neqo_crypto::{ constants::{TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256}, generate_ech_keys, init_db, random, AntiReplay, Cipher, @@ -89,6 +89,9 @@ impl std::error::Error for ServerError {} #[derive(Debug, Parser)] #[command(author, version, about, long_about = None)] struct Args { + #[command(flatten)] + verbose: clap_verbosity_flag::Verbosity, + #[command(flatten)] shared: neqo_bin::SharedArgs, @@ -166,17 +169,17 @@ fn qns_read_response(filename: &str) -> Option> { OpenOptions::new() .read(true) .open(&file_path) - .map_err(|_e| eprintln!("Could not open {}", file_path.display())) + .map_err(|_e| qerror!("Could not open {}", file_path.display())) .ok() .and_then(|mut f| { let mut data = Vec::new(); match f.read_to_end(&mut data) { Ok(sz) => { - println!("{} bytes read from {}", sz, file_path.display()); + qinfo!("{} bytes read from {}", sz, file_path.display()); Some(data) } Err(e) => { - eprintln!("Error reading data: {e:?}"); + qerror!("Error reading data: {e:?}"); None } } @@ -312,7 +315,7 @@ impl HttpServer for SimpleServer { headers, fin, } => { - println!("Headers (request={stream} fin={fin}): {headers:?}"); + qdebug!("Headers (request={stream} fin={fin}): {headers:?}"); let post = if let Some(method) = headers.iter().find(|&h| h.name() == ":method") { @@ -428,7 +431,7 @@ impl ServersRunner { pub fn new(args: Args) -> Result { let hosts = args.listen_addresses(); if hosts.is_empty() { - eprintln!("No valid hosts defined"); + qerror!("No valid hosts defined"); return Err(io::Error::new(io::ErrorKind::InvalidInput, "No hosts")); } let sockets = hosts @@ -436,7 +439,7 @@ impl ServersRunner { .map(|host| { let socket = udp::Socket::bind(host)?; let local_addr = socket.local_addr()?; - println!("Server waiting for connection on: {local_addr:?}"); + qinfo!("Server waiting for connection on: {local_addr:?}"); Ok((host, socket)) }) @@ -479,7 +482,7 @@ impl ServersRunner { } if args.ech { let cfg = svr.enable_ech(); - println!("ECHConfigList: {}", hex(cfg)); + qinfo!("ECHConfigList: {}", hex(cfg)); } svr } @@ -507,7 +510,7 @@ impl ServersRunner { socket.send(dgram)?; } Output::Callback(new_timeout) => { - qinfo!("Setting timeout of {:?}", new_timeout); + qdebug!("Setting timeout of {:?}", new_timeout); self.timeout = Some(Box::pin(tokio::time::sleep(new_timeout))); break; } @@ -573,6 +576,7 @@ async fn main() -> Result<(), io::Error> { const HQ_INTEROP: &str = "hq-interop"; let mut args = Args::parse(); + neqo_common::log::init(Some(args.verbose.log_level_filter())); assert!(!args.key.is_empty(), "Need at least one key"); init_db(args.db.clone()); diff --git a/neqo-bin/src/bin/server/old_https.rs b/neqo-bin/src/bin/server/old_https.rs index f36c99c484..ec32032a05 100644 --- a/neqo-bin/src/bin/server/old_https.rs +++ b/neqo-bin/src/bin/server/old_https.rs @@ -8,7 +8,7 @@ use std::{ cell::RefCell, collections::HashMap, fmt::Display, path::PathBuf, rc::Rc, time::Instant, }; -use neqo_common::{event::Provider, hex, qdebug, Datagram}; +use neqo_common::{event::Provider, hex, qdebug, qinfo, qwarn, Datagram}; use neqo_crypto::{generate_ech_keys, random, AllowZeroRtt, AntiReplay, Cipher}; use neqo_http3::Error; use neqo_transport::{ @@ -149,7 +149,7 @@ impl Http09Server { } Some(path) => { let path = path.as_str(); - eprintln!("Path = '{path}'"); + qdebug!("Path = '{path}'"); if args.shared.qns_test.is_some() { qns_read_response(path) } else { @@ -164,7 +164,7 @@ impl Http09Server { fn stream_writable(&mut self, stream_id: StreamId, conn: &mut ActiveConnectionRef) { match self.write_state.get_mut(&stream_id) { None => { - eprintln!("Unknown stream {stream_id}, ignoring event"); + qwarn!("Unknown stream {stream_id}, ignoring event"); } Some(stream_state) => { stream_state.writable = true; @@ -177,7 +177,7 @@ impl Http09Server { *offset += sent; self.server.add_to_waiting(conn); if *offset == data.len() { - eprintln!("Sent {sent} on {stream_id}, closing"); + qinfo!("Sent {sent} on {stream_id}, closing"); conn.borrow_mut().stream_close_send(stream_id).unwrap(); self.write_state.remove(&stream_id); } else { @@ -202,7 +202,7 @@ impl HttpServer for Http09Server { None => break, Some(e) => e, }; - eprintln!("Event {event:?}"); + qdebug!("Event {event:?}"); match event { ConnectionEvent::NewStream { stream_id } => { self.write_state @@ -222,7 +222,7 @@ impl HttpServer for Http09Server { } ConnectionEvent::StateChange(_) | ConnectionEvent::SendStreamComplete { .. } => (), - e => eprintln!("unhandled event {e:?}"), + e => qwarn!("unhandled event {e:?}"), } } } diff --git a/neqo-common/src/log.rs b/neqo-common/src/log.rs index c5b89be8a6..04028a26bd 100644 --- a/neqo-common/src/log.rs +++ b/neqo-common/src/log.rs @@ -50,7 +50,7 @@ fn since_start() -> Duration { START_TIME.get_or_init(Instant::now).elapsed() } -pub fn init() { +pub fn init(level_filter: Option) { static INIT_ONCE: Once = Once::new(); if ::log::STATIC_MAX_LEVEL == ::log::LevelFilter::Off { @@ -59,6 +59,9 @@ pub fn init() { INIT_ONCE.call_once(|| { let mut builder = Builder::from_env("RUST_LOG"); + if let Some(filter) = level_filter { + builder.filter_level(filter); + } builder.format(|buf, record| { let elapsed = since_start(); writeln!( @@ -71,9 +74,9 @@ pub fn init() { ) }); if let Err(e) = builder.try_init() { - do_log!(::log::Level::Info, "Logging initialization error {:?}", e); + do_log!(::log::Level::Warn, "Logging initialization error {:?}", e); } else { - do_log!(::log::Level::Info, "Logging initialized"); + do_log!(::log::Level::Debug, "Logging initialized"); } }); } @@ -81,32 +84,32 @@ pub fn init() { #[macro_export] macro_rules! log_invoke { ($lvl:expr, $ctx:expr, $($arg:tt)*) => ( { - ::neqo_common::log::init(); + ::neqo_common::log::init(None); ::neqo_common::do_log!($lvl, "[{}] {}", $ctx, format!($($arg)*)); } ) } #[macro_export] macro_rules! qerror { ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Error, $ctx, $($arg)*);); - ($($arg:tt)*) => ( { ::neqo_common::log::init(); ::neqo_common::do_log!(::log::Level::Error, $($arg)*); } ); + ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Error, $($arg)*); } ); } #[macro_export] macro_rules! qwarn { ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Warn, $ctx, $($arg)*);); - ($($arg:tt)*) => ( { ::neqo_common::log::init(); ::neqo_common::do_log!(::log::Level::Warn, $($arg)*); } ); + ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Warn, $($arg)*); } ); } #[macro_export] macro_rules! qinfo { ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Info, $ctx, $($arg)*);); - ($($arg:tt)*) => ( { ::neqo_common::log::init(); ::neqo_common::do_log!(::log::Level::Info, $($arg)*); } ); + ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Info, $($arg)*); } ); } #[macro_export] macro_rules! qdebug { ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Debug, $ctx, $($arg)*);); - ($($arg:tt)*) => ( { ::neqo_common::log::init(); ::neqo_common::do_log!(::log::Level::Debug, $($arg)*); } ); + ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Debug, $($arg)*); } ); } #[macro_export] macro_rules! qtrace { ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Trace, $ctx, $($arg)*);); - ($($arg:tt)*) => ( { ::neqo_common::log::init(); ::neqo_common::do_log!(::log::Level::Trace, $($arg)*); } ); + ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Trace, $($arg)*); } ); } diff --git a/neqo-crypto/src/agent.rs b/neqo-crypto/src/agent.rs index 82a6dacd48..90085cb759 100644 --- a/neqo-crypto/src/agent.rs +++ b/neqo-crypto/src/agent.rs @@ -670,7 +670,7 @@ impl SecretAgent { let info = self.capture_error(SecretAgentInfo::new(self.fd))?; HandshakeState::Complete(info) }; - qinfo!([self], "state -> {:?}", self.state); + qdebug!([self], "state -> {:?}", self.state); Ok(()) } @@ -898,7 +898,7 @@ impl Client { let len = usize::try_from(len).unwrap(); let mut v = Vec::with_capacity(len); v.extend_from_slice(null_safe_slice(token, len)); - qinfo!( + qdebug!( [format!("{fd:p}")], "Got resumption token {}", hex_snip_middle(&v) diff --git a/neqo-http3/src/connection.rs b/neqo-http3/src/connection.rs index 287ea2c2af..cfa78df787 100644 --- a/neqo-http3/src/connection.rs +++ b/neqo-http3/src/connection.rs @@ -354,7 +354,7 @@ impl Http3Connection { /// This function creates and initializes, i.e. send stream type, the control and qpack /// streams. fn initialize_http3_connection(&mut self, conn: &mut Connection) -> Res<()> { - qinfo!([self], "Initialize the http3 connection."); + qdebug!([self], "Initialize the http3 connection."); self.control_stream_local.create(conn)?; self.send_settings(); @@ -704,7 +704,7 @@ impl Http3Connection { ); } NewStreamType::Decoder => { - qinfo!([self], "A new remote qpack encoder stream {}", stream_id); + qdebug!([self], "A new remote qpack encoder stream {}", stream_id); self.check_stream_exists(Http3StreamType::Decoder)?; self.recv_streams.insert( stream_id, @@ -715,7 +715,7 @@ impl Http3Connection { ); } NewStreamType::Encoder => { - qinfo!([self], "A new remote qpack decoder stream {}", stream_id); + qdebug!([self], "A new remote qpack decoder stream {}", stream_id); self.check_stream_exists(Http3StreamType::Encoder)?; self.recv_streams.insert( stream_id, @@ -766,7 +766,7 @@ impl Http3Connection { /// This is called when an application closes the connection. pub fn close(&mut self, error: AppError) { - qinfo!([self], "Close connection error {:?}.", error); + qdebug!([self], "Close connection error {:?}.", error); self.state = Http3State::Closing(ConnectionError::Application(error)); if (!self.send_streams.is_empty() || !self.recv_streams.is_empty()) && (error == 0) { qwarn!("close(0) called when streams still active"); @@ -952,7 +952,7 @@ impl Http3Connection { stream_id: StreamId, buf: &mut [u8], ) -> Res<(usize, bool)> { - qinfo!([self], "read_data from stream {}.", stream_id); + qdebug!([self], "read_data from stream {}.", stream_id); let res = self .recv_streams .get_mut(&stream_id) @@ -1091,7 +1091,7 @@ impl Http3Connection { /// This is called when an application wants to close the sending side of a stream. pub fn stream_close_send(&mut self, conn: &mut Connection, stream_id: StreamId) -> Res<()> { - qinfo!([self], "Close the sending side for stream {}.", stream_id); + qdebug!([self], "Close the sending side for stream {}.", stream_id); debug_assert!(self.state.active()); let send_stream = self .send_streams @@ -1402,7 +1402,7 @@ impl Http3Connection { /// `PriorityUpdateRequestPush` which handling is specific to the client and server, we must /// give them to the specific client/server handler. fn handle_control_frame(&mut self, f: HFrame) -> Res> { - qinfo!([self], "Handle a control frame {:?}", f); + qdebug!([self], "Handle a control frame {:?}", f); if !matches!(f, HFrame::Settings { .. }) && !matches!( self.settings_state, @@ -1433,7 +1433,7 @@ impl Http3Connection { } fn handle_settings(&mut self, new_settings: HSettings) -> Res<()> { - qinfo!([self], "Handle SETTINGS frame."); + qdebug!([self], "Handle SETTINGS frame."); match &self.settings_state { Http3RemoteSettingsState::NotReceived => { self.set_qpack_settings(&new_settings)?; diff --git a/neqo-http3/src/connection_client.rs b/neqo-http3/src/connection_client.rs index 52572a760d..836816b337 100644 --- a/neqo-http3/src/connection_client.rs +++ b/neqo-http3/src/connection_client.rs @@ -590,7 +590,7 @@ impl Http3Client { /// /// An error will be return if stream does not exist. pub fn stream_close_send(&mut self, stream_id: StreamId) -> Res<()> { - qinfo!([self], "Close sending side stream={}.", stream_id); + qdebug!([self], "Close sending side stream={}.", stream_id); self.base_handler .stream_close_send(&mut self.conn, stream_id) } @@ -652,7 +652,7 @@ impl Http3Client { stream_id: StreamId, buf: &mut [u8], ) -> Res<(usize, bool)> { - qinfo!([self], "read_data from stream {}.", stream_id); + qdebug!([self], "read_data from stream {}.", stream_id); let res = self.base_handler.read_data(&mut self.conn, stream_id, buf); if let Err(e) = &res { if e.connection_error() { diff --git a/neqo-http3/src/connection_server.rs b/neqo-http3/src/connection_server.rs index 097209a226..dcf759f177 100644 --- a/neqo-http3/src/connection_server.rs +++ b/neqo-http3/src/connection_server.rs @@ -98,7 +98,7 @@ impl Http3ServerHandler { /// /// An error will be returned if stream does not exist. pub fn stream_close_send(&mut self, stream_id: StreamId, conn: &mut Connection) -> Res<()> { - qinfo!([self], "Close sending side stream={}.", stream_id); + qdebug!([self], "Close sending side stream={}.", stream_id); self.base_handler.stream_close_send(conn, stream_id)?; self.base_handler.stream_has_pending_data(stream_id); self.needs_processing = true; @@ -408,7 +408,7 @@ impl Http3ServerHandler { stream_id: StreamId, buf: &mut [u8], ) -> Res<(usize, bool)> { - qinfo!([self], "read_data from stream {}.", stream_id); + qdebug!([self], "read_data from stream {}.", stream_id); let res = self.base_handler.read_data(conn, stream_id, buf); if let Err(e) = &res { if e.connection_error() { diff --git a/neqo-http3/src/recv_message.rs b/neqo-http3/src/recv_message.rs index be58b7e47c..55970849ef 100644 --- a/neqo-http3/src/recv_message.rs +++ b/neqo-http3/src/recv_message.rs @@ -271,7 +271,7 @@ impl RecvMessage { } (None, false) => break Ok(()), (Some(frame), fin) => { - qinfo!( + qdebug!( [self], "A new frame has been received: {:?}; state={:?} fin={}", frame, diff --git a/neqo-http3/src/send_message.rs b/neqo-http3/src/send_message.rs index c50e3e056a..15965c44f6 100644 --- a/neqo-http3/src/send_message.rs +++ b/neqo-http3/src/send_message.rs @@ -6,7 +6,7 @@ use std::{cell::RefCell, cmp::min, fmt::Debug, rc::Rc}; -use neqo_common::{qdebug, qinfo, qtrace, Encoder, Header, MessageType}; +use neqo_common::{qdebug, qtrace, Encoder, Header, MessageType}; use neqo_qpack::encoder::QPackEncoder; use neqo_transport::{Connection, StreamId}; @@ -119,7 +119,7 @@ impl SendMessage { encoder: Rc>, conn_events: Box, ) -> Self { - qinfo!("Create a request stream_id={}", stream_id); + qdebug!("Create a request stream_id={}", stream_id); Self { state: MessageState::WaitingForHeaders, message_type, @@ -193,7 +193,7 @@ impl SendStream for SendMessage { min(buf.len(), available - 9) }; - qinfo!( + qdebug!( [self], "send_request_body: available={} to_send={}.", available, diff --git a/neqo-http3/src/server_events.rs b/neqo-http3/src/server_events.rs index a85ece0bfb..214a48c757 100644 --- a/neqo-http3/src/server_events.rs +++ b/neqo-http3/src/server_events.rs @@ -13,7 +13,7 @@ use std::{ rc::Rc, }; -use neqo_common::{qdebug, qinfo, Encoder, Header}; +use neqo_common::{qdebug, Encoder, Header}; use neqo_transport::{ server::ActiveConnectionRef, AppError, Connection, DatagramTracking, StreamId, StreamType, }; @@ -189,7 +189,7 @@ impl Http3OrWebTransportStream { /// /// It may return `InvalidStreamId` if a stream does not exist anymore. pub fn send_data(&mut self, data: &[u8]) -> Res { - qinfo!([self], "Set new response."); + qdebug!([self], "Set new response."); self.stream_handler.send_data(data) } @@ -199,7 +199,7 @@ impl Http3OrWebTransportStream { /// /// It may return `InvalidStreamId` if a stream does not exist anymore. pub fn stream_close_send(&mut self) -> Res<()> { - qinfo!([self], "Set new response."); + qdebug!([self], "Set new response."); self.stream_handler.stream_close_send() } } @@ -270,7 +270,7 @@ impl WebTransportRequest { /// /// It may return `InvalidStreamId` if a stream does not exist anymore. pub fn response(&mut self, accept: &WebTransportSessionAcceptAction) -> Res<()> { - qinfo!([self], "Set a response for a WebTransport session."); + qdebug!([self], "Set a response for a WebTransport session."); self.stream_handler .handler .borrow_mut() diff --git a/neqo-transport/src/cc/classic_cc.rs b/neqo-transport/src/cc/classic_cc.rs index 89be6c4b0f..a63d6e0b38 100644 --- a/neqo-transport/src/cc/classic_cc.rs +++ b/neqo-transport/src/cc/classic_cc.rs @@ -164,7 +164,7 @@ impl CongestionControl for ClassicCongestionControl { let mut is_app_limited = true; let mut new_acked = 0; for pkt in acked_pkts { - qinfo!( + qdebug!( "packet_acked this={:p}, pn={}, ps={}, ignored={}, lost={}, rtt_est={:?}", self, pkt.pn, @@ -198,7 +198,7 @@ impl CongestionControl for ClassicCongestionControl { if is_app_limited { self.cc_algorithm.on_app_limited(); - qinfo!("on_packets_acked this={:p}, limited=1, bytes_in_flight={}, cwnd={}, state={:?}, new_acked={}", self, self.bytes_in_flight, self.congestion_window, self.state, new_acked); + qdebug!("on_packets_acked this={:p}, limited=1, bytes_in_flight={}, cwnd={}, state={:?}, new_acked={}", self, self.bytes_in_flight, self.congestion_window, self.state, new_acked); return; } @@ -208,7 +208,7 @@ impl CongestionControl for ClassicCongestionControl { let increase = min(self.ssthresh - self.congestion_window, self.acked_bytes); self.congestion_window += increase; self.acked_bytes -= increase; - qinfo!([self], "slow start += {}", increase); + qdebug!([self], "slow start += {}", increase); if self.congestion_window == self.ssthresh { // This doesn't look like it is necessary, but it can happen // after persistent congestion. @@ -249,7 +249,7 @@ impl CongestionControl for ClassicCongestionControl { QlogMetric::BytesInFlight(self.bytes_in_flight), ], ); - qinfo!([self], "on_packets_acked this={:p}, limited=0, bytes_in_flight={}, cwnd={}, state={:?}, new_acked={}", self, self.bytes_in_flight, self.congestion_window, self.state, new_acked); + qdebug!([self], "on_packets_acked this={:p}, limited=0, bytes_in_flight={}, cwnd={}, state={:?}, new_acked={}", self, self.bytes_in_flight, self.congestion_window, self.state, new_acked); } /// Update congestion controller state based on lost packets. @@ -265,7 +265,7 @@ impl CongestionControl for ClassicCongestionControl { } for pkt in lost_packets.iter().filter(|pkt| pkt.cc_in_flight()) { - qinfo!( + qdebug!( "packet_lost this={:p}, pn={}, ps={}", self, pkt.pn, @@ -286,7 +286,7 @@ impl CongestionControl for ClassicCongestionControl { pto, lost_packets, ); - qinfo!( + qdebug!( "on_packets_lost this={:p}, bytes_in_flight={}, cwnd={}, state={:?}", self, self.bytes_in_flight, @@ -335,7 +335,7 @@ impl CongestionControl for ClassicCongestionControl { } self.bytes_in_flight += pkt.size; - qinfo!( + qdebug!( "packet_sent this={:p}, pn={}, ps={}", self, pkt.pn, @@ -498,7 +498,7 @@ impl ClassicCongestionControl { self.congestion_window = max(cwnd, CWND_MIN); self.acked_bytes = acked_bytes; self.ssthresh = self.congestion_window; - qinfo!( + qdebug!( [self], "Cong event -> recovery; cwnd {}, ssthresh {}", self.congestion_window, diff --git a/neqo-transport/src/connection/mod.rs b/neqo-transport/src/connection/mod.rs index 8d1c106358..75c3490cba 100644 --- a/neqo-transport/src/connection/mod.rs +++ b/neqo-transport/src/connection/mod.rs @@ -778,7 +778,7 @@ impl Connection { }); enc.encode(extra); let records = s.send_ticket(now, enc.as_ref())?; - qinfo!([self], "send session ticket {}", hex(&enc)); + qdebug!([self], "send session ticket {}", hex(&enc)); self.crypto.buffer_records(records)?; } else { unreachable!(); @@ -824,7 +824,7 @@ impl Connection { /// the connection to fail. However, if no packets have been /// exchanged, it's not OK. pub fn authenticated(&mut self, status: AuthenticationStatus, now: Instant) { - qinfo!([self], "Authenticated {:?}", status); + qdebug!([self], "Authenticated {:?}", status); self.crypto.tls.authenticated(status); let res = self.handshake(now, self.version, PacketNumberSpace::Handshake, None); self.absorb_error(now, res); @@ -1154,7 +1154,7 @@ impl Connection { fn discard_keys(&mut self, space: PacketNumberSpace, now: Instant) { if self.crypto.discard(space) { - qinfo!([self], "Drop packet number space {}", space); + qdebug!([self], "Drop packet number space {}", space); let primary = self.paths.primary(); self.loss_recovery.discard(&primary, space, now); self.acks.drop_space(space); @@ -2307,7 +2307,7 @@ impl Connection { } if encoder.is_empty() { - qinfo!("TX blocked, profile={:?} ", profile); + qdebug!("TX blocked, profile={:?} ", profile); Ok(SendOption::No(profile.paced())) } else { // Perform additional padding for Initial packets as necessary. @@ -2351,7 +2351,7 @@ impl Connection { } fn client_start(&mut self, now: Instant) -> Res<()> { - qinfo!([self], "client_start"); + qdebug!([self], "client_start"); debug_assert_eq!(self.role, Role::Client); qlog::client_connection_started(&mut self.qlog, &self.paths.primary()); qlog::client_version_information_initiated(&mut self.qlog, self.conn_params.get_versions()); @@ -2583,7 +2583,7 @@ impl Connection { fn confirm_version(&mut self, v: Version) { if self.version != v { - qinfo!([self], "Compatible upgrade {:?} ==> {:?}", self.version, v); + qdebug!([self], "Compatible upgrade {:?} ==> {:?}", self.version, v); } self.crypto.confirm_version(v); self.version = v; @@ -2882,7 +2882,7 @@ impl Connection { R: IntoIterator> + Debug, R::IntoIter: ExactSizeIterator, { - qinfo!([self], "Rx ACK space={}, ranges={:?}", space, ack_ranges); + qdebug!([self], "Rx ACK space={}, ranges={:?}", space, ack_ranges); let (acked_packets, lost_packets) = self.loss_recovery.on_ack_received( &self.paths.primary(), @@ -2936,7 +2936,7 @@ impl Connection { } fn set_connected(&mut self, now: Instant) -> Res<()> { - qinfo!([self], "TLS connection complete"); + qdebug!([self], "TLS connection complete"); if self.crypto.tls.info().map(SecretAgentInfo::alpn).is_none() { qwarn!([self], "No ALPN. Closing connection."); // 120 = no_application_protocol @@ -2979,7 +2979,7 @@ impl Connection { fn set_state(&mut self, state: State) { if state > self.state { - qinfo!([self], "State change from {:?} -> {:?}", self.state, state); + qdebug!([self], "State change from {:?} -> {:?}", self.state, state); self.state = state.clone(); if self.state.closed() { self.streams.clear_streams(); diff --git a/neqo-transport/src/crypto.rs b/neqo-transport/src/crypto.rs index 9840eaa1e1..acc02172d5 100644 --- a/neqo-transport/src/crypto.rs +++ b/neqo-transport/src/crypto.rs @@ -317,7 +317,7 @@ impl Crypto { } pub fn acked(&mut self, token: &CryptoRecoveryToken) { - qinfo!( + qdebug!( "Acked crypto frame space={} offset={} length={}", token.space, token.offset, @@ -367,7 +367,7 @@ impl Crypto { }); enc.encode_vvec(new_token.unwrap_or(&[])); enc.encode(t.as_ref()); - qinfo!("resumption token {}", hex_snip_middle(enc.as_ref())); + qdebug!("resumption token {}", hex_snip_middle(enc.as_ref())); Some(ResumptionToken::new(enc.into(), t.expiration_time())) } else { None @@ -433,7 +433,7 @@ impl CryptoDxState { cipher: Cipher, fuzzing: bool, ) -> Self { - qinfo!( + qdebug!( "Making {:?} {} CryptoDxState, v={:?} cipher={}", direction, epoch, @@ -980,7 +980,7 @@ impl CryptoStates { }; for v in versions { - qinfo!( + qdebug!( [self], "Creating initial cipher state v={:?}, role={:?} dcid={}", v, diff --git a/neqo-transport/src/lib.rs b/neqo-transport/src/lib.rs index be482c466f..8fabbeb9a3 100644 --- a/neqo-transport/src/lib.rs +++ b/neqo-transport/src/lib.rs @@ -6,7 +6,7 @@ #![allow(clippy::module_name_repetitions)] // This lint doesn't work here. -use neqo_common::qinfo; +use neqo_common::qwarn; use neqo_crypto::Error as CryptoError; mod ackrate; @@ -165,7 +165,7 @@ impl Error { impl From for Error { fn from(err: CryptoError) -> Self { - qinfo!("Crypto operation failed {:?}", err); + qwarn!("Crypto operation failed {:?}", err); match err { CryptoError::EchRetry(config) => Self::EchRetry(config), _ => Self::CryptoError(err), diff --git a/neqo-transport/src/path.rs b/neqo-transport/src/path.rs index 4e8d9958ab..50e458ff36 100644 --- a/neqo-transport/src/path.rs +++ b/neqo-transport/src/path.rs @@ -216,7 +216,7 @@ impl Paths { /// to a migration from a peer, in which case the old path needs to be probed. #[must_use] fn select_primary(&mut self, path: &PathRef) -> Option { - qinfo!([path.borrow()], "set as primary path"); + qdebug!([path.borrow()], "set as primary path"); let old_path = self.primary.replace(Rc::clone(path)).map(|old| { old.borrow_mut().set_primary(false); old diff --git a/neqo-transport/src/stats.rs b/neqo-transport/src/stats.rs index cdc378d71b..0a61097010 100644 --- a/neqo-transport/src/stats.rs +++ b/neqo-transport/src/stats.rs @@ -14,7 +14,7 @@ use std::{ time::Duration, }; -use neqo_common::qinfo; +use neqo_common::qwarn; use crate::packet::PacketNumber; @@ -168,7 +168,7 @@ impl Stats { pub fn pkt_dropped(&mut self, reason: impl AsRef) { self.dropped_rx += 1; - qinfo!( + qwarn!( [self.info], "Dropped received packet: {}; Total: {}", reason.as_ref(), diff --git a/test/upload_test.sh b/test/upload_test.sh index 685a6a926c..8edb55e75d 100755 --- a/test/upload_test.sh +++ b/test/upload_test.sh @@ -2,6 +2,8 @@ set -e +export RUST_LOG=neqo_transport::cc=debug + server_address=127.0.0.1 server_port=4433 upload_size=8388608 From 8775c593e6bfeb0dea92889e99797480fcfb6967 Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Fri, 22 Mar 2024 14:15:02 +1000 Subject: [PATCH 24/30] No `--all-targets` during test --- .github/workflows/check.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/check.yml b/.github/workflows/check.yml index a89e4859d3..e17d563905 100644 --- a/.github/workflows/check.yml +++ b/.github/workflows/check.yml @@ -113,7 +113,7 @@ jobs: - name: Run tests and determine coverage run: | # shellcheck disable=SC2086 - cargo +${{ matrix.rust-toolchain }} llvm-cov nextest $BUILD_TYPE --all-targets --features ci --no-fail-fast --lcov --output-path lcov.info + cargo +${{ matrix.rust-toolchain }} llvm-cov nextest $BUILD_TYPE --features ci --no-fail-fast --lcov --output-path lcov.info cargo +${{ matrix.rust-toolchain }} bench --features bench --no-run - name: Run client/server transfer From bb3ab602481c0ec61597ef76242a3008108d524b Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Sat, 23 Mar 2024 17:13:01 +1000 Subject: [PATCH 25/30] Don't fail if cached main-branch results don't exist --- .github/workflows/bench.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/bench.yml b/.github/workflows/bench.yml index 81ef297a9e..134f78f559 100644 --- a/.github/workflows/bench.yml +++ b/.github/workflows/bench.yml @@ -115,7 +115,7 @@ jobs: echo "### Benchmark results" echo } > results.md - SHA=$(cat target/criterion/baseline-sha.txt) + SHA=$(cat target/criterion/baseline-sha.txt || true) if [ -n "$SHA" ]; then { echo "Performance differences relative to $SHA." From 9814bcd907039349fdf08fad39209a38515414d4 Mon Sep 17 00:00:00 2001 From: Max Inden Date: Sun, 24 Mar 2024 18:20:27 +0100 Subject: [PATCH 26/30] fix(transport/bench): increase transfer bench noise threshold (#1771) The default Criterion noise threshold is 0.01, i.e. ``` rust /// Changes the noise threshold for benchmarks in this group. The noise threshold /// is used to filter out small changes in performance from one run to the next, even if they /// are statistically significant. Sometimes benchmarking the same code twice will result in /// small but statistically significant differences solely because of noise. This provides a way /// to filter out some of these false positives at the cost of making it harder to detect small /// changes to the true performance of the benchmark. /// /// The default is 0.01, meaning that changes smaller than 1% will be ignored. /// /// # Panics /// /// Panics if the threshold is set to a negative value pub fn noise_threshold(&mut self, threshold: f64) -> &mut Self { ``` https://bheisler.github.io/criterion.rs/criterion/struct.BenchmarkGroup.html#method.noise_threshold Multiple runs of the `neqo-transport` `transfer/*` benchmarks showed between 2% and 3% performance regression on unrelated changes. - https://github.com/mozilla/neqo/actions/runs/8402727182/job/23012699901 - https://github.com/mozilla/neqo/actions/runs/8408164062/job/23024217712 To improve the signal-to-noise ratio of the benchmarks, set the noise threshold to 3%. --- neqo-transport/benches/transfer.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/neqo-transport/benches/transfer.rs b/neqo-transport/benches/transfer.rs index b13075a4ff..98bd29ff05 100644 --- a/neqo-transport/benches/transfer.rs +++ b/neqo-transport/benches/transfer.rs @@ -23,6 +23,7 @@ const TRANSFER_AMOUNT: usize = 1 << 22; // 4Mbyte fn benchmark_transfer(c: &mut Criterion, label: &str, seed: Option>) { let mut group = c.benchmark_group("transfer"); group.throughput(Throughput::Bytes(u64::try_from(TRANSFER_AMOUNT).unwrap())); + group.noise_threshold(0.03); group.bench_function(label, |b| { b.iter_batched( || { From 6691c1a570a37a388dc2495b0e592c572b4129b6 Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Mon, 25 Mar 2024 02:38:50 +0200 Subject: [PATCH 27/30] ci: Run a daily baseline benchmark of `main` for the cache (#1770) --- .github/workflows/bench.yml | 3 +++ 1 file changed, 3 insertions(+) diff --git a/.github/workflows/bench.yml b/.github/workflows/bench.yml index 134f78f559..0e215f571f 100644 --- a/.github/workflows/bench.yml +++ b/.github/workflows/bench.yml @@ -2,6 +2,9 @@ name: Bench on: workflow_call: workflow_dispatch: + schedule: + # Run at 1 AM each day, so there is a `main`-branch baseline in the cache. + - cron: '0 1 * * *' env: CARGO_PROFILE_BENCH_BUILD_OVERRIDE_DEBUG: true CARGO_PROFILE_RELEASE_DEBUG: true From d8eeddaad505710bb60361a4da66bf2743e64e1f Mon Sep 17 00:00:00 2001 From: Martin Thomson Date: Mon, 25 Mar 2024 17:16:18 +1100 Subject: [PATCH 28/30] Maybe make the timer wheel faster (#1763) * Maybe make the timer wheel faster * Add some panics docs * Work around mozpkix issue * Add a simple benchmark for the timer wheel * Remove workaround * Make clippy happy --------- Co-authored-by: Lars Eggert --- neqo-common/Cargo.toml | 5 ++++ neqo-common/benches/timer.rs | 39 ++++++++++++++++++++++++++++++ neqo-common/src/timer.rs | 46 +++++++++++++++++++++++++++--------- 3 files changed, 79 insertions(+), 11 deletions(-) create mode 100644 neqo-common/benches/timer.rs diff --git a/neqo-common/Cargo.toml b/neqo-common/Cargo.toml index 89eaa53890..069d67b834 100644 --- a/neqo-common/Cargo.toml +++ b/neqo-common/Cargo.toml @@ -21,6 +21,7 @@ qlog = { version = "0.12", default-features = false } time = { version = "0.3", default-features = false, features = ["formatting"] } [dev-dependencies] +criterion = { version = "0.5", default-features = false, features = ["html_reports"] } test-fixture = { path = "../test-fixture" } [features] @@ -33,3 +34,7 @@ features = ["timeapi"] [lib] # See https://github.com/bheisler/criterion.rs/blob/master/book/src/faq.md#cargo-bench-gives-unrecognized-option-errors-for-valid-command-line-options bench = false + +[[bench]] +name = "timer" +harness = false diff --git a/neqo-common/benches/timer.rs b/neqo-common/benches/timer.rs new file mode 100644 index 0000000000..5ac8019db4 --- /dev/null +++ b/neqo-common/benches/timer.rs @@ -0,0 +1,39 @@ +// Licensed under the Apache License, Version 2.0 or the MIT license +// , at your +// option. This file may not be copied, modified, or distributed +// except according to those terms. + +use std::time::{Duration, Instant}; + +use criterion::{criterion_group, criterion_main, Criterion}; +use neqo_common::timer::Timer; +use test_fixture::now; + +fn benchmark_timer(c: &mut Criterion) { + c.bench_function("drain a timer quickly", |b| { + b.iter_batched_ref( + make_timer, + |(_now, timer)| { + while let Some(t) = timer.next_time() { + assert!(timer.take_next(t).is_some()); + } + }, + criterion::BatchSize::SmallInput, + ); + }); +} + +fn make_timer() -> (Instant, Timer<()>) { + const TIMES: &[u64] = &[1, 2, 3, 5, 8, 13, 21, 34]; + + let now = now(); + let mut timer = Timer::new(now, Duration::from_millis(777), 100); + for &t in TIMES { + timer.add(now + Duration::from_secs(t), ()); + } + (now, timer) +} + +criterion_group!(benches, benchmark_timer); +criterion_main!(benches); diff --git a/neqo-common/src/timer.rs b/neqo-common/src/timer.rs index a413252e08..3feddb2226 100644 --- a/neqo-common/src/timer.rs +++ b/neqo-common/src/timer.rs @@ -5,6 +5,7 @@ // except according to those terms. use std::{ + collections::VecDeque, mem, time::{Duration, Instant}, }; @@ -27,7 +28,7 @@ impl TimerItem { /// points). Time is relative, the wheel has an origin time and it is unable to represent times that /// are more than `granularity * capacity` past that time. pub struct Timer { - items: Vec>>, + items: Vec>>, now: Instant, granularity: Duration, cursor: usize, @@ -55,9 +56,14 @@ impl Timer { /// Return a reference to the time of the next entry. #[must_use] pub fn next_time(&self) -> Option { - for i in 0..self.items.len() { - let idx = self.bucket(i); - if let Some(t) = self.items[idx].first() { + let idx = self.bucket(0); + for i in idx..self.items.len() { + if let Some(t) = self.items[i].front() { + return Some(t.time); + } + } + for i in 0..idx { + if let Some(t) = self.items[i].front() { return Some(t.time); } } @@ -145,6 +151,9 @@ impl Timer { /// Given knowledge of the time an item was added, remove it. /// This requires use of a predicate that identifies matching items. + /// + /// # Panics + /// Impossible, I think. pub fn remove(&mut self, time: Instant, mut selector: F) -> Option where F: FnMut(&T) -> bool, @@ -167,7 +176,7 @@ impl Timer { break; } if selector(&self.items[bucket][i].item) { - return Some(self.items[bucket].remove(i).item); + return Some(self.items[bucket].remove(i).unwrap().item); } } // ... then forwards. @@ -176,7 +185,7 @@ impl Timer { break; } if selector(&self.items[bucket][i].item) { - return Some(self.items[bucket].remove(i).item); + return Some(self.items[bucket].remove(i).unwrap().item); } } None @@ -185,10 +194,25 @@ impl Timer { /// Take the next item, unless there are no items with /// a timeout in the past relative to `until`. pub fn take_next(&mut self, until: Instant) -> Option { - for i in 0..self.items.len() { - let idx = self.bucket(i); - if !self.items[idx].is_empty() && self.items[idx][0].time <= until { - return Some(self.items[idx].remove(0).item); + fn maybe_take(v: &mut VecDeque>, until: Instant) -> Option { + if !v.is_empty() && v[0].time <= until { + Some(v.pop_front().unwrap().item) + } else { + None + } + } + + let idx = self.bucket(0); + for i in idx..self.items.len() { + let res = maybe_take(&mut self.items[i], until); + if res.is_some() { + return res; + } + } + for i in 0..idx { + let res = maybe_take(&mut self.items[i], until); + if res.is_some() { + return res; } } None @@ -201,7 +225,7 @@ impl Timer { if until >= self.now + self.span() { // Drain everything, so a clean sweep. let mut empty_items = Vec::with_capacity(self.items.len()); - empty_items.resize_with(self.items.len(), Vec::default); + empty_items.resize_with(self.items.len(), VecDeque::default); let mut items = mem::replace(&mut self.items, empty_items); self.now = until; self.cursor = 0; From 50876af998b97b4a249be814b32f675704f9714a Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Mon, 25 Mar 2024 09:50:45 +0200 Subject: [PATCH 29/30] ci: Run `clippy` for all features except `gecko` (#1768) * ci: Run `clippy` for all features except `gecko` * Make clippy happy * Update .github/workflows/check.yml Co-authored-by: Max Inden Signed-off-by: Lars Eggert --------- Signed-off-by: Lars Eggert Co-authored-by: Max Inden --- .github/workflows/check.yml | 2 +- neqo-crypto/src/aead_fuzzing.rs | 3 +++ neqo-crypto/src/lib.rs | 2 +- neqo-transport/benches/range_tracker.rs | 16 +++++++++------- neqo-transport/benches/rx_stream_orderer.rs | 4 ++-- neqo-transport/benches/transfer.rs | 8 ++++---- neqo-transport/src/connection/tests/fuzzing.rs | 2 +- neqo-transport/src/connection/tests/handshake.rs | 5 +++-- 8 files changed, 24 insertions(+), 18 deletions(-) diff --git a/.github/workflows/check.yml b/.github/workflows/check.yml index e17d563905..9dc8ff2b7f 100644 --- a/.github/workflows/check.yml +++ b/.github/workflows/check.yml @@ -148,7 +148,7 @@ jobs: # respective default features only. Can reveal warnings otherwise # hidden given that a plain cargo clippy combines all features of the # workspace. See e.g. https://github.com/mozilla/neqo/pull/1695. - cargo +${{ matrix.rust-toolchain }} hack clippy --all-targets -- -D warnings || ${{ matrix.rust-toolchain == 'nightly' }} + cargo +${{ matrix.rust-toolchain }} hack clippy --all-targets --feature-powerset --exclude-features gecko -- -D warnings || ${{ matrix.rust-toolchain == 'nightly' }} if: success() || failure() - name: Check rustdoc links diff --git a/neqo-crypto/src/aead_fuzzing.rs b/neqo-crypto/src/aead_fuzzing.rs index 4e5a6de07f..1f3bfb14bd 100644 --- a/neqo-crypto/src/aead_fuzzing.rs +++ b/neqo-crypto/src/aead_fuzzing.rs @@ -20,6 +20,7 @@ pub struct FuzzingAead { } impl FuzzingAead { + #[allow(clippy::missing_errors_doc)] pub fn new( fuzzing: bool, version: Version, @@ -44,6 +45,7 @@ impl FuzzingAead { } } + #[allow(clippy::missing_errors_doc)] pub fn encrypt<'a>( &self, count: u64, @@ -61,6 +63,7 @@ impl FuzzingAead { Ok(&output[..l + 16]) } + #[allow(clippy::missing_errors_doc)] pub fn decrypt<'a>( &self, count: u64, diff --git a/neqo-crypto/src/lib.rs b/neqo-crypto/src/lib.rs index 2ec1b4a3ea..45f61f6127 100644 --- a/neqo-crypto/src/lib.rs +++ b/neqo-crypto/src/lib.rs @@ -9,7 +9,7 @@ mod aead; #[cfg(feature = "fuzzing")] -mod aead_fuzzing; +pub mod aead_fuzzing; pub mod agent; mod agentio; mod auth; diff --git a/neqo-transport/benches/range_tracker.rs b/neqo-transport/benches/range_tracker.rs index c2f78f4874..ee611cf4ea 100644 --- a/neqo-transport/benches/range_tracker.rs +++ b/neqo-transport/benches/range_tracker.rs @@ -11,30 +11,32 @@ const CHUNK: u64 = 1000; const END: u64 = 100_000; fn build_coalesce(len: u64) -> RangeTracker { let mut used = RangeTracker::default(); - used.mark_acked(0, CHUNK as usize); - used.mark_sent(CHUNK, END as usize); + let chunk = usize::try_from(CHUNK).expect("should fit"); + used.mark_acked(0, chunk); + used.mark_sent(CHUNK, usize::try_from(END).expect("should fit")); // leave a gap or it will coalesce here for i in 2..=len { // These do not get immediately coalesced when marking since they're not at the end or start - used.mark_acked(i * CHUNK, CHUNK as usize); + used.mark_acked(i * CHUNK, chunk); } used } fn coalesce(c: &mut Criterion, count: u64) { + let chunk = usize::try_from(CHUNK).expect("should fit"); c.bench_function( &format!("coalesce_acked_from_zero {count}+1 entries"), |b| { b.iter_batched_ref( || build_coalesce(count), |used| { - used.mark_acked(CHUNK, CHUNK as usize); + used.mark_acked(CHUNK, chunk); let tail = (count + 1) * CHUNK; - used.mark_sent(tail, CHUNK as usize); - used.mark_acked(tail, CHUNK as usize); + used.mark_sent(tail, chunk); + used.mark_acked(tail, chunk); }, criterion::BatchSize::SmallInput, - ) + ); }, ); } diff --git a/neqo-transport/benches/rx_stream_orderer.rs b/neqo-transport/benches/rx_stream_orderer.rs index 0a1e763e97..d58e11ee86 100644 --- a/neqo-transport/benches/rx_stream_orderer.rs +++ b/neqo-transport/benches/rx_stream_orderer.rs @@ -11,14 +11,14 @@ fn rx_stream_orderer() { let mut rx = RxStreamOrderer::new(); let data: &[u8] = &[0; 1337]; - for i in 0..100000 { + for i in 0..100_000 { rx.inbound_frame(i * 1337, data); } } fn criterion_benchmark(c: &mut Criterion) { c.bench_function("RxStreamOrderer::inbound_frame()", |b| { - b.iter(rx_stream_orderer) + b.iter(rx_stream_orderer); }); } diff --git a/neqo-transport/benches/transfer.rs b/neqo-transport/benches/transfer.rs index 98bd29ff05..32959f6cb5 100644 --- a/neqo-transport/benches/transfer.rs +++ b/neqo-transport/benches/transfer.rs @@ -20,7 +20,7 @@ const ZERO: Duration = Duration::from_millis(0); const JITTER: Duration = Duration::from_millis(10); const TRANSFER_AMOUNT: usize = 1 << 22; // 4Mbyte -fn benchmark_transfer(c: &mut Criterion, label: &str, seed: Option>) { +fn benchmark_transfer(c: &mut Criterion, label: &str, seed: &Option>) { let mut group = c.benchmark_group("transfer"); group.throughput(Throughput::Bytes(u64::try_from(TRANSFER_AMOUNT).unwrap())); group.noise_threshold(0.03); @@ -45,7 +45,7 @@ fn benchmark_transfer(c: &mut Criterion, label: &str, seed: Option Date: Mon, 25 Mar 2024 13:33:08 +0200 Subject: [PATCH 30/30] ci: Compare performance to msquic (#1750) * ci: Compare performance to msquic In progress * Make it run * Fixes * Fix path * Use msquic `secnetperf` * Fix actionlint * Sigh * Retry * Better reporting * Debug * Retry * Sigh^2 * Fix * Fixes * Fixes * Update bench.yml * Fix * Squashed commit of the following: commit 9ca5ecc434bcd2609845b3f27d72960bd5c7cb0a Merge: f50f4148 f4083215 Author: Lars Eggert Date: Fri Mar 15 00:12:29 2024 +0200 Merge branch 'main' into ci-bench-cc Signed-off-by: Lars Eggert commit f50f4148bdb04c21e1e0165d72a8181cbbb39274 Merge: 8e5290b2 bc262a53 Author: Lars Eggert Date: Wed Mar 13 07:59:01 2024 +0200 Merge branch 'main' into ci-bench-cc commit 8e5290b213ae4ea9459cb1b71a73a7118d4bdcc4 Merge: f0cd19ec 2ff9742e Author: Lars Eggert Date: Tue Mar 12 22:42:54 2024 +0200 Merge branch 'main' into ci-bench-cc commit f0cd19ecb6196ab861658b675146b57cf20a1f9a Merge: b2bb855b 17c4175b Author: Lars Eggert Date: Tue Mar 12 21:54:08 2024 +0200 Merge branch 'main' into ci-bench-cc commit b2bb855b25349d6c51d5877b18ce631b1c800250 Merge: d072504e 4ea2c566 Author: Lars Eggert Date: Tue Mar 12 17:25:13 2024 +0200 Merge branch 'ci-bench-cc' of github.com:larseggert/neqo into ci-bench-cc commit d072504e5e80e2bb541f948c6c7733c78e93cb4a Author: Lars Eggert Date: Tue Mar 12 17:24:52 2024 +0200 Reorder things so `results.ms` is included in the exported artifact commit 4ea2c5669cfc6bbb9d4b7eddb66ad2f5ab4d6aac Merge: c82ff3af 5c728907 Author: Lars Eggert Date: Tue Mar 12 17:18:37 2024 +0200 Merge branch 'main' into ci-bench-cc commit c82ff3af7dd92aa4b2218992f85faaeff0b7cecb Author: Lars Eggert Date: Tue Mar 12 16:41:59 2024 +0200 `killall` -> `pkill` commit d37e7068e65ed407e0dc38b15e67707dfc628fd5 Author: Lars Eggert Date: Tue Mar 12 16:37:50 2024 +0200 Go back to `killall` commit 11320d0095e4a8d637c40ed7eb57886582ce4a21 Author: Lars Eggert Date: Tue Mar 12 16:11:38 2024 +0200 No -INT commit 407bd4ff8cc34767063b234af1737dfc2ea06339 Author: Lars Eggert Date: Tue Mar 12 14:33:52 2024 +0200 kill -> killall Also reduce test transfer size. commit 9d3a8b792e8fed127503fd93ff0406c0b462768d Author: Lars Eggert Date: Tue Mar 12 13:57:51 2024 +0200 Use temp dir, and fix path error commit 84e22060c89c88ca699c185dc21d86d0902c3be9 Merge: 925cc120 b0d816a8 Author: Lars Eggert Date: Tue Mar 12 11:10:41 2024 +0200 Merge branch 'main' into ci-bench-cc commit 925cc120fb1c1330a9b12c9cf3ed6e5107251158 Merge: 3241f931 58890383 Author: Lars Eggert Date: Tue Mar 12 11:05:42 2024 +0200 Merge branch 'main' into ci-bench-cc commit 3241f9312951f205c827397a7fc0c59e5ef0b1ee Merge: 02620a7c d48fbed7 Author: Lars Eggert Date: Tue Mar 12 09:59:24 2024 +0200 Merge branch 'main' into ci-bench-cc Signed-off-by: Lars Eggert commit 02620a7c48bdfcad703a47b25f324554edb5de7c Author: Lars Eggert Date: Tue Mar 12 09:57:33 2024 +0200 Try to kill via `$!` commit b32ce9ef7b93c0960c071594b91cddc9fa674292 Merge: 9ea3a991 db1dbb29 Author: Lars Eggert Date: Tue Mar 12 09:15:18 2024 +0200 Merge branch 'ci-bench-cc' of github.com:larseggert/neqo into ci-bench-cc commit 9ea3a99119e9ad19c0e7157b8218d0a631d1de95 Author: Lars Eggert Date: Tue Mar 12 09:15:05 2024 +0200 Address comments from @martinthomson commit db1dbb29af26054d14a12c8d5b7f074bdc9c0c2b Merge: 681bbb7c 869afeaa Author: Lars Eggert Date: Mon Mar 11 19:33:53 2024 +0200 Merge branch 'main' into ci-bench-cc commit 681bbb7c6787094ff085aa6a65edff1dd0e2dd38 Merge: bd742af1 532dcc5f Author: Lars Eggert Date: Mon Mar 11 18:21:06 2024 +0200 Merge branch 'main' into ci-bench-cc Signed-off-by: Lars Eggert commit bd742af1b5b56422294a01a43ed50388d1bc31f5 Author: Lars Eggert Date: Mon Mar 11 17:00:34 2024 +0200 mkdir -p commit bc7b99fe0b156294590dda561318283693b88df6 Author: Lars Eggert Date: Mon Mar 11 16:29:14 2024 +0200 Fix commit e7bf50959d1c24b430414f38f242dd086b483a83 Merge: de64b3e1 cbd44418 Author: Lars Eggert Date: Mon Mar 11 16:27:56 2024 +0200 Merge branch 'main' into ci-bench-cc commit de64b3e1a0108a35af58cb8d6d433a576eaa13c4 Author: Lars Eggert Date: Mon Mar 11 16:00:19 2024 +0200 Wait for output before continuing commit 12386a32c2179727a6b4779d0ed96373571cfafd Author: Lars Eggert Date: Mon Mar 11 15:25:40 2024 +0200 ci: Benchmark NewReno and Cubic * Fixes * Fix * Fixes * Tweaks * Debug * actionlint * Fix sed * Pacing changed * Fixes * msquic server exits with non-zero * echo * Again * Again * A new hope * Finalize * Fixes * ls * Add comments * Report transfer size * Again * Quiet the server down * Remove debug output * Reformat table * Fix * Fix table * Mac sed != GNU sed * Avoid piping commands into themselves * Fix comment --------- Signed-off-by: Lars Eggert --- .github/actions/rust/action.yml | 2 +- .github/workflows/bench.yml | 158 +++++++++++++++++++-------- neqo-bin/src/bin/server/old_https.rs | 2 +- 3 files changed, 117 insertions(+), 45 deletions(-) diff --git a/.github/actions/rust/action.yml b/.github/actions/rust/action.yml index bfb09d332d..4b03b37b8d 100644 --- a/.github/actions/rust/action.yml +++ b/.github/actions/rust/action.yml @@ -30,7 +30,7 @@ runs: - name: Install Rust tools shell: bash - run: cargo +${{ inputs.version }} binstall --no-confirm cargo-llvm-cov cargo-nextest flamegraph cargo-hack cargo-mutants + run: cargo +${{ inputs.version }} binstall --no-confirm cargo-llvm-cov cargo-nextest flamegraph cargo-hack cargo-mutants hyperfine # sccache slows CI down, so we leave it disabled. # Leaving the steps below commented out, so we can re-evaluate enabling it later. diff --git a/.github/workflows/bench.yml b/.github/workflows/bench.yml index 0e215f571f..80c51c236d 100644 --- a/.github/workflows/bench.yml +++ b/.github/workflows/bench.yml @@ -12,7 +12,7 @@ env: RUST_BACKTRACE: 1 TOOLCHAIN: nightly RUSTFLAGS: -C link-arg=-fuse-ld=lld -C link-arg=-Wl,--no-rosegment, -C force-frame-pointers=yes - PERF_CMD: record -o perf.data -F997 --call-graph fp -g + PERF_OPT: record -F997 --call-graph fp -g jobs: bench: @@ -23,9 +23,17 @@ jobs: shell: bash steps: - - name: Checkout + - name: Checkout neqo uses: actions/checkout@v4 + - name: Checkout msquic + uses: actions/checkout@v4 + with: + repository: microsoft/msquic + ref: main + path: msquic + submodules: true + - name: Set PATH run: echo "/home/bench/.cargo/bin" >> "${GITHUB_PATH}" @@ -38,10 +46,17 @@ jobs: - name: Fetch and build NSS and NSPR uses: ./.github/actions/nss - - name: Build + - name: Build neqo run: | cargo "+$TOOLCHAIN" bench --features bench --no-run - cargo "+$TOOLCHAIN" build --release --bin neqo-client --bin neqo-server + cargo "+$TOOLCHAIN" build --release + + - name: Build msquic + run: | + mkdir -p msquic/build + cd msquic/build + cmake -GNinja -DCMAKE_BUILD_TYPE=RelWithDebInfo -DQUIC_BUILD_TOOLS=1 -DQUIC_BUILD_PERF=1 .. + cmake --build . - name: Download cached main-branch results id: criterion-cache @@ -61,56 +76,107 @@ jobs: taskset -c 0 nice -n -20 \ cargo "+$TOOLCHAIN" bench --features bench -- --noplot | tee results.txt - # Pin the transfer benchmark to core 0 and run it at elevated priority inside perf. - # Work around https://github.com/flamegraph-rs/flamegraph/issues/248 by passing explicit perf arguments. - - name: Profile cargo bench transfer - run: | - taskset -c 0 nice -n -20 \ - cargo "+$TOOLCHAIN" flamegraph -v -c "$PERF_CMD" --features bench --bench transfer -- \ - --bench --exact "Run multiple transfers with varying seeds" --noplot - - - name: Profile client/server transfer - run: | - { mkdir server; \ - cd server; \ - taskset -c 0 nice -n -20 \ - cargo "+$TOOLCHAIN" flamegraph -v -c "$PERF_CMD" \ - --bin neqo-server -- --db ../test-fixture/db "$HOST:4433" || true; } & - mkdir client; \ - cd client; \ - time taskset -c 1 nice -n -20 \ - cargo "+$TOOLCHAIN" flamegraph -v -c "$PERF_CMD" \ - --bin neqo-client -- --output-dir . "https://$HOST:4433/$SIZE" - killall -INT neqo-server - cd ${{ github.workspace }} - [ "$(wc -c < client/"$SIZE")" -eq "$SIZE" ] || exit 1 + # Compare various configurations of neqo against msquic, and gather perf data + # during the hyperfine runs. + - name: Compare neqo and msquic env: - HOST: localhost - SIZE: 1073741824 # 1 GB + HOST: 127.0.0.1 + PORT: 4433 + SIZE: 134217728 # 128 MB + run: | + TMP=$(mktemp -d) + # Make a cert and key for msquic. + openssl req -nodes -new -x509 -keyout "$TMP/key" -out "$TMP/cert" -subj "/CN=DOMAIN" 2>/dev/null + # Make a test file for msquic to serve. + truncate -s "$SIZE" "$TMP/$SIZE" + # Define the commands to run for each client and server. + declare -A client_cmd=( + ["neqo"]="target/release/neqo-client _cc _pacing --output-dir . -o -a hq-interop -Q 1 https://$HOST:$PORT/$SIZE" + ["msquic"]="msquic/build/bin/Release/quicinterop -test:D -custom:$HOST -port:$PORT -urls:https://$HOST:$PORT/$SIZE" + ) + declare -A server_cmd=( + ["neqo"]="target/release/neqo-server _cc _pacing -o -a hq-interop -Q 1 $HOST:$PORT 2> /dev/null" + ["msquic"]="msquic/build/bin/Release/quicinteropserver -root:$TMP -listen:$HOST -port:$PORT -file:$TMP/cert -key:$TMP/key -noexit > /dev/null || true" + ) + + # Replace various placeholders in the commands with the actual values. + # Also generate an extension to append to the file name. + function transmogrify { + CMD=$1 + local cc=$2 + local pacing=$3 + if [ "$cc" != "" ]; then + CMD=${CMD//_cc/--cc $cc} + EXT="-$cc" + fi + if [ "$pacing" == "on" ]; then + CMD=${CMD//_pacing/} + EXT="$EXT-pacing" + else + CMD=${CMD//_pacing/--no-pacing} + EXT="$EXT-nopacing" + fi + } + + for server in msquic neqo; do + for client in msquic neqo; do + # msquic doesn't let us configure the congestion control or pacing. + if [ "$client" == "msquic" ] && [ "$server" == "msquic" ]; then + cc_opt=("") + pacing_opt=("") + else + cc_opt=("reno" "cubic") + pacing_opt=("on" "") + fi + for cc in "${cc_opt[@]}"; do + for pacing in "${pacing_opt[@]}"; do + # Make a tag string for this test, for the results. + TAG="$client,$server,$cc,$pacing" + echo "Running benchmarks for $TAG" | tee -a comparison.txt + transmogrify "${server_cmd[$server]}" "$cc" "$pacing" + # shellcheck disable=SC2086 + taskset -c 0 nice -n -20 \ + perf $PERF_OPT -o "$client-$server$EXT.server.perf" $CMD & + PID=$! + transmogrify "${client_cmd[$client]}" "$cc" "$pacing" + # shellcheck disable=SC2086 + taskset -c 1 nice -n -20 \ + perf $PERF_OPT -o "$client-$server$EXT.client.perf" \ + hyperfine -N --output null -w 1 -s "sleep 1" -n "$TAG" -u millisecond --export-markdown step.md "$CMD" | + tee -a comparison.txt + echo >> comparison.txt + kill $PID + cat step.md >> steps.md + # Sanity check the size of the last retrieved file. + [ "$(wc -c <"$SIZE")" -eq "$SIZE" ] || exit 1 + done + done + done + done + # Merge the results tables generated by hyperfine into a single table. + echo "Transfer of $SIZE bytes over loopback." > comparison.md + awk '(!/^\| Command/ || !c++) && (!/^\|:/ || !d++)' < steps.md |\ + sed -E 's/`//g; s/^\|:/\|:---\|:---\|:---\|:/g; s/,/ \| /g; s/^\| Command/\| Client \| Server \| CC \| Pacing/g' >> comparison.md + rm -r "$TMP" # Re-enable turboboost, hyperthreading and use powersave governor. - name: Restore machine run: sudo /root/bin/unprep.sh if: success() || failure() || cancelled() - - name: Convert for profiler.firefox.com + - name: Post-process perf data run: | - perf script -i perf.data -F +pid > transfer.perf & - perf script -i client/perf.data -F +pid > client.perf & - perf script -i server/perf.data -F +pid > server.perf & + for f in *.perf; do + # Convert for profiler.firefox.com + perf script -i "$f" -F +pid > "$f.fx" & + # Generate perf reports + perf report -i "$f" --no-children --stdio > "$f.txt" & + # Generate flamegraphs + flamegraph --perfdata "$f" --palette rust -o "${f//.perf/.svg}" & + done wait - mv flamegraph.svg transfer.svg - mv client/flamegraph.svg client.svg - mv server/flamegraph.svg server.svg rm neqo.svg - - name: Generate perf reports - run: | - perf report -i perf.data --no-children --stdio > transfer.perf.txt & - perf report -i client/perf.data --no-children --stdio > client.perf.txt & - perf report -i server/perf.data --no-children --stdio > server.perf.txt & - wait - - name: Format results as Markdown id: results run: | @@ -132,6 +198,11 @@ jobs: -e 's/^([a-z0-9].*)$/* **\1**/gi' \ -e 's/(change:[^%]*% )([^%]*%)(.*)/\1**\2**\3/gi' \ >> results.md + { + echo "### Client/server transfer results" + cat comparison.md + } >> results.md + cat results.md > "$GITHUB_STEP_SUMMARY" - name: Remember main-branch push URL if: github.ref == 'refs/heads/main' @@ -158,6 +229,7 @@ jobs: path: | *.svg *.perf + *.perf.fx *.txt results.* target/criterion* diff --git a/neqo-bin/src/bin/server/old_https.rs b/neqo-bin/src/bin/server/old_https.rs index ec32032a05..505a16578f 100644 --- a/neqo-bin/src/bin/server/old_https.rs +++ b/neqo-bin/src/bin/server/old_https.rs @@ -202,7 +202,6 @@ impl HttpServer for Http09Server { None => break, Some(e) => e, }; - qdebug!("Event {event:?}"); match event { ConnectionEvent::NewStream { stream_id } => { self.write_state @@ -221,6 +220,7 @@ impl HttpServer for Http09Server { .unwrap(); } ConnectionEvent::StateChange(_) + | ConnectionEvent::SendStreamCreatable { .. } | ConnectionEvent::SendStreamComplete { .. } => (), e => qwarn!("unhandled event {e:?}"), }