From ce8f64176aca7236bf75977dc49957c1a8388667 Mon Sep 17 00:00:00 2001 From: Raja Subramanian Date: Thu, 26 Oct 2023 15:34:49 +0530 Subject: [PATCH] Log correct time difference (#2192) --- pkg/sfu/buffer/rtpstats_sender.go | 14 ++-- .../dependencydescriptor.go | 74 +++++++++++++------ .../dependencydescriptor_test.go | 3 +- 3 files changed, 63 insertions(+), 28 deletions(-) diff --git a/pkg/sfu/buffer/rtpstats_sender.go b/pkg/sfu/buffer/rtpstats_sender.go index 001bbad4d..567a5efad 100644 --- a/pkg/sfu/buffer/rtpstats_sender.go +++ b/pkg/sfu/buffer/rtpstats_sender.go @@ -541,12 +541,16 @@ func (r *RTPStatsSender) UpdateFromReceiverReport(rr rtcp.ReceptionReport) (rtt eis := &s.intervalStats eis.aggregate(&is) if is.packetsNotFound != 0 { + timeSinceLastRR := time.Since(r.lastRRTime) + if r.lastRRTime.IsZero() { + timeSinceLastRR = time.Since(r.startTime) + } if r.metadataCacheOverflowCount%10 == 0 { r.logger.Infow( "metadata cache overflow", "lastRRTime", r.lastRRTime.String(), "lastRR", r.lastRR, - "sinceLastRR", time.Since(r.lastRRTime).String(), + "timeSinceLastRR", timeSinceLastRR.String(), "receivedRR", rr, "extStartSN", r.extStartSN, "extHighestSN", r.extHighestSN, @@ -636,10 +640,10 @@ func (r *RTPStatsSender) GetRtcpSenderReport(ssrc uint32, calculatedClockRate ui At: now, } if r.srNewest != nil { - timeSinceLastReport := nowNTP.Time().Sub(r.srNewest.NTPTimestamp.Time()).Seconds() + timeSinceLastReport := nowNTP.Time().Sub(r.srNewest.NTPTimestamp.Time()) rtpDiffSinceLastReport := nowRTPExt - r.srNewest.RTPTimestampExt - windowClockRate := float64(rtpDiffSinceLastReport) / timeSinceLastReport - if timeSinceLastReport > 0.2 && math.Abs(float64(r.params.ClockRate)-windowClockRate) > 0.2*float64(r.params.ClockRate) { + windowClockRate := float64(rtpDiffSinceLastReport) / timeSinceLastReport.Seconds() + if timeSinceLastReport.Seconds() > 0.2 && math.Abs(float64(r.params.ClockRate)-windowClockRate) > 0.2*float64(r.params.ClockRate) { if r.clockSkewCount%10 == 0 { r.logger.Infow( "sending sender report, clock skew", @@ -655,7 +659,7 @@ func (r *RTPStatsSender) GetRtcpSenderReport(ssrc uint32, calculatedClockRate ui "nowRTPExtUsingTime", nowRTPExtUsingTime, "calculatedClockRate", calculatedClockRate, "nowRTPExtUsingRate", nowRTPExtUsingRate, - "timeSinceLastReport", timeSinceLastReport, + "timeSinceLastReport", timeSinceLastReport.String(), "rtpDiffSinceLastReport", rtpDiffSinceLastReport, "windowClockRate", windowClockRate, "count", r.clockSkewCount, diff --git a/pkg/sfu/videolayerselector/dependencydescriptor.go b/pkg/sfu/videolayerselector/dependencydescriptor.go index 72eb4c4a5..1f8a9390b 100644 --- a/pkg/sfu/videolayerselector/dependencydescriptor.go +++ b/pkg/sfu/videolayerselector/dependencydescriptor.go @@ -63,7 +63,7 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r ddwdt := extPkt.DependencyDescriptor if ddwdt == nil { // packet doesn't have dependency descriptor - d.logger.Debugw(fmt.Sprintf("drop packet, no DD, incoming %v", extPkt.VideoLayer)) + d.logger.Debugw(fmt.Sprintf("drop packet, no DD, incoming %v, sn: %d, isKeyFrame: %v", extPkt.VideoLayer, extPkt.Packet.SequenceNumber, extPkt.KeyFrame)) return } @@ -81,20 +81,22 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r sd, err := d.decisions.GetDecision(extFrameNum) if err != nil { // do not mark as dropped as only error is an old frame - d.logger.Debugw(fmt.Sprintf("drop packet on decision error, incoming %v, fn: %d/%d", + d.logger.Debugw(fmt.Sprintf("drop packet on decision error, incoming %v, fn: %d/%d, sn: %d", incomingLayer, dd.FrameNumber, extFrameNum, + extPkt.Packet.SequenceNumber, ), "err", err) return } switch sd { case selectorDecisionDropped: // a packet of an alreadty dropped frame, maintain decision - d.logger.Debugw(fmt.Sprintf("drop packet already dropped, incoming %v, fn: %d/%d", + d.logger.Debugw(fmt.Sprintf("drop packet already dropped, incoming %v, fn: %d/%d, sm: %d", incomingLayer, dd.FrameNumber, extFrameNum, + extPkt.Packet.SequenceNumber, )) return } @@ -144,23 +146,34 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r if highestDecodeTarget.Target < 0 { // no active decode target, do not select - d.logger.Debugw(fmt.Sprintf("drop packet for no target found, decodeTargets %v, tagetLayer %v, incoming %v", - d.decodeTargets, - d.targetLayer, - incomingLayer, - )) + d.logger.Debugw( + "drop packet for no target found", + "highestDecodeTarget", highestDecodeTarget, + "decodeTargets", d.decodeTargets, + "tagetLayer", d.targetLayer, + "incoming", incomingLayer, + "fn", dd.FrameNumber, + "efn", extFrameNum, + "sn", extPkt.Packet.SequenceNumber, + "isKeyFrame", extPkt.KeyFrame, + ) d.decisions.AddDropped(extFrameNum) return } // DD-TODO : if bandwidth in congest, could drop the 'Discardable' frame if dti == dede.DecodeTargetNotPresent { - d.logger.Debugw(fmt.Sprintf("drop packet for decode target not present, highestDecodeTarget %d, incoming %v, fn: %d/%d", - highestDecodeTarget, - incomingLayer, - dd.FrameNumber, - extFrameNum, - )) + d.logger.Debugw( + "drop packet for decode target not present", + "highestDecodeTarget", highestDecodeTarget, + "decodeTargets", d.decodeTargets, + "tagetLayer", d.targetLayer, + "incoming", incomingLayer, + "fn", dd.FrameNumber, + "efn", extFrameNum, + "sn", extPkt.Packet.SequenceNumber, + "isKeyFrame", extPkt.KeyFrame, + ) d.decisions.AddDropped(extFrameNum) return } @@ -180,12 +193,17 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r } } if !isDecodable { - d.logger.Debugw(fmt.Sprintf("drop packet for not decodable, highestDecodeTarget %d, incoming %v, fn: %d/%d", - highestDecodeTarget, - incomingLayer, - dd.FrameNumber, - extFrameNum, - )) + d.logger.Debugw( + "drop packet for not decodable", + "highestDecodeTarget", highestDecodeTarget, + "decodeTargets", d.decodeTargets, + "tagetLayer", d.targetLayer, + "incoming", incomingLayer, + "fn", dd.FrameNumber, + "efn", extFrameNum, + "sn", extPkt.Packet.SequenceNumber, + "isKeyFrame", extPkt.KeyFrame, + ) d.decisions.AddDropped(extFrameNum) return } @@ -203,7 +221,10 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r "req", d.requestSpatial, "maxSeen", d.maxSeenLayer, "feed", extPkt.Packet.SSRC, - "frame", extFrameNum, + "fn", dd.FrameNumber, + "efn", extFrameNum, + "sn", extPkt.Packet.SequenceNumber, + "isKeyFrame", extPkt.KeyFrame, ) } @@ -212,7 +233,16 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r d.previousActiveDecodeTargetsBitmask = d.activeDecodeTargetsBitmask d.activeDecodeTargetsBitmask = buffer.GetActiveDecodeTargetBitmask(d.currentLayer, ddwdt.DecodeTargets) - d.logger.Debugw("switch to target", "highest", highestDecodeTarget.Layer, "current", d.currentLayer, "bitmask", *d.activeDecodeTargetsBitmask, "frame", extFrameNum) + d.logger.Debugw( + "switch to target", + "highestDecodeTarget", highestDecodeTarget, + "current", d.currentLayer, + "bitmask", *d.activeDecodeTargetsBitmask, + "fn", dd.FrameNumber, + "efn", extFrameNum, + "sn", extPkt.Packet.SequenceNumber, + "isKeyFrame", extPkt.KeyFrame, + ) } ddExtension := &dede.DependencyDescriptorExtension{ diff --git a/pkg/sfu/videolayerselector/dependencydescriptor_test.go b/pkg/sfu/videolayerselector/dependencydescriptor_test.go index e9e158fda..a33f3b15f 100644 --- a/pkg/sfu/videolayerselector/dependencydescriptor_test.go +++ b/pkg/sfu/videolayerselector/dependencydescriptor_test.go @@ -137,7 +137,7 @@ func TestDependencyDescriptor(t *testing.T) { ddSelector.SetRequestSpatial(1) // no dd ext, dropped - ret := ddSelector.Select(&buffer.ExtPacket{}, 0) + ret := ddSelector.Select(&buffer.ExtPacket{Packet: &rtp.Packet{}}, 0) require.False(t, ret.IsSelected) require.True(t, ret.IsRelevant) @@ -153,6 +153,7 @@ func TestDependencyDescriptor(t *testing.T) { }, }, }, + Packet: &rtp.Packet{}, }, 0) require.False(t, ret.IsSelected) require.True(t, ret.IsRelevant)