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

Optimized front-end logging processing (#641)

Browse Source 
Avoid memory allocation and stringstream in log frontend calls (executed from worker threads). Uses a buffer pool of fixed buffer and vsnprintf
master
Ismael Gomez 5 years ago committed by GitHub
parent 67d6a25194
commit c92c61d560
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
11 changed files with 132 additions and 143 deletions
Show Stats Download Patch File Download Diff File

12
lib/include/srslte/common/log.h
Unescape Escape View File

@ -65,9 +65,7 @@ public:
tti = 0; tti = 0;
level = LOG_LEVEL_NONE; level = LOG_LEVEL_NONE;
hex_limit = 0; hex_limit = 0;
show_layer_en = true;
add_string_en = false; add_string_en = false;
level_text_short = true;
} }
log(std::string service_name_) { log(std::string service_name_) {
@ -75,9 +73,7 @@ public:
tti = 0; tti = 0;
level = LOG_LEVEL_NONE; level = LOG_LEVEL_NONE;
hex_limit = 0; hex_limit = 0;
show_layer_en = true;
add_string_en = false; add_string_en = false;
level_text_short = true;
} }
virtual ~log() {}; virtual ~log() {};
@ -131,12 +127,6 @@ public:
int get_hex_limit() { int get_hex_limit() {
return hex_limit; return hex_limit;
} }
void set_log_level_short(bool enable) {
level_text_short = enable;
}
void show_layer(bool enable) {
show_layer_en = enable;
}
// Pure virtual methods for logging // Pure virtual methods for logging
virtual void console(const char * message, ...) __attribute__ ((format (printf, 2, 3))) = 0; virtual void console(const char * message, ...) __attribute__ ((format (printf, 2, 3))) = 0;
@ -162,8 +152,6 @@ protected:
int hex_limit; int hex_limit;
std::string service_name; std::string service_name;
bool show_layer_en;
bool level_text_short;
bool add_string_en; bool add_string_en;
std::string add_string_val; std::string add_string_val;
}; };

9
lib/include/srslte/common/log_filter.h
Unescape Escape View File

@ -82,15 +82,16 @@ protected:
logger *logger_h; logger *logger_h;
bool do_tti; bool do_tti;
static const int char_buff_size = 512;
time_itf *time_src; time_itf *time_src;
time_format_t time_format; time_format_t time_format;
logger_stdout def_logger_stdout; logger_stdout def_logger_stdout;
void all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char *msg); void all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char* msg, const uint8_t* hex = nullptr, int size = 0);
void all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char *msg, const uint8_t *hex, int size); void now_time(char* buffer, const uint32_t buffer_len);
void all_log_line(srslte::LOG_LEVEL_ENUM level, uint32_t tti, std::string file, int line, char *msg); void get_tti_str(const uint32_t tti_, char* buffer, const uint32_t buffer_len);
std::string now_time();
std::string hex_string(const uint8_t *hex, int size); std::string hex_string(const uint8_t *hex, int size);
}; };

50
lib/include/srslte/common/logger.h
Unescape Escape View File

@ -27,6 +27,8 @@
#ifndef SRSLTE_LOGGER_H #ifndef SRSLTE_LOGGER_H
#define SRSLTE_LOGGER_H #define SRSLTE_LOGGER_H
#include "buffer_pool.h"
#include <memory>
#include <stdio.h> #include <stdio.h>
#include <string> #include <string>
@ -35,9 +37,55 @@ namespace srslte {
class logger class logger
{ {
public: public:
virtual void log(std::string *msg) = 0; logger() : pool(16 * 1024) {}
class log_str
{
public:
log_str(const char* msg_) { strncpy(msg, msg_, size); }
log_str() { reset(); }
void reset() { msg[0] = '\0'; }
const static int size = 512;
char msg[size];
};
typedef buffer_pool<log_str> log_str_pool_t;
class log_str_deleter
{
public:
explicit log_str_deleter(log_str_pool_t* pool_ = nullptr) : pool(pool_) {}
void operator()(log_str* buf)
{
if (buf) {
if (pool) {
buf->reset();
pool->deallocate(buf);
} else
delete buf;
}
}
private:
log_str_pool_t* pool;
};
typedef std::unique_ptr<log_str, log_str_deleter> unique_log_str_t;
void log_char(const char* msg) { log(std::move(unique_log_str_t(new log_str(msg), log_str_deleter()))); }
virtual void log(unique_log_str_t msg) = 0;
log_str_pool_t& get_pool() { return pool; }
private:
log_str_pool_t pool;
}; };
inline logger::unique_log_str_t allocate_unique_log_str(logger::log_str_pool_t& pool)
{
return logger::unique_log_str_t(pool.allocate(), logger::log_str_deleter(&pool));
}
} // namespace srslte } // namespace srslte
#endif // SRSLTE_LOGGER_H #endif // SRSLTE_LOGGER_H

