From eb7fcf5637f780fe1355002534430d95bb5b53c8 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Tue, 4 Nov 2025 12:13:06 -0500 Subject: [PATCH] qlog: split the PTO count updates ouf of the MetricsUpdated event (#5421) * qlog: split the PTO count updates ouf of the MetricsUpdated event This allows us to not use pointers for all member variables of both events. * ackhandler: avoid spurious call to GetCongestionWindow --- internal/ackhandler/sent_packet_handler.go | 54 +++++++-------- .../ackhandler/sent_packet_handler_test.go | 16 ++--- qlog/benchmark_test.go | 20 ++---- qlog/event.go | 67 ++++++++++++------- qlog/event_test.go | 26 +++---- 5 files changed, 88 insertions(+), 95 deletions(-) diff --git a/internal/ackhandler/sent_packet_handler.go b/internal/ackhandler/sent_packet_handler.go index 2c41f7f7f..e134232c4 100644 --- a/internal/ackhandler/sent_packet_handler.go +++ b/internal/ackhandler/sent_packet_handler.go @@ -15,10 +15,6 @@ import ( "github.com/quic-go/quic-go/qlogwriter" ) -func pointer[T any](v T) *T { - return &v -} - const ( // Maximum reordering in time space before time based loss detection considers a packet lost. // Specified as an RTT multiplier. @@ -220,7 +216,7 @@ func (h *sentPacketHandler) DropPackets(encLevel protocol.EncryptionLevel, now m panic(fmt.Sprintf("Cannot drop keys for encryption level %s", encLevel)) } if h.qlogger != nil && h.ptoCount != 0 { - h.qlogger.RecordEvent(qlog.MetricsUpdated{PTOCount: pointer(uint32(0))}) + h.qlogger.RecordEvent(qlog.PTOCountUpdated{PTOCount: 0}) } h.ptoCount = 0 h.numProbesToSend = 0 @@ -334,40 +330,40 @@ func (h *sentPacketHandler) qlogMetricsUpdated() { var metricsUpdatedEvent qlog.MetricsUpdated var updated bool if h.rttStats.HasMeasurement() { - if h.lastMetrics.MinRTT == nil || *h.lastMetrics.MinRTT != h.rttStats.MinRTT() { - metricsUpdatedEvent.MinRTT = pointer(h.rttStats.MinRTT()) - h.lastMetrics.MinRTT = pointer(h.rttStats.MinRTT()) + if h.lastMetrics.MinRTT != h.rttStats.MinRTT() { + metricsUpdatedEvent.MinRTT = h.rttStats.MinRTT() + h.lastMetrics.MinRTT = metricsUpdatedEvent.MinRTT updated = true } - if h.lastMetrics.SmoothedRTT == nil || *h.lastMetrics.SmoothedRTT != h.rttStats.SmoothedRTT() { - metricsUpdatedEvent.SmoothedRTT = pointer(h.rttStats.SmoothedRTT()) - h.lastMetrics.SmoothedRTT = pointer(h.rttStats.SmoothedRTT()) + if h.lastMetrics.SmoothedRTT != h.rttStats.SmoothedRTT() { + metricsUpdatedEvent.SmoothedRTT = h.rttStats.SmoothedRTT() + h.lastMetrics.SmoothedRTT = metricsUpdatedEvent.SmoothedRTT updated = true } - if h.lastMetrics.LatestRTT == nil || *h.lastMetrics.LatestRTT != h.rttStats.LatestRTT() { - metricsUpdatedEvent.LatestRTT = pointer(h.rttStats.LatestRTT()) - h.lastMetrics.LatestRTT = pointer(h.rttStats.LatestRTT()) + if h.lastMetrics.LatestRTT != h.rttStats.LatestRTT() { + metricsUpdatedEvent.LatestRTT = h.rttStats.LatestRTT() + h.lastMetrics.LatestRTT = metricsUpdatedEvent.LatestRTT updated = true } - if h.lastMetrics.RTTVariance == nil || *h.lastMetrics.RTTVariance != h.rttStats.MeanDeviation() { - metricsUpdatedEvent.RTTVariance = pointer(h.rttStats.MeanDeviation()) - h.lastMetrics.RTTVariance = pointer(h.rttStats.MeanDeviation()) + if h.lastMetrics.RTTVariance != h.rttStats.MeanDeviation() { + metricsUpdatedEvent.RTTVariance = h.rttStats.MeanDeviation() + h.lastMetrics.RTTVariance = metricsUpdatedEvent.RTTVariance updated = true } } - if h.lastMetrics.CongestionWindow == nil || *h.lastMetrics.CongestionWindow != int(h.congestion.GetCongestionWindow()) { - metricsUpdatedEvent.CongestionWindow = pointer(int(h.congestion.GetCongestionWindow())) - h.lastMetrics.CongestionWindow = pointer(int(h.congestion.GetCongestionWindow())) + if cwnd := h.congestion.GetCongestionWindow(); h.lastMetrics.CongestionWindow != int(cwnd) { + metricsUpdatedEvent.CongestionWindow = int(cwnd) + h.lastMetrics.CongestionWindow = metricsUpdatedEvent.CongestionWindow updated = true } - if h.lastMetrics.BytesInFlight == nil || *h.lastMetrics.BytesInFlight != int(h.bytesInFlight) { - metricsUpdatedEvent.BytesInFlight = pointer(int(h.bytesInFlight)) - h.lastMetrics.BytesInFlight = pointer(int(h.bytesInFlight)) + if h.lastMetrics.BytesInFlight != int(h.bytesInFlight) { + metricsUpdatedEvent.BytesInFlight = int(h.bytesInFlight) + h.lastMetrics.BytesInFlight = metricsUpdatedEvent.BytesInFlight updated = true } - if h.lastMetrics.PacketsInFlight == nil || *h.lastMetrics.PacketsInFlight != h.packetsInFlight() { - metricsUpdatedEvent.PacketsInFlight = pointer(h.packetsInFlight()) - h.lastMetrics.PacketsInFlight = pointer(h.packetsInFlight()) + if h.lastMetrics.PacketsInFlight != h.packetsInFlight() { + metricsUpdatedEvent.PacketsInFlight = h.packetsInFlight() + h.lastMetrics.PacketsInFlight = metricsUpdatedEvent.PacketsInFlight updated = true } if updated { @@ -476,7 +472,7 @@ func (h *sentPacketHandler) ReceivedAck(ack *wire.AckFrame, encLevel protocol.En // Reset the pto_count unless the client is unsure if the server has validated the client's address. if h.peerCompletedAddressValidation { if h.qlogger != nil && h.ptoCount != 0 { - h.qlogger.RecordEvent(qlog.MetricsUpdated{PTOCount: pointer(uint32(0))}) + h.qlogger.RecordEvent(qlog.PTOCountUpdated{PTOCount: 0}) } h.ptoCount = 0 } @@ -930,7 +926,7 @@ func (h *sentPacketHandler) OnLossDetectionTimeout(now monotime.Time) error { TimerType: qlog.TimerTypePTO, EncLevel: encLevel, }) - h.qlogger.RecordEvent(qlog.MetricsUpdated{PTOCount: pointer(h.ptoCount)}) + h.qlogger.RecordEvent(qlog.PTOCountUpdated{PTOCount: h.ptoCount}) } h.numProbesToSend += 2 //nolint:exhaustive // We never arm a PTO timer for 0-RTT packets. @@ -1112,7 +1108,7 @@ func (h *sentPacketHandler) ResetForRetry(now monotime.Time) { oldAlarm := h.alarm h.alarm = alarmTimer{} if h.qlogger != nil { - h.qlogger.RecordEvent(qlog.MetricsUpdated{PTOCount: pointer(uint32(0))}) + h.qlogger.RecordEvent(qlog.PTOCountUpdated{PTOCount: 0}) if !oldAlarm.Time.IsZero() { h.qlogger.RecordEvent(qlog.LossTimerUpdated{ Type: qlog.LossTimerUpdateTypeCancelled, diff --git a/internal/ackhandler/sent_packet_handler_test.go b/internal/ackhandler/sent_packet_handler_test.go index 1c3e851bd..1a9eaad9d 100644 --- a/internal/ackhandler/sent_packet_handler_test.go +++ b/internal/ackhandler/sent_packet_handler_test.go @@ -621,9 +621,7 @@ func testSentPacketHandlerPTO(t *testing.T, encLevel protocol.EncryptionLevel, p TimerType: qlog.TimerTypePTO, EncLevel: encLevel, }, - qlog.MetricsUpdated{ - PTOCount: pointer(uint32(1)), - }, + qlog.PTOCountUpdated{PTOCount: 1}, qlog.LossTimerUpdated{ Type: qlog.LossTimerUpdateTypeSet, TimerType: qlog.TimerTypePTO, @@ -631,7 +629,7 @@ func testSentPacketHandlerPTO(t *testing.T, encLevel protocol.EncryptionLevel, p Time: sendTimes[2].Add(2 * rttStats.PTO(encLevel == protocol.Encryption1RTT)).ToTime(), }, }, - eventRecorder.Events(qlog.MetricsUpdated{}, qlog.LossTimerUpdated{}), + eventRecorder.Events(qlog.PTOCountUpdated{}, qlog.LossTimerUpdated{}), ) // PTO timer expiration doesn't declare packets lost require.Empty(t, packets.Lost) @@ -677,9 +675,7 @@ func testSentPacketHandlerPTO(t *testing.T, encLevel protocol.EncryptionLevel, p TimerType: qlog.TimerTypePTO, EncLevel: encLevel, }, - qlog.MetricsUpdated{ - PTOCount: pointer(uint32(2)), - }, + qlog.PTOCountUpdated{PTOCount: 2}, qlog.LossTimerUpdated{ Type: qlog.LossTimerUpdateTypeSet, TimerType: qlog.TimerTypePTO, @@ -687,7 +683,7 @@ func testSentPacketHandlerPTO(t *testing.T, encLevel protocol.EncryptionLevel, p Time: sendTimes[6].Add(4 * rttStats.PTO(encLevel == protocol.Encryption1RTT)).ToTime(), }, }, - eventRecorder.Events(qlog.LossTimerUpdated{}, qlog.MetricsUpdated{}), + eventRecorder.Events(qlog.LossTimerUpdated{}, qlog.PTOCountUpdated{}), ) eventRecorder.Clear() // PTO timer expiration doesn't declare packets lost @@ -722,9 +718,9 @@ func testSentPacketHandlerPTO(t *testing.T, encLevel protocol.EncryptionLevel, p require.Len(t, eventRecorder.Events(qlog.PacketLost{}), 2) require.Equal(t, []qlogwriter.Event{ - qlog.MetricsUpdated{PTOCount: pointer(uint32(0))}, + qlog.PTOCountUpdated{PTOCount: 0}, }, - eventRecorder.Events(qlog.MetricsUpdated{})[:1], + eventRecorder.Events(qlog.PTOCountUpdated{})[:1], ) require.Equal(t, []qlogwriter.Event{ diff --git a/qlog/benchmark_test.go b/qlog/benchmark_test.go index c6263996c..1138fba98 100644 --- a/qlog/benchmark_test.go +++ b/qlog/benchmark_test.go @@ -57,20 +57,14 @@ func BenchmarkConnectionTracing(b *testing.B) { }, }) - minRTT := rttStats.MinRTT() - smoothedRTT := rttStats.SmoothedRTT() - latestRTT := rttStats.LatestRTT() - rttVariance := rttStats.MeanDeviation() - cwndInt := int(12345 + protocol.ByteCount(2*i)) - bytesInt := int(12345 + protocol.ByteCount(i)) tracer.RecordEvent(&MetricsUpdated{ - MinRTT: &minRTT, - SmoothedRTT: &smoothedRTT, - LatestRTT: &latestRTT, - RTTVariance: &rttVariance, - CongestionWindow: &cwndInt, - BytesInFlight: &bytesInt, - PacketsInFlight: &i, + MinRTT: rttStats.MinRTT(), + SmoothedRTT: rttStats.SmoothedRTT(), + LatestRTT: rttStats.LatestRTT(), + RTTVariance: rttStats.MeanDeviation(), + CongestionWindow: int(12345 + protocol.ByteCount(2*i)), + BytesInFlight: int(12345 + protocol.ByteCount(i)), + PacketsInFlight: i, }) if i%2 == 0 { diff --git a/qlog/event.go b/qlog/event.go index 226a043c5..77cdff232 100644 --- a/qlog/event.go +++ b/qlog/event.go @@ -412,15 +412,17 @@ func (e MTUUpdated) Encode(enc *jsontext.Encoder, _ time.Time) error { return h.err } +// MetricsUpdated logs RTT and congestion metrics as defined in the +// recovery:metrics_updated event. +// The PTO count is logged via PTOCountUpdated. type MetricsUpdated struct { - MinRTT *time.Duration - SmoothedRTT *time.Duration - LatestRTT *time.Duration - RTTVariance *time.Duration - CongestionWindow *int - BytesInFlight *int - PacketsInFlight *int - PTOCount *uint32 + MinRTT time.Duration + SmoothedRTT time.Duration + LatestRTT time.Duration + RTTVariance time.Duration + CongestionWindow int + BytesInFlight int + PacketsInFlight int } func (e MetricsUpdated) Name() string { return "recovery:metrics_updated" } @@ -428,42 +430,55 @@ func (e MetricsUpdated) Name() string { return "recovery:metrics_updated" } func (e MetricsUpdated) Encode(enc *jsontext.Encoder, _ time.Time) error { h := encoderHelper{enc: enc} h.WriteToken(jsontext.BeginObject) - if e.MinRTT != nil { + if e.MinRTT != 0 { h.WriteToken(jsontext.String("min_rtt")) - h.WriteToken(jsontext.Float(milliseconds(*e.MinRTT))) + h.WriteToken(jsontext.Float(milliseconds(e.MinRTT))) } - if e.SmoothedRTT != nil { + if e.SmoothedRTT != 0 { h.WriteToken(jsontext.String("smoothed_rtt")) - h.WriteToken(jsontext.Float(milliseconds(*e.SmoothedRTT))) + h.WriteToken(jsontext.Float(milliseconds(e.SmoothedRTT))) } - if e.LatestRTT != nil { + if e.LatestRTT != 0 { h.WriteToken(jsontext.String("latest_rtt")) - h.WriteToken(jsontext.Float(milliseconds(*e.LatestRTT))) + h.WriteToken(jsontext.Float(milliseconds(e.LatestRTT))) } - if e.RTTVariance != nil { + if e.RTTVariance != 0 { h.WriteToken(jsontext.String("rtt_variance")) - h.WriteToken(jsontext.Float(milliseconds(*e.RTTVariance))) + h.WriteToken(jsontext.Float(milliseconds(e.RTTVariance))) } - if e.CongestionWindow != nil { + if e.CongestionWindow != 0 { h.WriteToken(jsontext.String("congestion_window")) - h.WriteToken(jsontext.Uint(uint64(*e.CongestionWindow))) + h.WriteToken(jsontext.Uint(uint64(e.CongestionWindow))) } - if e.BytesInFlight != nil { + if e.BytesInFlight != 0 { h.WriteToken(jsontext.String("bytes_in_flight")) - h.WriteToken(jsontext.Uint(uint64(*e.BytesInFlight))) + h.WriteToken(jsontext.Uint(uint64(e.BytesInFlight))) } - if e.PacketsInFlight != nil { + if e.PacketsInFlight != 0 { h.WriteToken(jsontext.String("packets_in_flight")) - h.WriteToken(jsontext.Uint(uint64(*e.PacketsInFlight))) - } - if e.PTOCount != nil { - h.WriteToken(jsontext.String("pto_count")) - h.WriteToken(jsontext.Uint(uint64(*e.PTOCount))) + h.WriteToken(jsontext.Uint(uint64(e.PacketsInFlight))) } h.WriteToken(jsontext.EndObject) return h.err } +// PTOCountUpdated logs the pto_count value of the +// recovery:metrics_updated event. +type PTOCountUpdated struct { + PTOCount uint32 +} + +func (e PTOCountUpdated) Name() string { return "recovery:metrics_updated" } + +func (e PTOCountUpdated) Encode(enc *jsontext.Encoder, _ time.Time) error { + h := encoderHelper{enc: enc} + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("pto_count")) + h.WriteToken(jsontext.Uint(uint64(e.PTOCount))) + h.WriteToken(jsontext.EndObject) + return h.err +} + type PacketLost struct { Header PacketHeader Trigger PacketLossReason diff --git a/qlog/event_test.go b/qlog/event_test.go index f14d4cd86..24376e181 100644 --- a/qlog/event_test.go +++ b/qlog/event_test.go @@ -606,21 +606,14 @@ func TestMetricsUpdated(t *testing.T) { rttStats.UpdateRTT(15*time.Millisecond, 0) rttStats.UpdateRTT(20*time.Millisecond, 0) rttStats.UpdateRTT(25*time.Millisecond, 0) - minRTT := rttStats.MinRTT() - smoothedRTT := rttStats.SmoothedRTT() - latestRTT := rttStats.LatestRTT() - rttVariance := rttStats.MeanDeviation() - cwndInt := 4321 - bytesInt := 1234 - packetsInt := 42 name, ev := testEventEncoding(t, &MetricsUpdated{ - MinRTT: &minRTT, - SmoothedRTT: &smoothedRTT, - LatestRTT: &latestRTT, - RTTVariance: &rttVariance, - CongestionWindow: &cwndInt, - BytesInFlight: &bytesInt, - PacketsInFlight: &packetsInt, + MinRTT: rttStats.MinRTT(), + SmoothedRTT: rttStats.SmoothedRTT(), + LatestRTT: rttStats.LatestRTT(), + RTTVariance: rttStats.MeanDeviation(), + CongestionWindow: 4321, + BytesInFlight: 1234, + PacketsInFlight: 42, }) require.Equal(t, "recovery:metrics_updated", name) @@ -683,9 +676,8 @@ func TestCongestionStateUpdated(t *testing.T) { require.Equal(t, "congestion_avoidance", ev["new"]) } -func TestMetricsUpdatedPTO(t *testing.T) { - value := uint32(42) - name, ev := testEventEncoding(t, &MetricsUpdated{PTOCount: &value}) +func TestPTOCountUpdated(t *testing.T) { + name, ev := testEventEncoding(t, &PTOCountUpdated{PTOCount: 42}) require.Equal(t, "recovery:metrics_updated", name) require.Equal(t, float64(42), ev["pto_count"])