[Feature] Report slow synchronous rules

3 files changed, 32 insertions, 13 deletions

diff --git a/src/libserver/symcache/symcache_c.cxx b/src/libserver/symcache/symcache_c.cxx
index 3214aab2e..b7514d2f3 100644
--- a/src/libserver/symcache/symcache_c.cxx
+++ b/src/libserver/symcache/symcache_c.cxx
@@ -602,8 +602,14 @@ unsigned int rspamd_symcache_item_async_inc_full(struct rspamd_task *task,
 						 "subsystem %s (%s)",
 						 static_item->symbol.c_str(), static_item->id,
 						 real_dyn_item->async_events, subsystem, loc);
+	auto nevents = ++real_dyn_item->async_events;
 
-	return ++real_dyn_item->async_events;
+	if (nevents > 1) {
+		/* Item is async */
+		static_item->internal_flags &= ~rspamd::symcache::cache_item::bit_sync;
+	}
+
+	return nevents;
 }
 
 unsigned int rspamd_symcache_item_async_dec_full(struct rspamd_task *task,
diff --git a/src/libserver/symcache/symcache_item.hxx b/src/libserver/symcache/symcache_item.hxx
index 5f4056e4b..8ed973a82 100644
--- a/src/libserver/symcache/symcache_item.hxx
+++ b/src/libserver/symcache/symcache_item.hxx
@@ -225,7 +225,7 @@ struct cache_item : std::enable_shared_from_this<cache_item> {
 	static constexpr const auto bit_enabled = 0b0001;
 	static constexpr const auto bit_sync = 0b0010;
 	static constexpr const auto bit_slow = 0b0100;
-	int internal_flags = bit_enabled;
+	int internal_flags = bit_enabled | bit_sync;
 
 	/* Priority */
 	int priority = 0;
diff --git a/src/libserver/symcache/symcache_runtime.cxx b/src/libserver/symcache/symcache_runtime.cxx
index 148346cb5..8b341d6e0 100644
--- a/src/libserver/symcache/symcache_runtime.cxx
+++ b/src/libserver/symcache/symcache_runtime.cxx
@@ -771,7 +771,8 @@ auto symcache_runtime::finalize_item(struct rspamd_task *task, cache_dynamic_ite
 		return true;
 	};
 
-	if (profile) {
+	/* Check if we need to profile symbol (always profile when we have seen this item to be slow */
+	if (profile || item->flags & cache_item::bit_slow) {
 		ev_now_update_if_cheap(task->event_loop);
 		auto diff = ((ev_now(task->event_loop) - profile_start) * 1e3 -
 					 dyn_item->start_msec);
@@ -786,22 +787,34 @@ auto symcache_runtime::finalize_item(struct rspamd_task *task, cache_dynamic_ite
 
 		if (diff > slow_diff_limit) {
 
-			if (slow_status == slow_status::none) {
-				slow_status = slow_status::enabled;
+			item->internal_flags |= cache_item::bit_slow;
 
-				msg_info_task("slow rule: %s(%d): %.2f ms; enable 100ms idle timer to allow other rules to be finished",
-							  item->symbol.c_str(), item->id,
-							  diff);
-				if (enable_slow_timer()) {
-					return;
+			if (!(item->internal_flags & cache_item::bit_sync)) {
+				if (slow_status == slow_status::none) {
+					slow_status = slow_status::enabled;
+
+					msg_info_task("slow rule: %s(%d): %.2f ms; enable 100ms idle timer to allow other rules to be finished",
+								  item->symbol.c_str(), item->id,
+								  diff);
+					if (enable_slow_timer()) {
+						return;
+					}
+				}
+				else {
+					msg_info_task("slow rule: %s(%d): %.2f ms; idle timer has already been activated for this scan",
+								  item->symbol.c_str(), item->id,
+								  diff);
 				}
 			}
 			else {
-				msg_info_task("slow rule: %s(%d): %.2f ms; idle timer has already been activated for this scan",
-							  item->symbol.c_str(), item->id,
-							  diff);
+				msg_notice_task("slow synchronous rule: %s(%d): %.2f ms; no idle timer is needed",
+								item->symbol.c_str(), item->id,
+								diff);
 			}
 		}
+		else {
+			item->internal_flags &= ~cache_item::bit_slow;
+		}
 	}
 
 	process_item_rdeps(task, item);