diff --git a/internal/ackhandler/lost_packet_tracker.go b/internal/ackhandler/lost_packet_tracker.go new file mode 100644 index 000000000..40665734d --- /dev/null +++ b/internal/ackhandler/lost_packet_tracker.go @@ -0,0 +1,73 @@ +package ackhandler + +import ( + "iter" + "slices" + + "github.com/quic-go/quic-go/internal/monotime" + "github.com/quic-go/quic-go/internal/protocol" +) + +type lostPacket struct { + PacketNumber protocol.PacketNumber + SendTime monotime.Time +} + +type lostPacketTracker struct { + maxLength int + lostPackets []lostPacket +} + +func newLostPacketTracker(maxLength int) *lostPacketTracker { + return &lostPacketTracker{ + maxLength: maxLength, + // Preallocate a small slice only. + // Hopefully we won't lose many packets. + lostPackets: make([]lostPacket, 0, 4), + } +} + +func (t *lostPacketTracker) Add(p protocol.PacketNumber, sendTime monotime.Time) { + if len(t.lostPackets) == t.maxLength { + t.lostPackets = t.lostPackets[1:] + } + t.lostPackets = append(t.lostPackets, lostPacket{ + PacketNumber: p, + SendTime: sendTime, + }) +} + +// Delete deletes a packet from the lost packet tracker. +// This function is not optimized for performance if many packets are lost, +// but it is only used when a spurious loss is detected, which is rare. +func (t *lostPacketTracker) Delete(pn protocol.PacketNumber) { + t.lostPackets = slices.DeleteFunc(t.lostPackets, func(p lostPacket) bool { + return p.PacketNumber == pn + }) +} + +func (t *lostPacketTracker) All() iter.Seq2[protocol.PacketNumber, monotime.Time] { + return func(yield func(protocol.PacketNumber, monotime.Time) bool) { + for _, p := range t.lostPackets { + if !yield(p.PacketNumber, p.SendTime) { + return + } + } + } +} + +func (t *lostPacketTracker) DeleteBefore(ti monotime.Time) { + if len(t.lostPackets) == 0 { + return + } + if !t.lostPackets[0].SendTime.Before(ti) { + return + } + var idx int + for ; idx < len(t.lostPackets); idx++ { + if !t.lostPackets[idx].SendTime.Before(ti) { + break + } + } + t.lostPackets = slices.Delete(t.lostPackets, 0, idx) +} diff --git a/internal/ackhandler/lost_packet_tracker_test.go b/internal/ackhandler/lost_packet_tracker_test.go new file mode 100644 index 000000000..3394048fd --- /dev/null +++ b/internal/ackhandler/lost_packet_tracker_test.go @@ -0,0 +1,75 @@ +package ackhandler + +import ( + "maps" + "testing" + "time" + + "github.com/quic-go/quic-go/internal/monotime" + "github.com/quic-go/quic-go/internal/protocol" + + "github.com/stretchr/testify/require" +) + +func TestLostPacketTracker(t *testing.T) { + lt := newLostPacketTracker(4) + + start := monotime.Now() + lt.Add(1, start) + lt.Add(5, start.Add(time.Second)) + lt.Add(8, start.Add(2*time.Second)) + require.Equal(t, map[protocol.PacketNumber]monotime.Time{ + 1: start, + 5: start.Add(time.Second), + 8: start.Add(2 * time.Second), + }, maps.Collect(lt.All())) + + // Lose 2 more packets. The first one should be removed. + lt.Add(10, start.Add(3*time.Second)) + lt.Add(11, start.Add(4*time.Second)) + require.Equal(t, map[protocol.PacketNumber]monotime.Time{ + 5: start.Add(time.Second), + 8: start.Add(2 * time.Second), + 10: start.Add(3 * time.Second), + 11: start.Add(4 * time.Second), + }, maps.Collect(lt.All())) + + lt.Delete(5) + lt.Delete(10) + require.Equal(t, map[protocol.PacketNumber]monotime.Time{ + 8: start.Add(2 * time.Second), + 11: start.Add(4 * time.Second), + }, maps.Collect(lt.All())) +} + +func TestLostPacketTrackerDeleteBefore(t *testing.T) { + lt := newLostPacketTracker(4) + + trackedPackets := func(lt *lostPacketTracker) []protocol.PacketNumber { + var pns []protocol.PacketNumber + for pn := range lt.All() { + pns = append(pns, pn) + } + return pns + } + + start := monotime.Now() + lt.Add(1, start) + lt.Add(5, start.Add(time.Second)) + lt.Add(8, start.Add(2*time.Second)) + lt.Add(10, start.Add(3*time.Second)) + + require.Equal(t, []protocol.PacketNumber{1, 5, 8, 10}, trackedPackets(lt)) + + lt.DeleteBefore(start) // this should be a no-op + require.Equal(t, []protocol.PacketNumber{1, 5, 8, 10}, trackedPackets(lt)) + + lt.DeleteBefore(start.Add(2 * time.Second)) + require.Equal(t, []protocol.PacketNumber{8, 10}, trackedPackets(lt)) + + lt.DeleteBefore(start.Add(time.Second * 5 / 2)) + require.Equal(t, []protocol.PacketNumber{10}, trackedPackets(lt)) + + lt.DeleteBefore(start.Add(time.Hour)) + require.Empty(t, trackedPackets(lt)) +} diff --git a/internal/ackhandler/sent_packet_handler.go b/internal/ackhandler/sent_packet_handler.go index bf9ff0f96..11739e225 100644 --- a/internal/ackhandler/sent_packet_handler.go +++ b/internal/ackhandler/sent_packet_handler.go @@ -67,6 +67,7 @@ type sentPacketHandler struct { initialPackets *packetNumberSpace handshakePackets *packetNumberSpace appDataPackets *packetNumberSpace + lostPackets lostPacketTracker // only for application-data packet number space // Do we know that the peer completed address validation yet? // Always true for the server. @@ -145,6 +146,7 @@ func newSentPacketHandler( initialPackets: newPacketNumberSpace(initialPN, false), handshakePackets: newPacketNumberSpace(0, false), appDataPackets: newPacketNumberSpace(0, true), + lostPackets: *newLostPacketTracker(64), rttStats: rttStats, connStats: connStats, congestion: congestion, @@ -403,6 +405,17 @@ func (h *sentPacketHandler) ReceivedAck(ack *wire.AckFrame, encLevel protocol.En putPacket(p.packet) } } + + // detect spurious losses for application data packets, if the ACK was not reordered + if encLevel == protocol.Encryption1RTT && largestAcked == pnSpace.largestAcked { + h.detectSpuriousLosses( + ack, + rcvTime.Add(-min(ack.DelayTime, h.rttStats.MaxAckDelay())), + ) + // clean up lost packet history + h.lostPackets.DeleteBefore(rcvTime.Add(-3 * h.rttStats.PTO(false))) + } + // After this point, we must not use ackedPackets any longer! // We've already returned the buffers. ackedPackets = nil //nolint:ineffassign // This is just to be on the safe side. @@ -426,6 +439,41 @@ func (h *sentPacketHandler) ReceivedAck(ack *wire.AckFrame, encLevel protocol.En return acked1RTTPacket, nil } +func (h *sentPacketHandler) detectSpuriousLosses(ack *wire.AckFrame, ackTime monotime.Time) { + var maxPacketReordering protocol.PacketNumber + var maxTimeReordering time.Duration + ackRangeIdx := len(ack.AckRanges) - 1 + var spuriousLosses []protocol.PacketNumber + for pn, sendTime := range h.lostPackets.All() { + ackRange := ack.AckRanges[ackRangeIdx] + for pn > ackRange.Largest { + // this should never happen, since detectSpuriousLosses is only called for ACKs that increase the largest acked + if ackRangeIdx == 0 { + break + } + ackRangeIdx-- + ackRange = ack.AckRanges[ackRangeIdx] + } + if pn < ackRange.Smallest { + continue + } + if pn <= ackRange.Largest { + packetReordering := h.appDataPackets.history.Difference(ack.LargestAcked(), pn) + timeReordering := ackTime.Sub(sendTime) + maxPacketReordering = max(maxPacketReordering, packetReordering) + maxTimeReordering = max(maxTimeReordering, timeReordering) + + if h.tracer != nil && h.tracer.DetectedSpuriousLoss != nil { + h.tracer.DetectedSpuriousLoss(protocol.Encryption1RTT, pn, uint64(packetReordering), timeReordering) + } + spuriousLosses = append(spuriousLosses, pn) + } + } + for _, pn := range spuriousLosses { + h.lostPackets.Delete(pn) + } +} + func (h *sentPacketHandler) GetLowestPacketNotConfirmedAcked() protocol.PacketNumber { return h.lowestNotConfirmedAcked } @@ -730,6 +778,9 @@ func (h *sentPacketHandler) detectLostPackets(now monotime.Time, encLevel protoc pnSpace.lossTime = lossTime } if packetLost { + if encLevel == protocol.Encryption0RTT || encLevel == protocol.Encryption1RTT { + h.lostPackets.Add(pn, p.SendTime) + } pnSpace.history.DeclareLost(pn) if !p.isPathProbePacket { // the bytes in flight need to be reduced no matter if the frames in this packet will be retransmitted diff --git a/internal/ackhandler/sent_packet_handler_test.go b/internal/ackhandler/sent_packet_handler_test.go index bb66431ab..a4f354557 100644 --- a/internal/ackhandler/sent_packet_handler_test.go +++ b/internal/ackhandler/sent_packet_handler_test.go @@ -1344,6 +1344,93 @@ func testSentPacketHandlerRandomized(t *testing.T, seed uint64) { sph.OnLossDetectionTimeout(now) } +func TestSentPacketHandlerSpuriousLoss(t *testing.T) { + const rtt = time.Second + + mockCtrl := gomock.NewController(t) + tracer, tr := mocklogging.NewMockConnectionTracer(mockCtrl) + tr.EXPECT().UpdatedCongestionState(gomock.Any()).AnyTimes() + tr.EXPECT().UpdatedMetrics(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes() + tr.EXPECT().SetLossTimer(gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes() + tr.EXPECT().LossTimerCanceled().AnyTimes() + tr.EXPECT().AcknowledgedPacket(gomock.Any(), gomock.Any()).AnyTimes() + tr.EXPECT().LostPacket(gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes() + + sph := newSentPacketHandler( + 0, + 1200, + &utils.RTTStats{}, + &utils.ConnectionStats{}, + true, + false, + protocol.PerspectiveClient, + tracer, + utils.DefaultLogger, + ) + + var packets packetTracker + sendPacket := func(ti monotime.Time) protocol.PacketNumber { + pn := sph.PopPacketNumber(protocol.Encryption1RTT) + sph.SentPacket(ti, pn, protocol.InvalidPacketNumber, nil, []Frame{packets.NewPingFrame(pn)}, protocol.Encryption1RTT, protocol.ECNNon, 1000, false, false) + return pn + } + + start := monotime.Now() + now := start + var pns []protocol.PacketNumber + for range 20 { + pns = append(pns, sendPacket(now)) + now = now.Add(10 * time.Millisecond) + } + + now = start.Add(rtt) + _, err := sph.ReceivedAck( + &wire.AckFrame{AckRanges: ackRanges(pns[0], pns[6])}, + protocol.Encryption1RTT, + now, + ) + require.NoError(t, err) + require.Equal(t, []protocol.PacketNumber{pns[0], pns[6]}, packets.Acked) + // pns[4] and pns[5] are not yet declared lost + require.Equal(t, []protocol.PacketNumber{pns[1], pns[2], pns[3]}, packets.Lost) + + packets.Reset() + + const secondAckDelay = 50 * time.Millisecond + gomock.InOrder( + tr.EXPECT().DetectedSpuriousLoss(protocol.Encryption1RTT, pns[1], uint64(16-1), rtt+secondAckDelay-10*time.Millisecond), + tr.EXPECT().DetectedSpuriousLoss(protocol.Encryption1RTT, pns[2], uint64(16-2), rtt+secondAckDelay-20*time.Millisecond), + tr.EXPECT().DetectedSpuriousLoss(protocol.Encryption1RTT, pns[3], uint64(16-3), rtt+secondAckDelay-30*time.Millisecond), + ) + now = now.Add(secondAckDelay) + _, err = sph.ReceivedAck( + &wire.AckFrame{AckRanges: ackRanges(pns[0], pns[1], pns[2], pns[3], pns[4], pns[5], pns[6], pns[12], pns[16])}, + protocol.Encryption1RTT, + now, + ) + require.NoError(t, err) + require.Equal(t, []protocol.PacketNumber{pns[4], pns[5], pns[12], pns[16]}, packets.Acked) + require.Equal(t, []protocol.PacketNumber{pns[7], pns[8], pns[9], pns[10], pns[11], pns[13]}, packets.Lost) + + require.True(t, mockCtrl.Satisfied()) + + gomock.InOrder( + tr.EXPECT().DetectedSpuriousLoss(protocol.Encryption1RTT, pns[7], uint64(18-7), rtt+2*secondAckDelay-70*time.Millisecond), + tr.EXPECT().DetectedSpuriousLoss(protocol.Encryption1RTT, pns[8], uint64(18-8), rtt+2*secondAckDelay-80*time.Millisecond), + tr.EXPECT().DetectedSpuriousLoss(protocol.Encryption1RTT, pns[9], uint64(18-9), rtt+2*secondAckDelay-90*time.Millisecond), + tr.EXPECT().DetectedSpuriousLoss(protocol.Encryption1RTT, pns[10], uint64(18-10), rtt+2*secondAckDelay-100*time.Millisecond), + ) + now = now.Add(secondAckDelay) + _, err = sph.ReceivedAck( + &wire.AckFrame{AckRanges: ackRanges(pns[0], pns[1], pns[2], pns[3], pns[4], pns[5], pns[6], pns[7], pns[8], pns[9], pns[10], pns[16], pns[17], pns[18])}, + protocol.Encryption1RTT, + now, + ) + require.NoError(t, err) + require.Equal(t, []protocol.PacketNumber{pns[4], pns[5], pns[12], pns[16], pns[17], pns[18]}, packets.Acked) + require.Equal(t, []protocol.PacketNumber{pns[7], pns[8], pns[9], pns[10], pns[11], pns[13], pns[14], pns[15]}, packets.Lost) +} + func BenchmarkSendAndAcknowledge(b *testing.B) { b.Run("ack every: 2, in flight: 0", func(b *testing.B) { benchmarkSendAndAcknowledge(b, 2, 0) diff --git a/internal/mocks/logging/connection_tracer.go b/internal/mocks/logging/connection_tracer.go index 7d7f8c3a7..efb46780b 100644 --- a/internal/mocks/logging/connection_tracer.go +++ b/internal/mocks/logging/connection_tracer.go @@ -68,6 +68,9 @@ func NewMockConnectionTracer(ctrl *gomock.Controller) (*logging.ConnectionTracer LostPacket: func(encLevel logging.EncryptionLevel, pn logging.PacketNumber, reason logging.PacketLossReason) { t.LostPacket(encLevel, pn, reason) }, + DetectedSpuriousLoss: func(encLevel logging.EncryptionLevel, pn logging.PacketNumber, reordering uint64, dur time.Duration) { + t.DetectedSpuriousLoss(encLevel, pn, reordering, dur) + }, UpdatedMTU: func(mtu logging.ByteCount, done bool) { t.UpdatedMTU(mtu, done) }, diff --git a/internal/mocks/logging/internal/connection_tracer.go b/internal/mocks/logging/internal/connection_tracer.go index 7380a8757..190113662 100644 --- a/internal/mocks/logging/internal/connection_tracer.go +++ b/internal/mocks/logging/internal/connection_tracer.go @@ -258,6 +258,42 @@ func (c *MockConnectionTracerDebugCall) DoAndReturn(f func(string, string)) *Moc return c } +// DetectedSpuriousLoss mocks base method. +func (m *MockConnectionTracer) DetectedSpuriousLoss(arg0 logging.EncryptionLevel, arg1 logging.PacketNumber, arg2 uint64, arg3 time.Duration) { + m.ctrl.T.Helper() + m.ctrl.Call(m, "DetectedSpuriousLoss", arg0, arg1, arg2, arg3) +} + +// DetectedSpuriousLoss indicates an expected call of DetectedSpuriousLoss. +func (mr *MockConnectionTracerMockRecorder) DetectedSpuriousLoss(arg0, arg1, arg2, arg3 any) *MockConnectionTracerDetectedSpuriousLossCall { + mr.mock.ctrl.T.Helper() + call := mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DetectedSpuriousLoss", reflect.TypeOf((*MockConnectionTracer)(nil).DetectedSpuriousLoss), arg0, arg1, arg2, arg3) + return &MockConnectionTracerDetectedSpuriousLossCall{Call: call} +} + +// MockConnectionTracerDetectedSpuriousLossCall wrap *gomock.Call +type MockConnectionTracerDetectedSpuriousLossCall struct { + *gomock.Call +} + +// Return rewrite *gomock.Call.Return +func (c *MockConnectionTracerDetectedSpuriousLossCall) Return() *MockConnectionTracerDetectedSpuriousLossCall { + c.Call = c.Call.Return() + return c +} + +// Do rewrite *gomock.Call.Do +func (c *MockConnectionTracerDetectedSpuriousLossCall) Do(f func(logging.EncryptionLevel, logging.PacketNumber, uint64, time.Duration)) *MockConnectionTracerDetectedSpuriousLossCall { + c.Call = c.Call.Do(f) + return c +} + +// DoAndReturn rewrite *gomock.Call.DoAndReturn +func (c *MockConnectionTracerDetectedSpuriousLossCall) DoAndReturn(f func(logging.EncryptionLevel, logging.PacketNumber, uint64, time.Duration)) *MockConnectionTracerDetectedSpuriousLossCall { + c.Call = c.Call.DoAndReturn(f) + return c +} + // DroppedEncryptionLevel mocks base method. func (m *MockConnectionTracer) DroppedEncryptionLevel(arg0 logging.EncryptionLevel) { m.ctrl.T.Helper() diff --git a/internal/mocks/logging/mockgen.go b/internal/mocks/logging/mockgen.go index df4734b7a..847cb1793 100644 --- a/internal/mocks/logging/mockgen.go +++ b/internal/mocks/logging/mockgen.go @@ -38,6 +38,7 @@ type ConnectionTracer interface { UpdatedMetrics(rttStats *logging.RTTStats, cwnd, bytesInFlight logging.ByteCount, packetsInFlight int) AcknowledgedPacket(logging.EncryptionLevel, logging.PacketNumber) LostPacket(logging.EncryptionLevel, logging.PacketNumber, logging.PacketLossReason) + DetectedSpuriousLoss(logging.EncryptionLevel, logging.PacketNumber, uint64, time.Duration) UpdatedCongestionState(logging.CongestionState) UpdatedPTOCount(value uint32) UpdatedKeyFromTLS(logging.EncryptionLevel, logging.Perspective) diff --git a/logging/connection_tracer.go b/logging/connection_tracer.go index f218e046f..d6c2b48dc 100644 --- a/logging/connection_tracer.go +++ b/logging/connection_tracer.go @@ -26,6 +26,7 @@ type ConnectionTracer struct { UpdatedMetrics func(rttStats *RTTStats, cwnd, bytesInFlight ByteCount, packetsInFlight int) AcknowledgedPacket func(encLevel EncryptionLevel, pn PacketNumber) LostPacket func(encLevel EncryptionLevel, pn PacketNumber, reason PacketLossReason) + DetectedSpuriousLoss func(encLevel EncryptionLevel, pn PacketNumber, reordering uint64, dur time.Duration) UpdatedMTU func(mtu ByteCount, done bool) UpdatedCongestionState func(state CongestionState) UpdatedPTOCount func(value uint32) diff --git a/logging/connection_tracer_multiplexer.go b/logging/connection_tracer_multiplexer.go index 3a87058c8..48ac1d38f 100644 --- a/logging/connection_tracer_multiplexer.go +++ b/logging/connection_tracer_multiplexer.go @@ -134,6 +134,13 @@ func NewMultiplexedConnectionTracer(tracers ...*ConnectionTracer) *ConnectionTra } } }, + DetectedSpuriousLoss: func(encLevel EncryptionLevel, pn PacketNumber, reordering uint64, dur time.Duration) { + for _, t := range tracers { + if t.DetectedSpuriousLoss != nil { + t.DetectedSpuriousLoss(encLevel, pn, reordering, dur) + } + } + }, UpdatedMTU: func(mtu ByteCount, done bool) { for _, t := range tracers { if t.UpdatedMTU != nil { diff --git a/qlog/connection_tracer.go b/qlog/connection_tracer.go index f8873bc5d..1761b41cb 100644 --- a/qlog/connection_tracer.go +++ b/qlog/connection_tracer.go @@ -76,6 +76,9 @@ func NewConnectionTracer(w io.WriteCloser, p logging.Perspective, odcid protocol LostPacket: func(encLevel protocol.EncryptionLevel, pn protocol.PacketNumber, lossReason logging.PacketLossReason) { t.LostPacket(encLevel, pn, lossReason) }, + DetectedSpuriousLoss: func(encLevel protocol.EncryptionLevel, pn protocol.PacketNumber, reordering uint64, dur time.Duration) { + t.DetectedSpuriousLoss(encLevel, pn, reordering, dur) + }, UpdatedMTU: func(mtu logging.ByteCount, done bool) { t.UpdatedMTU(mtu, done) }, @@ -371,6 +374,15 @@ func (t *connectionTracer) LostPacket(encLevel protocol.EncryptionLevel, pn prot }) } +func (t *connectionTracer) DetectedSpuriousLoss(encLevel protocol.EncryptionLevel, pn protocol.PacketNumber, reordering uint64, dur time.Duration) { + t.recordEvent(time.Now(), &eventSpuriousLoss{ + EncLevel: encLevel, + PacketNumber: pn, + Reordering: reordering, + Duration: dur, + }) +} + func (t *connectionTracer) UpdatedMTU(mtu protocol.ByteCount, done bool) { t.recordEvent(time.Now(), &eventMTUUpdated{mtu: mtu, done: done}) } diff --git a/qlog/connection_tracer_test.go b/qlog/connection_tracer_test.go index b078222cd..563d84642 100644 --- a/qlog/connection_tracer_test.go +++ b/qlog/connection_tracer_test.go @@ -707,6 +707,22 @@ func TestLostPackets(t *testing.T) { require.Equal(t, "reordering_threshold", ev["trigger"]) } +func TestDetectedSpuriousLoss(t *testing.T) { + tracer, buf := newConnectionTracer() + tracer.DetectedSpuriousLoss(protocol.Encryption1RTT, 42, 1, 1337*time.Millisecond) + tracer.Close() + entry := exportAndParseSingle(t, buf) + require.WithinDuration(t, time.Now(), entry.Time, scaleDuration(10*time.Millisecond)) + require.Equal(t, "recovery:spurious_loss", entry.Name) + ev := entry.Event + require.Contains(t, ev, "packet_number") + require.Equal(t, float64(42), ev["packet_number"]) + require.Contains(t, ev, "reordering_packets") + require.Equal(t, float64(1), ev["reordering_packets"]) + require.Contains(t, ev, "reordering_time") + require.InDelta(t, 1337, ev["reordering_time"], float64(1)) +} + func TestMTUUpdates(t *testing.T) { tracer, buf := newConnectionTracer() tracer.UpdatedMTU(1337, true) diff --git a/qlog/event.go b/qlog/event.go index 393e6981a..4490d69bb 100644 --- a/qlog/event.go +++ b/qlog/event.go @@ -355,6 +355,23 @@ func (e eventPacketLost) MarshalJSONObject(enc *gojay.Encoder) { enc.StringKey("trigger", e.Trigger.String()) } +type eventSpuriousLoss struct { + EncLevel protocol.EncryptionLevel + PacketNumber protocol.PacketNumber + Reordering uint64 + Duration time.Duration +} + +func (e eventSpuriousLoss) Name() string { return "recovery:spurious_loss" } +func (e eventSpuriousLoss) IsNil() bool { return false } + +func (e eventSpuriousLoss) MarshalJSONObject(enc *gojay.Encoder) { + enc.StringKey("packet_number_space", encLevelToPacketNumberSpace(e.EncLevel)) + enc.Uint64Key("packet_number", uint64(e.PacketNumber)) + enc.Uint64Key("reordering_packets", e.Reordering) + enc.Float64Key("reordering_time", milliseconds(e.Duration)) +} + type eventKeyUpdated struct { Trigger keyUpdateTrigger KeyType keyType