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

Improved logging API for performance #182

Merged
merged 2 commits into from
Dec 4, 2017
Merged

Improved logging API for performance #182

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
99e07e9
Changed LOGC syntax, stream-send preserved. Introduced LOGF for forma…
Dec 4, 2017
19ecf63
Changed definition of LOGC so that the send-to-stream statement looks…
Dec 4, 2017
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
235 changes: 100 additions & 135 deletions srtcore/api.cpp
View file
Open in desktop

Large diffs are not rendered by default.

72 changes: 37 additions & 35 deletions srtcore/buffer.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -158,21 +158,21 @@ void CSndBuffer::addBuffer(const char* data, int len, int ttl, bool order, uint6
if ((len % m_iMSS) != 0)
size ++;

LOGC(mglog.Debug) << "addBuffer: size=" << m_iCount << " reserved=" << m_iSize << " needs=" << size << " buffers for " << len << " bytes";
LOGC(mglog.Debug, log << "addBuffer: size=" << m_iCount << " reserved=" << m_iSize << " needs=" << size << " buffers for " << len << " bytes");

// dynamically increase sender buffer
while (size + m_iCount >= m_iSize)
{
LOGC(mglog.Debug) << "addBuffer: ... still lacking " << (size + m_iCount - m_iSize) << " buffers...";
LOGC(mglog.Debug, log << "addBuffer: ... still lacking " << (size + m_iCount - m_iSize) << " buffers...");
increase();
}

uint64_t time = CTimer::getTime();
int32_t inorder = order ? MSGNO_PACKET_INORDER::mask : 0;

LOGC(dlog.Debug) << CONID() << "addBuffer: adding "
LOGC(dlog.Debug, log << CONID() << "addBuffer: adding "
<< size << " packets (" << len << " bytes) to send, msgno=" << m_iNextMsgNo
<< (inorder ? "" : " NOT") << " in order";
<< (inorder ? "" : " NOT") << " in order");

Block* s = m_pLastBlock;
msgno = m_iNextMsgNo;
Expand All @@ -182,7 +182,7 @@ void CSndBuffer::addBuffer(const char* data, int len, int ttl, bool order, uint6
if (pktlen > m_iMSS)
pktlen = m_iMSS;

LOGC(dlog.Debug) << "addBuffer: spreading from=" << (i*m_iMSS) << " size=" << pktlen << " TO BUFFER:" << (void*)s->m_pcData;
LOGC(dlog.Debug, log << "addBuffer: spreading from=" << (i*m_iMSS) << " size=" << pktlen << " TO BUFFER:" << (void*)s->m_pcData);
memcpy(s->m_pcData, data + i * m_iMSS, pktlen);
s->m_iLength = pktlen;

Expand Down Expand Up @@ -260,7 +260,7 @@ void CSndBuffer::updInputRate(uint64_t time, int pkts, int bytes)
m_iInRateBytesCount += (m_iInRatePktsCount * CPacket::SRT_DATA_HDR_SIZE);
m_iInRateBps = (int)(((int64_t)m_iInRateBytesCount * 1000000) / (time - m_InRateStartTime));

LOGC(dlog.Debug).form("updInputRate: pkts:%d bytes:%d avg=%d rate=%d kbps interval=%llu\n",
LOGF(dlog.Debug, "updInputRate: pkts:%d bytes:%d avg=%d rate=%d kbps interval=%llu\n",
m_iInRateBytesCount, m_iInRatePktsCount, m_iAvgPayloadSz, (m_iInRateBps*8)/1000,
(unsigned long long)(time - m_InRateStartTime));

Expand Down Expand Up @@ -306,17 +306,17 @@ int CSndBuffer::addBufferFromFile(fstream& ifs, int len)
if ((len % m_iMSS) != 0)
size ++;

LOGC(mglog.Debug) << "addBufferFromFile: size=" << m_iCount << " reserved=" << m_iSize << " needs=" << size << " buffers for " << len << " bytes";
LOGC(mglog.Debug, log << "addBufferFromFile: size=" << m_iCount << " reserved=" << m_iSize << " needs=" << size << " buffers for " << len << " bytes");

// dynamically increase sender buffer
while (size + m_iCount >= m_iSize)
{
LOGC(mglog.Debug) << "addBufferFromFile: ... still lacking " << (size + m_iCount - m_iSize) << " buffers...";
LOGC(mglog.Debug, log << "addBufferFromFile: ... still lacking " << (size + m_iCount - m_iSize) << " buffers...");
increase();
}

LOGC(dlog.Debug) << CONID() << "addBufferFromFile: adding "
<< size << " packets (" << len << " bytes) to send, msgno=" << m_iNextMsgNo;
LOGC(dlog.Debug, log << CONID() << "addBufferFromFile: adding "
<< size << " packets (" << len << " bytes) to send, msgno=" << m_iNextMsgNo);

Block* s = m_pLastBlock;
int total = 0;
Expand All @@ -329,7 +329,7 @@ int CSndBuffer::addBufferFromFile(fstream& ifs, int len)
if (pktlen > m_iMSS)
pktlen = m_iMSS;

LOGC(dlog.Debug) << "addBufferFromFile: reading from=" << (i*m_iMSS) << " size=" << pktlen << " TO BUFFER:" << (void*)s->m_pcData;
LOGC(dlog.Debug, log << "addBufferFromFile: reading from=" << (i*m_iMSS) << " size=" << pktlen << " TO BUFFER:" << (void*)s->m_pcData);
ifs.read(s->m_pcData, pktlen);
if ((pktlen = int(ifs.gcount())) <= 0)
break;
Expand Down Expand Up @@ -406,7 +406,7 @@ int CSndBuffer::readData(char** data, int32_t& msgno_bitset, uint64_t& srctime,

m_pCurrBlock = m_pCurrBlock->m_pNext;

LOGC(dlog.Debug) << CONID() << "CSndBuffer: extracting packet size=" << readlen << " to send";
LOGC(dlog.Debug, log << CONID() << "CSndBuffer: extracting packet size=" << readlen << " to send");

return readlen;
}
Expand Down Expand Up @@ -452,7 +452,7 @@ int CSndBuffer::readData(char** data, const int offset, int32_t& msgno_bitset, u
msglen ++;
}

LOGC(dlog.Debug) << "CSndBuffer::readData: due to TTL exceeded, " << msglen << " messages to drop, up to " << msgno;
LOGC(dlog.Debug, log << "CSndBuffer::readData: due to TTL exceeded, " << msglen << " messages to drop, up to " << msgno);

// If readData returns -1, then msgno_bitset is understood as a Message ID to drop.
// This means that in this case it should be written by the message sequence value only
Expand All @@ -476,7 +476,7 @@ int CSndBuffer::readData(char** data, const int offset, int32_t& msgno_bitset, u
p->m_ullSourceTime_us ? p->m_ullSourceTime_us :
p->m_ullOriginTime_us;

LOGC(dlog.Debug) << CONID() << "CSndBuffer: extracting packet size=" << readlen << " to send [REXMIT]";
LOGC(dlog.Debug, log << CONID() << "CSndBuffer: extracting packet size=" << readlen << " to send [REXMIT]");

return readlen;
}
Expand Down Expand Up @@ -552,7 +552,7 @@ void CSndBuffer::updAvgBufSize(uint64_t now)
int bytescount;
int count = getCurrBufSize(Ref(bytescount), Ref(instspan));

LOGC(dlog.Debug).form("updAvgBufSize: %6llu: %6d %6d %6d ms\n",
LOGF(dlog.Debug, "updAvgBufSize: %6llu: %6d %6d %6d ms\n",
(unsigned long long)elapsed, count, bytescount, instspan);

m_iCountMAvg = (int)(((count * (1000 - elapsed)) + (count * elapsed)) / 1000);
Expand Down Expand Up @@ -668,8 +668,8 @@ void CSndBuffer::increase()

m_iSize += unitsize;

LOGC(dlog.Debug) << "CSndBuffer: BUFFER FULL - adding " << (unitsize*m_iMSS) << " bytes spread to " << unitsize << " blocks"
<< " (total size: " << m_iSize << " bytes)";
LOGC(dlog.Debug, log << "CSndBuffer: BUFFER FULL - adding " << (unitsize*m_iMSS) << " bytes spread to " << unitsize << " blocks"
<< " (total size: " << m_iSize << " bytes)");

}

Expand Down Expand Up @@ -812,16 +812,18 @@ int CRcvBuffer::readBuffer(char* data, int len)
int p = m_iStartPos;
int lastack = m_iLastAckPos;
int rs = len;
char* begin = data; // logging only
#if ENABLE_LOGGING
char* begin = data;
#endif

uint64_t now = (m_bTsbPdMode ? CTimer::getTime() : 0LL);

LOGC(dlog.Debug) << CONID() << "readBuffer: start=" << p << " lastack=" << lastack;
LOGC(dlog.Debug, log << CONID() << "readBuffer: start=" << p << " lastack=" << lastack);
while ((p != lastack) && (rs > 0))
{
if (m_bTsbPdMode)
{
LOGC(dlog.Debug) << CONID() << "readBuffer: chk if time2play: NOW=" << now << " PKT TS=" << getPktTsbPdTime(m_pUnit[p]->m_Packet.getMsgTimeStamp());
LOGC(dlog.Debug, log << CONID() << "readBuffer: chk if time2play: NOW=" << now << " PKT TS=" << getPktTsbPdTime(m_pUnit[p]->m_Packet.getMsgTimeStamp()));
if ((getPktTsbPdTime(m_pUnit[p]->m_Packet.getMsgTimeStamp()) > now))
break; /* too early for this unit, return whatever was copied */
}
Expand All @@ -830,8 +832,8 @@ int CRcvBuffer::readBuffer(char* data, int len)
if (unitsize > rs)
unitsize = rs;

LOGC(dlog.Debug) << CONID() << "readBuffer: copying buffer #" << p
<< " targetpos=" << int(data-begin) << " sourcepos=" << m_iNotch << " size=" << unitsize << " left=" << (unitsize-rs);
LOGC(dlog.Debug, log << CONID() << "readBuffer: copying buffer #" << p
<< " targetpos=" << int(data-begin) << " sourcepos=" << m_iNotch << " size=" << unitsize << " left=" << (unitsize-rs));
memcpy(data, m_pUnit[p]->m_Packet.m_pcData + m_iNotch, unitsize);
data += unitsize;

Expand Down Expand Up @@ -1080,7 +1082,7 @@ bool CRcvBuffer::getRcvReadyMsg(ref_t<uint64_t> tsbpdtime, ref_t<int32_t> curpkt
int64_t towait = (*tsbpdtime - CTimer::getTime());
if (towait > 0)
{
LOGC(mglog.Debug) << "getRcvReadyMsg: found packet, but not ready to play (only in " << (towait/1000.0) << "ms)";
LOGC(mglog.Debug, log << "getRcvReadyMsg: found packet, but not ready to play (only in " << (towait/1000.0) << "ms)");
return false;
}

Expand All @@ -1091,7 +1093,7 @@ bool CRcvBuffer::getRcvReadyMsg(ref_t<uint64_t> tsbpdtime, ref_t<int32_t> curpkt
}
else
{
LOGC(mglog.Debug) << "getRcvReadyMsg: packet seq=" << curpktseq.get() << " ready to play (delayed " << (-towait/1000.0) << "ms)";
LOGC(mglog.Debug, log << "getRcvReadyMsg: packet seq=" << curpktseq.get() << " ready to play (delayed " << (-towait/1000.0) << "ms)");
return true;
}
}
Expand All @@ -1110,7 +1112,7 @@ bool CRcvBuffer::getRcvReadyMsg(ref_t<uint64_t> tsbpdtime, ref_t<int32_t> curpkt
}
}

LOGC(mglog.Debug) << "getRcvReadyMsg: nothing to deliver: " << reason;
LOGC(mglog.Debug, log << "getRcvReadyMsg: nothing to deliver: " << reason);
/* removed skipped, dropped, undecryptable bytes from rcv buffer */
countBytes(-rmpkts, -rmbytes, true);
return false;
Expand Down Expand Up @@ -1214,7 +1216,7 @@ void CRcvBuffer::updRcvAvgDataSize(uint64_t now)
m_iCountMAvg = getRcvDataSize(m_iBytesCountMAvg, m_TimespanMAvg);
m_LastSamplingTime = now;

LOGC(dlog.Debug).form("getRcvDataSize: %6d %6d %6d ms elapsed:%5llu ms\n", m_iCountMAvg, m_iBytesCountMAvg, m_TimespanMAvg, (unsigned long long)elapsed);
LOGF(dlog.Debug, "getRcvDataSize: %6d %6d %6d ms elapsed:%5llu ms\n", m_iCountMAvg, m_iBytesCountMAvg, m_TimespanMAvg, (unsigned long long)elapsed);
}
else if ((1000000 / SRT_MAVG_SAMPLING_RATE) / 1000 <= elapsed)
{
Expand All @@ -1234,7 +1236,7 @@ void CRcvBuffer::updRcvAvgDataSize(uint64_t now)
m_TimespanMAvg = (int)(((instspan * (1000 - elapsed)) + (instspan * elapsed)) / 1000);
m_LastSamplingTime = now;

LOGC(dlog.Debug).form("getRcvDataSize: %6d %6d %6d ms elapsed: %5llu ms\n", count, bytescount, instspan, (unsigned long long)elapsed);
LOGF(dlog.Debug, "getRcvDataSize: %6d %6d %6d ms elapsed: %5llu ms\n", count, bytescount, instspan, (unsigned long long)elapsed);
}
}
#endif /* SRT_ENABLE_RCVBUFSZ_MAVG */
Expand Down Expand Up @@ -1310,7 +1312,7 @@ int CRcvBuffer::getRcvDataSize(int &bytes, int &timespan)
timespan += 1;
}
}
LOGC(dlog.Debug).form("getRcvDataSize: %6d %6d %6d ms\n", m_iAckedPktsCount, m_iAckedBytesCount, timespan);
LOGF(dlog.Debug, "getRcvDataSize: %6d %6d %6d ms\n", m_iAckedPktsCount, m_iAckedBytesCount, timespan);
bytes = m_iAckedBytesCount;
return m_iAckedPktsCount;
}
Expand Down Expand Up @@ -1607,8 +1609,8 @@ int CRcvBuffer::readMsg(char* data, int len, ref_t<SRT_MSGCTRL> r_msgctl)
int64_t nowdiff = prev_now ? (nowtime - prev_now) : 0;
uint64_t srctimediff = prev_srctime ? (srctime - prev_srctime) : 0;

