diff --git a/lib/include/srslte/common/time_prof.h b/lib/include/srslte/common/time_prof.h index a69435798..15d5a4726 100644 --- a/lib/include/srslte/common/time_prof.h +++ b/lib/include/srslte/common/time_prof.h @@ -25,42 +25,74 @@ #include "srslte/common/logmap.h" #include +#ifdef ENABLE_TIMEPROF +#define TPROF_ENABLE_DEFAULT true +#else +#define TPROF_ENABLE_DEFAULT false +#endif + namespace srslte { -#ifdef ENABLE_TIMEPROF - -template -class tprof +// individual time interval measure +class tprof_measure { public: using tpoint = std::chrono::time_point; - template - explicit tprof(Args&&... args) : prof(std::forward(args)...) - { - srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO); - } - - void start() { t1 = std::chrono::high_resolution_clock::now(); } - + tprof_measure() = default; + void start() { t1 = std::chrono::high_resolution_clock::now(); } std::chrono::nanoseconds stop() { auto t2 = std::chrono::high_resolution_clock::now(); - auto d = std::chrono::duration_cast(t2 - t1); - prof.process(d); + return std::chrono::duration_cast(t2 - t1); + } + +private: + tpoint t1; +}; + +template +class tprof +{ +public: + template + explicit tprof(Args&&... args) : prof(std::forward(args)...) + { + } + + void start() { meas.start(); } + + std::chrono::nanoseconds stop() + { + auto d = meas.stop(); + prof(d); return d; } - tpoint t1; - Prof prof; + tprof_measure meas; + Prof prof; }; +// specialization for when the tprof is disabled template +class tprof +{ +public: + template + explicit tprof(Args&&... args) + { + } + + void start() {} + + std::chrono::nanoseconds stop() { return std::chrono::nanoseconds{0}; } +}; + +template struct mutexed_tprof { - using tpoint = std::chrono::time_point; struct measure { public: - measure(mutexed_tprof* h_) : t1(std::chrono::high_resolution_clock::now()), h(h_) {} + explicit measure(mutexed_tprof* h_) : h(h_) { meas.start(); } ~measure() { if (deferred) { @@ -69,15 +101,14 @@ struct mutexed_tprof { } std::chrono::nanoseconds stop() { - auto t2 = std::chrono::high_resolution_clock::now(); + auto d = meas.stop(); std::lock_guard lock(h->mutex); - std::chrono::nanoseconds d = std::chrono::duration_cast(t2 - t1); - h->prof.process(d); + h->prof(d); return d; } void defer_stop() { deferred = true; } - tpoint t1; + tprof_measure meas; mutexed_tprof* h; bool deferred = false; }; @@ -85,7 +116,6 @@ struct mutexed_tprof { template explicit mutexed_tprof(Args&&... args) : prof(std::forward(args)...) { - srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO); } measure start() { return measure{this}; } @@ -95,24 +125,11 @@ private: std::mutex mutex; }; -#else - template -struct tprof { - template - explicit tprof(Args&&... args) - { - } - - void start() {} - std::chrono::nanoseconds stop() { return {}; } -}; - -template -struct mutexed_tprof { +struct mutexed_tprof { struct measure { public: - std::chrono::nanoseconds stop() { return {}; } + std::chrono::nanoseconds stop() { return std::chrono::nanoseconds{0}; } void defer_stop() {} }; @@ -120,20 +137,14 @@ struct mutexed_tprof { explicit mutexed_tprof(Args&&... args) { } - - measure start() { return measure{}; } - -private: - void process(long duration) {} + measure start() {} }; -#endif - struct avg_time_stats { - avg_time_stats(const char* name_, size_t print_period_) : name(name_), print_period(print_period_) {} - void process(std::chrono::nanoseconds duration); + avg_time_stats(const char* name_, const char* logname, size_t print_period_); + void operator()(std::chrono::nanoseconds duration); - srslte::log_ref log_ptr = srslte::logmap::get("TPROF"); + srslte::log_ref log_ptr; std::string name; double avg_val = 1; long count = 0, max_val = 0, min_val = std::numeric_limits::max(); @@ -144,14 +155,13 @@ template class sliding_window_stats { public: - sliding_window_stats(const char* name_, size_t print_period_ = 10, TUnit warn_thres_ = 0); - void process(std::chrono::nanoseconds duration); + sliding_window_stats(const char* name_, const char* logname, size_t print_period_ = 10); + void operator()(std::chrono::nanoseconds duration); - srslte::log_ref log_ptr = srslte::logmap::get("TPROF"); + srslte::log_ref log_ptr; std::string name; std::vector sliding_window; size_t window_idx = 0; - TUnit warn_thres = 0; }; using sliding_window_stats_ms = sliding_window_stats; diff --git a/lib/src/common/time_prof.cc b/lib/src/common/time_prof.cc index a43b91cec..b427bd878 100644 --- a/lib/src/common/time_prof.cc +++ b/lib/src/common/time_prof.cc @@ -26,6 +26,8 @@ using namespace srslte; using std::chrono::nanoseconds; +// log utils + template const char* get_tunit_str() { @@ -57,14 +59,23 @@ const char* get_tunit_str() return "min"; } -void avg_time_stats::process(nanoseconds duration) +// tprof stats + +avg_time_stats::avg_time_stats(const char* name_, const char* logname, size_t print_period_) : + name(name_), + log_ptr(srslte::logmap::get(logname)), + print_period(print_period_) +{ +} + +void avg_time_stats::operator()(nanoseconds duration) { count++; avg_val = avg_val * (count - 1) / count + static_cast(duration.count()) / count; max_val = std::max(max_val, duration.count()); min_val = std::min(min_val, duration.count()); if (count % print_period == 0) { - log_ptr->info("%s: mean,max,min=%0.1f,%ld,%ld usec, nof_samples=%ld", + log_ptr->info("%s: {mean, max, min}={%0.1f, %ld, %ld} usec, nof_samples=%ld", name.c_str(), avg_val / 1e3, max_val / 1000, @@ -74,24 +85,21 @@ void avg_time_stats::process(nanoseconds duration) } template -sliding_window_stats::sliding_window_stats(const char* name_, size_t print_period_, TUnit warn_thres_) : +sliding_window_stats::sliding_window_stats(const char* name_, const char* logname, size_t print_period_) : name(name_), - sliding_window(print_period_), - warn_thres(warn_thres_) + log_ptr(srslte::logmap::get(logname)), + sliding_window(print_period_) { } template -void sliding_window_stats::process(nanoseconds duration) +void sliding_window_stats::operator()(nanoseconds duration) { using std::chrono::duration_cast; const char* unit_str = get_tunit_str(); TUnit dur = std::chrono::duration_cast(duration); log_ptr->debug("%s: duration=%ld %s\n", name.c_str(), dur.count(), unit_str); - if (warn_thres > TUnit{0} and dur > warn_thres) { - log_ptr->warning("%s: detected long duration=%ld %s\n", name.c_str(), dur.count(), unit_str); - } sliding_window[window_idx++] = duration; if (window_idx == sliding_window.size()) { @@ -100,7 +108,7 @@ void sliding_window_stats::process(nanoseconds duration) nanoseconds tmin = *std::min_element(sliding_window.begin(), sliding_window.end()); double tmean = static_cast(duration_cast(tsum).count()) / sliding_window.size(); - log_ptr->info("%s: mean,max,min = %0.2f,%ld,%ld %s\n", + log_ptr->info("%s: {mean, max, min} = {%0.2f, %ld, %ld} %s\n", name.c_str(), tmean, duration_cast(tmax).count(), diff --git a/srsenb/src/stack/mac/mac.cc b/srsenb/src/stack/mac/mac.cc index a39c8a100..d5080f57e 100644 --- a/srsenb/src/stack/mac/mac.cc +++ b/srsenb/src/stack/mac/mac.cc @@ -445,7 +445,7 @@ 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::mutexed_tprof rach_tprof("RACH", 1); + static srslte::mutexed_tprof rach_tprof("rach_tprof", "MAC", 1); log_h->step(tti); uint16_t rnti; auto rach_tprof_meas = rach_tprof.start(); diff --git a/srsue/src/stack/ue_stack_lte.cc b/srsue/src/stack/ue_stack_lte.cc index 64e333185..76dbae796 100644 --- a/srsue/src/stack/ue_stack_lte.cc +++ b/srsue/src/stack/ue_stack_lte.cc @@ -45,7 +45,7 @@ ue_stack_lte::ue_stack_lte() : thread("STACK"), pending_tasks(512), background_tasks(2), - tti_tprof("proc_time", TTI_STAT_PERIOD, TTI_WARN_THRESHOLD_MS) + tti_tprof("tti_tprof", "STCK", TTI_STAT_PERIOD) { ue_queue_id = pending_tasks.add_queue(); sync_queue_id = pending_tasks.add_queue(); @@ -305,7 +305,9 @@ void ue_stack_lte::run_tti(uint32_t tti) void ue_stack_lte::run_tti_impl(uint32_t tti) { - tti_tprof.start(); + if (args.have_tti_time_stats) { + tti_tprof.start(); + } // perform tasks in this TTI mac.run_tti(tti); @@ -314,7 +316,12 @@ void ue_stack_lte::run_tti_impl(uint32_t tti) timers.step_all(); if (args.have_tti_time_stats) { - tti_tprof.stop(); + std::chrono::nanoseconds dur = tti_tprof.stop(); + if (dur > TTI_WARN_THRESHOLD_MS) { + mac_log.warning("%s: detected long duration=%ld ms\n", + "proc_time", + std::chrono::duration_cast(dur).count()); + } } // print warning if PHY pushes new TTI messages faster than we process them