From: Jacob Erlbeck <jerlbeck@sysmocom.de> This commit adds this predicate function which can be used to avoid the execution of code if a certain log level is not enabled. The function will only return 0 (false), if it is sure that a logging call for the same facility and level will not produce any output. This safety criterion shall ensure, that no logging output is lost due to the use of this predicate as a guard. On the other hand, even if the predicate returns != 0 (true), no logging output might get generated by a similar logging command. Note that the current implementation is not focussed on performance, which could be improved by using a lookup table instead of iterating through every target. Sponsored-by: On-Waves ehf --- include/osmocom/core/logging.h | 1 + src/logging.c | 39 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 40 insertions(+) diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h index 1c159d0..290b33d 100644 --- a/include/osmocom/core/logging.h +++ b/include/osmocom/core/logging.h @@ -198,6 +198,7 @@ void logp2(int subsys, unsigned int level, const char *file, int line, int cont, const char *format, ...) __attribute__ ((format (printf, 6, 7))); int log_init(const struct log_info *inf, void *talloc_ctx); +int log_check_level(int subsys, unsigned int level); /* context management */ void log_reset_context(void); diff --git a/src/logging.c b/src/logging.c index 876964a..c7b1999 100644 --- a/src/logging.c +++ b/src/logging.c @@ -865,4 +865,43 @@ int log_init(const struct log_info *inf, void *ctx) return 0; } +/*! \brief Check whether a log entry will be generated. + * \returns != 0 if a log entry might get generated by at least one target */ +int log_check_level(int subsys, unsigned int level) +{ + struct log_target *tar; + + if (subsys < 0) + subsys = subsys_lib2index(subsys); + + if (subsys > osmo_log_info->num_cat) + subsys = DLGLOBAL; + + /* TODO: The following could/should be cached (update on config) */ + + llist_for_each_entry(tar, &osmo_log_target_list, entry) { + struct log_category *category; + + category = &tar->categories[subsys]; + /* subsystem is not supposed to be logged */ + if (!category->enabled) + continue; + + /* Check the global log level */ + if (tar->loglevel != 0 && level < tar->loglevel) + continue; + + /* Check the category log level */ + if (tar->loglevel == 0 && category->loglevel != 0 && + level < category->loglevel) + continue; + + /* This might get logged (ignoring filters) */ + return 1; + } + + /* We are sure, that this will not be logged. */ + return 0; +} + /*! @} */ -- 2.6.3
From: Jacob Erlbeck <jerlbeck@sysmocom.de> Currently the LOGP/DEBUGP arguments are always evaluated even if no logging will happen at all. This can be expensive, for instance if hexdumps or pretty printed object names are generated. This causes high base load especially on embedded devices and is a major part of CPU usage e.g. of the osmo-pcu. This commit uses the log_check_level function to avoid the evaluation of the parameters if it is known in advance, that no logging entry will be generated. Sponsored-by: On-Waves ehf --- include/osmocom/core/logging.h | 24 ++++++++++++++++++++---- 1 file changed, 20 insertions(+), 4 deletions(-) diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h index 290b33d..e51487b 100644 --- a/include/osmocom/core/logging.h +++ b/include/osmocom/core/logging.h @@ -19,8 +19,18 @@ #define DEBUG #ifdef DEBUG -#define DEBUGP(ss, fmt, args...) logp(ss, __FILE__, __LINE__, 0, fmt, ## args) -#define DEBUGPC(ss, fmt, args...) logp(ss, __FILE__, __LINE__, 1, fmt, ## args) +#define DEBUGP(ss, fmt, args...) \ + do { \ + if (log_check_level(ss, LOGL_DEBUG)) \ + logp(ss, __FILE__, __LINE__, 0, fmt, ## args); \ + } while(0) + +#define DEBUGPC(ss, fmt, args...) \ + do { \ + if (log_check_level(ss, LOGL_DEBUG)) \ + logp(ss, __FILE__, __LINE__, 1, fmt, ## args); \ + } while(0) + #else #define DEBUGP(xss, fmt, args...) #define DEBUGPC(ss, fmt, args...) @@ -39,7 +49,10 @@ void logp(int subsys, const char *file, int line, int cont, const char *format, * \param[in] args variable argument list */ #define LOGP(ss, level, fmt, args...) \ - logp2(ss, level, __FILE__, __LINE__, 0, fmt, ##args) + do { \ + if (log_check_level(ss, level)) \ + logp2(ss, level, __FILE__, __LINE__, 0, fmt, ##args); \ + } while(0) /*! \brief Continue a log message through the Osmocom logging framework * \param[in] ss logging subsystem (e.g. \ref DLGLOBAL) @@ -48,7 +61,10 @@ void logp(int subsys, const char *file, int line, int cont, const char *format, * \param[in] args variable argument list */ #define LOGPC(ss, level, fmt, args...) \ - logp2(ss, level, __FILE__, __LINE__, 1, fmt, ##args) + do { \ + if (log_check_level(ss, level)) \ + logp2(ss, level, __FILE__, __LINE__, 1, fmt, ##args); \ + } while(0) /*! \brief different log levels */ #define LOGL_DEBUG 1 /*!< \brief debugging information */ -- 2.6.3
From: Jacob Erlbeck <jerlbeck@sysmocom.de> This commit adds OSMO_ASSERTs for mandatory conditions related to log_check_level, and fprintfs for optional conditions, since it is always safe for log_check_level to return != 0. Sponsored-by: On-Waves ehf --- tests/logging/logging_test.c | 10 ++++++++++ tests/logging/logging_test.err | 2 +- 2 files changed, 11 insertions(+), 1 deletion(-) diff --git a/tests/logging/logging_test.c b/tests/logging/logging_test.c index b263f90..3c8bac4 100644 --- a/tests/logging/logging_test.c +++ b/tests/logging/logging_test.c @@ -78,16 +78,26 @@ int main(int argc, char **argv) log_parse_category_mask(stderr_target, "DRLL:DCC"); log_parse_category_mask(stderr_target, "DRLL"); DEBUGP(DCC, "You should not see this\n"); + if (log_check_level(DMM, LOGL_DEBUG) != 0) + fprintf(stderr, "log_check_level did not catch this case\n"); log_parse_category_mask(stderr_target, "DRLL:DCC"); DEBUGP(DRLL, "You should see this\n"); + OSMO_ASSERT(log_check_level(DRLL, LOGL_DEBUG) != 0); DEBUGP(DCC, "You should see this\n"); + OSMO_ASSERT(log_check_level(DCC, LOGL_DEBUG) != 0); DEBUGP(DMM, "You should not see this\n"); + if (log_check_level(DMM, LOGL_DEBUG) != 0) + fprintf(stderr, "log_check_level did not catch this case\n"); + OSMO_ASSERT(filter_called == 0); log_set_all_filter(stderr_target, 0); DEBUGP(DRLL, "You should not see this and filter is called\n"); OSMO_ASSERT(filter_called == 1); + if (log_check_level(DRLL, LOGL_DEBUG) != 0) + fprintf(stderr, + "log_check_level did not catch this case (filter)\n"); return 0; } diff --git a/tests/logging/logging_test.err b/tests/logging/logging_test.err index b59d2e8..c3b67cc 100644 --- a/tests/logging/logging_test.err +++ b/tests/logging/logging_test.err @@ -1,3 +1,3 @@ [1;31mYou should see this [0;m[1;32mYou should see this -[0;m \ No newline at end of file +[0;mlog_check_level did not catch this case (filter) -- 2.6.3
From: Holger Hans Peter Freyther <holger@moiji-mobile.com> Extract the mapping of the subsystem number and the checking for the loglevel to a inline method that is shared between the new and old. --- src/logging.c | 74 +++++++++++++++++++++++++++++------------------------------ 1 file changed, 37 insertions(+), 37 deletions(-) diff --git a/src/logging.c b/src/logging.c index c7b1999..7db7101 100644 --- a/src/logging.c +++ b/src/logging.c @@ -310,35 +310,52 @@ err: target->output(target, level, buf); } -/*! \brief vararg version of logging function */ -void osmo_vlogp(int subsys, int level, const char *file, int line, - int cont, const char *format, va_list ap) +static inline int map_subsys(int subsys) { - struct log_target *tar; - if (subsys < 0) subsys = subsys_lib2index(subsys); if (subsys > osmo_log_info->num_cat) subsys = DLGLOBAL; + return subsys; +} + +static inline int check_log_to_target(struct log_target *tar, int subsys, int level) +{ + struct log_category *category; + + category = &tar->categories[subsys]; + + /* subsystem is not supposed to be logged */ + if (!category->enabled) + return 0; + + /* Check the global log level */ + if (tar->loglevel != 0 && level < tar->loglevel) + return 0; + + /* Check the category log level */ + if (tar->loglevel == 0 && category->loglevel != 0 && + level < category->loglevel) + return 0; + + /* TODO: Check the filter/selector too? */ + return 1; +} + +/*! \brief vararg version of logging function */ +void osmo_vlogp(int subsys, int level, const char *file, int line, + int cont, const char *format, va_list ap) +{ + struct log_target *tar; + + subsys = map_subsys(subsys); llist_for_each_entry(tar, &osmo_log_target_list, entry) { - struct log_category *category; int output = 0; va_list bp; - category = &tar->categories[subsys]; - /* subsystem is not supposed to be logged */ - if (!category->enabled) - continue; - - /* Check the global log level */ - if (tar->loglevel != 0 && level < tar->loglevel) - continue; - - /* Check the category log level */ - if (tar->loglevel == 0 && category->loglevel != 0 && - level < category->loglevel) + if (!check_log_to_target(tar, subsys, level)) continue; /* Apply filters here... if that becomes messy we will @@ -871,29 +888,12 @@ int log_check_level(int subsys, unsigned int level) { struct log_target *tar; - if (subsys < 0) - subsys = subsys_lib2index(subsys); - - if (subsys > osmo_log_info->num_cat) - subsys = DLGLOBAL; + subsys = map_subsys(subsys); /* TODO: The following could/should be cached (update on config) */ llist_for_each_entry(tar, &osmo_log_target_list, entry) { - struct log_category *category; - - category = &tar->categories[subsys]; - /* subsystem is not supposed to be logged */ - if (!category->enabled) - continue; - - /* Check the global log level */ - if (tar->loglevel != 0 && level < tar->loglevel) - continue; - - /* Check the category log level */ - if (tar->loglevel == 0 && category->loglevel != 0 && - level < category->loglevel) + if (!check_log_to_target(tar, subsys, level)) continue; /* This might get logged (ignoring filters) */ -- 2.6.3
From: Holger Hans Peter Freyther <holger@moiji-mobile.com> There doesn't seem to be a reason not to check the filter. Update and extend the test. Currently the filter function will be called once for the log check and once for the output of it. --- src/logging.c | 20 +++++++++----------- tests/logging/logging_test.c | 19 +++++++++++++------ tests/logging/logging_test.err | 3 ++- 3 files changed, 24 insertions(+), 18 deletions(-) diff --git a/src/logging.c b/src/logging.c index 7db7101..1c9c663 100644 --- a/src/logging.c +++ b/src/logging.c @@ -339,6 +339,15 @@ static inline int check_log_to_target(struct log_target *tar, int subsys, int le level < category->loglevel) return 0; + /* Apply filters here... if that becomes messy we will + * need to put filters in a list and each filter will + * say stop, continue, output */ + if ((tar->filter_map & LOG_FILTER_ALL) != 0) + return 1; + + if (osmo_log_info->filter_fn) + return osmo_log_info->filter_fn(&log_context, tar); + /* TODO: Check the filter/selector too? */ return 1; } @@ -358,17 +367,6 @@ void osmo_vlogp(int subsys, int level, const char *file, int line, if (!check_log_to_target(tar, subsys, level)) continue; - /* Apply filters here... if that becomes messy we will - * need to put filters in a list and each filter will - * say stop, continue, output */ - if ((tar->filter_map & LOG_FILTER_ALL) != 0) - output = 1; - else if (osmo_log_info->filter_fn) - output = osmo_log_info->filter_fn(&log_context, - tar); - if (!output) - continue; - /* According to the manpage, vsnprintf leaves the value of ap * in undefined state. Since _output uses vsnprintf and it may * be called several times, we have to pass a copy of ap. */ diff --git a/tests/logging/logging_test.c b/tests/logging/logging_test.c index 3c8bac4..3d1b7d8 100644 --- a/tests/logging/logging_test.c +++ b/tests/logging/logging_test.c @@ -30,6 +30,7 @@ enum { }; static int filter_called = 0; +static int select_output = 0; static const struct log_info_cat default_categories[] = { [DRLL] = { @@ -56,7 +57,7 @@ static int test_filter(const struct log_context *ctx, struct log_target *target) { filter_called += 1; /* omit everything */ - return 0; + return select_output; } const struct log_info log_info = { @@ -77,6 +78,9 @@ int main(int argc, char **argv) log_parse_category_mask(stderr_target, "DRLL:DCC"); log_parse_category_mask(stderr_target, "DRLL"); + + select_output = 0; + DEBUGP(DCC, "You should not see this\n"); if (log_check_level(DMM, LOGL_DEBUG) != 0) fprintf(stderr, "log_check_level did not catch this case\n"); @@ -87,17 +91,20 @@ int main(int argc, char **argv) DEBUGP(DCC, "You should see this\n"); OSMO_ASSERT(log_check_level(DCC, LOGL_DEBUG) != 0); DEBUGP(DMM, "You should not see this\n"); - if (log_check_level(DMM, LOGL_DEBUG) != 0) - fprintf(stderr, "log_check_level did not catch this case\n"); + OSMO_ASSERT(log_check_level(DMM, LOGL_DEBUG) == 0); OSMO_ASSERT(filter_called == 0); log_set_all_filter(stderr_target, 0); DEBUGP(DRLL, "You should not see this and filter is called\n"); OSMO_ASSERT(filter_called == 1); - if (log_check_level(DRLL, LOGL_DEBUG) != 0) - fprintf(stderr, - "log_check_level did not catch this case (filter)\n"); + OSMO_ASSERT(log_check_level(DRLL, LOGL_DEBUG) == 0); + OSMO_ASSERT(filter_called == 2); + DEBUGP(DRLL, "You should not see this\n"); + OSMO_ASSERT(filter_called == 3); + select_output = 1; + DEBUGP(DRLL, "You should see this\n"); + OSMO_ASSERT(filter_called == 5); /* called twice on output */ return 0; } diff --git a/tests/logging/logging_test.err b/tests/logging/logging_test.err index c3b67cc..4891491 100644 --- a/tests/logging/logging_test.err +++ b/tests/logging/logging_test.err @@ -1,3 +1,4 @@ [1;31mYou should see this [0;m[1;32mYou should see this -[0;mlog_check_level did not catch this case (filter) +[0;m[1;31mYou should see this +[0;m \ No newline at end of file -- 2.6.3
participants (1)
-
Holger Hans Peter Freyther