6
lib/include/srslte/common/logger_file.h
Unescape Escape View File

@ -48,8 +48,7 @@ public:
~logger_file(); ~logger_file();
void init(std::string file, int max_length = -1); void init(std::string file, int max_length = -1);
// Implementation of log_out // Implementation of log_out
void log(str_ptr msg); void log(unique_log_str_t msg);
void log(const char *msg);
private: private:
void run_thread(); void run_thread();
@ -63,7 +62,8 @@ private:
std::string filename; std::string filename;
pthread_cond_t not_empty; pthread_cond_t not_empty;
pthread_mutex_t mutex; pthread_mutex_t mutex;
std::deque<str_ptr> buffer;
std::deque<unique_log_str_t> buffer;
}; };
} // namespace srslte } // namespace srslte

7
lib/include/srslte/common/logger_stdout.h
Unescape Escape View File

@ -36,12 +36,7 @@ namespace srslte {
class logger_stdout : public logger class logger_stdout : public logger
{ {
public: public:
void log(std::string *msg) { void log(unique_log_str_t log_str) { fprintf(stdout, "%s", log_str->msg); }
if (msg) {
fprintf(stdout, "%s", msg->c_str());
delete msg;
}
}
}; };
} // namespace srslte } // namespace srslte

153
lib/src/common/log_filter.cc
Unescape Escape View File

