diff --git a/internal/ackhandler/sent_packet_handler.go b/internal/ackhandler/sent_packet_handler.go index 6dcd7254a..c8f346153 100644 --- a/internal/ackhandler/sent_packet_handler.go +++ b/internal/ackhandler/sent_packet_handler.go @@ -10,6 +10,7 @@ import ( "github.com/lucas-clemente/quic-go/internal/qerr" "github.com/lucas-clemente/quic-go/internal/utils" "github.com/lucas-clemente/quic-go/internal/wire" + "github.com/lucas-clemente/quic-go/qlog" "github.com/lucas-clemente/quic-go/quictrace" ) @@ -73,7 +74,8 @@ type sentPacketHandler struct { traceCallback func(quictrace.Event) - logger utils.Logger + qlogger qlog.Tracer + logger utils.Logger } // NewSentPacketHandler creates a new sentPacketHandler @@ -81,6 +83,7 @@ func NewSentPacketHandler( initialPacketNumber protocol.PacketNumber, rttStats *congestion.RTTStats, traceCallback func(quictrace.Event), + qlogger qlog.Tracer, logger utils.Logger, ) SentPacketHandler { congestion := congestion.NewCubicSender( @@ -96,6 +99,7 @@ func NewSentPacketHandler( rttStats: rttStats, congestion: congestion, traceCallback: traceCallback, + qlogger: qlogger, logger: logger, } } @@ -209,6 +213,16 @@ func (h *sentPacketHandler) ReceivedAck(ackFrame *wire.AckFrame, withPacketNumbe h.logger.Debugf("\tupdated RTT: %s (σ: %s)", h.rttStats.SmoothedRTT(), h.rttStats.MeanDeviation()) } h.congestion.MaybeExitSlowStart() + if h.qlogger != nil { + packetsInFlight := h.appDataPackets.history.Len() + if h.handshakePackets != nil { + packetsInFlight += h.handshakePackets.history.Len() + } + if h.initialPackets != nil { + packetsInFlight += h.initialPackets.history.Len() + } + h.qlogger.UpdatedMetrics(rcvTime, h.rttStats, h.congestion.GetCongestionWindow(), h.bytesInFlight, packetsInFlight) + } } ackedPackets, err := h.determineNewlyAckedPackets(ackFrame, encLevel) diff --git a/internal/ackhandler/sent_packet_handler_test.go b/internal/ackhandler/sent_packet_handler_test.go index 04483f85e..e1f60953c 100644 --- a/internal/ackhandler/sent_packet_handler_test.go +++ b/internal/ackhandler/sent_packet_handler_test.go @@ -24,7 +24,7 @@ var _ = Describe("SentPacketHandler", func() { BeforeEach(func() { lostPackets = nil rttStats := &congestion.RTTStats{} - handler = NewSentPacketHandler(42, rttStats, nil, utils.DefaultLogger).(*sentPacketHandler) + handler = NewSentPacketHandler(42, rttStats, nil, nil, utils.DefaultLogger).(*sentPacketHandler) streamFrame = wire.StreamFrame{ StreamID: 5, Data: []byte{0x13, 0x37}, diff --git a/qlog/event.go b/qlog/event.go index d63c323a2..d0a8cf63c 100644 --- a/qlog/event.go +++ b/qlog/event.go @@ -3,6 +3,8 @@ package qlog import ( "time" + "github.com/lucas-clemente/quic-go/internal/protocol" + "github.com/francoispqt/gojay" ) @@ -96,3 +98,31 @@ func (e eventRetryReceived) MarshalJSONObject(enc *gojay.Encoder) { enc.StringKey("packet_type", packetTypeRetry.String()) enc.ObjectKey("header", e.Header) } + +func milliseconds(dur time.Duration) float64 { return float64(dur.Nanoseconds()) / 1e6 } + +type eventMetricsUpdated struct { + MinRTT time.Duration + SmoothedRTT time.Duration + LatestRTT time.Duration + RTTVariance time.Duration + + CongestionWindow protocol.ByteCount + BytesInFlight protocol.ByteCount + PacketsInFlight int +} + +func (e eventMetricsUpdated) Category() category { return categoryRecovery } +func (e eventMetricsUpdated) Name() string { return "metrics_updated" } +func (e eventMetricsUpdated) IsNil() bool { return false } + +func (e eventMetricsUpdated) MarshalJSONObject(enc *gojay.Encoder) { + enc.FloatKey("min_rtt", milliseconds(e.MinRTT)) + enc.FloatKey("smoothed_rtt", milliseconds(e.SmoothedRTT)) + enc.FloatKey("latest_rtt", milliseconds(e.LatestRTT)) + enc.FloatKey("rtt_variance", milliseconds(e.RTTVariance)) + + enc.Uint64Key("congestion_window", uint64(e.CongestionWindow)) + enc.Uint64Key("bytes_in_flight", uint64(e.BytesInFlight)) + enc.Uint64KeyOmitEmpty("packets_in_flight", uint64(e.PacketsInFlight)) +} diff --git a/qlog/qlog.go b/qlog/qlog.go index 982ee5af7..93ed659cf 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -4,6 +4,8 @@ import ( "io" "time" + "github.com/lucas-clemente/quic-go/internal/congestion" + "github.com/francoispqt/gojay" "github.com/lucas-clemente/quic-go/internal/protocol" "github.com/lucas-clemente/quic-go/internal/wire" @@ -15,6 +17,7 @@ type Tracer interface { SentPacket(time.Time, *wire.ExtendedHeader, *wire.AckFrame, []wire.Frame) ReceivedRetry(time.Time, *wire.Header) ReceivedPacket(time.Time, *wire.ExtendedHeader, []wire.Frame) + UpdatedMetrics(time time.Time, rttStats *congestion.RTTStats, cwnd protocol.ByteCount, bytesInFLight protocol.ByteCount, packetsInFlight int) } type tracer struct { @@ -101,3 +104,18 @@ func (t *tracer) ReceivedRetry(time time.Time, hdr *wire.Header) { }, }) } + +func (t *tracer) UpdatedMetrics(time time.Time, rttStats *congestion.RTTStats, cwnd, bytesInFlight protocol.ByteCount, packetsInFlight int) { + t.events = append(t.events, event{ + Time: time, + eventDetails: eventMetricsUpdated{ + MinRTT: rttStats.MinRTT(), + SmoothedRTT: rttStats.SmoothedRTT(), + LatestRTT: rttStats.LatestRTT(), + RTTVariance: rttStats.MeanDeviation(), + CongestionWindow: cwnd, + BytesInFlight: bytesInFlight, + PacketsInFlight: packetsInFlight, + }, + }) +} diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index a23291624..a3276e7a2 100644 --- a/qlog/qlog_test.go +++ b/qlog/qlog_test.go @@ -6,6 +6,7 @@ import ( "io" "time" + "github.com/lucas-clemente/quic-go/internal/congestion" "github.com/lucas-clemente/quic-go/internal/protocol" "github.com/lucas-clemente/quic-go/internal/wire" @@ -180,5 +181,39 @@ var _ = Describe("Tracer", func() { Expect(ev).To(HaveKey("header")) Expect(ev).ToNot(HaveKey("frames")) }) + + It("records metrics updates", func() { + now := time.Now() + rttStats := congestion.NewRTTStats() + rttStats.UpdateRTT(15*time.Millisecond, 0, now) + rttStats.UpdateRTT(20*time.Millisecond, 0, now) + rttStats.UpdateRTT(25*time.Millisecond, 0, now) + Expect(rttStats.MinRTT()).To(Equal(15 * time.Millisecond)) + Expect(rttStats.SmoothedRTT()).To(And( + BeNumerically(">", 15*time.Millisecond), + BeNumerically("<", 25*time.Millisecond), + )) + Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) + tracer.UpdatedMetrics( + now, + rttStats, + 4321, + 1234, + 42, + ) + t, category, eventName, ev := exportAndParse() + Expect(t).To(BeTemporally("~", now, time.Millisecond)) + Expect(category).To(Equal("recovery")) + Expect(eventName).To(Equal("metrics_updated")) + Expect(ev).To(HaveKeyWithValue("min_rtt", float64(15))) + Expect(ev).To(HaveKeyWithValue("latest_rtt", float64(25))) + Expect(ev).To(HaveKey("smoothed_rtt")) + Expect(time.Duration(ev["smoothed_rtt"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.SmoothedRTT(), time.Millisecond)) + Expect(ev).To(HaveKey("rtt_variance")) + Expect(time.Duration(ev["rtt_variance"].(float64)) * time.Millisecond).To(BeNumerically("~", rttStats.MeanDeviation(), time.Millisecond)) + Expect(ev).To(HaveKeyWithValue("congestion_window", float64(4321))) + Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(1234))) + Expect(ev).To(HaveKeyWithValue("packets_in_flight", float64(42))) + }) }) }) diff --git a/session.go b/session.go index e0bdcdfa3..94f113740 100644 --- a/session.go +++ b/session.go @@ -248,7 +248,7 @@ var newSession = func( s.queueControlFrame, ) s.preSetup() - s.sentPacketHandler = ackhandler.NewSentPacketHandler(0, s.rttStats, s.traceCallback, s.logger) + s.sentPacketHandler = ackhandler.NewSentPacketHandler(0, s.rttStats, s.traceCallback, s.qlogger, s.logger) initialStream := newCryptoStream() handshakeStream := newCryptoStream() params := &handshake.TransportParameters{ @@ -352,7 +352,7 @@ var newClientSession = func( s.queueControlFrame, ) s.preSetup() - s.sentPacketHandler = ackhandler.NewSentPacketHandler(initialPacketNumber, s.rttStats, s.traceCallback, s.logger) + s.sentPacketHandler = ackhandler.NewSentPacketHandler(initialPacketNumber, s.rttStats, s.traceCallback, s.qlogger, s.logger) initialStream := newCryptoStream() handshakeStream := newCryptoStream() params := &handshake.TransportParameters{