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 */ -- 1.9.1

Hi Jacob, I am in favour of such a patch to prevent doing work (formatting arguments) when it will not be used. What is the reasoning for this part? The below does not work yet but shows the general idea. If the check routine already finds the first target that will generate an output, then let us use it? This is why I have put an output parameter in there and pass it a long. The thing that is not pretty is how to print "tar" and everything that follows it, naturally I would like to use a do {} while() loop but not roll the llist_entry by hand (or maybe I do). It is no look-up table but we avoid to duplicate the selection criteria and to iterate over targets (the one or two) we already have looked at? diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h index e51487b..ed21e57 100644 --- a/include/osmocom/core/logging.h +++ b/include/osmocom/core/logging.h @@ -11,6 +11,8 @@ #include <stdarg.h> #include <osmocom/core/linuxlist.h> +struct log_target; + /*! \brief Maximum number of logging contexts */ #define LOG_MAX_CTX 8 /*! \brief Maximum number of logging filters */ @@ -18,17 +20,23 @@ #define DEBUG + + #ifdef DEBUG #define DEBUGP(ss, fmt, args...) \ do { \ - if (log_check_level(ss, LOGL_DEBUG)) \ - logp(ss, __FILE__, __LINE__, 0, fmt, ## args); \ + /* potentially shadow things */ \ + struct log_target *osmo_log_tgt; \ + if (log_check_level(ss, LOGL_DEBUG, &osmo_log_tgt)) \ + logp(ss, __FILE__, __LINE__, 0, osmo_log_tgt, fmt, ## args); \ } while(0) #define DEBUGPC(ss, fmt, args...) \ do { \ - if (log_check_level(ss, LOGL_DEBUG)) \ - logp(ss, __FILE__, __LINE__, 1, fmt, ## args); \ + /* potentially shadow things */ \ + struct log_target *osmo_log_tgt; \ + if (log_check_level(ss, LOGL_DEBUG, &osmo_log_tgt)) \ + logp(ss, __FILE__, __LINE__, 1, osmo_log_tgt, fmt, ## args); \ } while(0) #else @@ -38,9 +46,10 @@ void osmo_vlogp(int subsys, int level, const char *file, int line, - int cont, const char *format, va_list ap); + int cont, struct log_target *initial_target, + const char *format, va_list ap); -void logp(int subsys, const char *file, int line, int cont, const char *format, ...) __attribute__ ((format (printf, 5, 6))); +void logp(int subsys, const char *file, int line, int cont, struct log_target *initial_target, const char *format, ...) __attribute__ ((format (printf, 6, 7))); /*! \brief Log a new message through the Osmocom logging framework * \param[in] ss logging subsystem (e.g. \ref DLGLOBAL) @@ -50,8 +59,10 @@ void logp(int subsys, const char *file, int line, int cont, const char *format, */ #define LOGP(ss, level, fmt, args...) \ do { \ - if (log_check_level(ss, level)) \ - logp2(ss, level, __FILE__, __LINE__, 0, fmt, ##args); \ + /* potentially shadow things */ \ + struct log_target *osmo_log_tgt; \ + if (log_check_level(ss, level, &osmo_log_tgt)) \ + logp2(ss, level, __FILE__, __LINE__, 0, osmo_log_tgt, fmt, ##args); \ } while(0) /*! \brief Continue a log message through the Osmocom logging framework @@ -62,8 +73,10 @@ void logp(int subsys, const char *file, int line, int cont, const char *format, */ #define LOGPC(ss, level, fmt, args...) \ do { \ - if (log_check_level(ss, level)) \ - logp2(ss, level, __FILE__, __LINE__, 1, fmt, ##args); \ + /* potentially shadow things */ \ + struct log_target *osmo_log_tgt; \ + if (log_check_level(ss, level, &osmo_log_tgt)) \ + logp2(ss, level, __FILE__, __LINE__, 1, osmo_log_tgt, fmt, ##args); \ } while(0) /*! \brief different log levels */ @@ -107,8 +120,6 @@ struct log_context { void *ctx[LOG_MAX_CTX+1]; }; -struct log_target; - /*! \brief Log filter function */ typedef int log_filter(const struct log_context *ctx, struct log_target *target); @@ -211,10 +222,11 @@ struct log_target { /* use the above macros */ void logp2(int subsys, unsigned int level, const char *file, - int line, int cont, const char *format, ...) - __attribute__ ((format (printf, 6, 7))); + int line, int cont, struct log_target *iniial_target, + const char *format, ...) + __attribute__ ((format (printf, 7, 8))); int log_init(const struct log_info *inf, void *talloc_ctx); -int log_check_level(int subsys, unsigned int level); +int log_check_level(int subsys, unsigned int level, struct log_target **out_tar); /* context management */ void log_reset_context(void); diff --git a/src/logging.c b/src/logging.c index c7b1999..952b52e 100644 --- a/src/logging.c +++ b/src/logging.c @@ -310,35 +310,64 @@ 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; +} - llist_for_each_entry(tar, &osmo_log_target_list, entry) { - struct log_category *category; - int output = 0; - va_list bp; +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) - continue; + category = &tar->categories[subsys]; - /* Check the global log level */ - if (tar->loglevel != 0 && level < tar->loglevel) - continue; + /* subsystem is not supposed to be logged */ + if (!category->enabled) + return 0; - /* Check the category log level */ - if (tar->loglevel == 0 && category->loglevel != 0 && - level < category->loglevel) + /* 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, struct log_target *ini_tar, const char *format, va_list ap) +{ + struct log_target *tar = ini_tar; + + subsys = map_subsys(subsys); + + + if ((tar->filter_map & LOG_FILTER_ALL) == 0 + || (osmo_log_info->filter_fn && osmo_log_info->filter_fn(&log_context, tar))) { + va_list bp; + /* 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. */ + va_copy(bp, ap); + _output(tar, subsys, level, file, line, cont, format, bp); + va_end(bp); + } + + llist_for_each_entry_continue(tar, &osmo_log_target_list, entry) { + int output = 0; + va_list bp; + + if (!check_log_to_target(tar, subsys, level)) continue; /* Apply filters here... if that becomes messy we will @@ -363,22 +392,23 @@ void osmo_vlogp(int subsys, int level, const char *file, int line, /*! \brief logging function used by DEBUGP() macro */ void logp(int subsys, const char *file, int line, int cont, - const char *format, ...) + struct log_target *ini_tar, const char *format, ...) { va_list ap; va_start(ap, format); - osmo_vlogp(subsys, LOGL_DEBUG, file, line, cont, format, ap); + osmo_vlogp(subsys, LOGL_DEBUG, file, line, cont, ini_tar, format, ap); va_end(ap); } /*! \brief logging function used by LOGP() macro */ -void logp2(int subsys, unsigned int level, const char *file, int line, int cont, const char *format, ...) +void logp2(int subsys, unsigned int level, const char *file, int line, int cont, + struct log_target *ini_tar, const char *format, ...) { va_list ap; va_start(ap, format); - osmo_vlogp(subsys, level, file, line, cont, format, ap); + osmo_vlogp(subsys, level, file, line, cont, ini_tar, format, ap); va_end(ap); } @@ -867,40 +897,26 @@ int log_init(const struct log_info *inf, void *ctx) /*! \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) +int log_check_level(int subsys, unsigned int level, struct log_target **out_tar) { 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) */ + /* HHPF: Why? */ + *out_tar = tar; return 1; } /* We are sure, that this will not be logged. */ + *out_tar = NULL; return 0; } diff --git a/tests/logging/logging_test.c b/tests/logging/logging_test.c index 3c8bac4..7d0ba6b 100644 --- a/tests/logging/logging_test.c +++ b/tests/logging/logging_test.c @@ -68,6 +68,7 @@ const struct log_info log_info = { int main(int argc, char **argv) { struct log_target *stderr_target; + struct log_target *select_target; log_init(&log_info, NULL); stderr_target = log_target_create_stderr(); @@ -78,24 +79,31 @@ 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) + if (log_check_level(DMM, LOGL_DEBUG, &select_target) != 0) fprintf(stderr, "log_check_level did not catch this case\n"); + OSMO_ASSERT(select_target == stderr_target); log_parse_category_mask(stderr_target, "DRLL:DCC"); DEBUGP(DRLL, "You should see this\n"); - OSMO_ASSERT(log_check_level(DRLL, LOGL_DEBUG) != 0); + select_target = NULL; + OSMO_ASSERT(log_check_level(DRLL, LOGL_DEBUG, &select_target) != 0); + OSMO_ASSERT(select_target == stderr_target); DEBUGP(DCC, "You should see this\n"); - OSMO_ASSERT(log_check_level(DCC, LOGL_DEBUG) != 0); + select_target = NULL; + OSMO_ASSERT(log_check_level(DCC, LOGL_DEBUG, &select_target) != 0); + OSMO_ASSERT(select_target == stderr_target); DEBUGP(DMM, "You should not see this\n"); - if (log_check_level(DMM, LOGL_DEBUG) != 0) + select_target = NULL; + if (log_check_level(DMM, LOGL_DEBUG, &select_target) != 0) fprintf(stderr, "log_check_level did not catch this case\n"); + OSMO_ASSERT(select_target == stderr_target); 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) + if (log_check_level(DRLL, LOGL_DEBUG, &select_target) != 0) fprintf(stderr, "log_check_level did not catch this case (filter)\n");