LOGC(dlog.Debug) << CONID() << "readMsg: DELIVERED seq=" << seq << " T=" << logging::FormatTime(srctime) << " in " << (timediff/1000.0) << "ms - "
"TIME-PREVIOUS: PKT: " << (srctimediff/1000.0) << " LOCAL: " << (nowdiff/1000.0);
LOGC(dlog.Debug, log << CONID() << "readMsg: DELIVERED seq=" << seq << " T=" << logging::FormatTime(srctime) << " in " << (timediff/1000.0) << "ms - "
"TIME-PREVIOUS: PKT: " << (srctimediff/1000.0) << " LOCAL: " << (nowdiff/1000.0));

prev_now = nowtime;
prev_srctime = srctime;
Expand Down Expand Up @@ -1645,7 +1647,7 @@ bool CRcvBuffer::scanMsg(ref_t<int> r_p, ref_t<int> r_q, ref_t<bool> passack)
// empty buffer
if ((m_iStartPos == m_iLastAckPos) && (m_iMaxPos <= 0))
{
LOGC(mglog.Debug) << "scanMsg: empty buffer";
LOGC(mglog.Debug, log << "scanMsg: empty buffer");
return false;
}

Expand Down Expand Up @@ -1790,7 +1792,7 @@ bool CRcvBuffer::scanMsg(ref_t<int> r_p, ref_t<int> r_q, ref_t<bool> passack)
// the msg has to be ack'ed or it is allowed to read out of order, and was not read before
if (!*passack || !m_pUnit[q]->m_Packet.getMsgOrderFlag())
{
LOGC(mglog.Debug) << "scanMsg: found next-to-broken message, delivering OUT OF ORDER.";
LOGC(mglog.Debug, log << "scanMsg: found next-to-broken message, delivering OUT OF ORDER.");
break;
}

