commit 73d6f22: [Minor] Add some more logging

[Vsevolod Stakhov]

Author: Vsevolod Stakhov
Date: 2022-08-18 21:18:04 +0100
URL: https://github.com/rspamd/rspamd/commit/73d6f220251222a93d834cbd555ab9f4193ef78d (HEAD -> master)

[Minor] Add some more logging

---
 src/libserver/symcache/symcache_impl.cxx | 26 +++++++++++++++++++-------
 1 file changed, 19 insertions(+), 7 deletions(-)

diff --git a/src/libserver/symcache/symcache_impl.cxx b/src/libserver/symcache/symcache_impl.cxx
index 7508cbf95..4afe0dd4f 100644
--- a/src/libserver/symcache/symcache_impl.cxx
+++ b/src/libserver/symcache/symcache_impl.cxx
@@ -1185,7 +1185,8 @@ symcache::process_settings_elt(struct rspamd_config_settings_elt *elt) -> void
 
 auto symcache::get_max_timeout() const -> double
 {
-	double accumulated_timeout = 0;
+	auto accumulated_timeout = 0.0;
+	auto log_func = RSPAMD_LOG_FUNC;
 
 	auto get_item_timeout = [](const cache_item_ptr &it) {
 		return it->get_numeric_augmentation("timeout").value_or(0.0);
@@ -1194,7 +1195,7 @@ auto symcache::get_max_timeout() const -> double
 	/* This function returns the timeout for an item and all it's dependencies */
 	auto get_filter_timeout = [&](const cache_item_ptr &it, auto self) -> double {
 		auto own_timeout = get_item_timeout(it);
-		double max_child_timeout = 0;
+		auto max_child_timeout = 0.0;
 
 		for (const auto &dep : it->deps) {
 			auto cld_timeout = self(dep.item, self);
@@ -1208,12 +1209,15 @@ auto symcache::get_max_timeout() const -> double
 	};
 
 	/* For prefilters and postfilters, we just care about priorities */
-	auto pre_postfilter_iter = [&](const items_ptr_vec &vec) {
+	auto pre_postfilter_iter = [&](const items_ptr_vec &vec) -> double {
 		auto saved_priority = -1;
-		double max_timeout = 0;
+		auto max_timeout = 0.0, added_timeout = 0.0;
 		for (const auto &it : vec) {
 			if (it->priority != saved_priority) {
 				accumulated_timeout += max_timeout;
+				added_timeout += max_timeout;
+				msg_debug_cache_lambda("added %.2f to the timeout (%.2f) as the priority has changed (%d -> %d)",
+						max_timeout, accumulated_timeout, saved_priority, it->priority);
 				max_timeout = 0;
 				saved_priority = it->priority;
 			}
@@ -1224,11 +1228,13 @@ auto symcache::get_max_timeout() const -> double
 				max_timeout = timeout;
 			}
 		}
+
+		return added_timeout;
 	};
 
-	pre_postfilter_iter(this->prefilters);
-	pre_postfilter_iter(this->postfilters);
-	pre_postfilter_iter(this->idempotent);
+	auto prefilters_timeout = pre_postfilter_iter(this->prefilters);
+	auto postfilters_timeout = pre_postfilter_iter(this->postfilters);
+	auto idempotent_timeout = pre_postfilter_iter(this->idempotent);
 
 	/* For normal filters, we check the maximum chain of the dependencies
 	 * This function might have O(N^2) complexity if all symbols are in a single
@@ -1245,6 +1251,12 @@ auto symcache::get_max_timeout() const -> double
 
 	accumulated_timeout += max_filters_timeout;
 
+	msg_debug_cache("overall cache timeout: %.2f, %.2f from prefilters,"
+					" %.2f from postfilters, %.2f from idempotent filters,"
+					" %.2f from normal filters",
+					accumulated_timeout, prefilters_timeout, postfilters_timeout,
+					idempotent_timeout, max_filters_timeout);
+
 	return accumulated_timeout;
 }