Add TRACE support for timing analysis

5 files changed, 93 insertions, 14 deletions

diff --git a/src/DabMod.cpp b/src/DabMod.cpp
index a60bdd6..e0e7f8e 100644
--- a/src/DabMod.cpp
+++ b/src/DabMod.cpp
@@ -394,6 +394,12 @@ int launch_modulator(int argc, char* argv[])
             etiLog.register_backend(log_file);
         }
 
+        auto trace_filename = pt.get<std::string>("log.trace", "");
+        if (not trace_filename.empty()) {
+            LogTracer* tracer = new LogTracer(trace_filename);
+            etiLog.register_backend(tracer);
+        }
+
 
         // modulator parameters:
         gainMode = (GainMode)pt.get("modulator.gainmode", 0);
@@ -776,6 +782,7 @@ int launch_modulator(int argc, char* argv[])
         m.inputReader->PrintInfo();
 
         run_modulator_state_t st = run_modulator(m);
+        etiLog.log(trace, "DABMOD,run_modulator() = %d", st);
 
         switch (st) {
             case run_modulator_state_t::failure:
diff --git a/src/InputZeroMQReader.cpp b/src/InputZeroMQReader.cpp
index 69e1ffd..96e3223 100644
--- a/src/InputZeroMQReader.cpp
+++ b/src/InputZeroMQReader.cpp
@@ -96,11 +96,14 @@ int InputZeroMQReader::GetNextFrame(void* buffer)
      */
     if (in_messages_.size() < 4) {
         const size_t prebuffering = 10;
+        etiLog.log(trace, "ZMQ,wait1");
         in_messages_.wait_and_pop(incoming, prebuffering);
     }
     else {
+        etiLog.log(trace, "ZMQ,wait2");
         in_messages_.wait_and_pop(incoming);
     }
+    etiLog.log(trace, "ZMQ,pop");
 
     if (not worker_.is_running()) {
         throw zmq_input_overflow();
@@ -183,6 +186,7 @@ void InputZeroMQWorker::RecvProcess(struct InputZeroMQThreadData* workerdata)
                         offset += framesize;
 
                         queue_size = workerdata->in_messages->push(buf);
+                        etiLog.log(trace, "ZMQ,push %zu", queue_size);
                     }
                 }
             }
diff --git a/src/Log.cpp b/src/Log.cpp
index 6bbc7a9..7d6d6f5 100644
--- a/src/Log.cpp
+++ b/src/Log.cpp
@@ -24,9 +24,12 @@
 
 #include <list>
 #include <stdarg.h>
+#include <chrono>
 
 #include "Log.h"
 
+using namespace std;
+
 Logger etiLog;
 
 
@@ -72,15 +75,56 @@ void Logger::logstr(log_level_t level, std::string message)
         backend->log(level, message);
     }
 
-    {
+    if (level != log_level_t::trace) {
         std::lock_guard<std::mutex> guard(m_cerr_mutex);
         std::cerr << levels_as_str[level] << " " << message << std::endl;
     }
 }
 
-
 LogLine Logger::level(log_level_t level)
 {
     return LogLine(this, level);
 }
 
+void LogToFile::log(log_level_t level, std::string message)
+{
+    if (level != log_level_t::trace) {
+        const char* log_level_text[] = {
+            "DEBUG", "INFO", "WARN", "ERROR", "ALERT", "EMERG"};
+
+        // fprintf is thread-safe
+        fprintf(log_file, SYSLOG_IDENT ": %s: %s\n",
+                log_level_text[(size_t)level], message.c_str());
+        fflush(log_file);
+    }
+}
+
+LogTracer::LogTracer(const string& trace_filename)
+{
+    name = "TRACE";
+    etiLog.level(info) << "Setting up TRACE to " << trace_filename;
+
+    m_trace_file = fopen(trace_filename.c_str(), "a");
+    if (m_trace_file == NULL) {
+        fprintf(stderr, "Cannot open trace file !");
+        throw std::runtime_error("Cannot open trace file !");
+    }
+
+    auto now = chrono::steady_clock::now().time_since_epoch();
+    m_trace_micros_startup =
+        chrono::duration_cast<chrono::microseconds>(now).count();
+
+    fprintf(m_trace_file, "0,TRACER,startup at %ld\n", m_trace_micros_startup);
+}
+
+void LogTracer::log(log_level_t level, std::string message)
+{
+    if (level == log_level_t::trace) {
+        const auto now = chrono::steady_clock::now().time_since_epoch();
+        const auto micros = chrono::duration_cast<chrono::microseconds>(now).count();
+
+        fprintf(m_trace_file, "%ld,%s\n",
+                micros - m_trace_micros_startup,
+                message.c_str());
+    }
+}
diff --git a/src/Log.h b/src/Log.h
index f3b4409..cbc3569 100644
--- a/src/Log.h
+++ b/src/Log.h
@@ -44,10 +44,10 @@
 #define SYSLOG_IDENT "ODR-DabMod"
 #define SYSLOG_FACILITY LOG_LOCAL0
 