Expand All @@ -1816,17 +1818,17 @@ bool CRcvBuffer::scanMsg(ref_t<int> r_p, ref_t<int> r_q, ref_t<bool> passack)
// if the message is larger than the receiver buffer, return part of the message
if ((p != -1) && ((q + 1) % m_iSize == p))
{
LOGC(mglog.Debug) << "scanMsg: BUFFER FULL and message is INCOMPLETE. Returning PARTIAL MESSAGE.";
LOGC(mglog.Debug, log << "scanMsg: BUFFER FULL and message is INCOMPLETE. Returning PARTIAL MESSAGE.");
found = true;
}
else
{
LOGC(mglog.Debug) << "scanMsg: PARTIAL or NO MESSAGE found: p=" << p << " q=" << q;
LOGC(mglog.Debug, log << "scanMsg: PARTIAL or NO MESSAGE found: p=" << p << " q=" << q);
}
}
else
{
LOGC(mglog.Debug) << "scanMsg: extracted message p=" << p << " q=" << q << " (" << ((q-p+m_iSize+1)%m_iSize) << " packets)";
LOGC(mglog.Debug, log << "scanMsg: extracted message p=" << p << " q=" << q << " (" << ((q-p+m_iSize+1)%m_iSize) << " packets)");
}

return found;
Expand Down
16 changes: 8 additions & 8 deletions srtcore/channel.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -179,7 +179,7 @@ void CChannel::open(const sockaddr* addr)
::freeaddrinfo(res);
}

