Changed the log message.

Now shows TSBPD times of packets.
Haivision · Apr 12, 2021 · 55c1d9a · 55c1d9a
1 parent 7d17365
commit 55c1d9a
Show file tree

Hide file tree

Showing 3 changed files with 103 additions and 15 deletions.
diff --git a/srtcore/buffer.cpp b/srtcore/buffer.cpp
@@ -1724,6 +1724,43 @@ unsigned CRcvBuffer::getRcvAvgPayloadSize() const
     return m_uAvgPayloadSz;
 }
 
+CRcvBuffer::ReadingState CRcvBuffer::debugGetReadingState() const
+{
+    ReadingState readstate;
+
+    readstate.numAcknowledged = 0;
+    readstate.numUnacknowledged = m_iMaxPos;
+
+    if (m_bTsbPdMode)
+    {
+        if ((NULL != m_pUnit[m_iStartPos]) && (m_pUnit[m_iStartPos]->m_iFlag == CUnit::GOOD))
+        {
+            if (m_bTsbPdMode)
+                readstate.tsStart = getPktTsbPdTimeNoWrap(m_pUnit[m_iStartPos]->m_Packet.getMsgTimeStamp());
+
+            readstate.numAcknowledged = m_iLastAckPos > m_iStartPos
+                ? m_iLastAckPos - m_iStartPos
+                : m_iLastAckPos + (m_iSize - m_iStartPos);
+        }
+
+        const int iLastAckPos = (m_iLastAckPos - 1) % m_iSize;
+        if (m_iLastAckPos != m_iStartPos && (NULL != m_pUnit[iLastAckPos]) && (m_pUnit[iLastAckPos]->m_iFlag == CUnit::GOOD))
+        {
+            if (m_bTsbPdMode)
+                readstate.tsFirstUnack = getPktTsbPdTimeNoWrap(m_pUnit[iLastAckPos]->m_Packet.getMsgTimeStamp());
+        }
+
+        const int iEndPos = (m_iLastAckPos + m_iMaxPos - 1) % m_iSize;
+        if (m_iMaxPos != 0 && (NULL != m_pUnit[iEndPos]) && (m_pUnit[iEndPos]->m_iFlag == CUnit::GOOD))
+        {
+            if (m_bTsbPdMode)
+                readstate.tsEnd = getPktTsbPdTimeNoWrap(m_pUnit[iEndPos]->m_Packet.getMsgTimeStamp());
+        }
+    }
+
+    return readstate;
+}
+
 void CRcvBuffer::dropMsg(int32_t msgno, bool using_rexmit_flag)
 {
     for (int i = m_iStartPos, n = shift(m_iLastAckPos, m_iMaxPos); i != n; i = shiftFwd(i))
@@ -1792,6 +1829,17 @@ steady_clock::time_point CRcvBuffer::getTsbPdTimeBase(uint32_t timestamp_us)
     return (m_tsTsbPdTimeBase + microseconds_from(carryover));
 }
 
+CRcvBuffer::time_point CRcvBuffer::getTsbPdTimeBaseNoWrap(uint32_t timestamp_us) const
+{
+    int64_t carryover = 0;
+    if (m_bTsbPdWrapCheck && timestamp_us < TSBPD_WRAP_PERIOD)
+    {
+        carryover = int64_t(CPacket::MAX_TIMESTAMP) + 1;
+    }
+
+    return (m_tsTsbPdTimeBase + microseconds_from(carryover));
+}
+
 void CRcvBuffer::applyGroupTime(const steady_clock::time_point& timebase,
                                 bool                            wrp,
                                 uint32_t                        delay,
@@ -1848,6 +1896,13 @@ steady_clock::time_point CRcvBuffer::getPktTsbPdTime(uint32_t timestamp)
     return (time_base + m_tdTsbPdDelay + microseconds_from(timestamp + m_DriftTracer.drift()));
 }
 
