Pull request #3769: profiler: add rule time percentage table field

Merge in SNORT/snort3 from ~YCHALOV/snort3:snort_rule_profiler_per to master

Squashed commit of the following:

commit abd4ea019de96d2083c46c0d898e84099a83615e
Author: Yurii Chalov <ychalov@cisco.com>
Date:   Fri Feb 17 14:27:11 2023 +0100

    profiler: add rule time percentage table field

diff --git a/src/main/modules.cc b/src/main/modules.cc
index 4589d386b3ae6fcf5fccd6d46def04360e7af536..04716ac064f4cfd72088a9423c7a89a9bffdfe45 100644 (file)
--- a/src/main/modules.cc
+++ b/src/main/modules.cc
@@ -456,6 +456,7 @@ bool ProfilerModule::end(const char*, int, SnortConfig* sc)
 {
     TimeProfilerStats::set_enabled(sc->profiler->time.show);
     RuleContext::set_enabled(sc->profiler->rule.show);
+    RuleContext::set_start_time(get_time_curr());
     return true;
 }
 

diff --git a/src/profiler/rule_profiler.cc b/src/profiler/rule_profiler.cc
index 1e32bd5a70858f67af01be31fb508c9c56c0ebd4..68c4920ceb925f70d31fe9b79505feaebce32c76 100644 (file)
--- a/src/profiler/rule_profiler.cc
+++ b/src/profiler/rule_profiler.cc
@@ -42,6 +42,8 @@
 #include "main/thread_config.h"
 #include "parser/parser.h"
 #include "target_based/snort_protocols.h"
+#include "utils/stats.h"
+#include "time/timersub.h"
 
 #include "profiler_printer.h"
 #include "profiler_stats_table.h"
@@ -56,6 +58,9 @@ using namespace snort;
 #define s_rule_table_title "rule profile"
 
 bool RuleContext::enabled = false;
+struct timeval RuleContext::start_time = {0, 0};
+struct timeval RuleContext::end_time = {0, 0};
+struct timeval RuleContext::total_time = {0, 0};
 
 static inline OtnState& operator+=(OtnState& lhs, const OtnState& rhs)
 {
@@ -85,6 +90,7 @@ static const StatsTable::Field fields[] =
     { "avg/non-match", 14, '\0', 1, std::ios_base::fmtflags() },
     { "timeouts", 9, '\0', 0, std::ios_base::fmtflags() },
     { "suspends", 9, '\0', 0, std::ios_base::fmtflags() },
+    { "rule_time (%)", 14, '\0', 5, std::ios_base::fmtflags() },
     { nullptr, 0, '\0', 0, std::ios_base::fmtflags() }
 };
 
@@ -137,6 +143,13 @@ struct View
     hr_duration avg_check() const
     { return time_per(elapsed(), checks()); }
 
+    double rule_time_per(double total_time_usec) const
+    {
+        if (total_time_usec < 1.)
+            return 100.0;
+        return clock_usecs(TO_USECS(elapsed())) / total_time_usec * 100;
+    }
+
     View(const OtnState& otn_state, const SigInfo* si = nullptr) :
         state(otn_state)
     {
@@ -223,7 +236,7 @@ static std::vector<View> build_entries()
 }
 
 // FIXIT-L logic duplicated from ProfilerPrinter
-static void print_single_entry(const View& v, unsigned n)
+static void print_single_entry(const View& v, unsigned n, double total_time_usec)
 {
     using std::chrono::duration_cast;
     using std::chrono::microseconds;
@@ -252,6 +265,7 @@ static void print_single_entry(const View& v, unsigned n)
 
         table << v.timeouts();
         table << v.suspends();
+        table << v.rule_time_per(total_time_usec);
     }
 
     LogMessage("%s", ss.str().c_str());
@@ -261,6 +275,11 @@ static void print_single_entry(const View& v, unsigned n)
 static void print_entries(std::vector<View>& entries, ProfilerSorter<View>& sort, unsigned count)
 {
     std::ostringstream ss;
+    RuleContext::set_end_time(get_time_curr());
+    RuleContext::count_total_time();
+
+    double total_time_usec =
+        RuleContext::get_total_time()->tv_sec * 1000000.0 + RuleContext::get_total_time()->tv_usec;
 
     {
         StatsTable table(fields, ss);
@@ -290,7 +309,7 @@ static void print_entries(std::vector<View>& entries, ProfilerSorter<View>& sort
         std::partial_sort(entries.begin(), entries.begin() + count, entries.end(), sort);
 
     for ( unsigned i = 0; i < count; ++i )
-        print_single_entry(entries[i], i + 1);
+        print_single_entry(entries[i], i + 1, total_time_usec);
 }
 
 }
@@ -346,6 +365,49 @@ void RuleContext::stop(bool match)
     stats.update(sw.get(), match);
 }
 
