Logging improvements.

Logging of RTSP command summaries on debug 5
Logging for Performance/Locking on debug 6

Original patch tweaked and optimized by Rolf Ahrenberg.

rtp.c

@@ -5,6 +5,9 @@
  *
  */
 
+#define __STDC_FORMAT_MACROS // Required for format specifiers
+#include <inttypes.h>
+
 #include "config.h"
 #include "common.h"
 #include "log.h"
@@ -68,7 +71,7 @@ int cSatipRtp::GetHeaderLenght(unsigned int lengthP)
         // CSCR count
         unsigned int cc = bufferM[0] & 0x0F;
         // Payload type: MPEG2 TS = 33
-        //unsigned int pt = bufferAddrP[1] & 0x7F;
+        //unsigned int pt = bufferM[1] & 0x7F;
         // Sequence number
         int seq = ((bufferM[2] & 0xFF) << 8) | (bufferM[3] & 0xFF);
         if ((((sequenceNumberM + 1) % 0xFFFF) == 0) && (seq == 0xFFFF))
@@ -113,14 +116,22 @@ void cSatipRtp::Process(void)
 {
   debug8("%s [device %d]", __PRETTY_FUNCTION__, tunerM.GetId());
   if (bufferM) {
-     int length;
+     uint64_t elapsed;
+     int length, count = 0;
+     cTimeMs processing(0);
+
      while ((length = Read(bufferM, bufferLenM)) > 0) {
            int headerlen = GetHeaderLenght(length);
            if ((headerlen >= 0) && (headerlen < length))
                tunerM.ProcessVideoData(bufferM + headerlen, length - headerlen);
+           ++count;
            }
      if (errno != EAGAIN && errno != EWOULDBLOCK)
         error("Error %d reading in %s [device %d]", errno, *ToString(), tunerM.GetId());
+
+     elapsed = processing.Elapsed();
+     if (elapsed > 1)
+        debug6("%s %d read(s) took %" PRIu64 " ms [device %d]", __PRETTY_FUNCTION__, count, elapsed, tunerM.GetId());
      }
 }
 

rtsp.c

@@ -5,6 +5,9 @@
  *
  */
 
+#define __STDC_FORMAT_MACROS // Required for format specifiers
+#include <inttypes.h>
+
 #include "config.h"
 #include "common.h"
 #include "log.h"
@@ -143,7 +146,11 @@ cString cSatipRtsp::RtspUnescapeString(const char *strP)
 bool cSatipRtsp::Options(const char *uriP)
 {
   debug1("%s (%s) [device %d]", __PRETTY_FUNCTION__, uriP, tunerM.GetId());
+  bool result = false;
+
   if (handleM && !isempty(uriP)) {
+     long rc = 0;
+     cTimeMs processing(0);
      CURLcode res = CURLE_OK;
 
      if (!strstr(uriP, "?"))
@@ -152,16 +159,21 @@ bool cSatipRtsp::Options(const char *uriP)
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_RTSP_REQUEST, (long)CURL_RTSPREQ_OPTIONS);
      SATIP_CURL_EASY_PERFORM(handleM);
 
-     return ValidateLatestResponse();
+     result = ValidateLatestResponse(&rc);
+     debug5("%s (%s) Response %ld in %" PRIu64 " ms [device %d]", __PRETTY_FUNCTION__, uriP, rc, processing.Elapsed(), tunerM.GetId());
      }
 
-  return false;
+  return result;
 }
 
 bool cSatipRtsp::Setup(const char *uriP, int rtpPortP, int rtcpPortP)
 {
   debug1("%s (%s, %d, %d) [device %d]", __PRETTY_FUNCTION__, uriP, rtpPortP, rtcpPortP, tunerM.GetId());
+  bool result = false;
+
   if (handleM && !isempty(uriP)) {
+     long rc = 0;
+     cTimeMs processing(0);
      CURLcode res = CURLE_OK;
      cString transport = cString::sprintf("RTP/AVP;unicast;client_port=%d-%d", rtpPortP, rtcpPortP);
 
@@ -177,10 +189,11 @@ bool cSatipRtsp::Setup(const char *uriP, int rtpPortP, int rtcpPortP)
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_HEADERFUNCTION, NULL);
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_WRITEHEADER, NULL);
 
-     return ValidateLatestResponse();
+     result = ValidateLatestResponse(&rc);
+     debug5("%s (%s, %d, %d) Response %ld in %" PRIu64 " ms [device %d]", __PRETTY_FUNCTION__, uriP, rtpPortP, rtcpPortP, rc, processing.Elapsed(), tunerM.GetId());
      }
 
-  return false;
+  return result;
 }
 
 bool cSatipRtsp::SetSession(const char *sessionP)
