From 83e338fa269d9e35f0651d80aa2c4488328754c1 Mon Sep 17 00:00:00 2001 From: "Russ Combs (rucombs)" Date: Tue, 17 May 2016 08:51:09 -0400 Subject: [PATCH] Merge pull request #473 in SNORT/snort3 from ~JOCORNET/snort3:prevent_profiler_reentrance to master Squashed commit of the following: commit 82c885365cb68fb0ca4fc920176d790c55f4ef35 Author: Joel Cornett Date: Mon May 9 17:25:07 2016 -0400 fixed formatting commit f25f307aca52a7d48f27ef03740cb68e766fc746 Author: Joel Cornett Date: Mon May 9 16:09:04 2016 -0400 removed unused test case commit a86c9f19a7193375e9b029154db9e0d69d840f3b Author: Joel Cornett Date: Mon May 9 16:06:49 2016 -0400 added refcount to profiler context to prevent reentrance --- src/detection/detection_options.cc | 4 +- src/profiler/rule_profiler.cc | 12 +++++ src/profiler/rule_profiler_defs.h | 30 ++++++++++- src/profiler/time_profiler.cc | 84 ++++++++++++++---------------- src/profiler/time_profiler_defs.h | 78 +++++++++++---------------- 5 files changed, 109 insertions(+), 99 deletions(-) diff --git a/src/detection/detection_options.cc b/src/detection/detection_options.cc index 7a60d2247..04a244aff 100644 --- 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 ba6950ac2..6ba9d71d2 100644 --- 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 57e2591a3..d2aa9b469 100644 --- 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 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 5f6e9ce3d..461c0a35f 100644 --- 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 78deb2fea..372a3d607 100644 --- 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 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 sw; + bool stopped_once = false; }; class TimeExclude -- 2.47.3