From 269c8527672e941e0426a5210461ffdfa43f043e Mon Sep 17 00:00:00 2001 From: Francisco Paisana Date: Sun, 15 Mar 2020 22:52:39 +0000 Subject: [PATCH] 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 | 7 ++ lib/include/srslte/common/time_prof.h | 96 +++++++++++++++++++++++++++ srsenb/src/main.cc | 1 + srsenb/src/stack/mac/mac.cc | 5 ++ 4 files changed, 109 insertions(+) create mode 100644 lib/include/srslte/common/time_prof.h diff --git a/CMakeLists.txt b/CMakeLists.txt index b258ae6e4..7a4c9a499 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/lib/include/srslte/common/time_prof.h b/lib/include/srslte/common/time_prof.h new file mode 100644 index 000000000..4847c915f --- /dev/null +++ b/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 + +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(t2 - t1).count()); + } + + virtual void process(long sample) = 0; + + std::chrono::time_point 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(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::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 diff --git a/srsenb/src/main.cc b/srsenb/src/main.cc index 4e9e89990..b6baa9858 100644 --- a/srsenb/src/main.cc +++ b/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 enb{new srsenb::enb}; diff --git a/srsenb/src/stack/mac/mac.cc b/srsenb/src/stack/mac/mac.cc index 8e3fde0c9..6a9d5bf9e 100644 --- a/srsenb/src/stack/mac/mac.cc +++ b/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); });