@@ -199,7 +212,11 @@ bool cSatipRtsp::SetSession(const char *sessionP)
 bool cSatipRtsp::Describe(const char *uriP)
 {
   debug1("%s (%s) [device %d]", __PRETTY_FUNCTION__, uriP, tunerM.GetId());
+  bool result = false;
+
   if (handleM && !isempty(uriP)) {
+     long rc = 0;
+     cTimeMs processing(0);
      CURLcode res = CURLE_OK;
 
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_RTSP_STREAM_URI, uriP);
@@ -210,32 +227,42 @@ bool cSatipRtsp::Describe(const char *uriP)
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_WRITEFUNCTION, NULL);
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_WRITEDATA, NULL);
 
-     return ValidateLatestResponse();
+     result = ValidateLatestResponse(&rc);
+     debug5("%s (%s) Response %ld in %" PRIu64 " ms [device %d]", __PRETTY_FUNCTION__, uriP, rc, processing.Elapsed(), tunerM.GetId());
      }
 
-  return false;
+  return result;
 }
 
 bool cSatipRtsp::Play(const char *uriP)
 {
   debug1("%s (%s) [device %d]", __PRETTY_FUNCTION__, uriP, tunerM.GetId());
+  bool result = false;
+
   if (handleM && !isempty(uriP)) {
+     long rc = 0;
+     cTimeMs processing(0);
      CURLcode res = CURLE_OK;
 
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_RTSP_STREAM_URI, uriP);
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_RTSP_REQUEST, (long)CURL_RTSPREQ_PLAY);
      SATIP_CURL_EASY_PERFORM(handleM);
 
-     return ValidateLatestResponse();
+     result = ValidateLatestResponse(&rc);
+     debug5("%s (%s) Response %ld in %" PRIu64 " ms [device %d]", __PRETTY_FUNCTION__, uriP, rc, processing.Elapsed(), tunerM.GetId());
      }
 
-  return false;
+  return result;
 }
 
 bool cSatipRtsp::Teardown(const char *uriP)
 {
   debug1("%s (%s) [device %d]", __PRETTY_FUNCTION__, uriP, tunerM.GetId());
+  bool result = false;
+
   if (handleM && !isempty(uriP)) {
+     long rc = 0;
+     cTimeMs processing(0);
      CURLcode res = CURLE_OK;
 
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_RTSP_STREAM_URI, uriP);
@@ -245,15 +272,17 @@ bool cSatipRtsp::Teardown(const char *uriP)
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_RTSP_CLIENT_CSEQ, 1L);
      SATIP_CURL_EASY_SETOPT(handleM, CURLOPT_RTSP_SESSION_ID, NULL);
 
-     return ValidateLatestResponse();
+     result = ValidateLatestResponse(&rc);
+     debug5("%s (%s) Response %ld in %" PRIu64 " ms [device %d]", __PRETTY_FUNCTION__, uriP, rc, processing.Elapsed(), tunerM.GetId());
      }
 
-  return false;
+  return result;
 }
 
-bool cSatipRtsp::ValidateLatestResponse(void)
+bool cSatipRtsp::ValidateLatestResponse(long *rcP)
 {
   bool result = false;
+
   if (handleM) {
      long rc = 0;
      CURLcode res = CURLE_OK;
@@ -265,6 +294,8 @@ bool cSatipRtsp::ValidateLatestResponse(void)
         SATIP_CURL_EASY_GETINFO(handleM, CURLINFO_EFFECTIVE_URL, &url);
         error("Detected invalid status code %ld: %s [device %d]", rc, url, tunerM.GetId());
         }
+     if (rcP)
+        *rcP = rc;
      }
   debug1("%s result=%s [device %d]", __PRETTY_FUNCTION__, result ? "ok" : "failed", tunerM.GetId());
 

rtsp.h

@@ -31,7 +31,7 @@ private:
   CURL *handleM;
   struct curl_slist *headerListM;
 
-  bool ValidateLatestResponse(void);
+  bool ValidateLatestResponse(long *rcP);
 
   // to prevent copy constructor and assignment
   cSatipRtsp(const cSatipRtsp&);

tuner.c

@@ -5,6 +5,9 @@
  *
  */
 
+#define __STDC_FORMAT_MACROS // Required for format specifiers
+#include <inttypes.h>
+
 #include "common.h"
 #include "config.h"
 #include "discover.h"
@@ -245,8 +248,19 @@ void cSatipTuner::ProcessVideoData(u_char *bufferP, int lengthP)
 {
   debug8("%s (, %d) [device %d]", __PRETTY_FUNCTION__, lengthP, deviceIdM);
   if (lengthP > 0) {
+     uint64_t elapsed;
+     cTimeMs processing(0);
+
      AddTunerStatistic(lengthP);
+     elapsed = processing.Elapsed();
+     if (elapsed > 1)
+        debug6("%s AddTunerStatistic() took %" PRIu64 " ms [device %d]", __PRETTY_FUNCTION__, elapsed, deviceIdM);
+
+     processing.Set(0);
      deviceM->WriteData(bufferP, lengthP);
+     elapsed = processing.Elapsed();
+     if (elapsed > 1)
+        debug6("%s WriteData() took %" PRIu64 " ms [device %d]", __FUNCTION__, elapsed, deviceIdM);
      }
   reConnectM.Set(eConnectTimeoutMs);
 }