Merge pull request #473 in SNORT/snort3 from ~JOCORNET/snort3:prevent_profiler_reentr...

Squashed commit of the following:

commit 82c885365cb68fb0ca4fc920176d790c55f4ef35
Author: Joel Cornett <joel.cornett@gmail.com>
Date:   Mon May 9 17:25:07 2016 -0400

    fixed formatting

commit f25f307aca52a7d48f27ef03740cb68e766fc746
Author: Joel Cornett <joel.cornett@gmail.com>
Date:   Mon May 9 16:09:04 2016 -0400

    removed unused test case

commit a86c9f19a7193375e9b029154db9e0d69d840f3b
Author: Joel Cornett <joel.cornett@gmail.com>
Date:   Mon May 9 16:06:49 2016 -0400

    added refcount to profiler context to prevent reentrance

diff --git a/src/detection/detection_options.cc b/src/detection/detection_options.cc
index 7a60d2247c9fb04c3c604a32ada23de71b8854b1..04a244affe4d062976fa624266a2b78207e600e0 100644 (file)
--- a/src/detection/detection_options.cc
+++ b/src/detection/detection_options.cc
@@ -443,7 +443,7 @@ int detection_option_node_evaluate(
 
             // Don't include RTN time
             {
-                TimePause profile_pause(profile);
+                RulePause pause(profile);
                 eval_rtn_result = fpEvalRTN(getRuntimeRtnFromOtn(otn), p,
                     check_ports);
             }
@@ -558,7 +558,7 @@ int detection_option_node_evaluate(
         }
 
         {
-            TimePause profile_pause(profile);
+            RulePause pause(profile);
             // Passed, check the children.
             if ( node->num_children )
             {

diff --git a/src/profiler/rule_profiler.cc b/src/profiler/rule_profiler.cc
index ba6950ac2ba9662eb9918f8bde485ce8c4a669b3..6ba9d71d28d00f82fb3087b6d0eca2f6c46317c2 100644 (file)
--- a/src/profiler/rule_profiler.cc
+++ b/src/profiler/rule_profiler.cc
@@ -736,5 +736,17 @@ TEST_CASE( "rule profiler time context", "[profiler][rule_profiler]" )
     }
 }
 
+TEST_CASE( "rule pause", "[profiler][rule_profiler]" )
+{
+    dot_node_state_t stats;
+    RuleContext ctx(stats);
+
+    {
+        RulePause pause(ctx);
+        CHECK_FALSE( ctx.active() );
+    }
+
+    CHECK( ctx.active() );
+}
 
 #endif

diff --git a/src/profiler/rule_profiler_defs.h b/src/profiler/rule_profiler_defs.h
index 57e2591a3eac544c1db52044e626c19c2413b7d9..d2aa9b469b718834a99a14eb1a56cd82b708d2d9 100644 (file)
--- a/src/profiler/rule_profiler_defs.h
+++ b/src/profiler/rule_profiler_defs.h
@@ -44,19 +44,45 @@ struct RuleProfilerConfig
     unsigned count = 0;
 };
 
-class RuleContext : public TimeContextBase
+class RuleContext
 {
 public:
     RuleContext(dot_node_state_t& stats) :
-        TimeContextBase(), stats(stats) { }
+        stats(stats)
+    { start(); }
 
     ~RuleContext()
     { stop(); }
 
+    void start()
+    { sw.start(); }
+
+    void pause()
+    { sw.stop(); }
+
     void stop(bool = false);
 
+    bool active() const
+    { return sw.active(); }
+
 private:
     dot_node_state_t& stats;
+    Stopwatch<hr_clock> sw;
+    bool finished = false;
+};
+
+class RulePause
+{
+public:
+    RulePause(RuleContext& ctx) :
+        ctx(ctx)
+    { ctx.pause(); }
+
+    ~RulePause()
+    { ctx.start(); }
+
+private:
+    RuleContext& ctx;
 };
 
 #endif

