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
This commit is contained in:
Marten Seemann
2025-11-04 12:13:06 -05:00
committed by GitHub
parent 4930f90307
commit eb7fcf5637
5 changed files with 88 additions and 95 deletions

View File

@@ -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,

View File

@@ -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{

View File

@@ -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 {

View File

@@ -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

View File

@@ -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"])