@ -65,173 +65,128 @@ void log_filter::init(std::string layer, logger *logger_, bool tti)
do_tti = tti; do_tti = tti;
} }
void log_filter::all_log(srslte::LOG_LEVEL_ENUM level, void log_filter::all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char* msg, const uint8_t* hex, int size)
uint32_t tti,
const char *msg)
{ {
if(logger_h) { char buffer_tti[16];
std::stringstream ss; char buffer_time[64];
ss << now_time() << " "; if (logger_h) {
if (show_layer_en) { logger::unique_log_str_t log_str = allocate_unique_log_str(logger_h->get_pool());
ss << "[" <<get_service_name() << "] ";
}
if (level_text_short) {
ss << log_level_text_short[level] << " ";
} else {
ss << log_level_text[level] << " ";
}
if(do_tti) {
ss << "[" << std::setfill('0') << std::setw(5) << tti << "] ";
}
if (add_string_en) {
ss << add_string_val << " ";
}
ss << msg;
str_ptr s_ptr(new std::string(ss.str())); if (log_str) {
logger_h->log(s_ptr); now_time(buffer_time, sizeof(buffer_time));
} if (do_tti) {
} get_tti_str(tti, buffer_tti, sizeof(buffer_tti));
}
void log_filter::all_log(srslte::LOG_LEVEL_ENUM level, snprintf(log_str->msg,
uint32_t tti, log_str->size,
const char *msg, "%s [%s] %s %s%s%s%s%s",
const uint8_t *hex, buffer_time,
int size) get_service_name().c_str(),
{ log_level_text_short[level],
if(logger_h) { do_tti ? buffer_tti : "",
std::stringstream ss; add_string_en ? add_string_val.c_str() : "",
msg,
msg[strlen(msg) - 1] != '\n' ? "\n" : "",
(hex_limit > 0 && hex && size > 0) ? hex_string(hex, size).c_str() : "");
ss << now_time() << " "; logger_h->log(std::move(log_str));
if (show_layer_en) {
ss << "[" <<get_service_name() << "] ";
}
if (level_text_short) {
ss << log_level_text_short[level] << " ";
} else { } else {
ss << log_level_text[level] << " "; logger_h->log_char("Error in Log: Not enough buffers in pool\n");
}
if(do_tti) {
ss << "[" << std::setfill('0') << std::setw(5) << tti << "] ";
} }
if (add_string_en) {
ss << add_string_val << " ";
}
ss << msg;
if (msg[strlen(msg)-1] != '\n') {
ss << std::endl;
}
if (hex_limit > 0 && hex && size > 0) {
ss << hex_string(hex, size);
}
str_ptr s_ptr(new std::string(ss.str()));
logger_h->log(s_ptr);
} }
} }
void log_filter::console(const char * message, ...) { void log_filter::console(const char * message, ...) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
printf("%s",args_msg); // Print directly to stdout printf("%s",args_msg); // Print directly to stdout
fflush(stdout); fflush(stdout);
va_end(args); va_end(args);
free(args_msg);
} }
void log_filter::error(const char * message, ...) { void log_filter::error(const char * message, ...) {
if (level >= LOG_LEVEL_ERROR) { if (level >= LOG_LEVEL_ERROR) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
all_log(LOG_LEVEL_ERROR, tti, args_msg); all_log(LOG_LEVEL_ERROR, tti, args_msg);
va_end(args); va_end(args);
free(args_msg);
} }
} }
void log_filter::warning(const char * message, ...) { void log_filter::warning(const char * message, ...) {
if (level >= LOG_LEVEL_WARNING) { if (level >= LOG_LEVEL_WARNING) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
all_log(LOG_LEVEL_WARNING, tti, args_msg); all_log(LOG_LEVEL_WARNING, tti, args_msg);
va_end(args); va_end(args);
free(args_msg);
} }
} }
void log_filter::info(const char * message, ...) { void log_filter::info(const char * message, ...) {
if (level >= LOG_LEVEL_INFO) { if (level >= LOG_LEVEL_INFO) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
all_log(LOG_LEVEL_INFO, tti, args_msg); all_log(LOG_LEVEL_INFO, tti, args_msg);
va_end(args); va_end(args);
free(args_msg);
} }
} }
void log_filter::debug(const char * message, ...) { void log_filter::debug(const char * message, ...) {
if (level >= LOG_LEVEL_DEBUG) { if (level >= LOG_LEVEL_DEBUG) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
all_log(LOG_LEVEL_DEBUG, tti, args_msg); all_log(LOG_LEVEL_DEBUG, tti, args_msg);
va_end(args); va_end(args);
free(args_msg);
} }
} }
void log_filter::error_hex(const uint8_t *hex, int size, const char * message, ...) { void log_filter::error_hex(const uint8_t *hex, int size, const char * message, ...) {
if (level >= LOG_LEVEL_ERROR) { if (level >= LOG_LEVEL_ERROR) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
all_log(LOG_LEVEL_ERROR, tti, args_msg, hex, size); all_log(LOG_LEVEL_ERROR, tti, args_msg, hex, size);
va_end(args); va_end(args);
free(args_msg);
} }
} }
void log_filter::warning_hex(const uint8_t *hex, int size, const char * message, ...) { void log_filter::warning_hex(const uint8_t *hex, int size, const char * message, ...) {
if (level >= LOG_LEVEL_WARNING) { if (level >= LOG_LEVEL_WARNING) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
all_log(LOG_LEVEL_WARNING, tti, args_msg, hex, size); all_log(LOG_LEVEL_WARNING, tti, args_msg, hex, size);
va_end(args); va_end(args);
free(args_msg);
} }
} }
void log_filter::info_hex(const uint8_t *hex, int size, const char * message, ...) { void log_filter::info_hex(const uint8_t *hex, int size, const char * message, ...) {
if (level >= LOG_LEVEL_INFO) { if (level >= LOG_LEVEL_INFO) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
all_log(LOG_LEVEL_INFO, tti, args_msg, hex, size); all_log(LOG_LEVEL_INFO, tti, args_msg, hex, size);
va_end(args); va_end(args);
free(args_msg);
} }
} }
void log_filter::debug_hex(const uint8_t *hex, int size, const char * message, ...) { void log_filter::debug_hex(const uint8_t *hex, int size, const char * message, ...) {
if (level >= LOG_LEVEL_DEBUG) { if (level >= LOG_LEVEL_DEBUG) {
char *args_msg = NULL; char args_msg[char_buff_size];
va_list args; va_list args;
va_start(args, message); va_start(args, message);
if(vasprintf(&args_msg, message, args) > 0) if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
all_log(LOG_LEVEL_DEBUG, tti, args_msg, hex, size); all_log(LOG_LEVEL_DEBUG, tti, args_msg, hex, size);
va_end(args); va_end(args);
free(args_msg);
} }
} }
@ -239,42 +194,48 @@ void log_filter::set_time_src(time_itf *source, time_format_t format) {
this->time_src = source; this->time_src = source;
this->time_format = format; this->time_format = format;
} }
void log_filter::get_tti_str(const uint32_t tti_, char* buffer, const uint32_t buffer_len)
{
snprintf(buffer, buffer_len, "[%5d] ", tti_);
}
std::string log_filter::now_time() void log_filter::now_time(char* buffer, const uint32_t buffer_len)
{ {
struct timeval rawtime; struct timeval rawtime;
struct tm * timeinfo; struct tm * timeinfo;
char buffer[64];
char us[16]; char us[16];
srslte_timestamp_t now; srslte_timestamp_t now;
uint64_t usec_epoch; uint64_t usec_epoch;
if (buffer_len < 16) {
fprintf(stderr, "Error buffer provided for time too small\n");
return;
}
if (!time_src) { if (!time_src) {
gettimeofday(&rawtime, NULL); gettimeofday(&rawtime, NULL);
timeinfo = localtime(&rawtime.tv_sec); timeinfo = localtime(&rawtime.tv_sec);
if (time_format == TIME) { if (time_format == TIME) {
strftime(buffer, 64, "%H:%M:%S", timeinfo); strftime(buffer, buffer_len, "%H:%M:%S.", timeinfo);
strcat(buffer, ".");
snprintf(us, 16, "%06ld", rawtime.tv_usec); snprintf(us, 16, "%06ld", rawtime.tv_usec);
strcat(buffer, us); uint32_t dest_len = strlen(buffer);
strncat(buffer, us, buffer_len - dest_len - 1);
} else { } else {
usec_epoch = rawtime.tv_sec * 1000000 + rawtime.tv_usec; usec_epoch = rawtime.tv_sec * 1000000 + rawtime.tv_usec;
snprintf(buffer, 64, "%ld", usec_epoch); snprintf(buffer, buffer_len, "%ld", usec_epoch);
} }
} else { } else {
now = time_src->get_time(); now = time_src->get_time();
if (time_format == TIME) { if (time_format == TIME) {
snprintf(buffer, 64, "%ld:%06u", now.full_secs, (uint32_t) (now.frac_secs * 1e6)); snprintf(buffer, buffer_len, "%ld:%06u", now.full_secs, (uint32_t)(now.frac_secs * 1e6));
} else { } else {
usec_epoch = now.full_secs * 1000000 + (uint32_t) (now.frac_secs * 1e6); usec_epoch = now.full_secs * 1000000 + (uint32_t) (now.frac_secs * 1e6);
snprintf(buffer, 64, "%ld", usec_epoch); snprintf(buffer, buffer_len, "%ld", usec_epoch);
} }
} }
return std::string(buffer);
} }
std::string log_filter::hex_string(const uint8_t *hex, int size) std::string log_filter::hex_string(const uint8_t *hex, int size)

