From ced94b8645829263a1a9ef6c8101936897252d6b Mon Sep 17 00:00:00 2001
From: Raja Subramanian <raja.gobi@tutanota.com>
Date: Thu, 30 Jul 2026 17:10:59 +0530
Subject: [PATCH] log high stream start latency. (#4714)

* log high stream start latency.

There is something wrong in measurement as audio is showing high p99
latency. Must be misattributing samples. So, logging for high latency to
understand this better.

* use correct variable

* time since create
---
 pkg/rtc/subscriptionmanager.go |  2 +-
 pkg/sfu/downtrack.go           | 20 +++++++++++++++++---
 2 files changed, 18 insertions(+), 4 deletions(-)

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)