diff --git a/srtcore/buffer.cpp b/srtcore/buffer.cpp index e2efcefff..b29aa9322 100644 --- a/srtcore/buffer.cpp +++ b/srtcore/buffer.cpp @@ -1833,10 +1833,11 @@ void CRcvBuffer::setRcvTsbPdMode(const steady_clock::time_point& timebase, const } bool CRcvBuffer::addRcvTsbPdDriftSample(uint32_t timestamp_us, + int rtt, steady_clock::duration& w_udrift, steady_clock::time_point& w_newtimebase) { - return m_tsbpd.addDriftSample(timestamp_us, w_udrift, w_newtimebase); + return m_tsbpd.addDriftSample(timestamp_us, rtt, w_udrift, w_newtimebase); } int CRcvBuffer::readMsg(char* data, int len) diff --git a/srtcore/buffer.h b/srtcore/buffer.h index d32e1d29e..7f7680b8d 100644 --- a/srtcore/buffer.h +++ b/srtcore/buffer.h @@ -414,6 +414,7 @@ class CRcvBuffer /// @param [out] w_udrift current drift value /// @param [out] w_newtimebase current TSBPD base time bool addRcvTsbPdDriftSample(uint32_t timestamp, + int rtt, duration& w_udrift, time_point& w_newtimebase); diff --git a/srtcore/core.cpp b/srtcore/core.cpp index efc866164..a1985379d 100644 --- a/srtcore/core.cpp +++ b/srtcore/core.cpp @@ -8279,7 +8279,7 @@ void CUDT::processCtrlAckAck(const CPacket& ctrlpkt, const time_point& tsArrival steady_clock::duration udrift(0); steady_clock::time_point newtimebase; const bool drift_updated ATR_UNUSED = m_pRcvBuffer->addRcvTsbPdDriftSample(ctrlpkt.getMsgTimeStamp(), - (udrift), (newtimebase)); + rtt, (udrift), (newtimebase)); #if ENABLE_EXPERIMENTAL_BONDING if (drift_updated && m_parent->m_GroupOf) { diff --git a/srtcore/tsbpd_time.cpp b/srtcore/tsbpd_time.cpp index 0fe07fb7c..8fedf82ea 100644 --- a/srtcore/tsbpd_time.cpp +++ b/srtcore/tsbpd_time.cpp @@ -19,17 +19,110 @@ using namespace srt::sync; namespace srt { +#if SRT_DEBUG_TRACE_DRIFT +class drift_logger +{ + using steady_clock = srt::sync::steady_clock; + +public: + drift_logger() {} + + ~drift_logger() + { + ScopedLock lck(m_mtx); + m_fout.close(); + } + + void trace(unsigned ackack_timestamp, + int rtt_us, + int64_t drift_sample, + int64_t drift, + int64_t overdrift, + const std::chrono::steady_clock::time_point& tsbpd_base) + { + using namespace srt::sync; + ScopedLock lck(m_mtx); + create_file(); + + // std::string str_tnow = srt::sync::FormatTime(steady_clock::now()); + // str_tnow.resize(str_tnow.size() - 7); // remove trailing ' [STDY]' part + + std::string str_tbase = srt::sync::FormatTime(tsbpd_base); + str_tbase.resize(str_tbase.size() - 7); // remove trailing ' [STDY]' part + + // m_fout << str_tnow << ","; + m_fout << count_microseconds(steady_clock::now() - m_start_time) << ","; + m_fout << ackack_timestamp << ","; + m_fout << rtt_us << ","; + m_fout << drift_sample << ","; + m_fout << drift << ","; + m_fout << overdrift << ","; + m_fout << str_tbase << "\n"; + m_fout.flush(); + } + +private: + void print_header() + { + m_fout << "usElapsedStd,usAckAckTimestampStd,"; + m_fout << "usRTTStd,usDriftSampleStd,usDriftStd,usOverdriftStd,TSBPDBase\n"; + } + + void create_file() + { + if (m_fout.is_open()) + return; + + m_start_time = srt::sync::steady_clock::now(); + std::string str_tnow = srt::sync::FormatTimeSys(m_start_time); + str_tnow.resize(str_tnow.size() - 7); // remove trailing ' [SYST]' part + while (str_tnow.find(':') != std::string::npos) + { + str_tnow.replace(str_tnow.find(':'), 1, 1, '_'); + } + const std::string fname = "drift_trace_" + str_tnow + ".csv"; + m_fout.open(fname, std::ofstream::out); + if (!m_fout) + std::cerr << "IPE: Failed to open " << fname << "!!!\n"; + + print_header(); + } + +private: + srt::sync::Mutex m_mtx; + std::ofstream m_fout; + srt::sync::steady_clock::time_point m_start_time; +}; + +drift_logger g_drift_logger; + +#endif // SRT_DEBUG_TRACE_DRIFT + bool CTsbpdTime::addDriftSample(uint32_t usPktTimestamp, + int usRTTSample, steady_clock::duration& w_udrift, steady_clock::time_point& w_newtimebase) { if (!m_bTsbPdMode) return false; - + const time_point tsNow = steady_clock::now(); ScopedLock lck(m_mtxRW); - const steady_clock::duration tdDrift = tsNow - getPktTsbPdBaseTime(usPktTimestamp); + + // Remember the first RTT sample measured. Ideally we need RTT0 - the one from the handshaking phase, + // because TSBPD base is initialized there. But HS-based RTT is not yet implemented. + // Take the first one assuming it is close to RTT0. + if (m_iFirstRTT == -1) + { + m_iFirstRTT = usRTTSample; + } + + // A change in network delay has to be taken into account. The only way to get some estimation of it + // is to estimate RTT change and assume that the change of the one way network delay is + // approximated by the half of the RTT change. + const duration tdRTTDelta = microseconds_from((usRTTSample - m_iFirstRTT) / 2); + const steady_clock::duration tdDrift = tsNow - getPktTsbPdBaseTime(usPktTimestamp) - tdRTTDelta; const bool updated = m_DriftTracer.update(count_microseconds(tdDrift)); @@ -53,6 +146,14 @@ bool CTsbpdTime::addDriftSample(uint32_t usPktTimestamp, w_udrift = tdDrift; w_newtimebase = m_tsTsbPdTimeBase; +#if SRT_DEBUG_TRACE_DRIFT + g_drift_logger.trace(usPktTimestamp, + usRTTSample, + count_microseconds(tdDrift), + m_DriftTracer.drift(), + m_DriftTracer.overdrift(), + m_tsTsbPdTimeBase); +#endif return updated; } @@ -67,7 +168,7 @@ void CTsbpdTime::setTsbPdMode(const steady_clock::time_point& timebase, bool wra // // This function is called in the HSREQ reception handler only. m_tsTsbPdTimeBase = timebase; - m_tdTsbPdDelay = delay; + m_tdTsbPdDelay = delay; } void CTsbpdTime::applyGroupTime(const steady_clock::time_point& timebase, diff --git a/srtcore/tsbpd_time.h b/srtcore/tsbpd_time.h index 5dcc7ff3a..b6cb770f5 100644 --- a/srtcore/tsbpd_time.h +++ b/srtcore/tsbpd_time.h @@ -30,7 +30,8 @@ class CTsbpdTime public: CTsbpdTime() - : m_bTsbPdMode(false) + : m_iFirstRTT(-1) + , m_bTsbPdMode(false) , m_tdTsbPdDelay(0) , m_bTsbPdWrapCheck(false) { @@ -61,13 +62,17 @@ class CTsbpdTime /// @brief Add new drift sample from an ACK-ACKACK pair. /// ACKACK packets are sent immediately (except for UDP buffering). + /// Therefore their timestamp roughly corresponds to the time of sending + /// and can be used to estimate clock drift. /// /// @param [in] pktTimestamp Timestamp of the arrived ACKACK packet. + /// @param [in] usRTTSample RTT sample from an ACK-ACKACK pair. /// @param [out] w_udrift Current clock drift value. /// @param [out] w_newtimebase Current TSBPD base time. /// /// @return true if TSBPD base time has changed, false otherwise. bool addDriftSample(uint32_t pktTimestamp, + int usRTTSample, steady_clock::duration& w_udrift, steady_clock::time_point& w_newtimebase); @@ -116,8 +121,9 @@ class CTsbpdTime void getInternalTimeBase(time_point& w_tb, bool& w_wrp, duration& w_udrift) const; private: - bool m_bTsbPdMode; //< Rreceiver buffering and TSBPD is active when true. - duration m_tdTsbPdDelay; //< Negotiated buffering delay. + int m_iFirstRTT; // First measured RTT sample. + bool m_bTsbPdMode; // Receiver buffering and TSBPD is active when true. + duration m_tdTsbPdDelay; // Negotiated buffering delay. /// @brief Local time base for TsbPd. /// @note m_tsTsbPdTimeBase is changed in the following cases: diff --git a/srtcore/utilities.h b/srtcore/utilities.h index f0ad80271..7d73c8567 100644 --- a/srtcore/utilities.h +++ b/srtcore/utilities.h @@ -791,11 +791,13 @@ class DriftTracer m_qDriftSum += driftval; ++m_uDriftSpan; + // I moved it here to calculate accumulated overdrift. + if (CLEAR_ON_UPDATE) + m_qOverdrift = 0; + if (m_uDriftSpan < MAX_SPAN) return false; - if (CLEAR_ON_UPDATE) - m_qOverdrift = 0; // Calculate the median of all drift values. // In most cases, the divisor should be == MAX_SPAN.