Merge branch 'sysmocom/shared/log-speed'

4 files changed, 106 insertions, 34 deletions

diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h
index 1c159d0b..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 */
@@ -198,6 +214,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..1c9c6634 100644
--- a/src/logging.c
+++ b/src/logging.c
@@ -310,46 +310,61 @@ 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)
-			continue;
+	/* 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;
+
+	/* 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;
+}
+
+/*! \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;
 
-		/* 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)
+	subsys = map_subsys(subsys);
+
+	llist_for_each_entry(tar, &osmo_log_target_list, entry) {
+		int output = 0;
+		va_list bp;
+
+		if (!check_log_to_target(tar, subsys, level))
 			continue;
 
 		/* According to the manpage, vsnprintf leaves the value of ap
@@ -865,4 +880,26 @@ 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;
+
+	subsys = map_subsys(subsys);
+
+	/* TODO: The following could/should be cached (update on config) */
+
+	llist_for_each_entry(tar, &osmo_log_target_list, entry) {
+		if (!check_log_to_target(tar, subsys, level))
+			continue;
+
+		/* This might get logged (ignoring filters) */
+		return 1;
+	}
+
+	/* We are sure, that this will not be logged. */
+	return 0;
+}
+
 /*! @} */
diff --git a/tests/logging/logging_test.c b/tests/logging/logging_test.c
index b263f905..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,17 +78,33 @@ 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");
 
 	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");
+
+	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);
+	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 b59d2e83..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
+You should see this
 
\ No newline at end of file