24
lib/src/common/logger_file.cc
Unescape Escape View File

@ -35,7 +35,7 @@ logger_file::logger_file() : logfile(NULL), is_running(false), cur_length(0), ma
logger_file::~logger_file() { logger_file::~logger_file() {
if(is_running) { if(is_running) {
log(new std::string("Closing log\n")); logger::log_char("Closing log\n");
pthread_mutex_lock(&mutex); pthread_mutex_lock(&mutex);
is_running = false; is_running = false;
pthread_cond_signal(&not_empty); // wakeup thread and let it terminate pthread_cond_signal(&not_empty); // wakeup thread and let it terminate
@ -64,13 +64,10 @@ void logger_file::init(std::string file, int max_length_) {
start(-2); start(-2);
} }
void logger_file::log(const char *msg) { void logger_file::log(unique_log_str_t msg)
log(new std::string(msg)); {
}
void logger_file::log(str_ptr msg) {
pthread_mutex_lock(&mutex); pthread_mutex_lock(&mutex);
buffer.push_back(msg); buffer.push_back(std::move(msg));
pthread_cond_signal(&not_empty); pthread_cond_signal(&not_empty);
pthread_mutex_unlock(&mutex); pthread_mutex_unlock(&mutex);
} }
@ -85,11 +82,11 @@ void logger_file::run_thread() {
return; // Thread done. Messages in buffer will be handled in flush. return; // Thread done. Messages in buffer will be handled in flush.
} }
} }
str_ptr s = buffer.front(); unique_log_str_t s = std::move(buffer.front());
int n = 0; int n = 0;
if(logfile) if(logfile)
n = fprintf(logfile, "%s", s->c_str()); n = fprintf(logfile, "%s", s->msg);
delete s;
buffer.pop_front(); buffer.pop_front();
pthread_mutex_unlock(&mutex); pthread_mutex_unlock(&mutex);
if (n > 0) { if (n > 0) {
@ -111,13 +108,12 @@ void logger_file::run_thread() {
} }
void logger_file::flush() { void logger_file::flush() {
std::deque<str_ptr>::iterator it; std::deque<unique_log_str_t>::iterator it;
for(it=buffer.begin();it!=buffer.end();it++) for(it=buffer.begin();it!=buffer.end();it++)
{ {
str_ptr s = *it; unique_log_str_t s = std::move(*it);
if(logfile) if(logfile)
fprintf(logfile, "%s", s->c_str()); fprintf(logfile, "%s", s->msg);
delete s;
} }
} }

2
lib/test/common/logger_test.cc
Unescape Escape View File

@ -39,7 +39,7 @@ void* thread_loop(void *a) {
for(int i=0;i<NMSGS;i++) for(int i=0;i<NMSGS;i++)
{ {
sprintf(buf, "Thread %d: %d", args->thread_id, i); sprintf(buf, "Thread %d: %d", args->thread_id, i);
args->l->log(new std::string(buf)); args->l->log_char(buf);
} }
return NULL; return NULL;
} }