diff --git a/src/profiler/time_profiler.cc b/src/profiler/time_profiler.cc
index 5f6e9ce3d08f6e68baa7ac05355b5bcd4018b2eb..461c0a35fd1bc06755662687768a4b1a1757184d 100644 (file)
--- a/src/profiler/time_profiler.cc
+++ b/src/profiler/time_profiler.cc
@@ -48,8 +48,8 @@ static const StatsTable::Field fields[] =
     { "#", 5, ' ', 0, std::ios_base::left },
     { "module", 24, ' ', 0, std::ios_base::fmtflags() },
     { "layer", 6, ' ', 0, std::ios_base::fmtflags() },
-    { "checks", 7, ' ', 0, std::ios_base::fmtflags() },
-    { "time (us)", 10, ' ', 0, std::ios_base::fmtflags() },
+    { "checks", 10, ' ', 0, std::ios_base::fmtflags() },
+    { "time(us)", 11, ' ', 0, std::ios_base::fmtflags() },
     { "avg/check", 11, ' ', 1, std::ios_base::fmtflags() },
     { "%/caller", 10, ' ', 2, std::ios_base::fmtflags() },
     { "%/total", 9, ' ', 2, std::ios_base::fmtflags() },
@@ -465,79 +465,71 @@ TEST_CASE( "time profiler sorting", "[profiler][time_profiler]" )
     }
 }
 
