drifttracer: include msRcvBuf in debug trace drift

[oviano]

I found it useful to be able to view the current msRcvBuf along with the other information relating to the drift samples in order to confirm that the drift calculation was correctly keeping the receive buffer the right size.

[maxsharabayko]

I would like to avoid altering the CTsbpdTime::addDriftSample(..), but don't have a better suggestion yet. :)

[maxsharabayko]

I suppose you don't need msRcvBuf as an argument, because the receiver buffer already knows this value (getTimespan_ms()).

[oviano]

I tried that approach but it was crashing inside getTimespan_ms, and I couldn't really follow exactly what I needed to lock to prevent it. Then I noticed that it was the smoothed average I needed in any case, and this was updated regularly elsewhere, so it seemed safer to pass this value down instead.

But, you know, maybe nobody needs this feature anyway, I wouldn't spend too much time on it if you don't like the implementation, I'm just sharing what I did.

[maxsharabayko]

I guess the buffer fullness would indeed be helpful in the drift trace.
I just don't feel good that the debug tracing logic touches so many places. That might reduce the overall readability of the code. 🤔

[oviano]

Ok. I'll have a think - if I can see a less intrusive way of getting that info into the log, I'll update the PR.

[maxsharabayko]

Might be better to just attach those changes to issue #2477 in the form of a git diff patch.
This way it can be preserved. But I don't feel this PR should go to master.

[maxsharabayko]

Ok. I'll have a think - if I can see a less intrusive way of getting that info into the log, I'll update the PR.

Thank you, @oviano. And thanks for sharing your changes!

[maxsharabayko]

Saving the changes to have an option of restoring them if needed. The PR itself is not expected to be merged (see this conversation).

From cd7125a27a6a9648b62b04debfd16dae7bbbcdd6 Mon Sep 17 00:00:00 2001
From: Oliver Collyer <[email protected]>
Date: Thu, 6 Oct 2022 16:49:47 +0100
Subject: [PATCH] drifttracer: include msRcvBuf in debug trace drift

---
 srtcore/buffer_rcv.cpp |  8 +++++++-
 srtcore/buffer_rcv.h   |  5 ++++-
 srtcore/core.cpp       | 13 +++++++++++++
 srtcore/tsbpd_time.cpp | 15 +++++++++++----
 srtcore/tsbpd_time.h   |  8 ++++++--
 5 files changed, 41 insertions(+), 8 deletions(-)

diff --git a/srtcore/buffer_rcv.cpp b/srtcore/buffer_rcv.cpp
index a15e2f63d..7d234fabe 100644
--- a/srtcore/buffer_rcv.cpp
+++ b/srtcore/buffer_rcv.cpp
@@ -968,11 +968,17 @@ int CRcvBuffer::scanNotInOrderMessageLeft(const int startPos, int msgNo) const
     return -1;
 }
 
+#if SRT_DEBUG_TRACE_DRIFT
+bool CRcvBuffer::addRcvTsbPdDriftSample(uint32_t usTimestamp, const time_point& tsPktArrival, int usRTTSample, int msRcvBuf)
+{
+    return m_tsbpd.addDriftSample(usTimestamp, tsPktArrival, usRTTSample, msRcvBuf);
+}
+#else
 bool CRcvBuffer::addRcvTsbPdDriftSample(uint32_t usTimestamp, const time_point& tsPktArrival, int usRTTSample)
 {
     return m_tsbpd.addDriftSample(usTimestamp, tsPktArrival, usRTTSample);
 }
