Attention is currently required from: fixeria, laforge.
Hello Jenkins Builder, laforge, fixeria,
I'd like you to do a code review. Please visit
https://gerrit.osmocom.org/c/libosmocore/+/35525?usp=email
to review the following change.
Change subject: Revert "Revert "logging: add log level cache"" ......................................................................
Revert "Revert "logging: add log level cache""
This reverts commit 7f1fb3ea817578f3f2f63e8065aa50f8355caa3b.
Reason for revert: some fallout expected due to log manipulation in test code
Change-Id: I539872fc9e3c50b407e6bc388f1e091fa2c826c3 --- M include/osmocom/core/logging.h M src/core/libosmocore.map M src/core/logging.c M src/vty/logging_vty.c M tests/ctrl/ctrl_test.c 5 files changed, 136 insertions(+), 2 deletions(-)
git pull ssh://gerrit.osmocom.org:29418/libosmocore refs/changes/25/35525/1
diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h index e8433a1..e4859cd 100644 --- a/include/osmocom/core/logging.h +++ b/include/osmocom/core/logging.h @@ -409,7 +409,7 @@
/* 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 b66e37d..06a3864 100644 --- a/src/core/libosmocore.map +++ b/src/core/libosmocore.map @@ -58,6 +58,7 @@ 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 6941f9b..906d664 100644 --- a/src/core/logging.c +++ b/src/core/logging.c @@ -93,6 +93,68 @@ 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 @@ } } while ((category_token = strtok(NULL, ":")));
+#if !defined(EMBEDDED) + log_cache_update_all(); +#endif + free(mask); }
@@ -680,6 +746,11 @@
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 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_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_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 @@ 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 @@
/* 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 @@ 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 @@
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 @@
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 2a07422..678ae68 100644 --- a/src/vty/logging_vty.c +++ b/src/vty/logging_vty.c @@ -382,6 +382,10 @@ 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 @@
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 1d4d4d7..7b7e6ce 100644 --- a/tests/ctrl/ctrl_test.c +++ b/tests/ctrl/ctrl_test.c @@ -482,7 +482,7 @@ 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); }