created a better/more composable design for time measures

master
Francisco Paisana 5 years ago committed by Francisco Paisana
parent eb20f651b9
commit 8a54aef89d

@ -29,125 +29,87 @@
namespace srslte { namespace srslte {
template <typename Callable> struct tprof_handler {
class mutexed_tprof_measure explicit tprof_handler(const char* name_) : name(name_) { log_ptr->set_level(LOG_LEVEL_INFO); }
{ virtual void process(long sample) = 0;
using tpoint = std::chrono::time_point<std::chrono::high_resolution_clock>;
public: std::mutex mutex;
template <typename... Args> srslte::log_ref log_ptr = srslte::logmap::get("TPROF");
explicit mutexed_tprof_measure(Args&&... args) : c(std::forward<Args>(args)...) std::string name;
{ };
srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO);
}
uint8_t start() struct avg_tprof : public tprof_handler {
{ avg_tprof(const char* name_, size_t print_period_) : tprof_handler(name_), print_period(print_period_) {}
auto t1 = std::chrono::high_resolution_clock::now();
std::lock_guard<std::mutex> lock(mutex);
auto ret = start_tpoints.insert(std::make_pair(next_id++, t1));
return ret.first->first;
}
void stop(uint8_t id) void process(long duration) final
{ {
auto t2 = std::chrono::high_resolution_clock::now(); count++;
std::lock_guard<std::mutex> lock(mutex); avg_val = avg_val * (count - 1) / count + static_cast<double>(duration) / count;
auto& t1 = start_tpoints[id]; max_val = std::max(max_val, duration);
c.process(std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1).count()); min_val = std::min(min_val, duration);
start_tpoints.erase(id); if (count % print_period == 0) {
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);
}
} }
private: double avg_val = 1;
std::mutex mutex; long count = 0, max_val = 0, min_val = std::numeric_limits<long>::max();
Callable c; long print_period;
std::unordered_map<uint8_t, tpoint> start_tpoints;
uint8_t next_id = 0;
}; };
template <typename Callable> struct tprof_measure {
class tprof_measure
{
using tpoint = std::chrono::time_point<std::chrono::high_resolution_clock>; using tpoint = std::chrono::time_point<std::chrono::high_resolution_clock>;
public: explicit tprof_measure(tprof_handler* h_) : h(h_) {}
template <typename... Args>
explicit tprof_measure(Args&&... args) : c(std::forward<Args>(args)...)
{
srslte::logmap::get("TPROF")->set_level(LOG_LEVEL_INFO);
}
void start() { t1 = std::chrono::high_resolution_clock::now(); } void start() { t1 = std::chrono::high_resolution_clock::now(); }
void stop() void stop()
{ {
auto t2 = std::chrono::high_resolution_clock::now(); auto t2 = std::chrono::high_resolution_clock::now();
c.process(std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1).count()); std::lock_guard<std::mutex> lock(h->mutex);
h->process(std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1).count());
} }
private: private:
Callable c; tprof_handler* h;
tpoint t1; tpoint t1;
}; };
struct avg_tprof { struct tprof_measure_guard {
avg_tprof(const char* name_, size_t print_period_) : name(name_), print_period(print_period_) {} 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;
void process(long duration) private:
{ tprof_measure tmeas;
count++;
avg_val = avg_val * (count - 1) / count + static_cast<double>(duration) / count;
max_val = std::max(max_val, duration);
min_val = std::min(min_val, duration);
if (count % print_period == 0) {
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);
}
}
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<long>::max();
long print_period;
}; };
#else #else
namespace srslte { namespace srslte {
template <typename Callable> struct tprof_handler {
class mutexed_tprof_measure };
{
public: struct avg_tprof : public tprof_handler {
template <typename... Args> avg_tprof(const char*, size_t) {}
explicit mutexed_tprof_measure(Args&&... c)
{
}
uint8_t start() { return 0; }
void stop(uint8_t id) {}
}; };
template <typename Callable>
class tprof_measure class tprof_measure
{ {
public: public:
template <typename... Args> explicit tprof_measure(tprof_handler* h_) {}
explicit tprof_measure(Args&&... c)
{
}
void start() {} void start() {}
void stop() {} void stop() {}
}; };
struct avg_tprof {
avg_tprof(const char*, size_t) {}
};
#endif #endif
} // namespace srslte } // namespace srslte

@ -445,10 +445,11 @@ 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_measure<srslte::avg_tprof> rach_tprof("RACH", 1); static srslte::avg_tprof rach_tprof("RACH", 1);
log_h->step(tti); log_h->step(tti);
uint16_t rnti; uint16_t rnti;
uint8_t tprof_id = rach_tprof.start(); srslte::tprof_measure tprof_meas{&rach_tprof};
tprof_meas.start();
{ {
srslte::rwlock_write_guard lock(rwlock); srslte::rwlock_write_guard lock(rwlock);
@ -472,7 +473,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, tprof_id]() mutable { stack_task_queue.push([this, rnti, tti, enb_cc_idx, preamble_idx, time_adv, tprof_meas]() mutable {
// Generate RAR data // Generate RAR data
sched_interface::dl_sched_rar_info_t rar_info = {}; sched_interface::dl_sched_rar_info_t rar_info = {};
rar_info.preamble_idx = preamble_idx; rar_info.preamble_idx = preamble_idx;
@ -490,7 +491,7 @@ void mac::rach_detected(uint32_t tti, uint32_t enb_cc_idx, uint32_t preamble_idx
ue_cfg.dl_cfg.tm = SRSLTE_TM1; ue_cfg.dl_cfg.tm = SRSLTE_TM1;
if (scheduler.ue_cfg(rnti, ue_cfg) != SRSLTE_SUCCESS) { if (scheduler.ue_cfg(rnti, ue_cfg) != SRSLTE_SUCCESS) {
Error("Registering new user rnti=0x%x to SCHED\n", rnti); Error("Registering new user rnti=0x%x to SCHED\n", rnti);
rach_tprof.stop(tprof_id); tprof_meas.stop();
return; return;
} }
@ -500,14 +501,14 @@ void mac::rach_detected(uint32_t tti, uint32_t enb_cc_idx, uint32_t preamble_idx
// Add temporal rnti to the PHY // Add temporal rnti to the PHY
if (phy_h->add_rnti(rnti, enb_cc_idx, true) != SRSLTE_SUCCESS) { if (phy_h->add_rnti(rnti, enb_cc_idx, true) != SRSLTE_SUCCESS) {
Error("Registering temporal-rnti=0x%x to PHY\n", rnti); Error("Registering temporal-rnti=0x%x to PHY\n", rnti);
rach_tprof.stop(tprof_id); tprof_meas.stop();
return; return;
} }
// Trigger scheduler RACH // Trigger scheduler RACH
scheduler.dl_rach_info(enb_cc_idx, rar_info); scheduler.dl_rach_info(enb_cc_idx, rar_info);
rach_tprof.stop(tprof_id); 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->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); log_h->console("RACH: tti=%d, preamble=%d, offset=%d, temp_crnti=0x%x\n", tti, preamble_idx, time_adv, rnti);

Loading…
Cancel
Save