From de6dd72dbbbcc7facf25c4a2521c71f653c7b1b2 Mon Sep 17 00:00:00 2001 From: Jacob Erlbeck Date: Tue, 17 Nov 2015 11:52:24 +0100 Subject: log: Add log_check_level function 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 1c159d0b..290b33df 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 876964ae..c7b19999 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; +} + /*! @} */ -- cgit v1.2.3 From a89d22c0f08edda927ce62b071f17bd7e5edc5c6 Mon Sep 17 00:00:00 2001 From: Jacob Erlbeck Date: Tue, 17 Nov 2015 11:52:25 +0100 Subject: log: Add conditional logging based on log_check_level 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 290b33df..e51487b5 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 */ -- cgit v1.2.3 From 64e0eb56fde45d891da122c9685891d29634d03b Mon Sep 17 00:00:00 2001 From: Jacob Erlbeck Date: Tue, 17 Nov 2015 11:52:26 +0100 Subject: log/test: Extend test case for log_check_level 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 b263f905..3c8bac4b 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 b59d2e83..c3b67cc2 100644 --- a/tests/logging/logging_test.err +++ b/tests/logging/logging_test.err @@ -1,3 +1,3 @@ You should see this You should see this - \ No newline at end of file +log_check_level did not catch this case (filter) -- cgit v1.2.3 From e0dc6a1c7cd49433bdf592624ff484576a7ce4e4 Mon Sep 17 00:00:00 2001 From: Holger Hans Peter Freyther Date: Mon, 21 Dec 2015 14:45:16 +0100 Subject: logging: Remove some code duplication 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 c7b19999..7db7101e 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) */ -- cgit v1.2.3 From 79599acd663f7c488560d72d63f4e29587fc63a2 Mon Sep 17 00:00:00 2001 From: Holger Hans Peter Freyther Date: Fri, 15 Jan 2016 16:49:06 +0100 Subject: logging: Move the filter check up as well 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 7db7101e..1c9c6634 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 3c8bac4b..3d1b7d87 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 c3b67cc2..4891491b 100644 --- a/tests/logging/logging_test.err +++ b/tests/logging/logging_test.err @@ -1,3 +1,4 @@ You should see this You should see this -log_check_level did not catch this case (filter) +You should see this + \ No newline at end of file -- cgit v1.2.3