+void RuleContext::set_start_time(const struct timeval &time)
+{
+    start_time.tv_sec = time.tv_sec;
+    start_time.tv_usec = time.tv_usec;
+}
+
+void RuleContext::set_end_time(const struct timeval &time)
+{
+    end_time.tv_sec = time.tv_sec;
+    end_time.tv_usec = time.tv_usec;
+}
+
+void RuleContext::valid_start_time()
+{
+    const struct timeval &time = get_time_start();
+    if ((time.tv_sec > start_time.tv_sec ||
+        ((time.tv_sec == start_time.tv_sec) && (time.tv_usec > start_time.tv_usec))))
+    {
+        start_time.tv_sec = time.tv_sec;
+        start_time.tv_usec = time.tv_usec;
+    }
+}
+
+void RuleContext::valid_end_time()
+{
+    const struct timeval &time = get_time_end();
+    if (time.tv_sec && time.tv_usec &&
+        (time.tv_sec < end_time.tv_sec ||
+        ((time.tv_sec == end_time.tv_sec) && (time.tv_usec < end_time.tv_usec))))
+    {
+        end_time.tv_sec = time.tv_sec;
+        end_time.tv_usec = time.tv_usec;
+    }
+}
+
+void RuleContext::count_total_time()
+{
+    valid_start_time();
+    valid_end_time();
+
+    TIMERSUB(&end_time, &start_time, &total_time);
+}
+
 #ifdef UNIT_TEST
 
 namespace

diff --git a/src/profiler/rule_profiler_defs.h b/src/profiler/rule_profiler_defs.h
index 350a4a104be7123750effd94dc5def2b1ceb8981..38aef00390b39c7e4408356cdeabc171e1222bdb 100644 (file)
--- a/src/profiler/rule_profiler_defs.h
+++ b/src/profiler/rule_profiler_defs.h
@@ -68,11 +68,32 @@ public:
     static void set_enabled(bool b)
     { enabled = b; }
 
+    static const struct timeval *get_start_time()
+    { return &start_time; }
+
+    static void set_start_time(const struct timeval &time);
+
+    static const struct timeval *get_end_time()
+    { return &end_time; }
+
+    static void set_end_time(const struct timeval &time);
+
+    static const struct timeval *get_total_time()
+    { return &total_time; }
+
+    static void count_total_time();
+
 private:
     dot_node_state_t& stats;
     Stopwatch<SnortClock> sw;
     bool finished = false;
     static bool enabled;
+    static struct timeval start_time;
+    static struct timeval end_time;
+    static struct timeval total_time;
+
+    static void valid_start_time();
+    static void valid_end_time();
 };
 
 class RulePause

diff --git a/src/utils/stats.cc b/src/utils/stats.cc
index 41f6ecfc4550f4a20b3bf70de0594cf1e5b883c7..965501c1ac85fe6b99713e9ed8e587a245ec3e57 100644 (file)
--- a/src/utils/stats.cc
+++ b/src/utils/stats.cc
@@ -136,7 +136,7 @@ double CalcPct(uint64_t cnt, uint64_t total)
 
 //-------------------------------------------------------------------------
 
-static struct timeval starttime, endtime;
+static struct timeval starttime = {0, 0}, endtime = {0, 0}, currtime = {0, 0};
 
 void TimeStart()
 {
@@ -148,6 +148,22 @@ void TimeStop()
     gettimeofday(&endtime, nullptr);
 }
 
+const struct timeval& get_time_start()
+{
+    return starttime;
+}
+
+const struct timeval& get_time_end()
+{
+    return endtime;
+}
+
+const struct timeval& get_time_curr()
+{
+    gettimeofday(&currtime, nullptr);
+    return currtime;
+}
+
 static void timing_stats()
 {
     struct timeval difftime;

diff --git a/src/utils/stats.h b/src/utils/stats.h
index 8fb0dbb8b04533250ce15e272bf1c373e7a56ef8..a4a68215920f724a619bafd17bee942bf61b8d02 100644 (file)
--- a/src/utils/stats.h
+++ b/src/utils/stats.h
@@ -123,5 +123,8 @@ void DropStats(ControlConn* ctrlcon = nullptr);
 void PrintStatistics();
 void TimeStart();
 void TimeStop();
+const struct timeval& get_time_curr();
+const struct timeval& get_time_start();
+const struct timeval& get_time_end();
 
 #endif