From cd521a84cbf5c625d04337c5d98603bdc20ceddc Mon Sep 17 00:00:00 2001 From: Francisco Paisana Date: Tue, 17 Sep 2019 10:42:17 +0100 Subject: [PATCH] bigger log buffer. Now it is 1024 chars (#649) Use dynamic string for debug_long() function and known relation of size between log_str and log_filter --- lib/include/srslte/common/log_filter.h | 10 +- lib/include/srslte/common/logger.h | 41 +++++--- lib/include/srslte/common/logger_stdout.h | 2 +- lib/src/common/log_filter.cc | 122 +++++++++++----------- lib/src/common/logger_file.cc | 5 +- 5 files changed, 99 insertions(+), 81 deletions(-) diff --git a/lib/include/srslte/common/log_filter.h b/lib/include/srslte/common/log_filter.h index 086e7adc8..ff86cae0f 100644 --- a/lib/include/srslte/common/log_filter.h +++ b/lib/include/srslte/common/log_filter.h @@ -58,6 +58,7 @@ public: void warning(const char * message, ...) __attribute__ ((format (printf, 2, 3))); void info(const char * message, ...) __attribute__ ((format (printf, 2, 3))); void debug(const char * message, ...) __attribute__ ((format (printf, 2, 3))); + void debug_long(const char* message, ...) __attribute__((format(printf, 2, 3))); void error_hex(const uint8_t *hex, int size, const char * message, ...) __attribute__((format (printf, 4, 5))); void warning_hex(const uint8_t *hex, int size, const char * message, ...) __attribute__((format (printf, 4, 5))); @@ -82,14 +83,19 @@ protected: logger *logger_h; bool do_tti; - static const int char_buff_size = 512; + static const int char_buff_size = logger::preallocated_log_str_size - 64 * 3; time_itf *time_src; time_format_t time_format; logger_stdout def_logger_stdout; - 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 = nullptr, + int size = 0, + bool long_msg = false); void now_time(char* buffer, const uint32_t buffer_len); void get_tti_str(const uint32_t tti_, char* buffer, const uint32_t buffer_len); std::string hex_string(const uint8_t *hex, int size); diff --git a/lib/include/srslte/common/logger.h b/lib/include/srslte/common/logger.h index 1f7978d26..0b5da301b 100644 --- a/lib/include/srslte/common/logger.h +++ b/lib/include/srslte/common/logger.h @@ -37,16 +37,33 @@ namespace srslte { class logger { public: + const static uint32_t preallocated_log_str_size = 1024; + 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]; + log_str(const char* msg_ = nullptr, uint32_t size_ = 0) + { + size = size_ ? size_ : preallocated_log_str_size; + msg = new char[size]; + if (msg_) { + strncpy(msg, msg_, size); + } else { + msg[0] = '\0'; + } + } + log_str(const log_str&) = delete; + log_str& operator=(const log_str&) = delete; + ~log_str() { delete[] msg; } + void reset() { msg[0] = '\0'; } + char* str() { return msg; } + uint32_t get_buffer_size() { return size; } + + private: + uint32_t size; + char* msg; }; typedef buffer_pool log_str_pool_t; @@ -61,8 +78,9 @@ public: if (pool) { buf->reset(); pool->deallocate(buf); - } else + } else { delete buf; + } } } @@ -75,17 +93,16 @@ public: virtual void log(unique_log_str_t msg) = 0; - log_str_pool_t& get_pool() { return pool; } + log_str_pool_t& get_pool() { return pool; } + unique_log_str_t allocate_unique_log_str() + { + return unique_log_str_t(pool.allocate(), logger::log_str_deleter(&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 #endif // SRSLTE_LOGGER_H diff --git a/lib/include/srslte/common/logger_stdout.h b/lib/include/srslte/common/logger_stdout.h index ed99cf1d5..04055eaf7 100644 --- a/lib/include/srslte/common/logger_stdout.h +++ b/lib/include/srslte/common/logger_stdout.h @@ -36,7 +36,7 @@ namespace srslte { class logger_stdout : public logger { public: - void log(unique_log_str_t log_str) { fprintf(stdout, "%s", log_str->msg); } + void log(unique_log_str_t log_str) { fprintf(stdout, "%s", log_str->str()); } }; } // namespace srslte diff --git a/lib/src/common/log_filter.cc b/lib/src/common/log_filter.cc index c8e98639d..77b4d15ec 100644 --- a/lib/src/common/log_filter.cc +++ b/lib/src/common/log_filter.cc @@ -65,13 +65,22 @@ void log_filter::init(std::string layer, logger *logger_, bool tti) do_tti = tti; } -void log_filter::all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char* msg, const uint8_t* hex, int size) +void log_filter::all_log( + srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char* msg, const uint8_t* hex, int size, bool long_msg) { char buffer_tti[16]; char buffer_time[64]; if (logger_h) { - logger::unique_log_str_t log_str = allocate_unique_log_str(logger_h->get_pool()); + logger::unique_log_str_t log_str = nullptr; + + if (long_msg) { + // For long messages, dynamically allocate a new log_str with enough size outside the pool. + uint32_t log_str_msg_len = sizeof(buffer_tti) + sizeof(buffer_time) + 10 + strlen(msg); + log_str = logger::unique_log_str_t(new logger::log_str(nullptr, log_str_msg_len), logger::log_str_deleter()); + } else { + log_str = logger_h->allocate_unique_log_str(); + } if (log_str) { now_time(buffer_time, sizeof(buffer_time)); @@ -79,8 +88,8 @@ void log_filter::all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char* get_tti_str(tti, buffer_tti, sizeof(buffer_tti)); } - snprintf(log_str->msg, - log_str->size, + snprintf(log_str->str(), + log_str->get_buffer_size(), "%s [%s] %s %s%s%s%s%s", buffer_time, get_service_name().c_str(), @@ -108,86 +117,73 @@ void log_filter::console(const char * message, ...) { va_end(args); } +#define all_log_expand(log_level) \ + do { \ + if (level >= LOG_LEVEL_ERROR) { \ + char args_msg[char_buff_size]; \ + va_list args; \ + va_start(args, message); \ + if (vsnprintf(args_msg, char_buff_size, message, args) > 0) \ + all_log(LOG_LEVEL_ERROR, tti, args_msg); \ + va_end(args); \ + } \ + } while (0) + +#define all_log_hex_expand(log_level) \ + do { \ + if (level >= LOG_LEVEL_ERROR) { \ + char args_msg[char_buff_size]; \ + va_list args; \ + va_start(args, message); \ + if (vsnprintf(args_msg, char_buff_size, message, args) > 0) \ + all_log(LOG_LEVEL_ERROR, tti, args_msg, hex, size); \ + va_end(args); \ + } \ + } while (0) + void log_filter::error(const char * message, ...) { - if (level >= LOG_LEVEL_ERROR) { - char args_msg[char_buff_size]; - va_list args; - va_start(args, message); - if (vsnprintf(args_msg, char_buff_size, message, args) > 0) - all_log(LOG_LEVEL_ERROR, tti, args_msg); - va_end(args); - } + all_log_expand(LOG_LEVEL_ERROR); } + void log_filter::warning(const char * message, ...) { - if (level >= LOG_LEVEL_WARNING) { - char args_msg[char_buff_size]; - va_list args; - va_start(args, message); - if (vsnprintf(args_msg, char_buff_size, message, args) > 0) - all_log(LOG_LEVEL_WARNING, tti, args_msg); - va_end(args); - } + all_log_expand(LOG_LEVEL_WARNING); } + void log_filter::info(const char * message, ...) { - if (level >= LOG_LEVEL_INFO) { - char args_msg[char_buff_size]; - va_list args; - va_start(args, message); - if (vsnprintf(args_msg, char_buff_size, message, args) > 0) - all_log(LOG_LEVEL_INFO, tti, args_msg); - va_end(args); - } + all_log_expand(LOG_LEVEL_INFO); } + void log_filter::debug(const char * message, ...) { + all_log_expand(LOG_LEVEL_DEBUG); +} + +void log_filter::debug_long(const char* message, ...) +{ if (level >= LOG_LEVEL_DEBUG) { - char args_msg[char_buff_size]; + char* args_msg = NULL; va_list args; va_start(args, message); - if (vsnprintf(args_msg, char_buff_size, message, args) > 0) - all_log(LOG_LEVEL_DEBUG, tti, args_msg); + if (vasprintf(&args_msg, message, args) > 0) + all_log(LOG_LEVEL_ERROR, tti, args_msg); va_end(args); + free(args_msg); } } void log_filter::error_hex(const uint8_t *hex, int size, const char * message, ...) { - if (level >= LOG_LEVEL_ERROR) { - char args_msg[char_buff_size]; - va_list args; - va_start(args, message); - if (vsnprintf(args_msg, char_buff_size, message, args) > 0) - all_log(LOG_LEVEL_ERROR, tti, args_msg, hex, size); - va_end(args); - } + all_log_hex_expand(LOG_LEVEL_ERROR); } + void log_filter::warning_hex(const uint8_t *hex, int size, const char * message, ...) { - if (level >= LOG_LEVEL_WARNING) { - char args_msg[char_buff_size]; - va_list args; - va_start(args, message); - if (vsnprintf(args_msg, char_buff_size, message, args) > 0) - all_log(LOG_LEVEL_WARNING, tti, args_msg, hex, size); - va_end(args); - } + all_log_hex_expand(LOG_LEVEL_WARNING); } + void log_filter::info_hex(const uint8_t *hex, int size, const char * message, ...) { - if (level >= LOG_LEVEL_INFO) { - char args_msg[char_buff_size]; - va_list args; - va_start(args, message); - if (vsnprintf(args_msg, char_buff_size, message, args) > 0) - all_log(LOG_LEVEL_INFO, tti, args_msg, hex, size); - va_end(args); - } + all_log_hex_expand(LOG_LEVEL_INFO); } + void log_filter::debug_hex(const uint8_t *hex, int size, const char * message, ...) { - if (level >= LOG_LEVEL_DEBUG) { - char args_msg[char_buff_size]; - va_list args; - va_start(args, message); - if (vsnprintf(args_msg, char_buff_size, message, args) > 0) - all_log(LOG_LEVEL_DEBUG, tti, args_msg, hex, size); - va_end(args); - } + all_log_hex_expand(LOG_LEVEL_DEBUG); } void log_filter::set_time_src(time_itf *source, time_format_t format) { diff --git a/lib/src/common/logger_file.cc b/lib/src/common/logger_file.cc index 1ce449741..b38958d51 100644 --- a/lib/src/common/logger_file.cc +++ b/lib/src/common/logger_file.cc @@ -103,9 +103,8 @@ void logger_file::run_thread() { int n = 0; if (logfile) { - n = fprintf(logfile, "%s", s->msg); + n = fprintf(logfile, "%s", s->str()); } - buffer.pop_front(); if (n > 0) { @@ -133,7 +132,7 @@ void logger_file::flush() for (it = buffer.begin(); it != buffer.end(); it++) { unique_log_str_t s = std::move(*it); if (logfile) { - fprintf(logfile, "%s", s->msg); + fprintf(logfile, "%s", s->str()); } } buffer.clear();