created a class for time profiling. An object of such class, if disabled, has almost zero overhead. Added a compile-time flag to turn on/off time profiling

CMakeLists.txt

@@ -89,6 +89,8 @@ option(USE_LTE_RATES   "Use standard LTE sampling rates"          OFF)
 option(USE_GLIBC_IPV6  "Use glibc's own ipv6.h"                   ON)
 option(USE_MKL         "Use MKL instead of fftw"                  OFF)
 
+option(ENABLE_TIMEPROF "Enable time profiling"                    OFF)
+
 option(FORCE_32BIT     "Add flags to force 32 bit compilation"    OFF)
 
 if(${CMAKE_SYSTEM_PROCESSOR} MATCHES "aarch64")
@@ -214,6 +216,11 @@ if(ENABLE_ZEROMQ)
   endif(ZEROMQ_FOUND)
 endif(ENABLE_ZEROMQ)
 
+# TimeProf
+if(ENABLE_TIMEPROF)
+    add_definitions(-DENABLE_TIMEPROF)
+endif(ENABLE_TIMEPROF)
+
 if(BLADERF_FOUND OR UHD_FOUND OR SOAPYSDR_FOUND OR ZEROMQ_FOUND)
   set(RF_FOUND TRUE CACHE INTERNAL "RF frontend found")
 else(BLADERF_FOUND OR UHD_FOUND OR SOAPYSDR_FOUND OR ZEROMQ_FOUND)

lib/include/srslte/common/time_prof.h

@@ -0,0 +1,96 @@
+/*
+ * Copyright 2013-2019 Software Radio Systems Limited
+ *
+ * This file is part of srsLTE.
+ *
+ * srsLTE is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License as
+ * published by the Free Software Foundation, either version 3 of
+ * the License, or (at your option) any later version.
+ *
+ * srsLTE is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * A copy of the GNU Affero General Public License can be found in
+ * the LICENSE file in the top-level directory of this distribution
+ * and at http://www.gnu.org/licenses/.
+ *
+ */
+
+#ifndef SRSLTE_TIME_PROF_H
+#define SRSLTE_TIME_PROF_H
+
+#ifdef ENABLE_TIMEPROF
+
+#include "srslte/common/logmap.h"
+#include <chrono>
+
+namespace srslte {
+
+class time_prof
+{
+public:
+  explicit time_prof(const char* name_) : name(name_) { log_ptr->set_level(LOG_LEVEL_INFO); }
+  virtual ~time_prof() = default;
+
+  void start() { t1 = std::chrono::high_resolution_clock::now(); }
+
+  void stop()
+  {
+    auto t2 = std::chrono::high_resolution_clock::now();
+    process(std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1).count());
+  }
+
+  virtual void process(long sample) = 0;
+
+  std::chrono::time_point<std::chrono::high_resolution_clock> t1;
+  std::string                                                 name;
+  srslte::log_ref                                             log_ptr = srslte::logmap::get("PROF");
+};
+
+struct avg_time_prof : public time_prof {
+  avg_time_prof(const char* name_, size_t print_period_) : time_prof(name_), print_period(print_period_) {}
+
+  void process(long duration) final
+  {
+    count++;
+    avg_val = avg_val * (count - 1) / count + static_cast<double>(duration) / count;
+    max_val = std::max(max_val, duration);
+    min_val = std::min(min_val, duration);
+    if (count % print_period == 0) {
+      time_prof::log_ptr->info("%s: Mean=%0.1fusec, Max=%ldusec, Min=%ldusec, nof_samples=%ld",
+                               name.c_str(),
+                               avg_val / 1e3,
+                               max_val / 1000,
+                               min_val / 1000,
+                               count);
+    }
+  }
+
+  double avg_val = 1;
+  long   count = 0, max_val = 0, min_val = std::numeric_limits<long>::max();
+  long   print_period;
+};
+
+#else
+
+namespace srslte {
+
+class time_prof
+{
+public:
+  void start() {}
+  void stop() {}
+};
+
+struct avg_time_prof : public time_prof {
+  avg_time_prof(const char*, size_t) {}
+};
+
+#endif
+
+} // namespace srslte
+
+#endif // SRSLTE_TIME_PROF_H

srsenb/src/main.cc

@@ -393,6 +393,7 @@ int main(int argc, char* argv[])
     logger = &logger_file;
   }
   srslte::logmap::set_default_logger(logger);
+  srslte::logmap::get("COMMON")->set_level(srslte::LOG_LEVEL_INFO);
 
   // Create eNB
   unique_ptr<srsenb::enb> enb{new srsenb::enb};

srsenb/src/stack/mac/mac.cc

@@ -33,6 +33,7 @@
 #include "srsenb/hdr/stack/mac/mac.h"
 #include "srslte/common/log.h"
 #include "srslte/common/rwlock_guard.h"
+#include "srslte/common/time_prof.h"
 
 //#define WRITE_SIB_PCAP
 using namespace asn1::rrc;
@@ -444,8 +445,10 @@ int mac::sr_detected(uint32_t tti, uint16_t rnti)
 
 void mac::rach_detected(uint32_t tti, uint32_t enb_cc_idx, uint32_t preamble_idx, uint32_t time_adv)
 {
+  static srslte::avg_time_prof rach_tprof("RACH", 1);
   log_h->step(tti);
   uint16_t rnti;
+  rach_tprof.start();
 
   {
     srslte::rwlock_write_guard lock(rwlock);
@@ -502,6 +505,8 @@ void mac::rach_detected(uint32_t tti, uint32_t enb_cc_idx, uint32_t preamble_idx
     // Trigger scheduler RACH
     scheduler.dl_rach_info(enb_cc_idx, rar_info);
 
+    rach_tprof.stop();
+
     log_h->info("RACH:  tti=%d, preamble=%d, offset=%d, temp_crnti=0x%x\n", tti, preamble_idx, time_adv, rnti);
     log_h->console("RACH:  tti=%d, preamble=%d, offset=%d, temp_crnti=0x%x\n", tti, preamble_idx, time_adv, rnti);
   });