-TEST_CASE( "time profiler time context base", "[profiler][time_profiler]" )
-{
-    TimeContextBase ctx;
-
-    SECTION( "start called on instantiation" )
-    {
-        CHECK( ctx.active() );
-    }
-
-    SECTION( "time can be started and paused and restarted" )
-    {
-        REQUIRE( ctx.active() );
-
-        ctx.pause();
-        CHECK_FALSE( ctx.active() );
-
-        ctx.start();
-        CHECK( ctx.active() );
-    }
-}
-
 TEST_CASE( "time profiler time context", "[profiler][time_profiler]" )
 {
     TimeProfilerStats stats;
     REQUIRE_FALSE( stats );
 
-    SECTION( "automatically updates stats" )
+    SECTION( "lifetime" )
     {
         {
             TimeContext ctx(stats);
-            avoid_optimization();
+            CHECK( ctx.active() );
+            CHECK( stats.ref_count == 1 );
         }
 
-        INFO( "elapsed: " << stats.elapsed.count() );
-        CHECK( stats.elapsed > 0_ticks );
-        CHECK( stats.checks == 1 );
+        CHECK( stats.ref_count == 0 );
     }
 
-    SECTION( "explicitly calling stop updates stats ONCE" )
+    SECTION( "manually managed lifetime" )
     {
-        TimeProfilerStats save;
-
         {
             TimeContext ctx(stats);
-            avoid_optimization();
+            CHECK( ctx.active() );
+            CHECK( stats.ref_count == 1 );
             ctx.stop();
-
-            INFO( "elapsed: " << stats.elapsed.count() );
-            CHECK( stats.elapsed > 0_ticks );
-            CHECK( stats.checks == 1 );
-            save = stats;
+            CHECK_FALSE( ctx.active() );
+            CHECK( stats.ref_count == 0 );
         }
 
-        CHECK( stats == save );
+        CHECK( stats.ref_count == 0 );
     }
-}
-
-TEST_CASE( "time pause", "[profiler][time_profiler]" )
-{
-    TimeContextBase ctx;
 
+    SECTION( "updates stats" )
     {
-        TimePause pause(ctx);
-        CHECK_FALSE( ctx.active() );
+        TimeContext ctx(stats);
+        avoid_optimization();
+        ctx.stop();
+
+        CHECK( stats );
     }
 
-    CHECK( ctx.active() );
+    SECTION( "reentrance" )
+    {
+        {
+            TimeContext ctx1(stats);
+
+            CHECK( stats.ref_count == 1 );
+
+            {
+                TimeContext ctx2(stats);
+
+                CHECK( stats.ref_count == 2 );
+            }
+
+            CHECK( stats.ref_count == 1 );
+        }
+
+        CHECK( stats.ref_count == 0 ); // ref_count restored
+        CHECK( stats.checks == 1 ); // only updated once
+    }
 }
 
 TEST_CASE( "time context exclude", "[profiler][time_profiler]" )
 {
     // NOTE: this test *may* fail if the time it takes to execute the exclude context is 0_ticks (unlikely)
     TimeProfilerStats stats = { hr_duration::max(), 0 };
+
     {
         TimeExclude exclude(stats);
         avoid_optimization();

diff --git a/src/profiler/time_profiler_defs.h b/src/profiler/time_profiler_defs.h
index 78deb2feab7f5147b7a5f4739eeb942f44333654..372a3d60709e748cd65125197c3fb5e0dbab4915 100644 (file)
--- a/src/profiler/time_profiler_defs.h
+++ b/src/profiler/time_profiler_defs.h
@@ -44,6 +44,7 @@ struct SO_PUBLIC TimeProfilerStats
 {
     hr_duration elapsed;
     uint64_t checks;
+    mutable unsigned int ref_count;
 
     void update(hr_duration delta)
     { elapsed += delta; ++checks; }
@@ -54,11 +55,18 @@ struct SO_PUBLIC TimeProfilerStats
     operator bool() const
     { return ( elapsed > 0_ticks ) || checks; }
 
+    // reentrancy control
+    bool enter() const { return ref_count++ == 0; }
+    bool exit() const { return --ref_count == 0; }
+
     constexpr TimeProfilerStats() :
-        elapsed(0_ticks), checks(0) { }
+        TimeProfilerStats(0_ticks, 0, 0) { }
 
     constexpr TimeProfilerStats(hr_duration elapsed, uint64_t checks) :
-        elapsed(elapsed), checks(checks) { }
+        TimeProfilerStats(elapsed, checks, 0) { }
+
+    constexpr TimeProfilerStats(hr_duration elapsed, uint64_t checks, unsigned int ref_count) :
+        elapsed(elapsed), checks(checks), ref_count(ref_count) { }
 };
 
 inline bool operator==(const TimeProfilerStats& lhs, const TimeProfilerStats& rhs)
@@ -74,67 +82,39 @@ inline TimeProfilerStats& operator+=(TimeProfilerStats& lhs, const TimeProfilerS
     return lhs;
 }
 
-class TimeContextBase
-{
-public:
-    TimeContextBase() :
-        finished(false)
-    { start(); }
-
-    TimeContextBase(const TimeContextBase&) = delete;
-    TimeContextBase& operator=(const TimeContextBase&) = delete;
-
-    void start()
-    { sw.start(); }
-
-    void pause()
-    { sw.stop(); }
-
-    bool active() const
-    { return sw.active(); }
-
-protected:
-    Stopwatch<hr_clock> sw;
-    bool finished;
-};
-
-class TimeContext : public TimeContextBase
+class TimeContext
 {
 public:
     TimeContext(TimeProfilerStats& stats) :
-        TimeContextBase(), stats(stats) { }
+        stats(stats)
+    {
+        if ( stats.enter() )
+            sw.start();
+    }
 
     ~TimeContext()
     { stop(); }
 
+    // Use this for finer grained control of the TimeContext "lifetime"
     void stop()
     {
-        if ( finished )
-            return;
+        if ( stopped_once )
+            return; // stop() should only be executed once per context
 
-        finished = true;
-        stats.update(sw.get());
-    }
+        stopped_once = true;
 
-private:
-    TimeProfilerStats& stats;
-};
-
-class TimePause
-{
-public:
-    TimePause(TimeContextBase& ctx) :
-        ctx(ctx)
-    { ctx.pause(); }
-
-    TimePause(const TimePause&) = delete;
-    TimePause& operator=(const TimePause&) = delete;
+        // don't bother updating time if context is reentrant
+        if ( stats.exit() )
+            stats.update(sw.get());
+    }
 
-    ~TimePause()
-    { ctx.start(); }
+    bool active() const
+    { return !stopped_once; }
 
 private:
-    TimeContextBase& ctx;
+    TimeProfilerStats& stats;
+    Stopwatch<hr_clock> sw;
+    bool stopped_once = false;
 };
 
 class TimeExclude