LOGC(mglog.Debug) << "CHANNEL: Bound to local address: " << SockaddrToString(&m_BindAddr);
LOGC(mglog.Debug, log << "CHANNEL: Bound to local address: " << SockaddrToString(&m_BindAddr));

setUDPSockOpt();
}
Expand Down Expand Up @@ -358,9 +358,9 @@ int CChannel::sendto(const sockaddr* addr, CPacket& packet) const
spec << " [REXMIT]";
}

LOGC(mglog.Debug) << "CChannel::sendto: SENDING NOW DST=" << SockaddrToString(addr)
LOGC(mglog.Debug, log << "CChannel::sendto: SENDING NOW DST=" << SockaddrToString(addr)
<< " target=%" << packet.m_iID
<< spec.str();
<< spec.str());
#endif

// convert control information into network order
Expand Down Expand Up @@ -474,7 +474,7 @@ EReadStatus CChannel::recvfrom(sockaddr* addr, CPacket& packet) const
}
else
{
LOGC(mglog.Debug) << CONID() << "(sys)recvmsg: " << SysStrError(err) << " [" << err << "]";
LOGC(mglog.Debug, log << CONID() << "(sys)recvmsg: " << SysStrError(err) << " [" << err << "]");
status = RST_ERROR;
}

Expand Down Expand Up @@ -528,7 +528,7 @@ EReadStatus CChannel::recvfrom(sockaddr* addr, CPacket& packet) const
int err = NET_ERROR;
if (std::find(fatals, fatals_end, err) != fatals_end)
{
LOGC(mglog.Debug) << CONID() << "(sys)WSARecvFrom: " << SysStrError(err) << " [" << err << "]";
LOGC(mglog.Debug, log << CONID() << "(sys)WSARecvFrom: " << SysStrError(err) << " [" << err << "]");
status = RST_ERROR;
}
else
Expand All @@ -550,7 +550,7 @@ EReadStatus CChannel::recvfrom(sockaddr* addr, CPacket& packet) const
if ( size_t(res) < CPacket::HDR_SIZE )
{
status = RST_AGAIN;
LOGC(mglog.Debug) << CONID() << "POSSIBLE ATTACK: received too short packet with " << res << " bytes";
LOGC(mglog.Debug, log << CONID() << "POSSIBLE ATTACK: received too short packet with " << res << " bytes");
goto Return_error;
}

Expand All @@ -571,8 +571,8 @@ EReadStatus CChannel::recvfrom(sockaddr* addr, CPacket& packet) const

if ( msg_flags != 0 )
{
LOGC(mglog.Debug) << CONID() << "NET ERROR: packet size=" << res
<< " msg_flags=0x" << hex << msg_flags << ", possibly MSG_TRUNC (0x" << hex << int(MSG_TRUNC) << ")";
LOGC(mglog.Debug, log << CONID() << "NET ERROR: packet size=" << res
<< " msg_flags=0x" << hex << msg_flags << ", possibly MSG_TRUNC (0x" << hex << int(MSG_TRUNC) << ")");
status = RST_AGAIN;
goto Return_error;
}
Expand Down
6 changes: 3 additions & 3 deletions srtcore/common.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -847,11 +847,11 @@ std::string logging::FormatTime(uint64_t time)

logging::LogDispatcher::Proxy::Proxy(LogDispatcher& guy) : that(guy), that_enabled(that.CheckEnabled())
{
i_file = "";
i_line = 0;
flags = that.flags;
if (that_enabled)
{
i_file = "";
i_line = 0;
flags = that.flags;
// Create logger prefix
that.CreateLogLinePrefix(os);
}
Expand Down
Loading