Added perf logging

apps/logsupport.cpp

@@ -84,7 +84,16 @@ set<logging::LogFA> SrtParseLogFA(string fa)
     if ( fa == "" )
         return fas;
 
-    static string names [] = { "general", "bstats", "control", "data", "tsbpd", "rexmit" };
+    static string names [] = {
+        "general",
+        "bstats",
+        "control",
+        "data",
+        "tsbpd",
+        "rexmit",
+        "haicrypt",
+        "perf"
+    };
     size_t names_s = sizeof (names)/sizeof (names[0]);
 
     if ( fa == "all" )

srtcore/core.cpp

@@ -105,6 +105,7 @@ logging::Logger mglog(SRT_LOGFA_CONTROL, srt_logger_config, "SRT.c");
 logging::Logger dlog(SRT_LOGFA_DATA, srt_logger_config, "SRT.d");
 logging::Logger tslog(SRT_LOGFA_TSBPD, srt_logger_config, "SRT.t");
 logging::Logger rxlog(SRT_LOGFA_REXMIT, srt_logger_config, "SRT.r");
+logging::Logger perflog(SRT_LOGFA_PERF, srt_logger_config, "SRT.p");
 
 CUDTUnited CUDT::s_UDTUnited;
 

srtcore/core.h

@@ -79,7 +79,8 @@ extern logging::Logger
     mglog,
     dlog,
     tslog,
-    rxlog;
+    rxlog,
+    perflog;
 
 
 // XXX Utility function - to be moved to utilities.h?

srtcore/queue.cpp

@@ -1163,7 +1163,9 @@ void* CRcvQueue::worker(void* param)
    while (!self->m_bClosing)
    {
        bool have_received SRT_ATR_UNUSED = false; // used in HLOG only
+       HLOGP(perflog.Debug, "worker_RetrieveUnit - START");
        EReadStatus rst = self->worker_RetrieveUnit(Ref(id), Ref(unit), &sa, uptime_us);
+       HLOGC(perflog.Debug, log << "worker_RetrieveUnit - FINISHED. return=" << rst << ", " << (rst ? (rst == -1 ? "ERROR" : "AGAIN") : "RETRIEVED"));
        uint64_t currtime_tk;
 
        // take care of the timing event for all UDT sockets
@@ -1192,6 +1194,7 @@ void* CRcvQueue::worker(void* param)
            // Note to rendezvous connection. This can accept:
            // - ID == 0 - take the first waiting rendezvous socket
            // - ID > 0  - find the rendezvous socket that has this ID.
+           HLOGC(perflog.Debug, log << "PROCESSING PACKET: START");
            if (id == 0)
            {
                // ID 0 is for connection request, which should be passed to the listening socket or rendezvous sockets
@@ -1204,6 +1207,7 @@ void* CRcvQueue::worker(void* param)
                // - a socket connected to a peer
                cst = self->worker_ProcessAddressedPacket(id, unit, &sa);
            }
+           HLOGC(perflog.Debug, log << "PROCESSING PACKET: END");
            HLOGC(mglog.Debug, log << self->CONID() << "worker: result for the unit: " << ConnectStatusStr(cst));
            if (cst == CONN_AGAIN)
            {
@@ -1240,6 +1244,7 @@ void* CRcvQueue::worker(void* param)
        // OTHERWISE: this is an "AGAIN" situation. No data was read, but the process should continue.
 
 Handle_timer_events:
+       HLOGC(perflog.Debug, log << "TIMER CHECK: START");
 
        CRNode* ul = self->m_pRcvUList->m_pUList;
        uint64_t ctime_tk = currtime_tk - TIMER_UPDATE_INTERVAL_US * CTimer::getCPUFrequency();
@@ -1327,6 +1332,7 @@ void* CRcvQueue::worker(void* param)
        uint64_t now_us = currtime_tk/CTimer::getCPUFrequency();
        bool timely = self->m_tConnUpTime_us < now_us;  // (including when m_tConnUpTime_us == 0)
 
+       HLOGC(perflog.Debug, log << "TIMER CHECK: END. DOING updateConnStatus");
        if (timely || rst == RST_OK)
        {
            // If this is the beginning (m_tConnUpTime_us == 0), it will be always called.
@@ -1375,6 +1381,7 @@ void* CRcvQueue::worker(void* param)
        {
            HLOGC(mglog.Debug, log << "worker: NO updateConnStatus - no packet and T=" << logging::FormatTime(self->m_tConnUpTime_us));
        }
+       HLOGC(perflog.Debug, log << "TIMER CHECK: END. updateConnStatus FINISHED. LOOP ROLLING.");
 
        // Use the time reported by updateConnStatus as a next processing time
        // (time until when the next reading operation should wait at maximum),

srtcore/srt.h

@@ -464,6 +464,7 @@ static const SRT_ERRNO SRT_EISDGRAM  SRT_ATR_DEPRECATED = (SRT_ERRNO) MN(NOTSUP,
 #define SRT_LOGFA_TSBPD 4
 #define SRT_LOGFA_REXMIT 5
 #define SRT_LOGFA_HAICRYPT 6
+#define SRT_LOGFA_PERF 7
 
 // To make a typical int32_t size, although still use std::bitset.
 // C API will carry it over.

testing/srt-test-live.cpp

@@ -290,7 +290,7 @@ int main( int argc, char** argv )
 
     bool crashonx = Option("no", "k", "crash") != "no";
     string loglevel = Option("error", "loglevel");
-    string logfa = Option("general", "logfa");
+    string logfa = Option("", "logfa");
     string logfile = Option("", "logfile");
     bool internal_log = Option("no", "loginternal") != "no";
     bool skip_flushing = Option("no", "S", "skipflush") != "no";
@@ -315,9 +315,17 @@ int main( int argc, char** argv )
     std::ofstream logfile_stream; // leave unused if not set
 
     srt_setloglevel(SrtParseLogLevel(loglevel));
-    set<logging::LogFA> fas = SrtParseLogFA(logfa);
-    for (set<logging::LogFA>::iterator i = fas.begin(); i != fas.end(); ++i)
-        srt_addlogfa(*i);
+
+    // Without logfa option, use the defaults of the library.
+    // With logfa, enable those selected only.
+    if (logfa != "")
+    {
+        set<logging::LogFA> fas = SrtParseLogFA(logfa);
+
+        // Stupid, but that's how you link C and C++ API.
+        vector<int> falist(fas.begin(), fas.end());
+        srt_resetlogfa(falist.data(), falist.size());
+    }
 
     char NAME[] = "SRTLIB";
     if ( internal_log )