-enum log_level_t {debug = 0, info, warn, error, alert, emerg};
+enum log_level_t {debug = 0, info, warn, error, alert, emerg, trace};
 
 static const std::string levels_as_str[] =
-    { "     ", "     ", "WARN ", "ERROR", "ALERT", "EMERG"} ;
+    { "     ", "     ", "WARN ", "ERROR", "ALERT", "EMERG", "TRACE"} ;
 
 /** Abstract class all backends must inherit from */
 class LogBackend {
@@ -72,6 +72,7 @@ class LogToSyslog : public LogBackend {
 
             int syslog_level = LOG_EMERG;
             switch (level) {
+                case trace: break; // Do not handle TRACE in syslog
                 case debug: syslog_level = LOG_DEBUG; break;
                 case info:  syslog_level = LOG_INFO; break;
                 /* we don't have the notice level */
@@ -89,6 +90,9 @@ class LogToSyslog : public LogBackend {
 
     private:
         std::string name;
+
+        LogToSyslog(const LogToSyslog& other) = delete;
+        const LogToSyslog& operator=(const LogToSyslog& other) = delete;
 };
 
 class LogToFile : public LogBackend {
@@ -109,22 +113,37 @@ class LogToFile : public LogBackend {
             }
         }
 
-        void log(log_level_t level, std::string message) {
+        void log(log_level_t level, std::string message);
+
+        std::string get_name() { return name; }
 
-            const char* log_level_text[] =
-                {"DEBUG", "INFO", "WARN", "ERROR", "ALERT", "EMERG"};
+    private:
+        std::string name;
+        FILE* log_file;
 
-            // fprintf is thread-safe
-            fprintf(log_file, SYSLOG_IDENT ": %s: %s\n",
-                    log_level_text[(size_t)level], message.c_str());
-            fflush(log_file);
+        LogToFile(const LogToFile& other) = delete;
+        const LogToFile& operator=(const LogToFile& other) = delete;
+};
+
+class LogTracer : public LogBackend {
+    public:
+        LogTracer(const std::string& filename);
+
+        ~LogTracer() {
+            if (m_trace_file != NULL) {
+                fclose(m_trace_file);
+            }
         }
 
+        void log(log_level_t level, std::string message);
         std::string get_name() { return name; }
-
     private:
         std::string name;
-        FILE* log_file;
+        uint64_t m_trace_micros_startup;
+        FILE* m_trace_file;
+
+        LogTracer(const LogTracer& other) = delete;
+        const LogTracer& operator=(const LogTracer& other) = delete;
 };
 
 class LogLine;
diff --git a/src/OutputUHD.cpp b/src/OutputUHD.cpp
index 4d51dc4..a49b659 100644
--- a/src/OutputUHD.cpp
+++ b/src/OutputUHD.cpp
@@ -407,7 +407,8 @@ int OutputUHD::process(Buffer* dataIn, Buffer* dataOut)
                     usleep(10000); // 10ms
                 }
 
-                uwd.frames.push(frame);
+                size_t num_frames = uwd.frames.push(frame);
+                etiLog.log(trace, "UHD,push %zu", num_frames);
                 break;
             }
         }
@@ -619,7 +620,9 @@ void UHDWorker::process()
         md.time_spec      = uhd::time_spec_t(0.0);
 
         struct UHDWorkerFrameData frame;
+        etiLog.log(trace, "UHD,wait");
         uwd->frames.wait_and_pop(frame);
+        etiLog.log(trace, "UHD,pop");
 
         handle_frame(&frame);
     }
@@ -708,6 +711,7 @@ void UHDWorker::handle_frame(const struct UHDWorkerFrameData *frame)
 
         md.has_time_spec = true;
         md.time_spec = uhd::time_spec_t(tx_second, pps_offset);
+        etiLog.log(trace, "UHD,tist %f", md.time_spec.get_real_secs());
 
         // md is defined, let's do some checks
         if (md.time_spec.get_real_secs() + tx_timeout < usrp_time) {
@@ -801,6 +805,7 @@ void UHDWorker::tx_frame(const struct UHDWorkerFrameData *frame, bool ts_update)
         size_t num_tx_samps = myTxStream->send(
                 &in_data[num_acc_samps],
                 samps_to_send, md_tx, tx_timeout);
+        etiLog.log(trace, "UHD,sent %zu of %zu", num_tx_samps, samps_to_send);
 #endif
 
         num_acc_samps += num_tx_samps;