From bab9d654f028a214e6f3abe8ade1c1da002d25ff Mon Sep 17 00:00:00 2001 From: "Matthias P. Braendli" Date: Fri, 17 Jun 2016 11:19:29 +0200 Subject: Add TRACE support for timing analysis --- src/DabMod.cpp | 7 +++++++ src/InputZeroMQReader.cpp | 4 ++++ src/Log.cpp | 48 +++++++++++++++++++++++++++++++++++++++++++++-- src/Log.h | 41 +++++++++++++++++++++++++++++----------- src/OutputUHD.cpp | 7 ++++++- 5 files changed, 93 insertions(+), 14 deletions(-) (limited to 'src') 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("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 #include +#include #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 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(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(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; -- cgit v1.2.3