From 9182a901d5740132957b28dda2a921212947491c Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Mon, 30 Mar 2020 14:19:38 +0700 Subject: [PATCH 1/2] only export changed metrics in the metrics_updated event --- qlog/event.go | 35 +++++++++++++++++++++++++++-------- qlog/qlog.go | 9 ++++++++- qlog/qlog_test.go | 44 ++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 79 insertions(+), 9 deletions(-) diff --git a/qlog/event.go b/qlog/event.go index 5e114fece..77da6ec93 100644 --- a/qlog/event.go +++ b/qlog/event.go @@ -182,7 +182,7 @@ func (e eventPacketDropped) MarshalJSONObject(enc *gojay.Encoder) { func milliseconds(dur time.Duration) float64 { return float64(dur.Nanoseconds()) / 1e6 } -type eventMetricsUpdated struct { +type metrics struct { MinRTT time.Duration SmoothedRTT time.Duration LatestRTT time.Duration @@ -193,19 +193,38 @@ type eventMetricsUpdated struct { PacketsInFlight int } +type eventMetricsUpdated struct { + Last *metrics + Current *metrics +} + 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)) + if e.Last == nil || e.Last.MinRTT != e.Current.MinRTT { + enc.FloatKey("min_rtt", milliseconds(e.Current.MinRTT)) + } + if e.Last == nil || e.Last.SmoothedRTT != e.Current.SmoothedRTT { + enc.FloatKey("smoothed_rtt", milliseconds(e.Current.SmoothedRTT)) + } + if e.Last == nil || e.Last.LatestRTT != e.Current.LatestRTT { + enc.FloatKey("latest_rtt", milliseconds(e.Current.LatestRTT)) + } + if e.Last == nil || e.Last.RTTVariance != e.Current.RTTVariance { + enc.FloatKey("rtt_variance", milliseconds(e.Current.RTTVariance)) + } - enc.Uint64Key("congestion_window", uint64(e.CongestionWindow)) - enc.Uint64Key("bytes_in_flight", uint64(e.BytesInFlight)) - enc.Uint64KeyOmitEmpty("packets_in_flight", uint64(e.PacketsInFlight)) + if e.Last == nil || e.Last.CongestionWindow != e.Current.CongestionWindow { + enc.Uint64Key("congestion_window", uint64(e.Current.CongestionWindow)) + } + if e.Last == nil || e.Last.BytesInFlight != e.Current.BytesInFlight { + enc.Uint64Key("bytes_in_flight", uint64(e.Current.BytesInFlight)) + } + if e.Last == nil || e.Last.PacketsInFlight != e.Current.PacketsInFlight { + enc.Uint64KeyOmitEmpty("packets_in_flight", uint64(e.Current.PacketsInFlight)) + } } type eventUpdatedPTO struct { diff --git a/qlog/qlog.go b/qlog/qlog.go index e165b479a..4f4818c93 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -46,6 +46,8 @@ type tracer struct { events chan event encodeErr error runStopped chan struct{} + + lastMetrics *metrics } var _ Tracer = &tracer{} @@ -231,7 +233,7 @@ func (t *tracer) DroppedPacket(packetType PacketType, size protocol.ByteCount, d } func (t *tracer) UpdatedMetrics(rttStats *congestion.RTTStats, cwnd, bytesInFlight protocol.ByteCount, packetsInFlight int) { - t.recordEvent(&eventMetricsUpdated{ + m := &metrics{ MinRTT: rttStats.MinRTT(), SmoothedRTT: rttStats.SmoothedRTT(), LatestRTT: rttStats.LatestRTT(), @@ -239,7 +241,12 @@ func (t *tracer) UpdatedMetrics(rttStats *congestion.RTTStats, cwnd, bytesInFlig CongestionWindow: cwnd, BytesInFlight: bytesInFlight, PacketsInFlight: packetsInFlight, + } + t.recordEvent(&eventMetricsUpdated{ + Last: t.lastMetrics, + Current: m, }) + t.lastMetrics = m } func (t *tracer) LostPacket(encLevel protocol.EncryptionLevel, pn protocol.PacketNumber, lossReason PacketLossReason) { diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index 952525a33..a0e0309ab 100644 --- a/qlog/qlog_test.go +++ b/qlog/qlog_test.go @@ -377,6 +377,50 @@ var _ = Describe("Tracer", func() { Expect(ev).To(HaveKeyWithValue("packets_in_flight", float64(42))) }) + It("only logs the diff between two 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)) + + rttStats2 := congestion.NewRTTStats() + rttStats2.UpdateRTT(15*time.Millisecond, 0, now) + rttStats2.UpdateRTT(15*time.Millisecond, 0, now) + rttStats2.UpdateRTT(15*time.Millisecond, 0, now) + Expect(rttStats2.MinRTT()).To(Equal(15 * time.Millisecond)) + + Expect(rttStats.LatestRTT()).To(Equal(25 * time.Millisecond)) + tracer.UpdatedMetrics( + rttStats, + 4321, + 1234, + 42, + ) + tracer.UpdatedMetrics( + rttStats2, + 4321, + 12345, // changed + 42, + ) + entries := exportAndParse() + Expect(entries).To(HaveLen(2)) + Expect(entries[0].Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) + Expect(entries[0].Category).To(Equal("recovery")) + Expect(entries[0].Name).To(Equal("metrics_updated")) + Expect(entries[0].Event).To(HaveLen(7)) + Expect(entries[1].Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) + Expect(entries[1].Category).To(Equal("recovery")) + Expect(entries[1].Name).To(Equal("metrics_updated")) + ev := entries[1].Event + Expect(ev).ToNot(HaveKey("min_rtt")) + Expect(ev).ToNot(HaveKey("congestion_window")) + Expect(ev).ToNot(HaveKey("packets_in_flight")) + Expect(ev).To(HaveKeyWithValue("bytes_in_flight", float64(12345))) + Expect(ev).To(HaveKeyWithValue("smoothed_rtt", float64(15))) + }) + It("records lost packets", func() { tracer.LostPacket(protocol.EncryptionHandshake, 42, PacketLossReorderingThreshold) entry := exportAndParseSingle() From 3e2c27e4cd31565bdd586bf26ef9a5924f2d6126 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Mon, 30 Mar 2020 14:25:33 +0700 Subject: [PATCH 2/2] qlog updated metrics when sending a packet --- internal/ackhandler/sent_packet_handler.go | 23 ++++++++++++++-------- 1 file changed, 15 insertions(+), 8 deletions(-) diff --git a/internal/ackhandler/sent_packet_handler.go b/internal/ackhandler/sent_packet_handler.go index 222388f4a..c978f427c 100644 --- a/internal/ackhandler/sent_packet_handler.go +++ b/internal/ackhandler/sent_packet_handler.go @@ -167,6 +167,17 @@ func (h *sentPacketHandler) dropPackets(encLevel protocol.EncryptionLevel) { h.ptoMode = SendNone } +func (h *sentPacketHandler) packetsInFlight() int { + packetsInFlight := h.appDataPackets.history.Len() + if h.handshakePackets != nil { + packetsInFlight += h.handshakePackets.history.Len() + } + if h.initialPackets != nil { + packetsInFlight += h.initialPackets.history.Len() + } + return packetsInFlight +} + func (h *sentPacketHandler) SentPacket(packet *Packet) { // For the client, drop the Initial packet number space when the first Handshake packet is sent. if h.perspective == protocol.PerspectiveClient && packet.EncryptionLevel == protocol.EncryptionHandshake && h.initialPackets != nil { @@ -176,6 +187,9 @@ func (h *sentPacketHandler) SentPacket(packet *Packet) { if isAckEliciting { h.getPacketNumberSpace(packet.EncryptionLevel).history.SentPacket(packet) } + if h.qlogger != nil { + h.qlogger.UpdatedMetrics(h.rttStats, h.congestion.GetCongestionWindow(), h.bytesInFlight, h.packetsInFlight()) + } if isAckEliciting || !h.peerCompletedAddressValidation { h.setLossDetectionTimer() } @@ -256,14 +270,7 @@ func (h *sentPacketHandler) ReceivedAck(ack *wire.AckFrame, encLevel protocol.En } 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(h.rttStats, h.congestion.GetCongestionWindow(), h.bytesInFlight, packetsInFlight) + h.qlogger.UpdatedMetrics(h.rttStats, h.congestion.GetCongestionWindow(), h.bytesInFlight, h.packetsInFlight()) } }