diff --git a/lib/include/srslte/common/time_prof.h b/lib/include/srslte/common/time_prof.h index 4847c915f..b9ee34da3 100644 --- a/lib/include/srslte/common/time_prof.h +++ b/lib/include/srslte/common/time_prof.h @@ -29,64 +29,123 @@ namespace srslte { -class time_prof +template +class mutexed_tprof_measure { + using tpoint = std::chrono::time_point; + public: - explicit time_prof(const char* name_) : name(name_) { log_ptr->set_level(LOG_LEVEL_INFO); } - virtual ~time_prof() = default; + template + explicit mutexed_tprof_measure(Args&&... args) : c(std::forward(args)...) + { + srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO); + } + + uint8_t start() + { + auto t1 = std::chrono::high_resolution_clock::now(); + std::lock_guard lock(mutex); + auto ret = start_tpoints.insert(std::make_pair(next_id++, t1)); + return ret.first->first; + } + + void stop(uint8_t id) + { + auto t2 = std::chrono::high_resolution_clock::now(); + std::lock_guard lock(mutex); + auto& t1 = start_tpoints[id]; + c.process(std::chrono::duration_cast(t2 - t1).count()); + start_tpoints.erase(id); + } + +private: + std::mutex mutex; + Callable c; + std::unordered_map start_tpoints; + uint8_t next_id = 0; +}; + +template +class tprof_measure +{ + using tpoint = std::chrono::time_point; + +public: + template + explicit tprof_measure(Args&&... args) : c(std::forward(args)...) + { + srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO); + } 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()); + c.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"); +private: + Callable c; + tpoint t1; }; -struct avg_time_prof : public time_prof { - avg_time_prof(const char* name_, size_t print_period_) : time_prof(name_), print_period(print_period_) {} +struct avg_tprof { + avg_tprof(const char* name_, size_t print_period_) : name(name_), print_period(print_period_) {} - void process(long duration) final + void process(long duration) { 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); + 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; + 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; }; #else namespace srslte { -class time_prof +template +class mutexed_tprof_measure { public: + template + explicit mutexed_tprof_measure(Args&&... c) + { + } + uint8_t start() { return 0; } + void stop(uint8_t id) {} +}; + +template +class tprof_measure +{ +public: + template + explicit tprof_measure(Args&&... c) + { + } void start() {} void stop() {} }; -struct avg_time_prof : public time_prof { - avg_time_prof(const char*, size_t) {} +struct avg_tprof { + avg_tprof(const char*, size_t) {} }; #endif diff --git a/srsenb/src/stack/mac/mac.cc b/srsenb/src/stack/mac/mac.cc index 6a9d5bf9e..5ae1a025d 100644 --- a/srsenb/src/stack/mac/mac.cc +++ b/srsenb/src/stack/mac/mac.cc @@ -445,10 +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); + static srslte::mutexed_tprof_measure rach_tprof("RACH", 1); log_h->step(tti); uint16_t rnti; - rach_tprof.start(); + uint8_t tprof_id = rach_tprof.start(); { srslte::rwlock_write_guard lock(rwlock); @@ -472,7 +472,7 @@ 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]() { + stack_task_queue.push([this, rnti, tti, enb_cc_idx, preamble_idx, time_adv, tprof_id]() mutable { // Generate RAR data sched_interface::dl_sched_rar_info_t rar_info = {}; rar_info.preamble_idx = preamble_idx; @@ -505,7 +505,7 @@ 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(); + rach_tprof.stop(tprof_id); 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);