Skip to content
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

Jump to bottom

[core] Slowdown ACKACK outoforder log frequency. #3007

Merged
merged 2 commits into from
Aug 16, 2024
Merged

[core] Slowdown ACKACK outoforder log frequency. #3007

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
ffdaed9
[core] Slowdown ACKACK outoforder log frequency.
maxsharabayko Aug 14, 2024
c217ebb
[core] Reordered MAX_FREQLOGFA.
maxsharabayko Aug 15, 2024
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
27 changes: 19 additions & 8 deletions srtcore/core.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5965,7 +5965,7 @@ bool srt::CUDT::frequentLogAllowed(size_t logid, const time_point& tnow, std::st
#endif

bool is_suppressed = IsSet(m_LogSlowDownExpired, BIT(logid));
bool isnow = (m_tsLogSlowDown.load() + milliseconds_from(SRT_LOG_SLOWDOWN_FREQ_MS)) <= tnow;
const bool isnow = (m_tsLogSlowDown[logid].load() + milliseconds_from(SRT_LOG_SLOWDOWN_FREQ_MS)) <= tnow;
if (isnow)
{
// Theoretically this should prevent other calls of this function to take
Expand All @@ -5977,19 +5977,19 @@ bool srt::CUDT::frequentLogAllowed(size_t logid, const time_point& tnow, std::st
// Note: it may happen that two threads could intermix one another between
// the check and setting up, but this will at worst case set the slightly
// later time again.
m_tsLogSlowDown.store(tnow);
m_tsLogSlowDown[logid].store(tnow);

is_suppressed = false;

int supr = m_aSuppressedMsg[logid];
const int supr = m_aSuppressedMsg[logid];

if (supr > 0)
w_why = Sprint("++SUPPRESSED: ", supr);
m_aSuppressedMsg[logid] = 0;
}
else
{
w_why = Sprint("Too early - last one was ", FormatDuration<DUNIT_MS>(tnow - m_tsLogSlowDown.load()));
w_why = Sprint("Too early - last one was ", FormatDuration<DUNIT_MS>(tnow - m_tsLogSlowDown[logid].load()));
// Set YOUR OWN bit, atomically.
m_LogSlowDownExpired |= uint8_t(BIT(logid));
++m_aSuppressedMsg[logid];
Expand Down Expand Up @@ -8688,10 +8688,21 @@ void srt::CUDT::processCtrlAckAck(const CPacket& ctrlpkt, const time_point& tsAr
{
if (ctrlpkt.getAckSeqNo() > (m_iAckSeqNo - static_cast<int>(ACK_WND_SIZE)) && ctrlpkt.getAckSeqNo() <= m_iAckSeqNo)
{
LOGC(inlog.Note,
log << CONID() << "ACKACK out of order, skipping RTT calculation "
<< "(ACK number: " << ctrlpkt.getAckSeqNo() << ", last ACK sent: " << m_iAckSeqNo
<< ", RTT (EWMA): " << m_iSRTT << ")");
string why;
if (frequentLogAllowed(FREQLOGFA_ACKACK_OUTOFORDER, tsArrival, (why)))
{
LOGC(inlog.Note,
log << CONID() << "ACKACK out of order, skipping RTT calculation "
<< "(ACK number: " << ctrlpkt.getAckSeqNo() << ", last ACK sent: " << m_iAckSeqNo
<< ", RTT (EWMA): " << m_iSRTT << ")." << why);
}
#if SRT_ENABLE_FREQUENT_LOG_TRACE
else
{
LOGC(qrlog.Note, log << "SUPPRESSED: ACKACK out of order LOG: " << why);
}
#endif

return;
}

Expand Down
14 changes: 8 additions & 6 deletions srtcore/core.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -948,13 +948,15 @@ class CUDT
int32_t m_iReXmitCount; // Re-Transmit Count since last ACK

static const size_t
MAX_FREQLOGFA = 2,
FREQLOGFA_ENCRYPTION_FAILURE = 0,
FREQLOGFA_RCV_DROPPED = 1;
atomic_time_point m_tsLogSlowDown; // The last time a log message from the "slow down" group was shown.
// The "slow down" group of logs are those that can be printed too often otherwise, but can't be turned off (warnings and errors).
// Currently only used by decryption failure message, therefore no mutex protection needed.
sync::atomic<uint8_t> m_LogSlowDownExpired; // Can't use bitset because atomic
FREQLOGFA_RCV_DROPPED = 1,
FREQLOGFA_ACKACK_OUTOFORDER = 2,
MAX_FREQLOGFA = 3;

atomic_time_point m_tsLogSlowDown[MAX_FREQLOGFA]; // The last time a log message from the "slow down" group was shown.
// The "slow down" group of logs are those that can be printed too often otherwise, but can't be turned off (warnings and errors).
// Currently only used by decryption failure message, therefore no mutex protection needed.
sync::atomic<uint8_t> m_LogSlowDownExpired; // Can't use bitset because atomic
sync::atomic<int> m_aSuppressedMsg[MAX_FREQLOGFA];

/// @brief Check if a frequent log can be shown.
Expand Down
Loading