-
+#endif
 void CRcvBuffer::setTsbPdMode(const steady_clock::time_point& timebase, bool wrap, duration delay)
 {
     m_tsbpd.setTsbPdMode(timebase, wrap, delay);
diff --git a/srtcore/buffer_rcv.h b/srtcore/buffer_rcv.h
index 02e48ad66..630d30024 100644
--- a/srtcore/buffer_rcv.h
+++ b/srtcore/buffer_rcv.h
@@ -335,8 +335,11 @@ class CRcvBuffer
 
     void applyGroupDrift(const time_point& timebase, bool wrp, const duration& udrift);
 
+#if SRT_DEBUG_TRACE_DRIFT
+    bool addRcvTsbPdDriftSample(uint32_t usTimestamp, const time_point& tsPktArrival, int usRTTSample, int msRcvBuf);
+#else
     bool addRcvTsbPdDriftSample(uint32_t usTimestamp, const time_point& tsPktArrival, int usRTTSample);
-
+#endif
     time_point getPktTsbPdTime(uint32_t usPktTimestamp) const;
 
     time_point getTsbPdTimeBase(uint32_t usPktTimestamp) const;
diff --git a/srtcore/core.cpp b/srtcore/core.cpp
index c099fe671..9e9c21a99 100644
--- a/srtcore/core.cpp
+++ b/srtcore/core.cpp
@@ -8456,7 +8456,16 @@ void srt::CUDT::processCtrlAckAck(const CPacket& ctrlpkt, const time_point& tsAr
     // srt_recvfile (which doesn't make any sense), you'll have a deadlock.
     if (m_config.bDriftTracer)
     {
+#if SRT_DEBUG_TRACE_DRIFT
+        int byteRcvBuf, msRcvBuf;
+        {
+            ScopedLock lck(m_RcvBufferLock);
+            m_pRcvBuffer->getRcvAvgDataSize(byteRcvBuf, msRcvBuf);
+        }
+        const bool drift_updated SRT_ATR_UNUSED = m_pRcvBuffer->addRcvTsbPdDriftSample(ctrlpkt.getMsgTimeStamp(), tsArrival, rtt, msRcvBuf);
+#else
         const bool drift_updated SRT_ATR_UNUSED = m_pRcvBuffer->addRcvTsbPdDriftSample(ctrlpkt.getMsgTimeStamp(), tsArrival, rtt);
+#endif
 #if ENABLE_BONDING
         if (drift_updated && m_parent->m_GroupOf)
         {
@@ -11553,5 +11562,9 @@ void srt::CUDT::processKeepalive(const CPacket& ctrlpkt, const time_point& tsArr
     ScopedLock lck(m_RcvBufferLock);
     m_pRcvBuffer->updateTsbPdTimeBase(ctrlpkt.getMsgTimeStamp());
     if (m_config.bDriftTracer)
+#if SRT_DEBUG_TRACE_DRIFT
+        m_pRcvBuffer->addRcvTsbPdDriftSample(ctrlpkt.getMsgTimeStamp(), tsArrival, -1, 0);
+#else
         m_pRcvBuffer->addRcvTsbPdDriftSample(ctrlpkt.getMsgTimeStamp(), tsArrival, -1);
+#endif
 }
diff --git a/srtcore/tsbpd_time.cpp b/srtcore/tsbpd_time.cpp
index 046c90b74..ed9ebd91f 100644
--- a/srtcore/tsbpd_time.cpp
+++ b/srtcore/tsbpd_time.cpp
@@ -39,7 +39,8 @@ class drift_logger
                int64_t                                    drift,
                int64_t                                    overdrift,
                const srt::sync::steady_clock::time_point& pkt_base,
-               const srt::sync::steady_clock::time_point& tsbpd_base)
+               const srt::sync::steady_clock::time_point& tsbpd_base,
+               int                                        timespan_ms)
     {
         using namespace srt::sync;
         ScopedLock lck(m_mtx);
@@ -62,7 +63,8 @@ class drift_logger
         m_fout << drift << ",";
         m_fout << overdrift << ",";
         m_fout << str_pkt_base << ",";
-        m_fout << str_tbase << "\n";
+        m_fout << str_tbase << ",";
+        m_fout << timespan_ms << "\n";
         m_fout.flush();
     }
 
@@ -70,7 +72,7 @@ class drift_logger
     void print_header()
     {
         m_fout << "usElapsedStd,usAckAckTimestampStd,";
-        m_fout << "usRTTStd,usDriftSampleStd,usDriftStd,usOverdriftStd,tsPktBase,TSBPDBase\n";
+        m_fout << "usRTTStd,usDriftSampleStd,usDriftStd,usOverdriftStd,tsPktBase,TSBPDBase,msRcvBuf\n";
     }
 
     void create_file()
@@ -103,7 +105,11 @@ drift_logger g_drift_logger;
 
 #endif // SRT_DEBUG_TRACE_DRIFT
 
+#if SRT_DEBUG_TRACE_DRIFT
+bool CTsbpdTime::addDriftSample(uint32_t usPktTimestamp, const time_point& tsPktArrival, int usRTTSample, int msRcvBuf)
+#else
 bool CTsbpdTime::addDriftSample(uint32_t usPktTimestamp, const time_point& tsPktArrival, int usRTTSample)
+#endif
 {
     if (!m_bTsbPdMode)
         return false;
@@ -151,7 +157,8 @@ bool CTsbpdTime::addDriftSample(uint32_t usPktTimestamp, const time_point& tsPkt
                          m_DriftTracer.drift(),
                          m_DriftTracer.overdrift(),
                          tsPktBaseTime,
-                         m_tsTsbPdTimeBase);
+                         m_tsTsbPdTimeBase,
+                         msRcvBuf);
 #endif
     return updated;
 }
diff --git a/srtcore/tsbpd_time.h b/srtcore/tsbpd_time.h
index 3483c197f..99d0a483a 100644
--- a/srtcore/tsbpd_time.h
+++ b/srtcore/tsbpd_time.h
@@ -68,10 +68,14 @@ class CTsbpdTime
     /// @param [in] pktTimestamp Timestamp of the arrived ACKACK packet.
     /// @param [in] tsPktArrival packet arrival time.
     /// @param [in] usRTTSample RTT sample from an ACK-ACKACK pair. If no sample, pass '-1'.
-    /// 
+    /// @param [in] msRcvBuf Undelivered timespan (msec) of UDT receiver
+    ///
     /// @return true if TSBPD base time has changed, false otherwise.
+#if SRT_DEBUG_TRACE_DRIFT
+    bool addDriftSample(uint32_t pktTimestamp, const time_point& tsPktArrival, int usRTTSample, int msRcvBuf);
+#else
     bool addDriftSample(uint32_t pktTimestamp, const time_point& tsPktArrival, int usRTTSample);
-
+#endif
     /// @brief Handle timestamp of data packet when 32-bit integer carryover is about to happen.
     /// When packet timestamp approaches CPacket::MAX_TIMESTAMP, the TSBPD base time should be
     /// shifted accordingly to correctly handle new packets with timestamps starting from zero.