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

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

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)