diff --git a/pkg/rtc/subscriptionmanager.go b/pkg/rtc/subscriptionmanager.go index 31705bf60..52aef3ee3 100644 --- a/pkg/rtc/subscriptionmanager.go +++ b/pkg/rtc/subscriptionmanager.go @@ -1543,7 +1543,7 @@ func (s *mediaTrackSubscription) recordStreamStartLatency(elapsed time.Duration) return } - s.logger.Debugw("track subscribe stream started", "cost", elapsed.Microseconds()) + s.logger.Debugw("track subscribe stream started", "cost", elapsed.Milliseconds()) subscriber := subTrack.Subscriber() prometheus.RecordSubscribeStreamStartTime( subscriber.GetCountry(), diff --git a/pkg/sfu/downtrack.go b/pkg/sfu/downtrack.go index 72038403c..d30de32a4 100644 --- a/pkg/sfu/downtrack.go +++ b/pkg/sfu/downtrack.go @@ -1163,11 +1163,25 @@ func (d *DownTrack) WriteRTP(extPkt *buffer.ExtPacket, layer int32) int32 { if tp.isStarting { writableAt := d.writableAt.Load() lastUnmutedAt := d.lastUnmutedAt.Load() + anchorTo := lastUnmutedAt if !writableAt.IsZero() && !lastUnmutedAt.IsZero() { if writableAt.After(lastUnmutedAt) { - lastUnmutedAt = writableAt + anchorTo = writableAt + } + d.params.Listener.OnStreamStarted(time.Since(anchorTo)) + if time.Since(anchorTo) > time.Second { + d.params.Logger.Debugw( + "stream start high latency", + "latency", time.Since(anchorTo), + "createdAt", time.Unix(0, d.createdAt), + "sinceCreate", time.Since(time.Unix(0, d.createdAt)), + "writableAt", writableAt, + "sinceWritable", time.Since(writableAt), + "lastUnmutedAt", lastUnmutedAt, + "sinceLastUnmute", time.Since(lastUnmutedAt), + "rtpStats", d.rtpStats, + ) } - d.params.Listener.OnStreamStarted(time.Since(lastUnmutedAt)) } } return 1 @@ -2500,7 +2514,7 @@ func (d *DownTrack) onBindAndConnectedChange() { return } writable := d.connected.Load() && d.bindState.Load() == bindStateBound - if writable { + if writable && !d.writable.Load() { d.writableAt.Store(time.Now()) } d.writable.Store(writable)