diff --git a/qlog/event.go b/qlog/event.go index 5e114fec..77da6ec9 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 e165b479..4f4818c9 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 952525a3..a0e0309a 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()