logging: add log level cache

This ensures multithreaded logging attempts, in particular ones that do
nothing, do not hold the lock just for checking the level, which
interferes with other logging attempts.

Closes: OS#5818

Change-Id: I35f8dd9127dd6e7feae392094fd6b3ce2d32558d

5 files changed, 123 insertions, 2 deletions

diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h
index e8433a14..e4859cd8 100644
--- a/include/osmocom/core/logging.h
+++ b/include/osmocom/core/logging.h
@@ -409,7 +409,7 @@ int log_set_context(uint8_t ctx, void *value);
 
 /* filter on the targets */
 void log_set_all_filter(struct log_target *target, int);
-
+void log_cache_update(int mapped_subsys, uint8_t enabled, uint8_t level);
 void log_set_use_color(struct log_target *target, int);
 void log_set_print_extended_timestamp(struct log_target *target, int);
 void log_set_print_timestamp(struct log_target *target, int);
diff --git a/src/core/libosmocore.map b/src/core/libosmocore.map
index b66e37d6..06a3864c 100644
--- a/src/core/libosmocore.map
+++ b/src/core/libosmocore.map
@@ -58,6 +58,7 @@ gsmtap_type_names;
 log_add_target;
 log_category_name;
 log_check_level;
+log_cache_update;
 log_del_target;
 log_enable_multithread;
 log_fini;
diff --git a/src/core/logging.c b/src/core/logging.c
index 6941f9bf..906d6641 100644
--- a/src/core/logging.c
+++ b/src/core/logging.c
@@ -93,6 +93,68 @@ LLIST_HEAD(osmo_log_target_list);
 static __thread long int logging_tid;
 
 #if (!EMBEDDED)
+/*! One global copy that contains the union of log levels for all targets
+*  for all categories, used for quick lock free checks of log targets. */
+static volatile uint8_t *log_level_lookup_cache;
+
+/*! Updates cache for all targets for all categies, caller must hold osmo_log_tgt_mutex. */
+static void log_cache_update_all(void)
+{
+	struct log_target *tgt;
+	uint8_t tmp_en[osmo_log_info->num_cat];
+	uint8_t tmp_level[osmo_log_info->num_cat];
+	memset(tmp_en, 0, osmo_log_info->num_cat);
+	memset(tmp_level, UINT8_MAX, osmo_log_info->num_cat);
+
+	/* values can also decrease.. */
+	llist_for_each_entry(tgt, &osmo_log_target_list, entry) {
+		for (int i = 0; i < osmo_log_info->num_cat; i++) {
+			struct log_category *cat = &tgt->categories[i];
+			tmp_en[i] = OSMO_MAX(tmp_en[i], cat->enabled);
+			tmp_level[i] = OSMO_MIN(tmp_level[i], cat->loglevel);
+			tmp_level[i] = tgt->loglevel ? OSMO_MIN(tmp_level[i], tgt->loglevel) : tmp_level[i];
+		}
+	}
+
+	for (int i = 0; i < osmo_log_info->num_cat; i++)
+		log_level_lookup_cache[i] = tmp_en[i] ? tmp_level[i] : UINT8_MAX;
+}
+
+/*! Updates single cache entry, caller must hold osmo_log_tgt_mutex.
+ *
+ *  \param[in] mapped_subsys plain category index (after mapping)
+ *  \param[in] enabled log category enabled?
+ *  \param[in] level log level
+ */
+void log_cache_update(int mapped_subsys, uint8_t enabled, uint8_t level)
+{
+	struct log_target *tgt;
+	struct log_category tmp = { UINT8_MAX, 0 };
+
+	/* values can also decrease.. */
+	llist_for_each_entry(tgt, &osmo_log_target_list, entry) {
+		struct log_category *cat = &tgt->categories[mapped_subsys];
+		tmp.enabled = OSMO_MAX(tmp.enabled, cat->enabled);
+		tmp.loglevel = OSMO_MIN(tmp.loglevel, cat->loglevel);
+		tmp.loglevel = tgt->loglevel ? OSMO_MIN(tmp.loglevel, tgt->loglevel) : tmp.loglevel;
+	}
+	tmp.enabled = OSMO_MAX(tmp.enabled, enabled);
+	tmp.loglevel = OSMO_MIN(tmp.loglevel, level);
+
+	log_level_lookup_cache[mapped_subsys] = tmp.enabled ? tmp.loglevel : UINT8_MAX;
+}
+
+/*! Queries log level cache.
+ *
+ *  \param[in] mapped_subsys plain category index (after mapping)
+ *  \param[in] level log level
+ *  \returns true if logging should happen for at least one log target
+*/
+static bool log_cache_check(int mapped_subsys, int level)
+{
+	return (level < log_level_lookup_cache[mapped_subsys]) ? false : true;
+}
+
 /*! This mutex must be held while using osmo_log_target_list or any of its
   log_targets in a multithread program. Prevents race conditions between threads
   like producing unordered timestamps or VTY deleting a target while another
@@ -426,6 +488,10 @@ void log_parse_category_mask(struct log_target* target, const char *_mask)
 		}
 	} while ((category_token = strtok(NULL, ":")));
 
+#if !defined(EMBEDDED)
+	log_cache_update_all();
+#endif
+
 	free(mask);
 }
 
@@ -680,6 +746,11 @@ void osmo_vlogp(int subsys, int level, const char *file, int line,
 
 	subsys = map_subsys(subsys);
 
+#if !defined(EMBEDDED)
+	if (!log_cache_check(subsys, level))
+		return;
+#endif
+
 	log_tgt_mutex_lock();
 
 	llist_for_each_entry(tar, &osmo_log_target_list, entry) {
@@ -754,6 +825,9 @@ void logp_stub(const char *file, int line, int cont, const char *format, ...)
 void log_add_target(struct log_target *target)
 {
 	llist_add_tail(&target->entry, &osmo_log_target_list);
+#if (!EMBEDDED)
+	log_cache_update_all();
+#endif
 }
 
 /*! Unregister a log target from the logging core
@@ -762,6 +836,9 @@ void log_add_target(struct log_target *target)
 void log_del_target(struct log_target *target)
 {
 	llist_del(&target->entry);
+#if (!EMBEDDED)
+	log_cache_update_all();
+#endif
 }
 
 /*! Reset (clear) the logging context */
