5g-team
/
srsRAN_4G
mirror of https://github.com/pvnis/srsRAN_4G.git
2
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

now we can disable tprofs individually

Browse Source
master
Francisco Paisana 5 years ago committed by Francisco Paisana
parent e73cbb09b0
commit fb967d17a2
4 changed files with 86 additions and 61 deletions
Show Stats Download Patch File Download Diff File

104
lib/include/srslte/common/time_prof.h
Unescape Escape View File

@ -25,42 +25,74 @@
#include "srslte/common/logmap.h" #include "srslte/common/logmap.h"
#include <chrono> #include <chrono>
namespace srslte {
#ifdef ENABLE_TIMEPROF #ifdef ENABLE_TIMEPROF
#define TPROF_ENABLE_DEFAULT true
#else
#define TPROF_ENABLE_DEFAULT false
#endif
template <typename Prof> namespace srslte {
class tprof
// individual time interval measure
class tprof_measure
{ {
public: public:
using tpoint = std::chrono::time_point<std::chrono::high_resolution_clock>; using tpoint = std::chrono::time_point<std::chrono::high_resolution_clock>;
tprof_measure() = default;
void start() { t1 = std::chrono::high_resolution_clock::now(); }
std::chrono::nanoseconds stop()
{
auto t2 = std::chrono::high_resolution_clock::now();
return std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1);
}
private:
tpoint t1;
};
template <typename Prof, bool Enabled = TPROF_ENABLE_DEFAULT>
class tprof
{
public:
template <typename... Args> template <typename... Args>
explicit tprof(Args&&... args) : prof(std::forward<Args>(args)...) explicit tprof(Args&&... args) : prof(std::forward<Args>(args)...)
{ {
srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO);
} }
void start() { t1 = std::chrono::high_resolution_clock::now(); } void start() { meas.start(); }
std::chrono::nanoseconds stop() std::chrono::nanoseconds stop()
{ {
auto t2 = std::chrono::high_resolution_clock::now(); auto d = meas.stop();
auto d = std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1); prof(d);
prof.process(d);
return d; return d;
} }
tpoint t1; tprof_measure meas;
Prof prof; Prof prof;
}; };
// specialization for when the tprof is disabled
template <typename Prof> template <typename Prof>
class tprof<Prof, false>
{
public:
template <typename... Args>
explicit tprof(Args&&... args)
{
}
void start() {}
std::chrono::nanoseconds stop() { return std::chrono::nanoseconds{0}; }
};
template <typename Prof, bool Enabled = TPROF_ENABLE_DEFAULT>
struct mutexed_tprof { struct mutexed_tprof {
using tpoint = std::chrono::time_point<std::chrono::high_resolution_clock>;
struct measure { struct measure {
public: public:
measure(mutexed_tprof<Prof>* h_) : t1(std::chrono::high_resolution_clock::now()), h(h_) {} explicit measure(mutexed_tprof<Prof>* h_) : h(h_) { meas.start(); }
~measure() ~measure()
{ {
if (deferred) { if (deferred) {
@ -69,15 +101,14 @@ struct mutexed_tprof {
} }
std::chrono::nanoseconds stop() std::chrono::nanoseconds stop()
{ {
auto t2 = std::chrono::high_resolution_clock::now(); auto d = meas.stop();
std::lock_guard<std::mutex> lock(h->mutex); std::lock_guard<std::mutex> lock(h->mutex);
std::chrono::nanoseconds d = std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1); h->prof(d);
h->prof.process(d);
return d; return d;
} }
void defer_stop() { deferred = true; } void defer_stop() { deferred = true; }
tpoint t1; tprof_measure meas;
mutexed_tprof<Prof>* h; mutexed_tprof<Prof>* h;
bool deferred = false; bool deferred = false;
}; };
@ -85,7 +116,6 @@ struct mutexed_tprof {
template <typename... Args> template <typename... Args>
explicit mutexed_tprof(Args&&... args) : prof(std::forward<Args>(args)...) explicit mutexed_tprof(Args&&... args) : prof(std::forward<Args>(args)...)
{ {
srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO);
} }
measure start() { return measure{this}; } measure start() { return measure{this}; }
@ -95,24 +125,11 @@ private:
std::mutex mutex; std::mutex mutex;
}; };
#else
template <typename Prof>
struct tprof {
template <typename... Args>
explicit tprof(Args&&... args)
{
}
void start() {}
std::chrono::nanoseconds stop() { return {}; }
};
template <typename Prof> template <typename Prof>
struct mutexed_tprof { struct mutexed_tprof<Prof, false> {
struct measure { struct measure {
public: public:
std::chrono::nanoseconds stop() { return {}; } std::chrono::nanoseconds stop() { return std::chrono::nanoseconds{0}; }
void defer_stop() {} void defer_stop() {}
}; };
@ -120,20 +137,14 @@ struct mutexed_tprof {
explicit mutexed_tprof(Args&&... args) explicit mutexed_tprof(Args&&... args)
{ {
} }
measure start() {}
measure start() { return measure{}; }
private:
void process(long duration) {}
}; };
#endif
struct avg_time_stats { struct avg_time_stats {
avg_time_stats(const char* name_, size_t print_period_) : name(name_), print_period(print_period_) {} avg_time_stats(const char* name_, const char* logname, size_t print_period_);
void process(std::chrono::nanoseconds duration); void operator()(std::chrono::nanoseconds duration);
srslte::log_ref log_ptr = srslte::logmap::get("TPROF"); srslte::log_ref log_ptr;
std::string name; std::string name;
double avg_val = 1; double avg_val = 1;
long count = 0, max_val = 0, min_val = std::numeric_limits<long>::max(); long count = 0, max_val = 0, min_val = std::numeric_limits<long>::max();
@ -144,14 +155,13 @@ template <typename TUnit>
class sliding_window_stats class sliding_window_stats
{ {
public: public:
sliding_window_stats(const char* name_, size_t print_period_ = 10, TUnit warn_thres_ = 0); sliding_window_stats(const char* name_, const char* logname, size_t print_period_ = 10);
void process(std::chrono::nanoseconds duration); void operator()(std::chrono::nanoseconds duration);
srslte::log_ref log_ptr = srslte::logmap::get("TPROF"); srslte::log_ref log_ptr;
std::string name; std::string name;
std::vector<std::chrono::nanoseconds> sliding_window; std::vector<std::chrono::nanoseconds> sliding_window;
size_t window_idx = 0; size_t window_idx = 0;
TUnit warn_thres = 0;
}; };
using sliding_window_stats_ms = sliding_window_stats<std::chrono::milliseconds>; using sliding_window_stats_ms = sliding_window_stats<std::chrono::milliseconds>;

28
lib/src/common/time_prof.cc
Unescape Escape View File

@ -26,6 +26,8 @@
using namespace srslte; using namespace srslte;
using std::chrono::nanoseconds; using std::chrono::nanoseconds;
// log utils
template <typename TUnit> template <typename TUnit>
const char* get_tunit_str() const char* get_tunit_str()
{ {
@ -57,14 +59,23 @@ const char* get_tunit_str<std::chrono::minutes>()
return "min"; 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++; count++;
avg_val = avg_val * (count - 1) / count + static_cast<double>(duration.count()) / count; avg_val = avg_val * (count - 1) / count + static_cast<double>(duration.count()) / count;
max_val = std::max(max_val, duration.count()); max_val = std::max(max_val, duration.count());
min_val = std::min(min_val, duration.count()); min_val = std::min(min_val, duration.count());
if (count % print_period == 0) { 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(), name.c_str(),
avg_val / 1e3, avg_val / 1e3,
max_val / 1000, max_val / 1000,
@ -74,24 +85,21 @@ void avg_time_stats::process(nanoseconds duration)
} }
template <typename TUnit> template <typename TUnit>
sliding_window_stats<TUnit>::sliding_window_stats(const char* name_, size_t print_period_, TUnit warn_thres_) : sliding_window_stats<TUnit>::sliding_window_stats(const char* name_, const char* logname, size_t print_period_) :
name(name_), name(name_),
sliding_window(print_period_), log_ptr(srslte::logmap::get(logname)),
warn_thres(warn_thres_) sliding_window(print_period_)
{ {
} }
template <typename TUnit> template <typename TUnit>
void sliding_window_stats<TUnit>::process(nanoseconds duration) void sliding_window_stats<TUnit>::operator()(nanoseconds duration)
{ {
using std::chrono::duration_cast; using std::chrono::duration_cast;
const char* unit_str = get_tunit_str<TUnit>(); const char* unit_str = get_tunit_str<TUnit>();
TUnit dur = std::chrono::duration_cast<TUnit>(duration); TUnit dur = std::chrono::duration_cast<TUnit>(duration);
log_ptr->debug("%s: duration=%ld %s\n", name.c_str(), dur.count(), unit_str); 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; sliding_window[window_idx++] = duration;
if (window_idx == sliding_window.size()) { if (window_idx == sliding_window.size()) {
@ -100,7 +108,7 @@ void sliding_window_stats<TUnit>::process(nanoseconds duration)
nanoseconds tmin = *std::min_element(sliding_window.begin(), sliding_window.end()); nanoseconds tmin = *std::min_element(sliding_window.begin(), sliding_window.end());
double tmean = static_cast<double>(duration_cast<TUnit>(tsum).count()) / sliding_window.size(); double tmean = static_cast<double>(duration_cast<TUnit>(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(), name.c_str(),
tmean, tmean,
duration_cast<TUnit>(tmax).count(), duration_cast<TUnit>(tmax).count(),

2
srsenb/src/stack/mac/mac.cc
Unescape Escape View File

@ -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) void mac::rach_detected(uint32_t tti, uint32_t enb_cc_idx, uint32_t preamble_idx, uint32_t time_adv)
{ {
static srslte::mutexed_tprof<srslte::avg_time_stats> rach_tprof("RACH", 1); static srslte::mutexed_tprof<srslte::avg_time_stats> rach_tprof("rach_tprof", "MAC", 1);
log_h->step(tti); log_h->step(tti);
uint16_t rnti; uint16_t rnti;
auto rach_tprof_meas = rach_tprof.start(); auto rach_tprof_meas = rach_tprof.start();

13
srsue/src/stack/ue_stack_lte.cc
Unescape Escape View File

@ -45,7 +45,7 @@ ue_stack_lte::ue_stack_lte() :
thread("STACK"), thread("STACK"),
pending_tasks(512), pending_tasks(512),
background_tasks(2), 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(); ue_queue_id = pending_tasks.add_queue();
sync_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) 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 // perform tasks in this TTI
mac.run_tti(tti); mac.run_tti(tti);
@ -314,7 +316,12 @@ void ue_stack_lte::run_tti_impl(uint32_t tti)
timers.step_all(); timers.step_all();
if (args.have_tti_time_stats) { 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<std::chrono::milliseconds>(dur).count());
}
} }
// print warning if PHY pushes new TTI messages faster than we process them // print warning if PHY pushes new TTI messages faster than we process them

Write Preview
Loading…
Cancel
Save