4
srsenb/src/enb.cc
Unescape Escape View File

@ -84,8 +84,8 @@ int enb::init(const all_args_t& args_)
logger = &logger_stdout; logger = &logger_stdout;
} else { } else {
logger_file.init(args.log.filename, args.log.file_max_size); logger_file.init(args.log.filename, args.log.file_max_size);
logger_file.log("\n\n"); logger_file.log_char("\n\n");
logger_file.log(get_build_string().c_str()); logger_file.log_char(get_build_string().c_str());
logger = &logger_file; logger = &logger_file;
} }

6
srsepc/src/main.cc
Unescape Escape View File

@ -401,9 +401,9 @@ int main(int argc, char* argv[])
logger = &logger_stdout; logger = &logger_stdout;
} else { } else {
logger_file.init(args.log_args.filename); logger_file.init(args.log_args.filename);
logger_file.log("\n\n"); logger_file.log_char("\n\n");
logger_file.log(get_build_string().c_str()); logger_file.log_char(get_build_string().c_str());
logger_file.log("\n--- Software Radio Systems EPC log ---\n\n"); logger_file.log_char("\n--- Software Radio Systems EPC log ---\n\n");
logger = &logger_file; logger = &logger_file;
} }

2
srsepc/src/mbms-gw/main.cc
Unescape Escape View File

@ -204,7 +204,7 @@ main (int argc,char * argv[] )
logger = &logger_stdout; logger = &logger_stdout;
} else { } else {
logger_file.init(args.log_args.filename); logger_file.init(args.log_args.filename);
logger_file.log("\n--- Software Radio Systems MBMS log ---\n\n"); logger_file.log_char("\n--- Software Radio Systems MBMS log ---\n\n");
logger = &logger_file; logger = &logger_file;
} }

Write Preview
Loading…
Cancel
Save