diff --git a/srtcore/buffer.cpp b/srtcore/buffer.cpp index 89c2dab723..6e00f4dba7 100644 --- 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 index f0a499fd4f..7df7b7e70f 100644 --- 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 index f1feed28b7..4d81ceaa4d 100644 --- 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; }