diff --git a/lib/include/srslte/common/time_prof.h b/lib/include/srslte/common/time_prof.h index 6b32f02ac..6eaac7880 100644 --- a/lib/include/srslte/common/time_prof.h +++ b/lib/include/srslte/common/time_prof.h @@ -29,19 +29,88 @@ namespace srslte { -struct tprof_handler { - explicit tprof_handler(const char* name_) : name(name_) { log_ptr->set_level(LOG_LEVEL_INFO); } - virtual void process(long sample) = 0; +template +class tprof +{ +public: + using tpoint = std::chrono::time_point; - std::mutex mutex; - srslte::log_ref log_ptr = srslte::logmap::get("TPROF"); - std::string name; + struct measure { + public: + measure(tprof* h_) : t1(std::chrono::high_resolution_clock::now()), h(h_) {} + ~measure() + { + if (deferred) { + stop(); + } + } + void stop() + { + auto t2 = std::chrono::high_resolution_clock::now(); + h->process(std::chrono::duration_cast(t2 - t1).count()); + } + void defer_stop() { deferred = true; } + + tpoint t1; + tprof* h; + bool deferred = false; + }; + + template + explicit tprof(Args&&... args) : prof(std::forward(args)...) + { + srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO); + } + + measure start() { return measure{this}; } + + virtual void process(long duration) { prof.process(duration); } + + Prof prof; }; -struct avg_tprof : public tprof_handler { - avg_tprof(const char* name_, size_t print_period_) : tprof_handler(name_), print_period(print_period_) {} - +template +struct mutexed_tprof : public tprof { + using tprof::tprof; void process(long duration) final + { + std::lock_guard lock(mutex); + tprof::prof.process(duration); + } + std::mutex mutex; +}; + +#else + +namespace srslte { + +template +struct tprof { + struct measure { + public: + void stop() {} + void defer_stop() {} + }; + + template + explicit tprof(Args&&... args) + { + } + + measure start() { return measure{}; } + +private: + void process(long duration) {} +}; +template +using mutexed_tprof = tprof; + +#endif + +struct avg_time_stats { + avg_time_stats(const char* name_, size_t print_period_) : name(name_), print_period(print_period_) {} + + void process(long duration) { count++; avg_val = avg_val * (count - 1) / count + static_cast(duration) / count; @@ -57,61 +126,13 @@ struct avg_tprof : public tprof_handler { } } - double avg_val = 1; - long count = 0, max_val = 0, min_val = std::numeric_limits::max(); - long print_period; + srslte::log_ref log_ptr = srslte::logmap::get("TPROF"); + std::string name; + double avg_val = 1; + long count = 0, max_val = 0, min_val = std::numeric_limits::max(); + long print_period; }; -struct tprof_measure { - using tpoint = std::chrono::time_point; - - explicit tprof_measure(tprof_handler* h_) : h(h_) {} - - void start() { t1 = std::chrono::high_resolution_clock::now(); } - - void stop() - { - auto t2 = std::chrono::high_resolution_clock::now(); - std::lock_guard lock(h->mutex); - h->process(std::chrono::duration_cast(t2 - t1).count()); - } - -private: - tprof_handler* h; - tpoint t1; -}; - -struct tprof_measure_guard { - tprof_measure_guard(tprof_handler* h_) : tmeas(h_) { tmeas.start(); } - ~tprof_measure_guard() { tmeas.stop(); } - tprof_measure_guard(const tprof_measure_guard&) = delete; - tprof_measure_guard& operator=(const tprof_measure_guard&) = delete; - -private: - tprof_measure tmeas; -}; - -#else - -namespace srslte { - -struct tprof_handler { -}; - -struct avg_tprof : public tprof_handler { - avg_tprof(const char*, size_t) {} -}; - -class tprof_measure -{ -public: - explicit tprof_measure(tprof_handler* h_) {} - void start() {} - void stop() {} -}; - -#endif - } // namespace srslte #endif // SRSLTE_TIME_PROF_H diff --git a/srsenb/src/stack/mac/mac.cc b/srsenb/src/stack/mac/mac.cc index 6168ddcba..a39c8a100 100644 --- a/srsenb/src/stack/mac/mac.cc +++ b/srsenb/src/stack/mac/mac.cc @@ -445,11 +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_tprof rach_tprof("RACH", 1); + static srslte::mutexed_tprof rach_tprof("RACH", 1); log_h->step(tti); - uint16_t rnti; - srslte::tprof_measure tprof_meas{&rach_tprof}; - tprof_meas.start(); + uint16_t rnti; + auto rach_tprof_meas = rach_tprof.start(); { srslte::rwlock_write_guard lock(rwlock); @@ -473,7 +472,8 @@ void mac::rach_detected(uint32_t tti, uint32_t enb_cc_idx, uint32_t preamble_idx } } - stack_task_queue.push([this, rnti, tti, enb_cc_idx, preamble_idx, time_adv, tprof_meas]() mutable { + stack_task_queue.push([this, rnti, tti, enb_cc_idx, preamble_idx, time_adv, rach_tprof_meas]() mutable { + rach_tprof_meas.defer_stop(); // Generate RAR data sched_interface::dl_sched_rar_info_t rar_info = {}; rar_info.preamble_idx = preamble_idx; @@ -491,7 +491,6 @@ void mac::rach_detected(uint32_t tti, uint32_t enb_cc_idx, uint32_t preamble_idx ue_cfg.dl_cfg.tm = SRSLTE_TM1; if (scheduler.ue_cfg(rnti, ue_cfg) != SRSLTE_SUCCESS) { Error("Registering new user rnti=0x%x to SCHED\n", rnti); - tprof_meas.stop(); return; } @@ -501,15 +500,12 @@ void mac::rach_detected(uint32_t tti, uint32_t enb_cc_idx, uint32_t preamble_idx // Add temporal rnti to the PHY if (phy_h->add_rnti(rnti, enb_cc_idx, true) != SRSLTE_SUCCESS) { Error("Registering temporal-rnti=0x%x to PHY\n", rnti); - tprof_meas.stop(); return; } // Trigger scheduler RACH scheduler.dl_rach_info(enb_cc_idx, rar_info); - tprof_meas.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); });