Skip to content

drifttracer: include msRcvBuf in debug trace drift #2480

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
oviano wants to merge 1 commit into from
Closed

drifttracer: include msRcvBuf in debug trace drift #2480

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 7 additions & 1 deletion srtcore/buffer_rcv.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Comment on lines +971 to +976
Copy link
Collaborator

@maxsharabayko maxsharabayko Oct 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

@oviano oviano Oct 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

@maxsharabayko maxsharabayko Oct 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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. 🤔

Copy link
Contributor Author

@oviano oviano Oct 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

@maxsharabayko maxsharabayko Oct 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

@maxsharabayko maxsharabayko Oct 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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!

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);
Expand Down
5 changes: 4 additions & 1 deletion srtcore/buffer_rcv.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
13 changes: 13 additions & 0 deletions srtcore/core.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand Down Expand Up @@ -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
}
15 changes: 11 additions & 4 deletions srtcore/tsbpd_time.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -62,15 +63,16 @@ 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();
}

private:
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()
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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;
}
Expand Down
8 changes: 6 additions & 2 deletions srtcore/tsbpd_time.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down