Good Morning,

during the 30C3 we had some "broken channels" because the BTS didn't respond within four seconds to a Channel Activation/Deactivation. I started to look at it with perf and "snprintf" appears to be called a lot and did show up in the top.

snprintf is mostly called from within osmo_hexdump and gsm_lchan_name. Both of these function calls are used in our logging calls throughout the code.

Going forward I think we can do

* Remove some LOGP/DEBUG with osmo_hexdump (I did so for some call sites in the osmo-bts)

* Start handlin -DNDEBUG inside logging.h and undefine/not define 'DEBUG' in logging.h. But this would take away some code paths that would be nice to look at.

* gsm_lchan_name could 'cache' the last lchan and then not call snprintf. I did this once but it didn't appear to be much help. I will have another look.

* Introduce a DEBUGQ, 'Q' for quick and check if the output would be enabled and then log. This can be useful when the cost of checking all targets twice is smaller than the cost of snprintf.

comments? holger

diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h index 1d57e22..a8476d2 100644 --- a/include/osmocom/core/logging.h +++ b/include/osmocom/core/logging.h @@ -27,6 +27,10 @@ #define DEBUGPC(ss, fmt, args...) #endif

+#define DEBUGQ(ss, fmt, args) \ + if (log_would_log(ss, LOGL_DEBUG)) \ + logp(ss, __FILE__, __LINE__, 0, fmt ## args); +

void osmo_vlogp(int subsys, int level, const char *file, int line, int cont, const char *format, va_list ap); @@ -215,6 +219,9 @@ const char *log_vty_command_description(const struct log_info *info); struct log_target *log_target_find(int type, const char *fname); extern struct llist_head osmo_log_target_list;

+/* helper to check if it would log without using filter_fn */ +int log_would_log(int subsys, unsigned int level); + /*! @} */

#endif /* _OSMOCORE_LOGGING_H */ diff --git a/src/logging.c b/src/logging.c index 2e3a80a..1e64ba5 100644 --- a/src/logging.c +++ b/src/logging.c @@ -268,6 +268,26 @@ err: target->output(target, level, buf); }

+ +static int cat_enabled(const struct log_target *tar, + const struct log_category *category, int level) +{ + /* 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; + + 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) @@ -286,17 +306,8 @@ void osmo_vlogp(int subsys, int level, const char *file, int line, 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 (!cat_enabled(tar, category, level)) continue;

/* Apply filters here... if that becomes messy we will @@ -799,4 +810,19 @@ int log_init(const struct log_info *inf, void *ctx) return 0; }

+int log_would_log(int subsys, unsigned int level) +{ + struct log_target *tar; + + llist_for_each_entry(tar, &osmo_log_target_list, entry) { + if (!cat_enabled(tar, &tar->categories[subsys], level)) + continue; + + if ((tar->filter_map & LOG_FILTER_ALL) != 0) + return 1; + } + + return 0; +} + /*! @} */