@@ -922,6 +999,9 @@ void log_set_print_level(struct log_target *target, int print_level)
 void log_set_log_level(struct log_target *target, int log_level)
 {
 	target->loglevel = log_level;
+#if !defined(EMBEDDED)
+	log_cache_update_all();
+#endif
 }
 
 /*! Set a category filter on a given log target
@@ -938,6 +1018,10 @@ void log_set_category_filter(struct log_target *target, int category,
 	category = map_subsys(category);
 	target->categories[category].enabled = !!enable;
 	target->categories[category].loglevel = level;
+
+#if !defined(EMBEDDED)
+	log_cache_update(category, !!enable, level);
+#endif
 }
 
 #if (!EMBEDDED)
@@ -1046,6 +1130,15 @@ struct log_target *log_target_create(void)
 
 	/* global log level */
 	target->loglevel = 0;
+
+#if !defined(EMBEDDED)
+	/* update cache */
+	for (i = 0; i < osmo_log_info->num_cat; i++) {
+		const struct log_info_cat *c = &osmo_log_info->cat[i];
+		log_cache_update(i, c->enabled, c->loglevel);
+	}
+#endif
+
 	return target;
 }
 
@@ -1424,6 +1517,15 @@ int log_init(const struct log_info *inf, void *ctx)
 		osmo_log_info->num_cat += inf->num_cat;
 	}
 
+#if !defined(EMBEDDED)
+	log_level_lookup_cache = talloc_zero_array(osmo_log_info, uint8_t, osmo_log_info->num_cat);
+	if (!log_level_lookup_cache) {
+		talloc_free(osmo_log_info);
+		osmo_log_info = NULL;
+		return -ENOMEM;
+	}
+#endif
+
 	cat_ptr = talloc_zero_array(osmo_log_info, struct log_info_cat,
 				    osmo_log_info->num_cat);
 	if (!cat_ptr) {
@@ -1454,6 +1556,12 @@ int log_init(const struct log_info *inf, void *ctx)
 
 	osmo_log_info->cat = cat_ptr;
 
+#if !defined(EMBEDDED)
+	/* copy everything for level lookup cache */
+	for (i = 0; i < osmo_log_info->num_cat; i++)
+		log_level_lookup_cache[i] = cat_ptr[i].loglevel;
+#endif
+
 	return 0;
 }
 
@@ -1486,6 +1594,11 @@ int log_check_level(int subsys, unsigned int level)
 
 	subsys = map_subsys(subsys);
 
+#if !defined(EMBEDDED)
+	if (!log_cache_check(subsys, level))
+		return 0;
+#endif
+
 	/* TODO: The following could/should be cached (update on config) */
 
 	log_tgt_mutex_lock();
diff --git a/src/vty/logging_vty.c b/src/vty/logging_vty.c
index 2a074222..678ae686 100644
--- a/src/vty/logging_vty.c
+++ b/src/vty/logging_vty.c
@@ -382,6 +382,10 @@ DEFUN(logging_level,
 	tgt->categories[category].enabled = 1;
 	tgt->categories[category].loglevel = level;
 
+#if !defined(EMBEDDED)
+	log_cache_update(category, 1, level);
+#endif
+
 	RET_WITH_UNLOCK(CMD_SUCCESS);
 }
 
@@ -406,6 +410,9 @@ DEFUN(logging_level_set_all, logging_level_set_all_cmd,
 
 		cat->enabled = 1;
 		cat->loglevel = level;
+#if !defined(EMBEDDED)
+		log_cache_update(i, 1, level);
+#endif
 	}
 	RET_WITH_UNLOCK(CMD_SUCCESS);
 }
diff --git a/tests/ctrl/ctrl_test.c b/tests/ctrl/ctrl_test.c
index 1d4d4d74..7b7e6cec 100644
--- a/tests/ctrl/ctrl_test.c
+++ b/tests/ctrl/ctrl_test.c
@@ -482,7 +482,7 @@ int main(int argc, char **argv)
 	test_deferred_cmd();
 
 	/* Expecting root ctx + msgb root ctx + 5 logging elements */
-	if (talloc_total_blocks(ctx) != 7) {
+	if (talloc_total_blocks(ctx) != 8) {
 		talloc_report_full(ctx, stdout);
 		OSMO_ASSERT(false);
 	}