[Feature] Report slow synchronous rules

diff --git a/src/libserver/symcache/symcache_c.cxx b/src/libserver/symcache/symcache_c.cxx
index 3214aab2e4c2b86ecae51054b8970db2ddfbdb69..b7514d2f36f30fd1a016166efb10d560c5329b9c 100644 (file)
--- 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 5f4056e4b6a00f8eb57bf747dedbbeff7de8cb05..8ed973a8275af0b16caec36863773a880c342287 100644 (file)
--- 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 148346cb550908898cd2661872bd1f7e72f4cc0f..8b341d6e04e260ab8ac2dee8edfbd9ac370353d4 100644 (file)
--- 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);