+steady_clock::time_point CRcvBuffer::getPktTsbPdTimeNoWrap(uint32_t timestamp) const
+{
+    const steady_clock::time_point time_base = getTsbPdTimeBaseNoWrap(timestamp);
+
+    return (time_base + m_tdTsbPdDelay + microseconds_from(timestamp + m_DriftTracer.drift()));
+}
+
 int CRcvBuffer::setRcvTsbPdMode(const steady_clock::time_point& timebase, const steady_clock::duration& delay)
 {
     m_bTsbPdMode      = true;

diff --git a/srtcore/buffer.h b/srtcore/buffer.h
@@ -348,6 +348,18 @@ class CRcvBuffer
     /// @return size (bytes) of payload size
     unsigned getRcvAvgPayloadSize() const;
 
+
+    struct ReadingState
+    {
+        time_point tsStart;
+        time_point tsFirstUnack;
+        time_point tsEnd;
+        int numAcknowledged;
+        int numUnacknowledged;
+    };
+
+    ReadingState debugGetReadingState() const;
+
     /// Mark the message to be dropped from the message list.
     /// @param [in] msgno message number.
     /// @param [in] using_rexmit_flag whether the MSGNO field uses rexmit flag (if not, one more bit is part of the
@@ -469,6 +481,11 @@ class CRcvBuffer
     /// @return local delivery time (usec)
     time_point getTsbPdTimeBase(uint32_t timestamp_us);
 
+    /// @brief Gets TSBPD time for a packet without diving into the TSBPD wrap check period.
+    /// @param timestamp_us packet timestamp
+    /// @return packet TSBPD time
+    time_point getTsbPdTimeBaseNoWrap(uint32_t timestamp_us) const;
+
     int64_t getDrift() const { return m_DriftTracer.drift(); }
 
 public:
@@ -480,6 +497,7 @@ class CRcvBuffer
     void       applyGroupTime(const time_point& timebase, bool wrapcheck, uint32_t delay, const duration& udrift);
     void       applyGroupDrift(const time_point& timebase, bool wrapcheck, const duration& udrift);
     time_point getPktTsbPdTime(uint32_t timestamp);
+    time_point getPktTsbPdTimeNoWrap(uint32_t timestamp) const;
     int        debugGetSize() const;
     time_point debugGetDeliveryTime(int offset);
 

diff --git a/srtcore/core.cpp b/srtcore/core.cpp
@@ -9443,31 +9443,46 @@ int CUDT::processData(CUnit* in_unit)
                 else
                 {
 #if ENABLE_LOGGING
-                    sync::steady_clock::time_point tsbpdtime;
-                    int32_t curpktseq = 0;
-                    int32_t skiptoseqno = SRT_SEQNO_NONE;
-                    bool    passack = true; // Get next packet to wait for even if not acked
-                    const bool read_ready = m_pRcvBuffer->isRcvDataReady(tsbpdtime, curpktseq, -1);
+                    const time_point curtime = steady_clock::now();
+                    const CRcvBuffer::ReadingState bufstate = m_pRcvBuffer->debugGetReadingState();
                     stringstream ss;
-                    if (is_zero(tsbpdtime))
+
+
+                    ss << "Packets ACKed: " << bufstate.numAcknowledged << " (TSBPD ready in ";
+                    if (!is_zero(bufstate.tsStart) && !is_zero(bufstate.tsFirstUnack))
                     {
-                        ss << "n/a";
+                        ss << count_milliseconds(bufstate.tsStart - curtime);
+                        ss << " : ";
+                        ss << count_milliseconds(bufstate.tsFirstUnack - curtime);
+                        ss << " ms)";
                     }
                     else
                     {
-                        ss << count_milliseconds(steady_clock::now() - tsbpdtime);
+                        ss << "n/a)";
                     }
-#endif
 
-                    LOGC(qrlog.Warn, log << CONID() << "No room to store incoming packet: space left " << avail_bufsize
-                        << ", insert offset " << offset
+
+                    ss << ", not ACKed: " << bufstate.numUnacknowledged;
+                    ss << ", timespan ";
+                    if (!is_zero(bufstate.tsStart) && !is_zero(bufstate.tsEnd))
+                    {
+                        ss << count_milliseconds(bufstate.tsEnd - bufstate.tsStart);
+                        ss << " ms. ";
+                    }
+                    else
+                    {
+                        ss << "n/a. ";
+                    }
+
+                    LOGC(qrlog.Warn, log << CONID() << "No room to store incoming packet: insert offset " << offset
+                        << ", space avail " << avail_bufsize
                         << " (pkt.seq=" << rpkt.m_iSeqNo
-                        << " ack.seq=" << m_iRcvLastSkipAck
-                        << ") " << (read_ready ? "READ-READY " : "READ-NOT-READY ")
-                        << ss.str() << " ms, "
-                        << m_pRcvBuffer->debugGetSize() << " pkts ACK-ed, " << SRT_SYNC_CLOCK_STR
+                        << ", ack.seq=" << m_iRcvLastSkipAck
+                        << "). " << ss.str()
+                        << SRT_SYNC_CLOCK_STR
                         << " drift=" << m_pRcvBuffer->getDrift()
                     );
+#endif
 
                     return -1;
                 }