From: Russ Combs (rucombs) Date: Tue, 1 Dec 2015 17:47:09 +0000 (-0500) Subject: Merge pull request #160 in SNORT/snort3 from ~JOCORNET/snort3:profiler to master X-Git-Tag: 3.0.0-233~705 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=ec807d19677bf1782413e69e6836cd53075d0cbb;p=thirdparty%2Fsnort3.git Merge pull request #160 in SNORT/snort3 from ~JOCORNET/snort3:profiler to master Squashed commit of the following: commit 9ce1ed19de6e852ced185e39a6ae4d3dfec3fb75 Author: Joel Cornett Date: Tue Dec 1 11:19:29 2015 -0500 updated per review comments, bug fixes fixed copyright header fixed bug in copy construction of profiler nodes, added profiler tree unit tests updated help, default sorting method, and default conf commit 7ff00e9fd1e723be9dd80914e299ac240582c393 Author: Joel Cornett Date: Mon Nov 30 13:43:20 2015 -0500 updated snort2lua and profiler dev_notes and extras updated snort2lua with profiler config changes update profiler dev_notes fix profiler.h includes updated extras to work with profiler fixed gcc-5 includes commit 81064668e36200d359cd7c78551a0aad5e60b126 Author: Joel Cornett Date: Mon Nov 30 12:00:21 2015 -0500 fixed gcc build fixed gcc error with std::ios_base::fmtflags added include for std::partial_sort to fix gcc error fixed gcc warning in unit test comment commit 64fbe752c34d0aa92555dc73f4b229e48aa1f0cb Author: Joel Cornett Date: Mon Nov 30 11:31:46 2015 -0500 added copyright headers to files commit 8a3df7a7a681669154f374383e4197e5918bbc08 Author: Joel Cornett Date: Fri Nov 27 17:31:32 2015 -0500 addressed FIXITs, failing unit tests, bugs, added show config option added show (bool) config option to profiler fixed formatting fixed failing unit tests addressed FIXITs commit 7f120f843ff90d0284bfb409d369f4bc69e9f756 Author: Joel Cornett Date: Fri Nov 27 16:21:51 2015 -0500 expanded PERF_PROFILE_* macros commit b3a1602f50336ef64ee9c9d1f9b51636a5bc3137 Author: Joel Cornett Date: Fri Nov 27 15:37:31 2015 -0500 added profiler stats table commit 73701935dc7dc4ff55f82a6baa87c41ca35339a4 Author: Joel Cornett Date: Wed Nov 25 16:20:34 2015 -0500 improved stats outputting factored out entry builder suppressed printing of stats when theres nothing to print commit d3834c874428a18f26b932b833f982e012397259 Author: Joel Cornett Date: Wed Nov 18 22:50:40 2015 -0500 restructured profiler in prep for memory moved total & meta perf stats to snort.cc unit tests moved stopwatch unit test to time/ refactored time context fixed profiler counts printout fixed error in dnp3 due to change of profilestats struct --- diff --git a/extra/src/inspectors/data_log.cc b/extra/src/inspectors/data_log.cc index 49f498630..be370bc93 100644 --- a/extra/src/inspectors/data_log.cc +++ b/extra/src/inspectors/data_log.cc @@ -35,7 +35,7 @@ #include "log/messages.h" #include "log/text_log.h" #include "protocols/packet.h" -#include "time/profiler.h" +#include "profiler/profiler.h" #include "utils/stats.h" #include "flow/flow.h" #include "sfip/sfip_t.h" diff --git a/extra/src/inspectors/dpx.cc b/extra/src/inspectors/dpx.cc index e4788fcf0..4ccd7cd0c 100644 --- a/extra/src/inspectors/dpx.cc +++ b/extra/src/inspectors/dpx.cc @@ -34,7 +34,7 @@ #include "framework/module.h" #include "log/messages.h" #include "protocols/packet.h" -#include "time/profiler.h" +#include "profiler/profiler.h" #include "utils/stats.h" #define DPX_GID 256 diff --git a/extra/src/ips_options/ips_pkt_num.cc b/extra/src/ips_options/ips_pkt_num.cc index af9d64695..175021d6c 100644 --- a/extra/src/ips_options/ips_pkt_num.cc +++ b/extra/src/ips_options/ips_pkt_num.cc @@ -37,7 +37,7 @@ #include "hash/sfhashfcn.h" #include "protocols/packet.h" #include "protocols/tcp.h" -#include "time/profiler.h" +#include "profiler/profiler.h" #include "utils/stats.h" static const char* s_name = "pkt_num"; @@ -89,7 +89,7 @@ bool PktNumOption::operator==(const IpsOption& ips) const int PktNumOption::eval(Cursor&, Packet*) { - PERF_PROFILE(pkt_num_perf_stats); + ProfileContext profile(pkt_num_perf_stats); int rval; diff --git a/extra/src/ips_options/ips_urg.cc b/extra/src/ips_options/ips_urg.cc index 485c0b65b..630cd0493 100644 --- a/extra/src/ips_options/ips_urg.cc +++ b/extra/src/ips_options/ips_urg.cc @@ -37,7 +37,7 @@ #include "hash/sfhashfcn.h" #include "protocols/packet.h" #include "protocols/tcp.h" -#include "time/profiler.h" +#include "profiler/profiler.h" static const char* s_name = "urg"; static const char* s_help = "detection for TCP urgent pointer"; @@ -88,7 +88,7 @@ bool TcpUrgOption::operator==(const IpsOption& ips) const int TcpUrgOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(tcpUrgPerfStats); + Profile profile(tcpUrgPerfStats); int rval = DETECTION_OPTION_NO_MATCH; diff --git a/extra/src/search_engines/lowmem.cc b/extra/src/search_engines/lowmem.cc index 68310984c..5db98fa0f 100644 --- a/extra/src/search_engines/lowmem.cc +++ b/extra/src/search_engines/lowmem.cc @@ -37,7 +37,7 @@ #include "main/snort_types.h" #include "log/messages.h" #include "framework/mpse.h" -#include "time/profiler.h" +#include "profiler/profiler.h" //------------------------------------------------------------------------- // "lowmem" diff --git a/extra/src/search_engines/lowmem_q.cc b/extra/src/search_engines/lowmem_q.cc index 156712362..048da6ba7 100644 --- a/extra/src/search_engines/lowmem_q.cc +++ b/extra/src/search_engines/lowmem_q.cc @@ -40,7 +40,7 @@ #include "framework/mpse.h" #include "framework/module.h" #include "log/messages.h" -#include "time/profiler.h" +#include "profiler/profiler.h" using namespace std; diff --git a/lua/snort.lua b/lua/snort.lua index 45aa52a98..7e31ede4c 100644 --- a/lua/snort.lua +++ b/lua/snort.lua @@ -51,12 +51,11 @@ dofile(conf_dir .. '/file_magic.lua') -- uncomment ppm if you built with --enable-ppm --ppm = { } --- uncomment profile if you built with --enable-perfprofile ---profile = { } - -- uncomment normalizer if you are inline or not --pedantic --normalizer = { } +profiler = { } + stream = { } stream_ip = { } stream_icmp = { } diff --git a/src/actions/act_react.cc b/src/actions/act_react.cc index 69d0fb2c3..4c1ef63b7 100644 --- a/src/actions/act_react.cc +++ b/src/actions/act_react.cc @@ -141,7 +141,7 @@ ReactAction::~ReactAction() void ReactAction::exec(Packet* p) { - PERF_PROFILE(reactPerfStats); + Profile profile(reactPerfStats); if ( Active::is_reset_candidate(p) ) send(p); diff --git a/src/actions/act_reject.cc b/src/actions/act_reject.cc index 33eb4e4cf..4384cc433 100644 --- a/src/actions/act_reject.cc +++ b/src/actions/act_reject.cc @@ -95,7 +95,7 @@ private: void RejectAction::exec(Packet* p) { - PERF_PROFILE(rejPerfStats); + Profile profile(rejPerfStats); send(p); } diff --git a/src/detection/detect.cc b/src/detection/detect.cc index dc0bb6562..ed6f14034 100644 --- a/src/detection/detect.cc +++ b/src/detection/detect.cc @@ -194,7 +194,7 @@ void snort_inspect(Packet* p) } #endif - PERF_PROFILE(eventqPerfStats); + Profile profile(eventqPerfStats); SnortEventqLog(p); SnortEventqReset(); } @@ -356,7 +356,7 @@ bool snort_detect(Packet* p) ** This is where we short circuit so ** that we can do IP checks. */ - PERF_PROFILE(detectPerfStats); + Profile profile(detectPerfStats); return fpEvalPacket(p); } diff --git a/src/detection/detection_options.cc b/src/detection/detection_options.cc index 1ec96a815..2a7a237b9 100644 --- a/src/detection/detection_options.cc +++ b/src/detection/detection_options.cc @@ -385,10 +385,8 @@ int detection_option_node_evaluate( if ( !node ) return 0; - dot_node_state_t* state = node->state + get_instance_id(); - - auto& node_stats = *state; - NODE_PERF_PROFILE(node_stats); + auto& state = node->state[get_instance_id()]; + RuleContext profile(state); int result = 0; int rval = DETECTION_OPTION_NO_MATCH; @@ -410,7 +408,7 @@ int detection_option_node_evaluate( // see if evaluated it before ... if ( !node->is_relative ) { - auto last_check = state->last_check; + auto last_check = state.last_check; if ( last_check.ts == p->pkth->ts && last_check.packet_number == cur_eval_pkt_count && @@ -426,10 +424,10 @@ int detection_option_node_evaluate( } } - state->last_check.ts = eval_data->p->pkth->ts; - state->last_check.packet_number = cur_eval_pkt_count; - state->last_check.flowbit_failed = 0; - state->last_check.rebuild_flag = p->packet_flags & PKT_REBUILT_STREAM; + state.last_check.ts = eval_data->p->pkth->ts; + state.last_check.packet_number = cur_eval_pkt_count; + state.last_check.flowbit_failed = 0; + state.last_check.rebuild_flag = p->packet_flags & PKT_REBUILT_STREAM; // Save some stuff off for repeated pattern tests bool try_again = false; @@ -494,8 +492,8 @@ int detection_option_node_evaluate( int eval_rtn_result = 0; // Don't include RTN time - PERF_PAUSE_BLOCK(node_stats) { + TimePause profile_pause(profile); eval_rtn_result = fpEvalRTN(getRuntimeRtnFromOtn(otn), p, check_ports); } @@ -574,7 +572,7 @@ int detection_option_node_evaluate( if ( rval == DETECTION_OPTION_NO_MATCH ) { - state->last_check.result = result; + state.last_check.result = result; return result; } @@ -582,8 +580,8 @@ int detection_option_node_evaluate( { eval_data->flowbit_failed = 1; // clear the timestamp so failed flowbit gets eval'd again - state->last_check.flowbit_failed = 1; - state->last_check.result = result; + state.last_check.flowbit_failed = 1; + state.last_check.result = result; return 0; } @@ -608,19 +606,16 @@ int detection_option_node_evaluate( { // bail if we exceeded time - // FIXIT-M J this is unconditional (match or no match) since this - // block is guaranteed to return - if ( result != DETECTION_OPTION_NO_MATCH ) - NODE_PERF_PROFILE_STOP_MATCH(node_stats); + profile.stop(result != DETECTION_OPTION_NO_MATCH); - state->last_check.result = result; + state.last_check.result = result; return result; } } #endif - PERF_PAUSE_BLOCK(node_stats) { + TimePause profile_pause(profile); // Passed, check the children. if ( node->num_children ) { @@ -700,7 +695,7 @@ int detection_option_node_evaluate( if ( PPM_PACKET_ABORT_FLAG() ) { // bail if we exceeded time - state->last_check.result = result; + state.last_check.result = result; return result; } } @@ -743,13 +738,10 @@ int detection_option_node_evaluate( // We're essentially checking this node again and it potentially // might match again if ( continue_loop ) - state->checks++; + state.checks++; loop_count++; } - - // FIXIT-H What's the point of this? - // either it infinite loops, or effective no-op while ( continue_loop ); if ( flowbits_setoperation && result == DETECTION_OPTION_MATCH ) @@ -765,19 +757,19 @@ int detection_option_node_evaluate( { // something deeper in the tree failed a flowbit test, we may need to // reeval this node - state->last_check.flowbit_failed = 1; + state.last_check.flowbit_failed = 1; } - state->last_check.result = result; + state.last_check.result = result; - NODE_PERF_PROFILE_STOP(node_stats, result != DETECTION_OPTION_NO_MATCH); + profile.stop(result != DETECTION_OPTION_NO_MATCH); return result; } struct node_profile_stats { - // FIXIT-L J should be use factored out field from dot_node_state_t + // FIXIT-L J duplicated from dot_node_state_t and OtnState hr_duration elapsed; hr_duration elapsed_match; hr_duration elapsed_no_match; @@ -833,7 +825,10 @@ static void detection_option_node_update_otn_stats( if (node->option_type == RULE_OPTION_TYPE_LEAF_NODE) { /* Update stats for this otn */ - // FIXIT-M should be sum of instances (only called from main thread) + // FIXIT-H J this should either be called from the packet threads at exit + // or *all* the states should get totalled by the main thread + // Right now, it looks like we're missing out on some stats although it's possible + // that this is "corrected" in the profiler code OptTreeNode* otn = (OptTreeNode*)node->option_data; OtnState* state = otn->state + get_instance_id(); state->elapsed += local_stats.elapsed; diff --git a/src/detection/fp_detect.cc b/src/detection/fp_detect.cc index b51529bbc..f0158c87a 100644 --- a/src/detection/fp_detect.cc +++ b/src/detection/fp_detect.cc @@ -369,8 +369,8 @@ int fpAddMatch(OTNX_MATCH_DATA* omd_local, int pLen, const OptTreeNode* otn) */ int fpEvalRTN(RuleTreeNode* rtn, Packet* p, int check_ports) { - PERF_PROFILE(rulePerfStats); - PERF_PROFILE(ruleRTNEvalPerfStats); + Profile rule_profile(rulePerfStats); + Profile rule_rtn_eval_profile(ruleRTNEvalPerfStats); if ( !rtn ) return 0; @@ -474,8 +474,8 @@ static int rule_tree_match( eval_data.flowbit_failed = 0; eval_data.flowbit_noalert = 0; - PERF_PROFILE_BLOCK(rulePerfStats) { + Profile rule_profile(rulePerfStats); /* NOTE: The otn will be the first one in the match state. If there are * multiple rules associated with a match state, mucking with the otn * may muck with an unintended rule */ @@ -499,8 +499,8 @@ static int rule_tree_match( } int ret = 0; - PERF_PROFILE_BLOCK(ruleOTNEvalPerfStats) { + Profile rule_otn_eval_profile(ruleOTNEvalPerfStats); ret = detection_option_tree_evaluate(root, &eval_data); } @@ -1029,9 +1029,9 @@ static inline int fpEvalHeaderSW(PortGroup* port_group, Packet* p, eval_data.flowbit_noalert = 0; int rval = 0; - PERF_PROFILE_BLOCK(rulePerfStats) - PERF_PROFILE_BLOCK(ruleNFPEvalPerfStats) { + Profile rule_profile(rulePerfStats); + Profile rule_nfp_eval_profile(ruleNFPEvalPerfStats); rval = detection_option_tree_evaluate( (detection_option_tree_root_t*)port_group->nfp_tree, &eval_data); } diff --git a/src/detection/treenodes.h b/src/detection/treenodes.h index b4eef194c..ec5d3a22c 100644 --- a/src/detection/treenodes.h +++ b/src/detection/treenodes.h @@ -70,6 +70,16 @@ struct OtnState // ppm uint64_t ppm_suspend_time; uint64_t ppm_disable_cnt; + + operator bool() const + { return elapsed > 0_ticks || checks > 0; } + + void reset() + { + elapsed = elapsed_match = elapsed_no_match = 0_ticks; + checks = matches = noalerts = alerts = 0; + ppm_suspend_time = ppm_disable_cnt = 0; + } }; // one of these for each rule diff --git a/src/framework/mpse.cc b/src/framework/mpse.cc index b4459b7e2..c6704bcb0 100644 --- a/src/framework/mpse.cc +++ b/src/framework/mpse.cc @@ -49,7 +49,7 @@ int Mpse::search( const unsigned char* T, int n, MpseMatch match, void* context, int* current_state) { - PERF_PROFILE(mpsePerfStats); + Profile profile(mpsePerfStats); int ret = _search(T, n, match, context, current_state); diff --git a/src/ips_options/ips_ack.cc b/src/ips_options/ips_ack.cc index e9025567f..fd85d6b0f 100644 --- a/src/ips_options/ips_ack.cc +++ b/src/ips_options/ips_ack.cc @@ -92,7 +92,7 @@ bool TcpAckOption::operator==(const IpsOption& ips) const int TcpAckOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(tcpAckPerfStats); + Profile profile(tcpAckPerfStats); if ( p->ptrs.tcph && config.eval(p->ptrs.tcph->th_ack) ) return DETECTION_OPTION_MATCH; diff --git a/src/ips_options/ips_asn1.cc b/src/ips_options/ips_asn1.cc index cb184add1..a6a500a2a 100644 --- a/src/ips_options/ips_asn1.cc +++ b/src/ips_options/ips_asn1.cc @@ -167,7 +167,7 @@ bool Asn1Option::operator==(const IpsOption& rhs) const int Asn1Option::eval(Cursor& c, Packet* p) { - PERF_PROFILE(asn1PerfStats); + Profile profile(asn1PerfStats); // Failed if there is no data to decode. if (!p->data) diff --git a/src/ips_options/ips_base64.cc b/src/ips_options/ips_base64.cc index 7f43485c5..4f642e767 100644 --- a/src/ips_options/ips_base64.cc +++ b/src/ips_options/ips_base64.cc @@ -126,7 +126,7 @@ bool Base64DecodeOption::operator==(const IpsOption& ips) const int Base64DecodeOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(base64PerfStats); + Profile profile(base64PerfStats); @@ -296,7 +296,7 @@ public: int Base64DataOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(base64PerfStats); + Profile profile(base64PerfStats); if ( !base64_decode_size ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/ips_options/ips_bufferlen.cc b/src/ips_options/ips_bufferlen.cc index 4e31d4ecc..b94785472 100644 --- a/src/ips_options/ips_bufferlen.cc +++ b/src/ips_options/ips_bufferlen.cc @@ -87,7 +87,7 @@ bool LenOption::operator==(const IpsOption& ips) const int LenOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(lenCheckPerfStats); + Profile profile(lenCheckPerfStats); if ( config.eval(c.length()) ) return DETECTION_OPTION_MATCH; diff --git a/src/ips_options/ips_byte_extract.cc b/src/ips_options/ips_byte_extract.cc index d210102c2..b4b0a393b 100644 --- a/src/ips_options/ips_byte_extract.cc +++ b/src/ips_options/ips_byte_extract.cc @@ -144,7 +144,7 @@ bool ByteExtractOption::operator==(const IpsOption& ips) const int ByteExtractOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(byteExtractPerfStats); + Profile profile(byteExtractPerfStats); ByteExtractData* data = &config; diff --git a/src/ips_options/ips_byte_jump.cc b/src/ips_options/ips_byte_jump.cc index 727f63c8c..6018ac51e 100644 --- a/src/ips_options/ips_byte_jump.cc +++ b/src/ips_options/ips_byte_jump.cc @@ -198,7 +198,7 @@ bool ByteJumpOption::operator==(const IpsOption& ips) const int ByteJumpOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(byteJumpPerfStats); + Profile profile(byteJumpPerfStats); ByteJumpData* bjd = (ByteJumpData*)&config; diff --git a/src/ips_options/ips_byte_test.cc b/src/ips_options/ips_byte_test.cc index f8c64301f..ebfb693b3 100644 --- a/src/ips_options/ips_byte_test.cc +++ b/src/ips_options/ips_byte_test.cc @@ -296,7 +296,7 @@ bool ByteTestOption::operator==(const IpsOption& ips) const int ByteTestOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(byteTestPerfStats); + Profile profile(byteTestPerfStats); ByteTestData* btd = (ByteTestData*)&config; uint32_t cmp_value = 0; diff --git a/src/ips_options/ips_content.cc b/src/ips_options/ips_content.cc index 1ad05c0be..e846dbb22 100644 --- a/src/ips_options/ips_content.cc +++ b/src/ips_options/ips_content.cc @@ -400,7 +400,7 @@ static int uniSearchReal(ContentData* cd, Cursor& c) static int CheckANDPatternMatch(ContentData* idx, Cursor& c) { - PERF_PROFILE(contentPerfStats); + Profile profile(contentPerfStats); DebugMessage(DEBUG_PATTERN_MATCH, "CheckPatternANDMatch: "); diff --git a/src/ips_options/ips_dsize.cc b/src/ips_options/ips_dsize.cc index 9677eea0b..788691c2c 100644 --- a/src/ips_options/ips_dsize.cc +++ b/src/ips_options/ips_dsize.cc @@ -92,7 +92,7 @@ bool DsizeOption::operator==(const IpsOption& ips) const // Test the packet's payload size against the rule payload size value int DsizeOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(dsizePerfStats); + Profile profile(dsizePerfStats); /* fake packet dsizes are always wrong (unless they are PDUs) */ diff --git a/src/ips_options/ips_file_data.cc b/src/ips_options/ips_file_data.cc index 9d83ae350..e6e31f61b 100644 --- a/src/ips_options/ips_file_data.cc +++ b/src/ips_options/ips_file_data.cc @@ -58,7 +58,7 @@ public: int FileDataOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(fileDataPerfStats); + Profile profile(fileDataPerfStats); uint8_t* data = g_file_data.data; uint16_t len = g_file_data.len; diff --git a/src/ips_options/ips_flags.cc b/src/ips_options/ips_flags.cc index ecd7d55bc..677551384 100644 --- a/src/ips_options/ips_flags.cc +++ b/src/ips_options/ips_flags.cc @@ -122,7 +122,7 @@ bool TcpFlagOption::operator==(const IpsOption& ips) const int TcpFlagOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(tcpFlagsPerfStats); + Profile profile(tcpFlagsPerfStats); // if error appeared when tcp header was processed, // test fails automagically. diff --git a/src/ips_options/ips_flow.cc b/src/ips_options/ips_flow.cc index c134a7b6f..76920f7a4 100644 --- a/src/ips_options/ips_flow.cc +++ b/src/ips_options/ips_flow.cc @@ -124,7 +124,7 @@ bool FlowCheckOption::operator==(const IpsOption& ips) const int FlowCheckOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(flowCheckPerfStats); + Profile profile(flowCheckPerfStats); FlowCheckData* fcd = &config; diff --git a/src/ips_options/ips_flowbits.cc b/src/ips_options/ips_flowbits.cc index 40255055c..1ea9faf09 100644 --- a/src/ips_options/ips_flowbits.cc +++ b/src/ips_options/ips_flowbits.cc @@ -256,7 +256,7 @@ bool FlowBitsOption::operator==(const IpsOption& ips) const int FlowBitsOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(flowBitsPerfStats); + Profile profile(flowBitsPerfStats); FLOWBITS_OP* flowbits = config; diff --git a/src/ips_options/ips_fragbits.cc b/src/ips_options/ips_fragbits.cc index 5c574cb1c..42ffba7f8 100644 --- a/src/ips_options/ips_fragbits.cc +++ b/src/ips_options/ips_fragbits.cc @@ -143,7 +143,7 @@ bool FragBitsOption::operator==(const IpsOption& ips) const int FragBitsOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(fragBitsPerfStats); + Profile profile(fragBitsPerfStats); FragBitsData* fb = &config; diff --git a/src/ips_options/ips_fragoffset.cc b/src/ips_options/ips_fragoffset.cc index 5151779fc..db37e0251 100644 --- a/src/ips_options/ips_fragoffset.cc +++ b/src/ips_options/ips_fragoffset.cc @@ -88,7 +88,7 @@ bool FragOffsetOption::operator==(const IpsOption& ips) const int FragOffsetOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(fragOffsetPerfStats); + Profile profile(fragOffsetPerfStats); if (!p->has_ip()) return DETECTION_OPTION_NO_MATCH; diff --git a/src/ips_options/ips_hash.cc b/src/ips_options/ips_hash.cc index 1440cf58b..cf873faec 100644 --- a/src/ips_options/ips_hash.cc +++ b/src/ips_options/ips_hash.cc @@ -200,7 +200,7 @@ int HashOption::match(Cursor& c) int HashOption::eval(Cursor& c, Packet*) { - PERF_PROFILE_THREAD_LOCAL(hash_ps, idx); + Profile profile(hash_ps[idx]); int found = match(c); diff --git a/src/ips_options/ips_http.cc b/src/ips_options/ips_http.cc index e43136169..49e04c494 100644 --- a/src/ips_options/ips_http.cc +++ b/src/ips_options/ips_http.cc @@ -92,7 +92,7 @@ private: int HttpIpsOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE_THREAD_LOCAL(http_ps, idx); + Profile profile(http_ps[idx]); InspectionBuffer hb; diff --git a/src/ips_options/ips_http_header.cc b/src/ips_options/ips_http_header.cc index 5b2130ea0..aa5e544d4 100644 --- a/src/ips_options/ips_http_header.cc +++ b/src/ips_options/ips_http_header.cc @@ -162,7 +162,7 @@ static bool find( int HttpHeaderOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(httpHeaderPerfStats); + Profile profile(httpHeaderPerfStats); InspectionBuffer hb; diff --git a/src/ips_options/ips_icmp_id.cc b/src/ips_options/ips_icmp_id.cc index 795af90d5..0b2408501 100644 --- a/src/ips_options/ips_icmp_id.cc +++ b/src/ips_options/ips_icmp_id.cc @@ -107,7 +107,7 @@ bool IcmpIdOption::operator==(const IpsOption& ips) const int IcmpIdOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(icmpIdPerfStats); + Profile profile(icmpIdPerfStats); if (!p->ptrs.icmph) return DETECTION_OPTION_NO_MATCH; diff --git a/src/ips_options/ips_icmp_seq.cc b/src/ips_options/ips_icmp_seq.cc index e628ffcad..84165dad4 100644 --- a/src/ips_options/ips_icmp_seq.cc +++ b/src/ips_options/ips_icmp_seq.cc @@ -109,7 +109,7 @@ bool IcmpSeqOption::operator==(const IpsOption& ips) const int IcmpSeqOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(icmpSeqPerfStats); + Profile profile(icmpSeqPerfStats); if (!p->ptrs.icmph) return DETECTION_OPTION_NO_MATCH; diff --git a/src/ips_options/ips_icode.cc b/src/ips_options/ips_icode.cc index 48948fd8f..d7b64515e 100644 --- a/src/ips_options/ips_icode.cc +++ b/src/ips_options/ips_icode.cc @@ -86,7 +86,7 @@ bool IcodeOption::operator==(const IpsOption& ips) const int IcodeOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(icmpCodePerfStats); + Profile profile(icmpCodePerfStats); // return 0 if we don't have an icmp header if (!p->ptrs.icmph) diff --git a/src/ips_options/ips_id.cc b/src/ips_options/ips_id.cc index 6fb8de880..221771d65 100644 --- a/src/ips_options/ips_id.cc +++ b/src/ips_options/ips_id.cc @@ -83,7 +83,7 @@ bool IpIdOption::operator==(const IpsOption& ips) const int IpIdOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(ipIdPerfStats); + Profile profile(ipIdPerfStats); if (!p->has_ip()) return DETECTION_OPTION_NO_MATCH; diff --git a/src/ips_options/ips_ip_proto.cc b/src/ips_options/ips_ip_proto.cc index 34769a760..056a88818 100644 --- a/src/ips_options/ips_ip_proto.cc +++ b/src/ips_options/ips_ip_proto.cc @@ -112,7 +112,7 @@ bool IpProtoOption::operator==(const IpsOption& ips) const int IpProtoOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(ipProtoPerfStats); + Profile profile(ipProtoPerfStats); IpProtoData* ipd = &config; diff --git a/src/ips_options/ips_ipopts.cc b/src/ips_options/ips_ipopts.cc index 6d2d2fab3..9f3252ce8 100644 --- a/src/ips_options/ips_ipopts.cc +++ b/src/ips_options/ips_ipopts.cc @@ -110,7 +110,7 @@ bool IpOptOption::operator==(const IpsOption& ips) const int IpOptOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(ipOptionPerfStats); + Profile profile(ipOptionPerfStats); IpOptionData* ipOptionData = &config; diff --git a/src/ips_options/ips_isdataat.cc b/src/ips_options/ips_isdataat.cc index 437d75cdc..182fdf865 100644 --- a/src/ips_options/ips_isdataat.cc +++ b/src/ips_options/ips_isdataat.cc @@ -137,7 +137,7 @@ bool IsDataAtOption::operator==(const IpsOption& ips) const int IsDataAtOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(isDataAtPerfStats); + Profile profile(isDataAtPerfStats); IsDataAtData* isdata = &config; diff --git a/src/ips_options/ips_itype.cc b/src/ips_options/ips_itype.cc index 4bba006c0..5003e41bc 100644 --- a/src/ips_options/ips_itype.cc +++ b/src/ips_options/ips_itype.cc @@ -83,7 +83,7 @@ bool IcmpTypeOption::operator==(const IpsOption& ips) const int IcmpTypeOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(icmpTypePerfStats); + Profile profile(icmpTypePerfStats); // return 0 if we don't have an icmp header if (!p->ptrs.icmph) diff --git a/src/ips_options/ips_luajit.cc b/src/ips_options/ips_luajit.cc index 35fd91ca3..d8ad0f021 100644 --- a/src/ips_options/ips_luajit.cc +++ b/src/ips_options/ips_luajit.cc @@ -21,6 +21,7 @@ #include #include "main/snort_types.h" +#include "main/thread.h" #include "helpers/chunk.h" #include "lua/lua.h" #include "managers/ips_manager.h" @@ -187,7 +188,7 @@ bool LuaJitOption::operator==(const IpsOption& ips) const int LuaJitOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(luaIpsPerfStats); + Profile profile(luaIpsPerfStats); cursor = &c; diff --git a/src/ips_options/ips_pcre.cc b/src/ips_options/ips_pcre.cc index 67da20c6d..a5e1d0c1a 100644 --- a/src/ips_options/ips_pcre.cc +++ b/src/ips_options/ips_pcre.cc @@ -570,7 +570,7 @@ bool PcreOption::operator==(const IpsOption& ips) const int PcreOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(pcrePerfStats); + Profile profile(pcrePerfStats); PcreData* pcre_data = config; diff --git a/src/ips_options/ips_pkt_data.cc b/src/ips_options/ips_pkt_data.cc index 97276f789..8cbda0481 100644 --- a/src/ips_options/ips_pkt_data.cc +++ b/src/ips_options/ips_pkt_data.cc @@ -48,7 +48,7 @@ public: int PktDataOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(pktDataPerfStats); + Profile profile(pktDataPerfStats); c.reset(p); return DETECTION_OPTION_MATCH; diff --git a/src/ips_options/ips_raw_data.cc b/src/ips_options/ips_raw_data.cc index ca806d011..31e153833 100644 --- a/src/ips_options/ips_raw_data.cc +++ b/src/ips_options/ips_raw_data.cc @@ -48,7 +48,7 @@ public: int RawDataOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(rawDataPerfStats); + Profile profile(rawDataPerfStats); c.set(s_name, p->data, p->dsize); return DETECTION_OPTION_MATCH; diff --git a/src/ips_options/ips_regex.cc b/src/ips_options/ips_regex.cc index 321fc579d..59c62c307 100644 --- a/src/ips_options/ips_regex.cc +++ b/src/ips_options/ips_regex.cc @@ -145,7 +145,7 @@ static int hs_match( int RegexOption::eval(Cursor& c, Packet*) { - PERF_PROFILE(regex_perf_stats); + Profile profile(regex_perf_stats); unsigned pos = c.get_delta(); diff --git a/src/ips_options/ips_replace.cc b/src/ips_options/ips_replace.cc index c4ac92dab..b8711f4d2 100644 --- a/src/ips_options/ips_replace.cc +++ b/src/ips_options/ips_replace.cc @@ -160,7 +160,7 @@ bool ReplaceOption::operator==(const IpsOption& ips) const int ReplaceOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(replacePerfStats); + Profile profile(replacePerfStats); if ( p->is_cooked() ) return false; @@ -178,7 +178,7 @@ int ReplaceOption::eval(Cursor& c, Packet* p) void ReplaceOption::action(Packet*) { - PERF_PROFILE(replacePerfStats); + Profile profile(replacePerfStats); if ( pending() ) Replace_QueueChange(repl, (unsigned)pos()); diff --git a/src/ips_options/ips_rpc.cc b/src/ips_options/ips_rpc.cc index 648f0db35..b7d172163 100644 --- a/src/ips_options/ips_rpc.cc +++ b/src/ips_options/ips_rpc.cc @@ -121,7 +121,7 @@ bool RpcOption::operator==(const IpsOption& ips) const int RpcOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(rpcCheckPerfStats); + Profile profile(rpcCheckPerfStats); RpcCheckData* ds_ptr = &config; diff --git a/src/ips_options/ips_seq.cc b/src/ips_options/ips_seq.cc index 6814810ce..caf913f3e 100644 --- a/src/ips_options/ips_seq.cc +++ b/src/ips_options/ips_seq.cc @@ -82,7 +82,7 @@ bool TcpSeqOption::operator==(const IpsOption& ips) const int TcpSeqOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(tcpSeqPerfStats); + Profile profile(tcpSeqPerfStats); if (!p->ptrs.tcph) return DETECTION_OPTION_NO_MATCH; diff --git a/src/ips_options/ips_session.cc b/src/ips_options/ips_session.cc index c5f2f682d..3e5bbab6d 100644 --- a/src/ips_options/ips_session.cc +++ b/src/ips_options/ips_session.cc @@ -137,7 +137,7 @@ bool SessionOption::operator==(const IpsOption& ips) const int SessionOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(sessionPerfStats); + Profile profile(sessionPerfStats); SessionData* session_data = &config; diff --git a/src/ips_options/ips_so.cc b/src/ips_options/ips_so.cc index f048adb1b..b1870c963 100644 --- a/src/ips_options/ips_so.cc +++ b/src/ips_options/ips_so.cc @@ -28,6 +28,7 @@ using namespace std; #include "framework/parameter.h" #include "framework/module.h" +#include "main/thread.h" #include "managers/so_manager.h" #include "hash/sfhashfcn.h" #include "log/messages.h" @@ -96,7 +97,7 @@ bool SoOption::operator==(const IpsOption& ips) const int SoOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(soPerfStats); + Profile profile(soPerfStats); return func(data, c, p); } diff --git a/src/ips_options/ips_tos.cc b/src/ips_options/ips_tos.cc index 4f289ad26..1a70aee23 100644 --- a/src/ips_options/ips_tos.cc +++ b/src/ips_options/ips_tos.cc @@ -84,7 +84,7 @@ bool IpTosOption::operator==(const IpsOption& ips) const int IpTosOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(ipTosPerfStats); + Profile profile(ipTosPerfStats); if(!p->ptrs.ip_api.is_ip()) return DETECTION_OPTION_NO_MATCH; diff --git a/src/ips_options/ips_ttl.cc b/src/ips_options/ips_ttl.cc index 6a1fd1f61..4853921b9 100644 --- a/src/ips_options/ips_ttl.cc +++ b/src/ips_options/ips_ttl.cc @@ -82,7 +82,7 @@ bool TtlOption::operator==(const IpsOption& ips) const int TtlOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(ttlCheckPerfStats); + Profile profile(ttlCheckPerfStats); if(!p->ptrs.ip_api.is_ip()) return DETECTION_OPTION_NO_MATCH; diff --git a/src/ips_options/ips_window.cc b/src/ips_options/ips_window.cc index 1dafff676..10d0f2a3f 100644 --- a/src/ips_options/ips_window.cc +++ b/src/ips_options/ips_window.cc @@ -82,7 +82,7 @@ bool TcpWinOption::operator==(const IpsOption& ips) const int TcpWinOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(tcpWinPerfStats); + Profile profile(tcpWinPerfStats); if (!p->ptrs.tcph) return DETECTION_OPTION_NO_MATCH; diff --git a/src/loggers/alert_luajit.cc b/src/loggers/alert_luajit.cc index d931b4a04..efc9bfe78 100644 --- a/src/loggers/alert_luajit.cc +++ b/src/loggers/alert_luajit.cc @@ -206,7 +206,7 @@ LuaJitLogger::~LuaJitLogger() void LuaJitLogger::alert(Packet* p, const char*, Event* e) { - PERF_PROFILE(luaLogPerfStats); + Profile profile(luaLogPerfStats); packet = p; event = e; diff --git a/src/main/modules.cc b/src/main/modules.cc index bdd7ef09c..f1c8dda19 100644 --- a/src/main/modules.cc +++ b/src/main/modules.cc @@ -312,88 +312,91 @@ bool SearchEngineModule::set(const char*, Value& v, SnortConfig* sc) return true; } -//------------------------------------------------------------------------- -// profile module -//------------------------------------------------------------------------- +// ----------------------------------------------------------------------------- +// profiler module +// ----------------------------------------------------------------------------- -static const Parameter profile_rule_params[] = +static const Parameter profiler_time_params[] = { - { "count", Parameter::PT_INT, "-1:", "-1", - "print results to given level (-1 = all, 0 = off)" }, + { "show", Parameter::PT_BOOL, nullptr, "true", + "show module time profile stats" }, + + { "count", Parameter::PT_INT, "0:", "0", + "print results to given level (0 = all)" }, { "sort", Parameter::PT_ENUM, - "checks | avg_ticks | total_ticks | matches | no_matches | " - "avg_ticks_per_match | avg_ticks_per_no_match", - "avg_ticks", "sort by given field" }, + "none | checks | avg_check | total_time ", + "total_time", "sort by given field" }, { nullptr, Parameter::PT_MAX, nullptr, nullptr, nullptr } }; -static const Parameter profile_module_params[] = +static const Parameter profiler_rule_params[] = { - { "count", Parameter::PT_INT, "-1:", "-1", - "print results to given level (-1 = all, 0 = off)" }, + { "show", Parameter::PT_BOOL, nullptr, "true", + "show rule time profile stats" }, + + { "count", Parameter::PT_INT, "0:", "0", + "print results to given level (0 = all)" }, { "sort", Parameter::PT_ENUM, - "checks | avg_ticks | total_ticks", "avg_ticks", - "sort by given field" }, + "none | checks | avg_check | total_time | matches | no_matches | " + "avg_match | avg_no_match", + "total_time", "sort by given field" }, { nullptr, Parameter::PT_MAX, nullptr, nullptr, nullptr } }; -static const Parameter profile_params[] = +static const Parameter profiler_params[] = { - { "rules", Parameter::PT_TABLE, profile_rule_params, nullptr, + // FIXIT-L J rename to time or vice-versa? + { "modules", Parameter::PT_TABLE, profiler_time_params, nullptr, "" }, - { "modules", Parameter::PT_TABLE, profile_module_params, nullptr, + { "rules", Parameter::PT_TABLE, profiler_rule_params, nullptr, "" }, { nullptr, Parameter::PT_MAX, nullptr, nullptr, nullptr } }; -#define profile_help \ - "configure profiling of rules and/or modules (requires --enable-perf-profiling)" +#define profiler_help \ + "configure profiling of rules and/or modules" -class ProfileModule : public Module +template +static bool s_profiler_module_set(T& config, Value& v) { -public: - ProfileModule() : Module("profile", profile_help, profile_params) { } - bool set(const char*, Value&, SnortConfig*) override; - bool begin(const char*, int, SnortConfig*) override; -}; + if ( v.is("count") ) + config.count = v.get_long(); -bool ProfileModule::begin(const char* fqn, int, SnortConfig* sc) -{ - if ( !strcmp(fqn, "profile.rules") ) - sc->profile_rules->count = -1; + else if ( v.is("show") ) + config.show = v.get_bool(); + + else if ( v.is("sort") ) + config.sort = static_cast(v.get_long()); - else if ( !strcmp(fqn, "profile.modules") ) - sc->profile_modules->count = -1; + else + return false; return true; } -bool ProfileModule::set(const char* fqn, Value& v, SnortConfig* sc) +class ProfilerModule : public Module { - ProfileConfig* p; - const char* spr = "profile.rules"; - const char* spp = "profile.modules"; - - if ( !strncmp(fqn, spr, strlen(spr)) ) - p = sc->profile_rules; - - else if ( !strncmp(fqn, spp, strlen(spp)) ) - p = sc->profile_modules; +public: + ProfilerModule() : Module("profiler", profiler_help, profiler_params) { } + bool set(const char*, Value&, SnortConfig*) override; +}; - else - return false; +bool ProfilerModule::set(const char* fqn, Value& v, SnortConfig* sc) +{ + const char* spm = "profiler.modules"; + const char* spr = "profiler.rules"; - if ( v.is("count") ) - p->count = v.get_long(); + if ( !strncmp(fqn, spm, strlen(spr)) ) + return s_profiler_module_set(sc->profiler->time, v); - else if ( v.is("sort") ) - p->sort = static_cast(v.get_long() + 1); + else if ( !strncmp(fqn, spr, strlen(spr)) ) + return s_profiler_module_set(sc->profiler->rule, v); else return false; @@ -2002,7 +2005,7 @@ void module_init() ModuleManager::add_module(new DetectionModule); ModuleManager::add_module(new PacketsModule); ModuleManager::add_module(new ProcessModule); - ModuleManager::add_module(new ProfileModule); + ModuleManager::add_module(new ProfilerModule); ModuleManager::add_module(new ReferencesModule); ModuleManager::add_module(new RuleStateModule); ModuleManager::add_module(new SearchEngineModule); diff --git a/src/main/snort.cc b/src/main/snort.cc index 3efc19f63..b84e77a2a 100644 --- a/src/main/snort.cc +++ b/src/main/snort.cc @@ -124,6 +124,9 @@ static THREAD_LOCAL Packet* s_packet = nullptr; // FIXIT-M move these to appropriate modules //------------------------------------------------------------------------- +static THREAD_LOCAL ProfileStats totalPerfStats; +static THREAD_LOCAL ProfileStats metaPerfStats; + static ProfileStats* get_profile(const char* key) { if ( !strcmp(key, "detect") ) @@ -164,17 +167,17 @@ static ProfileStats* get_profile(const char* key) static void register_profiles() { - PerfProfilerManager::register_module("detect", nullptr, get_profile); - PerfProfilerManager::register_module("mpse", "detect", get_profile); - PerfProfilerManager::register_module("rebuilt_packet", "detect", get_profile); - PerfProfilerManager::register_module("rule_eval", "detect", get_profile); - PerfProfilerManager::register_module("rtn_eval", "rule_eval", get_profile); - PerfProfilerManager::register_module("rule_tree_eval", "rule_eval", get_profile); - PerfProfilerManager::register_module("nfp_rule_tree_eval", "rule_eval", get_profile); - PerfProfilerManager::register_module("decode", nullptr, get_profile); - PerfProfilerManager::register_module("eventq", nullptr, get_profile); - PerfProfilerManager::register_module("total", nullptr, get_profile); - PerfProfilerManager::register_module("daq_meta", nullptr, get_profile); + Profiler::register_module("detect", nullptr, get_profile); + Profiler::register_module("mpse", "detect", get_profile); + Profiler::register_module("rebuilt_packet", "detect", get_profile); + Profiler::register_module("rule_eval", "detect", get_profile); + Profiler::register_module("rtn_eval", "rule_eval", get_profile); + Profiler::register_module("rule_tree_eval", "rule_eval", get_profile); + Profiler::register_module("nfp_rule_tree_eval", "rule_eval", get_profile); + Profiler::register_module("decode", nullptr, get_profile); + Profiler::register_module("eventq", nullptr, get_profile); + Profiler::register_module("total", nullptr, get_profile); + Profiler::register_module("daq_meta", nullptr, get_profile); } //------------------------------------------------------------------------- @@ -667,7 +670,7 @@ void Snort::thread_term() DAQ_Delete(); - PerfProfilerManager::consolidate_stats(); + Profiler::consolidate_stats(); otnx_match_data_term(); detection_filter_term(); @@ -681,8 +684,8 @@ void Snort::thread_term() void Snort::detect_rebuilt_packet(Packet* p) { // Need to include this b/c call is outside the detect tree - PERF_PROFILE(detectPerfStats); - PERF_PROFILE(rebuiltPacketPerfStats); + Profile detect_profile(detectPerfStats); + Profile rebuilt_profile(rebuiltPacketPerfStats); int tmp_do_detect = do_detect; int tmp_do_detect_content = do_detect_content; @@ -793,7 +796,7 @@ static DAQ_Verdict update_verdict(DAQ_Verdict verdict, int& inject) DAQ_Verdict Snort::packet_callback( void*, const DAQ_PktHdr_t* pkthdr, const uint8_t* pkt) { - PERF_PROFILE(totalPerfStats); + Profile profile(totalPerfStats); pc.total_from_daq++; rule_eval_pkt_count++; @@ -802,8 +805,8 @@ DAQ_Verdict Snort::packet_callback( if ( snort_conf->pkt_skip && pc.total_from_daq <= snort_conf->pkt_skip ) return DAQ_VERDICT_PASS; - PERF_PROFILE_BLOCK(eventqPerfStats) { + Profile eventq_profile(eventqPerfStats); SnortEventqReset(); } diff --git a/src/main/snort_config.cc b/src/main/snort_config.cc index 8e5ca43ef..44bb3fb26 100644 --- a/src/main/snort_config.cc +++ b/src/main/snort_config.cc @@ -174,8 +174,7 @@ SnortConfig::SnortConfig() num_slots = get_instance_max(); state = (SnortState*)SnortAlloc(sizeof(SnortState)*num_slots); - profile_rules = (ProfileConfig*)SnortAlloc(sizeof(*profile_rules)); - profile_modules = (ProfileConfig*)SnortAlloc(sizeof(*profile_modules)); + profiler = new ProfilerConfig; #ifdef PPM_MGR ppm_cfg = (ppm_cfg_t*)SnortAlloc(sizeof(*ppm_cfg)); @@ -258,8 +257,8 @@ SnortConfig::~SnortConfig() if (gtp_ports) delete gtp_ports; - free(profile_rules); - free(profile_modules); + delete profiler; + free(ppm_cfg); #ifdef INTEL_SOFT_CPM diff --git a/src/main/snort_config.h b/src/main/snort_config.h index d631fc86b..a971530f8 100644 --- a/src/main/snort_config.h +++ b/src/main/snort_config.h @@ -120,6 +120,7 @@ struct srmm_table_t; struct sopg_table_t; struct PORT_RULE_MAP; struct SFXHASH; +struct ProfilerConfig; SO_PUBLIC extern THREAD_LOCAL struct SnortConfig* snort_conf; @@ -322,8 +323,7 @@ public: //------------------------------------------------------ // deliberately not conditional // to avoid plugin compatibility issues - struct ProfileConfig* profile_rules = nullptr; - struct ProfileConfig* profile_modules = nullptr; + ProfilerConfig* profiler = nullptr; struct ppm_cfg_t* ppm_cfg = nullptr; struct _IntelPmHandles* ipm_handles = nullptr; @@ -545,13 +545,8 @@ public: static long int get_pcre_match_limit_recursion() { return snort_conf->pcre_match_limit_recursion; } - // FIXIT-H J No longer necessary, since this is always true - // or, we make it conditional on definition of table in lua - static bool get_profile_modules() - { return snort_conf->profile_modules; } - - static bool get_profile_rules() - { return snort_conf->profile_rules; } + static const ProfilerConfig* get_profiler() + { return snort_conf->profiler; } static long int get_tagged_packet_limit() { return snort_conf->tagged_packet_limit; } diff --git a/src/managers/module_manager.cc b/src/managers/module_manager.cc index ae42f53fc..f30c2739c 100644 --- a/src/managers/module_manager.cc +++ b/src/managers/module_manager.cc @@ -784,7 +784,7 @@ void ModuleManager::add_module(Module* m, const BaseApi* b) ModHook* mh = new ModHook(m, b); s_modules.push_back(mh); - PerfProfilerManager::register_module(m); + Profiler::register_module(m); } Module* ModuleManager::get_module(const char* s) diff --git a/src/network_inspectors/arp_spoof/arp_spoof.cc b/src/network_inspectors/arp_spoof/arp_spoof.cc index 6116440d7..773a46a5e 100644 --- a/src/network_inspectors/arp_spoof/arp_spoof.cc +++ b/src/network_inspectors/arp_spoof/arp_spoof.cc @@ -178,7 +178,7 @@ void ArpSpoof::show(SnortConfig*) void ArpSpoof::eval(Packet* p) { - PERF_PROFILE(arpPerfStats); + Profile profile(arpPerfStats); // preconditions - what we registered for assert(p->type() == PktType::ARP); diff --git a/src/network_inspectors/normalize/normalize.cc b/src/network_inspectors/normalize/normalize.cc index dfb9ab244..330c9cac0 100644 --- a/src/network_inspectors/normalize/normalize.cc +++ b/src/network_inspectors/normalize/normalize.cc @@ -244,7 +244,7 @@ void Normalizer::show(SnortConfig* sc) void Normalizer::eval(Packet* p) { - PERF_PROFILE(norm_perf_stats); + Profile profile(norm_perf_stats); if ( !p->is_rebuilt() && !Active::packet_was_dropped() ) Norm_Packet(&config, p); diff --git a/src/network_inspectors/perf_monitor/perf_monitor.cc b/src/network_inspectors/perf_monitor/perf_monitor.cc index b1fc307c9..6d448ff0e 100644 --- a/src/network_inspectors/perf_monitor/perf_monitor.cc +++ b/src/network_inspectors/perf_monitor/perf_monitor.cc @@ -304,7 +304,7 @@ void PerfMonitor::tterm() void PerfMonitor::eval(Packet* p) { - PERF_PROFILE(perfmonStats); + Profile profile(perfmonStats); static THREAD_LOCAL bool first = true; diff --git a/src/network_inspectors/port_scan/port_scan.cc b/src/network_inspectors/port_scan/port_scan.cc index af1c31608..daaaaaa7b 100644 --- a/src/network_inspectors/port_scan/port_scan.cc +++ b/src/network_inspectors/port_scan/port_scan.cc @@ -912,7 +912,7 @@ void PortScan::show(SnortConfig*) void PortScan::eval(Packet* p) { - PERF_PROFILE(psPerfStats); + Profile profile(psPerfStats); assert(p->ptrs.ip_api.is_ip()); diff --git a/src/profiler/CMakeLists.txt b/src/profiler/CMakeLists.txt index 9b3113ddf..5740cc644 100644 --- a/src/profiler/CMakeLists.txt +++ b/src/profiler/CMakeLists.txt @@ -1,5 +1,20 @@ -set ( PROFILER_INCLUDES profiler.h ) -set ( PROFILER_SOURCES profiler.cc ) +set ( PROFILER_INCLUDES profiler.h + profiler_defs.h + time_profiler_defs.h + rule_profiler_defs.h + ) + +set ( PROFILER_SOURCES profiler.cc + profiler_nodes.h + profiler_nodes.cc + time_profiler.h + time_profiler.cc + rule_profiler.h + rule_profiler.cc + profiler_stats_table.cc + profiler_stats_table.h + profiler_builder.h + ) add_library ( profiler STATIC ${PROFILER_SOURCES} diff --git a/src/profiler/Makefile.am b/src/profiler/Makefile.am index e491fc115..8ab6568fd 100644 --- a/src/profiler/Makefile.am +++ b/src/profiler/Makefile.am @@ -2,8 +2,21 @@ noinst_LIBRARIES = libprofiler.a x_includedir = $(pkgincludedir)/profiler -x_include_HEADERS = profiler.h +x_include_HEADERS = \ +profiler.h \ +profiler_defs.h \ +time_profiler_defs.h \ +rule_profiler_defs.h libprofiler_a_SOURCES = \ profiler.cc \ -profiler.h +profiler.h \ +profiler_nodes.cc \ +profiler_nodes.h \ +time_profiler.cc \ +time_profiler.h \ +rule_profiler.cc \ +rule_profiler.h \ +profiler_stats_table.cc \ +profiler_stats_table.h \ +profiler_builder.h diff --git a/src/profiler/dev_notes.txt b/src/profiler/dev_notes.txt index b5c5d7e61..28258e6f1 100644 --- a/src/profiler/dev_notes.txt +++ b/src/profiler/dev_notes.txt @@ -1,3 +1,34 @@ Performance Profiling provides facilities for evaluating the performance of individual components of snort. It manages the collection of profiling statistics, as well as the display of those statistics at shutdown. + +This module provides a data structure (called ProfileStats) which stores +information about timing and entry counts. Similar data structures exist +for accumulating rule profiling and can be found in the detection/ subdirectory. + +To facilitate accumulation of these statistics, this module provides a +class called ProfileContext (aliased as Profile). Instantiating this +class at the top of a scope allows for the automatic accumulation of +statistics for a given ProfileStats struct upon scope exit. + +At startup, ProfileStats structs for different modules are registered +via one of the Profiler::register_* functions. Internally, this +defines a tree hierarchy of statistics intended to reflect the +call graph of the different modules being profiled. + +Right before the packet threads are joined, +ProfileStats for different thread-local statistics are consolidated +in the internal tree. If configured to output statistics, +this tree is traversed at shutdown and the statistics are displayed. + +Rule profiling is slightly different in that instead of a tree, +a flat list of evaluated rules is output at shutdown. +Additionally, rule profiling uses different accumulation logic. +This logic is currently shared between the detection/ and profiler/ +subdirectory. + +Notes: +* statistics are *always* accumulated, regardless of whether + profiler output is enabled. + +* by default, output is sorted by total_time diff --git a/src/profiler/profiler.cc b/src/profiler/profiler.cc index 5146be594..dff5f50c7 100644 --- a/src/profiler/profiler.cc +++ b/src/profiler/profiler.cc @@ -1,9 +1,9 @@ //-------------------------------------------------------------------------- -// Copyright (C) 2014-2015 Cisco and/or its affiliates. All rights reserved. -// Copyright (C) 2005-2013 Sourcefire, Inc. +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. // // This program is free software; you can redistribute it and/or modify it // under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute // this program under any other version of the GNU General Public License. // // This program is distributed in the hope that it will be useful, but @@ -15,1256 +15,66 @@ // with this program; if not, write to the Free Software Foundation, Inc., // 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. //-------------------------------------------------------------------------- + // profiler.cc author Joel Cornett -// based on work by Steven Sturges #include "profiler.h" -#ifdef HAVE_CONFIG_H -#include "config.h" -#endif - -#include -#include - -#include +#include #include -#include -#include -#include -#include "detection/fp_detect.h" -#include "detection/treenodes.h" -#include "detection/detection_options.h" #include "framework/module.h" -#include "hash/sfghash.h" #include "main/snort_config.h" -#include "parser/parser.h" - -#ifdef UNIT_TEST -#include "catch/catch.hpp" -#endif - -#define TOTAL "total" - -// ----------------------------------------------------------------------------- -// types -// ----------------------------------------------------------------------------- - -class ModStatsFunctor -{ -public: - const ProfileStats* operator()(const std::string&); - - bool is_set() const - { return type != NONE; } - - void set(Module* m) - { owner = m; type = MODULE; } - - void set(get_profile_func cb) - { callback = cb; type = CALLBACK; } - -private: - enum { NONE, MODULE, CALLBACK } type = NONE; - union - { - Module* owner; - get_profile_func callback; - }; -}; - -class ModStatsNode -{ -public: - ModStatsNode(const std::string& key) : - name { key } { } - - template - void set(T v) - { getter.set(v); } - - bool is_set() const - { return getter.is_set(); } - - void add_child(ModStatsNode* p) - { children.insert(p); } - - void reset() - { stats.reset(); totalled = false; } - - const ProfileStats& get_total() - { return stats; } - - void accumulate(); - - const std::string name; - std::set children; - -private: - ProfileStats stats; - bool totalled = false; - ModStatsFunctor getter; -}; - -struct ModEntry -{ - using microseconds = std::chrono::microseconds; - - std::string name; - ModStatsNode* node; - ProfileStats stats; - ProfileStats caller_stats; - - std::vector entries; - - - microseconds us() const - { - using std::chrono::duration_cast; - return duration_cast(stats.elapsed); - } - - double avg_check() const - { return stats.checks? double(us().count()) / double(stats.checks) : 0.0; } - - double pct_of(const ProfileStats& other) const - { - using std::chrono::duration_cast; - - auto other_us = duration_cast(other.elapsed).count(); - if ( other_us ) - return double(us().count()) / double(other_us) * 100.0; - - return 0.0; - } - - double pct_of_caller() const - { return pct_of(caller_stats); } - - ModEntry(ModStatsNode*, const ProfileStats&); -}; - -using ModEntrySortFunc = std::function; - -// Wraps std::unordered_map with some initialization for operator[] -class ModStatsTree -{ - std::unordered_map nodes; - -public: - ModStatsNode& operator[](std::string key) - { - auto result = nodes.emplace(key, key); - return result.first->second; - } - - auto begin() -> decltype(nodes.begin()) - { return nodes.begin(); } - - auto end() -> decltype(nodes.end()) - { return nodes.end(); } -}; - -struct RuleEntry -{ - using microseconds = std::chrono::microseconds; - - SigInfo sig_info; - OtnState state; - - microseconds us() const - { - using std::chrono::duration_cast; - return duration_cast(state.elapsed); - } - - microseconds us_match() const - { - using std::chrono::duration_cast; - return duration_cast(state.elapsed_match); - } - - microseconds us_no_match() const - { - using std::chrono::duration_cast; - return duration_cast(state.elapsed_no_match); - } - - template - double us_per(microseconds t, T v) const - { return v ? double(t.count()) / double(v) : 0.0; } - - double avg_match() const - { return us_per(us_match(), state.matches); } - - double avg_no_match() const - { return us_per(us_no_match(), state.checks - state.matches); } - - double avg_check() const - { return us_per(us(), state.checks); } - - RuleEntry(const SigInfo&, const OtnState&); -}; - -using RuleEntrySortFunc = std::function; - -// ----------------------------------------------------------------------------- -// global variables -// ----------------------------------------------------------------------------- - -THREAD_LOCAL ProfileStats totalPerfStats; -THREAD_LOCAL ProfileStats metaPerfStats; - -static ModStatsTree s_module_nodes; - -// ----------------------------------------------------------------------------- -// static functions -// ----------------------------------------------------------------------------- - -static inline OtnState& operator+=(OtnState& lhs, const OtnState& rhs) -{ - lhs.elapsed += rhs.elapsed; - lhs.elapsed_match += rhs.elapsed_match; - lhs.elapsed_no_match += rhs.elapsed_no_match; - lhs.checks += rhs.checks; - lhs.matches += rhs.matches; - lhs.noalerts += rhs.noalerts; - lhs.alerts += rhs.alerts; - return lhs; -} - -template -static void add_module(std::string name, const char* pname, T v) -{ - ModStatsNode& node = s_module_nodes[name]; - - assert(!node.is_set()); - node.set(v); - - if ( !pname ) - pname = TOTAL; - - // don't allow parent to be child of self - if ( name == pname ) - return; - - ModStatsNode& parent = s_module_nodes[pname]; - parent.add_child(&node); -} - -static void get_mod_entries(ModEntry& parent, ModEntrySortFunc* sort_fn, int count) -{ - std::vector entries; - - for ( auto child : parent.node->children ) - { - if ( bool(child->get_total()) ) - entries.emplace_back(child, parent.stats); - } - - if ( sort_fn ) - std::stable_sort(entries.begin(), entries.end(), *sort_fn); - - size_t n = (count < 0) ? entries.size() : static_cast(count); - - for ( size_t i = 0; i < n && i < entries.size(); ++i ) - { - parent.entries.push_back(entries[i]); - get_mod_entries(parent.entries.back(), sort_fn, count); - } -} -static void print_mod_entry(int layer, int num, const ModEntry& root, const ModEntry& cur) -{ - unsigned indent = 6 - (5 - layer) + 2; +#include "profiler_nodes.h" +#include "time_profiler.h" +#include "rule_profiler.h" - LogMessage("%*d%*s%*d" FMTu64("*") FMTu64("*") "%*.2f%*.2f%*.2f\n", - indent, num, - 28 - indent, cur.name.c_str(), 6, layer, - 11, cur.stats.checks, - 20, cur.us().count(), - 11, cur.avg_check(), - 10, cur.pct_of_caller(), - 10, cur.pct_of(root.stats)); +static ProfilerTree s_profiler_nodes; - int num2 = 0; - for ( const auto& entry : cur.entries ) - print_mod_entry(layer + 1, ++num2, root, entry); -} - -static void print_mod_entries(ModEntry& root, int count) -{ - LogMessage("--------------------------------------------------\n"); - - // print table title - if (count != -1) - LogMessage("Module Profile Statistics (worst %d)\n", count); - else - LogMessage("Module Profile Statistics (all)\n"); - - // print headers - LogMessage("%*s%*s%*s%*s%*s%*s%*s%*s\n", - 4, "Num", - 24, "Module", - 6, "Layer", - 11, "Checks", - 20, "Microsecs", - 11, "Avg/Check", - 10, "%/Caller", - 10, "%/Total"); - - LogMessage("%*s%*s%*s%*s%*s%*s%*s%*s\n", - 4, "===", - 24, "======", - 6, "=====", - 11, "======", - 20, "=========", - 11, "=========", - 10, "========", - 10, "========"); - - int num = 0; - for ( const auto& entry : root.entries ) - print_mod_entry(0, ++num, root, entry); - - unsigned indent = root.name.size() + 1; - - LogMessage("%*s%*s%*d" FMTu64("*") FMTu64("*") "%*.2f%*.2f%*.2f\n", - indent, root.name.c_str(), - 28 - indent, root.name.c_str(), 6, 0, - 11, root.stats.checks, - 20, root.us().count(), - 11, root.avg_check(), - 10, root.pct_of_caller(), - 10, root.pct_of_caller()); -} - -bool get_mod_sort_function(ProfileSort sort_mode, ModEntrySortFunc& sort_fn) -{ - switch ( sort_mode ) - { - case PROFILE_SORT_CHECKS: - sort_fn = [](const ModEntry& a, const ModEntry& b) -> bool - { return a.stats.checks > b.stats.checks; }; - break; - - case PROFILE_SORT_TOTAL_TICKS: - sort_fn = [](const ModEntry& a, const ModEntry& b) -> bool - { return a.stats.elapsed > b.stats.elapsed; }; - break; - - case PROFILE_SORT_AVG_TICKS: - sort_fn = [](const ModEntry& a, const ModEntry& b) -> bool - { return a.avg_check() > b.avg_check(); }; - break; - - default: - return false; - break; - } - - return true; -} - -static void consolidate_otn_states(OtnState* states) -{ - for ( unsigned i = 1; i < get_instance_max(); ++i ) - states[0] += states[i]; -} - -static void sort_rule_stats(std::vector& entries, ProfileSort sort_mode) -{ - RuleEntrySortFunc sort_fn; - switch ( sort_mode ) - { - case PROFILE_SORT_CHECKS: - sort_fn = [](const RuleEntry& a, const RuleEntry& b) - { return a.state.checks >= b.state.checks; }; - break; - - case PROFILE_SORT_MATCHES: - sort_fn = [](const RuleEntry& a, const RuleEntry& b) - { return a.state.matches >= b.state.matches; }; - break; - - case PROFILE_SORT_NOMATCHES: - sort_fn = [](const RuleEntry& a, const RuleEntry& b) - { return (a.state.checks - a.state.matches) > (b.state.checks - b.state.matches); }; - break; - - case PROFILE_SORT_AVG_TICKS_PER_MATCH: - sort_fn = [](const RuleEntry& a, const RuleEntry& b) - { return a.avg_match() >= b.avg_match(); }; - break; - - case PROFILE_SORT_AVG_TICKS_PER_NOMATCH: - sort_fn = [](const RuleEntry& a, const RuleEntry& b) - { return a.avg_no_match() >= b.avg_no_match(); }; - break; - - case PROFILE_SORT_TOTAL_TICKS: - sort_fn = [](const RuleEntry& a, const RuleEntry& b) - { return a.state.elapsed >= b.state.elapsed; }; - break; - - case PROFILE_SORT_AVG_TICKS: - sort_fn = [](const RuleEntry& a, const RuleEntry& b) - { return a.avg_check() >= b.avg_check(); }; - break; - - default: - return; - break; - } - - std::sort(entries.begin(), entries.end(), sort_fn); -} - -static void get_rule_stats_entries(std::vector& entries) -{ - assert(snort_conf); - - detection_option_tree_update_otn_stats(snort_conf->detection_option_tree_hash_table); - - for ( SFGHASH_NODE* h = sfghash_findfirst(snort_conf->otn_map); h; h = sfghash_findnext(snort_conf->otn_map) ) - { - OptTreeNode* otn = static_cast(h->data); - assert(otn); - - OtnState* states = otn->state; - OtnState& state = states[0]; - - consolidate_otn_states(states); - - if ( !state.checks || (state.elapsed == hr_duration::zero()) ) - continue; - - entries.emplace_back(otn->sigInfo, state); - } -} - -static void print_rule_stats(std::vector& entries, int num) -{ - // if ( entries.empty ) return; - - LogMessage("--------------------------------------------------\n"); - - // print table title - if ( num != -1 ) - LogMessage("Rule Profile Statistics (worst %d rules)\n", num); - - else - LogMessage("Rule Profile Statistics (all rules)\n"); - - // print headers - LogMessage( -#ifdef PPM_MGR - "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n", -#else - "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n", -#endif - 6, "Num", - 9, "SID", 4, "GID", 4, "Rev", - 11, "Checks", - 10, "Matches", - 10, "Alerts", - 20, "Microsecs", - 11, "Avg/Check", - 11, "Avg/Match", - 13, "Avg/Nonmatch" -#ifdef PPM_MGR - , 11, "Disabled" -#endif - ); - - LogMessage( -#ifdef PPM_MGR - "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n", -#else - "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n", -#endif - 6, "===", - 9, "===", 4, "===", 4, "===", - 11, "======", - 10, "=======", - 10, "======", - 20, "=========", - 11, "=========", - 11, "=========", - 13, "============" -#ifdef PPM_MGR - , 11, "========" -#endif - ); - - int i = 0; - for ( const auto& entry : entries ) - { - if ( (num != -1) && (i >= num) ) - break; - - LogMessage( -#ifdef PPM_MGR - "%*d%*d%*d%*d" FMTu64("*") FMTu64("*") FMTu64("*") FMTu64( - "*") "%*.1f%*.1f%*.1f" FMTu64("*") "\n", -#else - "%*d%*d%*d%*d" FMTu64("*") FMTu64("*") FMTu64("*") FMTu64("*") "%*.1f%*.1f%*.1f" "\n", -#endif - 6, ++i, - 9, entry.sig_info.id, 4, entry.sig_info.generator, 4, entry.sig_info.rev, - 11, entry.state.checks, - 10, entry.state.matches, - 10, entry.state.alerts, - 20, entry.us().count(), - 11, entry.avg_check(), - 11, entry.avg_match(), - 13, entry.avg_no_match() -#ifdef PPM_MGR - , 11, entry.state.ppm_disable_cnt -#endif - ); - } -} - -// ----------------------------------------------------------------------------- -// class/struct implementation -// ----------------------------------------------------------------------------- - -void NodePerfProfiler::update(bool match) -{ stats.update(get_delta(), match); } - -const ProfileStats* ModStatsFunctor::operator()(const std::string& key) -{ - assert(is_set()); - - if ( type == MODULE ) - { - const auto *ps = owner->get_profile(); - if ( ps ) - return ps; - - unsigned i = 0; - const char* name, * pname; - while ( (ps = owner->get_profile(i++, name, pname)) && key != name ); - - return ps; - } - - else if ( type == CALLBACK ) - return callback(key.c_str()); - - return nullptr; -} - -void ModStatsNode::accumulate() -{ - assert(!name.empty()); - - if ( is_set() ) - { - const auto* ps = getter(name); - if ( ps ) - stats += *ps; - } -} - -ModEntry::ModEntry(ModStatsNode* node, const ProfileStats& caller_stats) : - name(node->name), node(node), stats(node->get_total()), caller_stats(caller_stats) -{ assert(caller_stats.elapsed >= stats.elapsed); } - -RuleEntry::RuleEntry(const SigInfo& si, const OtnState& os) : - sig_info(si), state(os) -{ state.checks = std::max(state.checks, state.matches); } - -// ----------------------------------------------------------------------------- -// public API -// ----------------------------------------------------------------------------- - -void PerfProfilerManager::register_module(Module* m) +void Profiler::register_module(Module* m) { if ( m->get_profile() ) register_module(m->get_name(), nullptr, m); else { - const char* name, * pname; - const ProfileStats* ps; unsigned i = 0; - - while ( (ps = m->get_profile(i++, name, pname)) ) - register_module(name, pname, m); + const char* n, * pn; + // const ProfilerStats* ps = nullptr; + const ProfileStats* ps = nullptr; + while ( (ps = m->get_profile(i++, n, pn)) ) + register_module(n, pn, m); } } -void PerfProfilerManager::register_module(const char* name, const char* pname, Module* m) -{ add_module(name, pname, m); } - -void PerfProfilerManager::register_module(const char* name, const char* pname, - get_profile_func getter) -{ add_module(name, pname, getter); } - -// thread local -void PerfProfilerManager::consolidate_stats() +void Profiler::register_module(const char* n, const char* pn, Module* m) { - static std::mutex stats_mutex; - std::lock_guard lock(stats_mutex); - - for ( auto it = s_module_nodes.begin(); it != s_module_nodes.end(); ++it ) - it->second.accumulate(); + assert(n); + s_profiler_nodes.register_node(n, pn, m); } -void PerfProfilerManager::show_module_stats() +void Profiler::register_module(const char* n, const char* pn, get_profile_stats_fn fn) { - const auto& config = *snort_conf->profile_modules; - - if ( !config.count ) - return; - - ModStatsNode& root_node = s_module_nodes[TOTAL]; - ModEntry root(&root_node, root_node.get_total()); - - ModEntrySortFunc sort_fn; - if ( get_mod_sort_function(config.sort, sort_fn) ) - get_mod_entries(root, &sort_fn, config.count); - - else - get_mod_entries(root, nullptr, config.count); - - print_mod_entries(root, config.count); + assert(n); + s_profiler_nodes.register_node(n, pn, fn); } -void PerfProfilerManager::reset_module_stats() -{ - for ( auto it = s_module_nodes.begin(); it != s_module_nodes.end(); ++it ) - it->second.reset(); -} +void Profiler::consolidate_stats() +{ s_profiler_nodes.accumulate_nodes(); } -void PerfProfilerManager::show_rule_stats() +void Profiler::reset_stats() { - const auto& config = *snort_conf->profile_rules; - - if ( !config.count ) - return; - - std::vector entries; - get_rule_stats_entries(entries); - - if ( entries.empty() ) - return; - - sort_rule_stats(entries, config.sort); - print_rule_stats(entries, config.count); -} - -void PerfProfilerManager::reset_rule_stats() -{ - auto* otn_map = snort_conf->otn_map; - - for ( SFGHASH_NODE* h = sfghash_findfirst(otn_map); h; h = sfghash_findnext(otn_map) ) - { - auto* otn = static_cast(h->data); - assert(otn); - - auto* rtn = getRtnFromOtn(otn); - - if ( !rtn || !is_network_protocol(rtn->proto) ) - continue; - - for ( unsigned i = 0; i < get_instance_max(); ++i ) - { - auto& state = otn->state[i]; - memset(&state, 0, sizeof(state)); - } - } + s_profiler_nodes.reset_nodes(); + reset_rule_profiler_stats(); } -void PerfProfilerManager::show_all_stats() -{ - if ( SnortConfig::get_profile_modules() ) - show_module_stats(); - - if ( SnortConfig::get_profile_rules() ) - show_rule_stats(); -} - -void PerfProfilerManager::reset_all_stats() -{ - if ( SnortConfig::get_profile_modules() ) - reset_module_stats(); - - if ( SnortConfig::get_profile_rules() ) - reset_rule_stats(); -} - -// ----------------------------------------------------------------------------- -// unit tests -// ----------------------------------------------------------------------------- - -#ifdef UNIT_TEST - -constexpr hr_duration operator "" _dur(unsigned long long v) -{ return hr_duration(v); } - -struct ProfilePauseObserver +void Profiler::show_stats() { - void start() - { - start_called = true; - if ( pause_called ) - pause_called_before_start = true; - } - - void pause() - { pause_called = true; } - - bool pause_called = false; - bool start_called = false; - bool pause_called_before_start = false; -}; - -TEST_CASE( "profile stats", "[profiler]" ) -{ - ProfileStats stats = { 1_ticks , 2 }; - - SECTION( "operator bool()" ) - { - CHECK( stats ); - stats = { 0_dur, 0 }; - CHECK_FALSE( stats ); - } - - SECTION( "operator==" ) - { - ProfileStats compare = { 0_ticks, 0 }; - CHECK_FALSE( stats == compare ); - compare = stats; - CHECK( stats == compare ); - } - - SECTION( "reset" ) - { - stats.reset(); - CHECK_FALSE( stats ); - } - - SECTION( "operator+=" ) - { - ProfileStats inc = { 3_ticks, 4 }; - ProfileStats expected = { stats.elapsed + inc.elapsed, stats.checks + inc.checks }; - stats += inc; - - CHECK( stats == expected ); - } -} - -TEST_CASE( "stopwatch", "[profiler]" ) -{ - Stopwatch sw; - - REQUIRE_FALSE( sw.alive() ); - REQUIRE( sw.get() == 0_ticks ); - - SECTION( "start" ) - { - sw.start(); - - SECTION( "sets clock to alive" ) - { - CHECK( sw.alive() ); - } - - SECTION( "running elapsed time should be non-zero" ) - { - CHECK( sw.get() > 0_ticks ); - } - - SECTION( "start on running clock has no effect" ) - { - auto val = sw.get(); - sw.start(); - CHECK( sw.alive() ); - CHECK( sw.get() > val ); - } - } - - SECTION( "stop" ) - { - sw.start(); - sw.stop(); - - SECTION( "sets clock to be dead" ) - { - CHECK_FALSE( sw.alive() ); - } - - SECTION( "ticks should not increase after death" ) - { - auto val = sw.get(); - CHECK( val == sw.get() ); - } - - SECTION( "stop on stopped clock has no effect" ) - { - auto val = sw.get(); - sw.stop(); - CHECK_FALSE( sw.alive() ); - CHECK( val == sw.get() ); - } - } - - SECTION( "reset" ) - { - sw.start(); - - SECTION( "reset on running clock" ) - { - sw.reset(); - CHECK_FALSE( sw.alive() ); - CHECK( sw.get() == 0_ticks ); - } - - SECTION( "reset on stopped clock" ) - { - sw.stop(); - sw.reset(); - CHECK_FALSE( sw.alive() ); - CHECK( sw.get() == 0_ticks ); - } - } - - SECTION( "cancel" ) - { - sw.start(); - SECTION( "cancel on running clock that has no lap time" ) - { - sw.cancel(); - CHECK_FALSE( sw.alive() ); - CHECK( sw.get() == 0_ticks ); - } - - SECTION( "cancel on stopped clock that has lap time" ) - { - sw.stop(); - auto val = sw.get(); - sw.cancel(); - - CHECK_FALSE( sw.alive() ); - CHECK( val == sw.get() ); - } - } -} - -TEST_CASE( "perf profiler base", "[profiler]" ) -{ - SECTION( "profiler is started on instantiation" ) - { - PerfProfilerBase prof; - CHECK( prof.get_delta() > 0_ticks ); - } - - SECTION( "profiler evaluates to true" ) - { - PerfProfilerBase prof; - CHECK( prof ); - } -} - -TEST_CASE( "perf profiler", "[profiler]" ) -{ - ProfileStats stats = { 0_ticks, 0 }; - - REQUIRE( stats.elapsed == 0_ticks ); - REQUIRE( stats.checks == 0 ); - - SECTION( "going out of scope causes profiler to update stats" ) - { - { - PerfProfiler prof(stats); - } - - CHECK( stats.elapsed > 0_ticks ); - CHECK( stats.checks == 1 ); - } - - SECTION( "stopping profiler is only done once" ) - { - PerfProfiler prof(stats); - prof.stop(); - ProfileStats saved = stats; - prof.stop(); - - CHECK( saved.elapsed == stats.elapsed ); - CHECK( saved.checks == stats.checks ); - } - - SECTION( "profiler can be stopped while paused" ) - { - PerfProfiler prof(stats); - prof.pause(); - prof.stop(); - - CHECK( stats.elapsed > 0_ticks ); - CHECK( stats.checks == 1 ); - } - - SECTION( "profiler can be pause and restarted" ) - { - PerfProfiler prof(stats); - prof.pause(); - prof.start(); - - CHECK( stats.elapsed == 0_ticks ); - CHECK( stats.checks == 0 ); - - prof.stop(); - - CHECK( stats.elapsed > 0_ticks ); - CHECK( stats.checks == 1 ); - } - - SECTION( "profiler correctly handles exceptions" ) - { - try - { - PerfProfiler prof(stats); - throw int(1); - } - - catch( int& ) - { } - - CHECK( stats.elapsed > 0_ticks ); - CHECK( stats.checks == 1 ); - } -} - -TEST_CASE( "node perf profiler", "[profiler]" ) -{ - dot_node_state_t stats; - memset(&stats, 0, sizeof(stats)); - - SECTION( "going out of scope causes profiler to update stats" ) - { - { - NodePerfProfiler prof(stats); - } - - CHECK( stats.elapsed > 0_ticks ); - CHECK( stats.checks == 1 ); - - SECTION( "evaluates to NO MATCH by default" ) - { - CHECK( stats.elapsed_no_match > 0_ticks ); - } - } - - SECTION( "stopping profiler is only done once" ) - { - NodePerfProfiler prof(stats); - prof.stop(false); - dot_node_state_t saved = stats; - prof.stop(true); - - CHECK( saved.elapsed == stats.elapsed ); - CHECK( saved.checks == stats.checks ); - - SECTION( "only one of match or no match is updated" ) - { - CHECK( stats.elapsed_no_match > 0_ticks ); - CHECK( stats.elapsed_match == 0_ticks ); - } - } - - SECTION( "profiler can be stopped while paused" ) - { - NodePerfProfiler prof(stats); - prof.pause(); - prof.stop(false); - - CHECK( stats.elapsed > 0_ticks ); - CHECK( stats.checks == 1 ); - } - - SECTION( "profiler can be pause and restarted" ) - { - NodePerfProfiler prof(stats); - prof.pause(); - prof.start(); - - CHECK( stats.elapsed == 0_ticks ); - CHECK( stats.checks == 0 ); - - prof.stop(false); - - CHECK( stats.elapsed > 0_ticks ); - CHECK( stats.checks == 1 ); - } - - SECTION( "profiler uses MATCH when stop(true) is called" ) - { - NodePerfProfiler prof(stats); - prof.stop(true); - - CHECK( stats.elapsed_match > 0_ticks ); - - SECTION( "and doesn't update NO MATCH" ) - { - CHECK( stats.elapsed_no_match == 0_ticks ); - } - } - - SECTION( "profiler correctly handles exceptions" ) - { - try - { - NodePerfProfiler prof(stats); - throw int(1); - } - - catch( int& ) - { } - - CHECK( stats.elapsed > 0_ticks ); - CHECK( stats.checks == 1 ); - } -} - -TEST_CASE( "perf profiler pause", "[profiler]" ) -{ - ProfilePauseObserver observer; - - { - ProfilerPause pause(observer); - } - - CHECK( observer.pause_called ); - CHECK( observer.start_called ); - CHECK( observer.pause_called_before_start ); -} - -// FIXIT-M Add unit tests for internally used types - -class MockProfilerModule : public Module -{ -public: - MockProfilerModule(ProfileStats* ps = nullptr) : - Module(nullptr, nullptr), stats(ps) { } - - ProfileStats* get_profile() const override - { - get_profile_called = true; - return stats; - } - - ProfileStats* stats; - mutable bool get_profile_called = false; -}; - -static ProfileStats mod_stats_test_stats; - -static ProfileStats* mock_get_profile_func(const char*) -{ return &mod_stats_test_stats; } - -TEST_CASE( "mod stats functor", "[profiler]" ) -{ - static_assert(std::is_default_constructible::value, ""); - static_assert(std::is_copy_constructible::value, ""); - - ModStatsFunctor functor; - - SECTION( "is not set by default" ) - { - CHECK_FALSE( functor.is_set() ); - } - - SECTION( "calls Module::get_profile() if module is set" ) - { - MockProfilerModule m; - REQUIRE_FALSE( m.get_profile_called ); - functor.set(&m); - - REQUIRE( functor.is_set() ); - functor(""); - - CHECK( m.get_profile_called ); - } - - SECTION( "calls get_profile_func if callback is set" ) - { - functor.set(mock_get_profile_func); - REQUIRE( functor.is_set() ); - auto ps = functor(""); - REQUIRE( ps ); - CHECK( ps == &mod_stats_test_stats ); - } - - SECTION( "last set() overrides any previous set()" ) - { - MockProfilerModule m; - functor.set(&m); - functor.set(mock_get_profile_func); - - REQUIRE( functor.is_set() ); - - auto ps = functor(""); - CHECK( ps == &mod_stats_test_stats ); - CHECK_FALSE( m.get_profile_called ); - - functor.set(&m); - ps = functor(""); - CHECK_FALSE( ps ); - CHECK( m.get_profile_called ); - } - - SECTION( "copy-constructed functor retains information" ) - { - SECTION( "unset" ) - { - ModStatsFunctor copied(functor); - CHECK_FALSE( copied.is_set() ); - } - - SECTION( "set(Module*)" ) - { - MockProfilerModule m; - functor.set(&m); - - ModStatsFunctor copied(functor); - REQUIRE( functor.is_set() ); - - copied(""); - CHECK( m.get_profile_called ); - } - - SECTION( "set(get_profile_func)" ) - { - functor.set(mock_get_profile_func); - - ModStatsFunctor copied(functor); - REQUIRE( functor.is_set() ); - - auto ps = copied(""); - CHECK( ps == &mod_stats_test_stats ); - } - } -} - -TEST_CASE( "mod stats node", "[profiler]" ) -{ - ModStatsNode node("a"); - - SECTION( "copy-constructed node retains children and name" ) - { - ModStatsNode child_1("1"); - ModStatsNode child_2("2"); - - node.add_child(&child_1); - node.add_child(&child_2); - - ModStatsNode copied(node); - - CHECK( copied.name == node.name ); - CHECK( copied.children == node.children ); - } - - SECTION( "copy-constructed node retains stats" ) - { - mod_stats_test_stats = { 1_ticks, 2 }; - node.set(mock_get_profile_func); - node.accumulate(); - auto orig_stats = node.get_total(); - - ModStatsNode copied(node); - auto copied_stats = copied.get_total(); - - CHECK( copied_stats == orig_stats ); - } - - SECTION( "accumulate() and get_total() correctly adds stats" ) - { - mod_stats_test_stats = { 1_ticks, 2 }; - ProfileStats expected = mod_stats_test_stats; - expected += mod_stats_test_stats; - - node.set(mock_get_profile_func); - - node.accumulate(); - node.accumulate(); - - auto ps = node.get_total(); - CHECK( ps == expected ); - } - - SECTION( "stats are zero initially" ) - { - auto ps = node.get_total(); - CHECK_FALSE( ps ); - } -} - -TEST_CASE( "mod stats tree", "[profiler]" ) -{ - ModStatsTree tree; - SECTION( "correctly sets the name of a node when accessed" ) - { - auto& foo = tree["foo"]; - CHECK( foo.name == "foo" ); - } -} - -TEST_CASE( "mod entry", "[profiler]" ) -{ - ProfileStats stats = { 200_ticks, 1 }; - ProfileStats caller_stats = { 2000_ticks, 10 }; - MockProfilerModule m(&stats); - ModStatsNode node("a"); - - node.set(&m); - node.accumulate(); - - ModEntry entry(&node, caller_stats); - - REQUIRE( entry.stats == stats ); - - SECTION( "ctor calculates percentages" ) - { - using std::chrono::duration_cast; - using std::chrono::microseconds; - - const auto exp_avg_check = double(duration_cast(200_ticks).count()); - const auto exp_pct = double(duration_cast(200_ticks).count()) / - double(duration_cast(2000_ticks).count()) * 100.0; - - - CHECK( entry.avg_check() == exp_avg_check ); - CHECK( entry.pct_of_caller() == exp_pct ); - } - - SECTION( "zeros" ) - { - stats = { 0_ticks, 0 }; - caller_stats = { 0_ticks, 0 }; - node.reset(); - node.accumulate(); - - ModEntry entry(&node, caller_stats); - - CHECK( entry.avg_check() == 0.0 ); - CHECK( entry.pct_of_caller() == 0.0 ); - } -} - -TEST_CASE( "rule entry", "[profiler]" ) -{ -} - -TEST_CASE( "module stats algorithms", "[profiler]" ) -{ -} + const auto* config = SnortConfig::get_profiler(); + if ( !config ) + return; -TEST_CASE( "rule stats algorithms", "[profiler]" ) -{ + show_time_profiler_stats(s_profiler_nodes, config->time); + show_rule_profiler_stats(config->rule); } - -#endif diff --git a/src/profiler/profiler.h b/src/profiler/profiler.h index 7ae91de7c..2404d15fc 100644 --- a/src/profiler/profiler.h +++ b/src/profiler/profiler.h @@ -1,6 +1,5 @@ //-------------------------------------------------------------------------- -// Copyright (C) 2014-2015 Cisco and/or its affiliates. All rights reserved. -// Copyright (C) 2005-2013 Sourcefire, Inc. +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. // // This program is free software; you can redistribute it and/or modify it // under the terms of the GNU General Public License Version 2 as published @@ -16,229 +15,28 @@ // with this program; if not, write to the Free Software Foundation, Inc., // 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. //-------------------------------------------------------------------------- + // profiler.h author Joel Cornett -// based on work by Steven Sturges #ifndef PROFILER_H #define PROFILER_H -// Facilities for performance profiling - -#ifdef HAVE_CONFIG_H -#include "config.h" -#endif - -#include "main/snort_types.h" -#include "main/thread.h" -#include "time/stopwatch.h" +#include "profiler_defs.h" class Module; -enum ProfileSort -{ - PROFILE_SORT_NONE = 0, - PROFILE_SORT_CHECKS, - PROFILE_SORT_AVG_TICKS, - PROFILE_SORT_TOTAL_TICKS, - PROFILE_SORT_MATCHES, - PROFILE_SORT_NOMATCHES, - PROFILE_SORT_AVG_TICKS_PER_MATCH, - PROFILE_SORT_AVG_TICKS_PER_NOMATCH -}; - -struct ProfileStats -{ - hr_duration elapsed; - uint64_t checks; - - void update(hr_duration delta) - { ++checks; elapsed += delta; } - - void reset() - { elapsed = 0_ticks; checks = 0; } - - bool operator==(const ProfileStats& rhs) - { return elapsed == rhs.elapsed && checks == rhs.checks; } - - operator bool() const - { return (elapsed > hr_duration::zero()) || checks; } - - ProfileStats& operator+=(const ProfileStats& rhs) - { - elapsed += rhs.elapsed; - checks += rhs.checks; - return *this; - } - - constexpr ProfileStats() : - elapsed { 0_ticks }, checks { 0 } { } - - constexpr ProfileStats(hr_duration elapsed, uint64_t checks) : - elapsed { elapsed }, checks { checks } { } -}; - - -class PerfProfilerBase -{ -public: - PerfProfilerBase() - { start(); } - - void start() - { sw.start(); } - - void pause() - { sw.stop(); } - - // for macro block - operator bool() const - { return true; } - - hr_duration get_delta() const - { return sw.get(); } - -private: - Stopwatch sw; -}; - -class PerfProfiler : public PerfProfilerBase -{ -public: - PerfProfiler(ProfileStats& ps) : - PerfProfilerBase(), stats(ps), closed { false } { } - - ~PerfProfiler() - { stop(); } - - // Once a profiler is stopped, it cannot be restarted - void stop() - { - if ( closed ) - return; - - stats.update(get_delta()); - closed = true; - } - -private: - ProfileStats& stats; - bool closed; -}; - -struct dot_node_state_t; - -class NodePerfProfiler : public PerfProfilerBase -{ -public: - NodePerfProfiler(dot_node_state_t& dns) : - PerfProfilerBase(), stats(dns), closed { false } { } - - // If no stop is explicitly specified, assume no match - ~NodePerfProfiler() - { stop(false); } - - void stop(bool match) - { - if ( closed ) - return; - - update(match); - closed = true; - } - -private: - void update(bool); - - dot_node_state_t& stats; - bool closed; -}; - -template -struct ProfilerPause -{ - ProfilerPause(Profiler& prof) : - profiler(prof) - { profiler.pause(); } - - ~ProfilerPause() - { profiler.start(); } - - // for macro block - operator bool() const - { return true; } - - Profiler& profiler; -}; - -// thread local access method -using get_profile_func = ProfileStats* (*)(const char*); - -#define PERF_PROFILER_NAME(stats) \ - stats ## _perf_profiler - -#define PERF_PAUSE_NAME(stats) \ - stats ## _perf_pause - -#define PERF_PROFILE(stats) \ - PerfProfiler PERF_PROFILER_NAME(stats) { stats } - -#define PERF_PROFILE_THREAD_LOCAL(stats, idx) \ - PerfProfiler PERF_PROFILER_NAME(stats) { stats [ idx ] } - -#define PERF_PROFILE_BLOCK(stats) \ - if ( PERF_PROFILE(stats) ) - -#define PERF_PROFILE_THREAD_LOCAL_BLOCK (stats, idx) \ - if ( PERF_PROFILE_THREAD_LOCAL(stats, idx) ) - -#define NODE_PERF_PROFILE(stats) \ - NodePerfProfiler PERF_PROFILER_NAME(stats) { stats } - -#define NODE_PERF_PROFILE_BLOCK(stats) \ - if ( NODE_PERF_PROFILE(stats) ) - -#define NODE_PERF_PROFILE_STOP(stats, match) \ - PERF_PROFILER_NAME(stats) .stop(match) - -#define NODE_PERF_PROFILE_STOP_MATCH(stats) \ - NODE_PERF_PROFILE_STOP(stats, true) - -#define NODE_PERF_PROFILE_STOP_NO_MATCH(stats) \ - NODE_PERF_PROFILE_STOP(stats, false) - -#define PERF_PAUSE_BLOCK(stats) \ - if ( ProfilerPause \ - PERF_PAUSE_NAME(stats) { PERF_PROFILER_NAME(stats) } ) - - -class PerfProfilerManager +class Profiler { public: static void register_module(Module*); static void register_module(const char*, const char*, Module*); - static void register_module(const char*, const char*, get_profile_func); + static void register_module(const char*, const char*, get_profile_stats_fn); - // thread local + // FIXIT-L J do we need to call on main thread? + // call from packet threads, just before thread termination static void consolidate_stats(); - - static void show_module_stats(); - static void reset_module_stats(); - - static void show_rule_stats(); - static void reset_rule_stats(); - - static void show_all_stats(); - static void reset_all_stats(); + static void reset_stats(); + static void show_stats(); }; -struct ProfileConfig -{ - int count; - ProfileSort sort; -}; - -extern THREAD_LOCAL ProfileStats totalPerfStats; -extern THREAD_LOCAL ProfileStats metaPerfStats; - #endif - diff --git a/src/profiler/profiler_builder.h b/src/profiler/profiler_builder.h new file mode 100644 index 000000000..3c8b3c21c --- /dev/null +++ b/src/profiler/profiler_builder.h @@ -0,0 +1,83 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// profiler_builder.h author Joel Cornett + +#ifndef PROFILER_BUILDER_H +#define PROFILER_BUILDER_H + +#include +#include +#include +#include + +#include "profiler_nodes.h" + +class ProfilerNode; + +template +class ProfilerBuilder +{ +public: + using IncludeFn = std::function; + using SortFn = std::function; + + struct Config + { + IncludeFn* include_fn = nullptr; + SortFn* sort_fn = nullptr; + unsigned max_entries = 0; + }; + + ProfilerBuilder(Config config) : + config { config } { } + + void build(Entry& entry) + { + for ( const auto* child_node : entry.child_nodes() ) + if ( include(*child_node) ) + entry.child_entries().emplace_back(*child_node, entry.node); + + sort(entry.child_entries()); + + for ( auto& child_entry : entry.child_entries() ) + build(child_entry); + } + +private: + bool include(const ProfilerNode& node) + { return !config.include_fn || (*config.include_fn)(node); } + + template + void sort(Container& entries) + { + if ( !config.sort_fn ) + return; + + auto stop = + ( !config.max_entries || config.max_entries >= entries.size() ) ? + entries.end() : + entries.begin() + config.max_entries; + + std::partial_sort(entries.begin(), stop, entries.end(), *config.sort_fn); + } + + Config config; +}; + +#endif diff --git a/src/profiler/profiler_defs.h b/src/profiler/profiler_defs.h new file mode 100644 index 000000000..5db13b347 --- /dev/null +++ b/src/profiler/profiler_defs.h @@ -0,0 +1,88 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// profiler_defs.h author Joel Cornett + +#ifndef PROFILER_DEFS_H +#define PROFILER_DEFS_H + +#include "main/snort_types.h" +#include "time_profiler_defs.h" +#include "rule_profiler_defs.h" + +#define ROOT_NODE "total" + +struct ProfilerConfig +{ + TimeProfilerConfig time; + RuleProfilerConfig rule; +}; + +struct SO_PUBLIC ProfileStats +{ + TimeProfilerStats time; + + void reset() + { time.reset(); } + + constexpr ProfileStats() : + time() { } + + constexpr ProfileStats(TimeProfilerStats time) : + time(time) { } +}; + +inline bool operator==(const ProfileStats& lhs, const ProfileStats& rhs) +{ return lhs.time == rhs.time; } + +inline bool operator!=(const ProfileStats& lhs, const ProfileStats& rhs) +{ return !(lhs == rhs); } + +inline ProfileStats& operator+=(ProfileStats& lhs, const ProfileStats& rhs) +{ + lhs.time += rhs.time; + return lhs; +} + +using get_profile_stats_fn = ProfileStats* (*)(const char*); + +struct SO_PUBLIC ProfileContext +{ + TimeContext time; + + void start() + { time.start(); } + + void pause() + { time.pause(); } + + ProfileContext(ProfileStats& stats) : + time(stats.time) { } +}; + +struct SO_PUBLIC ProfilePause +{ + TimePause time; + + ProfilePause(ProfileContext& ctx) : + time(ctx.time) { } +}; + +using Profile = ProfileContext; + +#endif diff --git a/src/profiler/profiler_nodes.cc b/src/profiler/profiler_nodes.cc new file mode 100644 index 000000000..67aefb689 --- /dev/null +++ b/src/profiler/profiler_nodes.cc @@ -0,0 +1,363 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// profiler_nodes.cc author Joel Cornett + +#include "profiler_nodes.h" + +#ifdef HAVE_CONFIG_H +#include "config.h" +#endif + +#include +#include + +#include "framework/module.h" +#include "profiler_defs.h" + +#ifdef UNIT_TEST +#include "catch/catch.hpp" +#endif + +// ----------------------------------------------------------------------------- +// types +// ----------------------------------------------------------------------------- + +struct GetProfileFunctor +{ + GetProfileFunctor(std::string name) : name(name) { } + + virtual ~GetProfileFunctor() = default; + virtual const ProfileStats* operator()() = 0; + + const std::string name; +}; + +struct GetProfileFromModule : GetProfileFunctor +{ + GetProfileFromModule(std::string name, Module* m) : + GetProfileFunctor(name), m(m) { } + + const ProfileStats* operator()() override + { + // const auto *ps = m->get_profiler_stats(); + const auto *ps = m->get_profile(); + if ( ps ) + return ps; + + unsigned i = 0; + const char* n, * pn; + // while ( (ps = m->get_profiler_stats(i++, n, pn)) && name != n ); + while ( (ps = m->get_profile(i++, n, pn)) && name != n ); + + return ps; + } + + Module* m; +}; + +struct GetProfileFromFunction : GetProfileFunctor +{ + GetProfileFromFunction(std::string name, get_profile_stats_fn fn) : + GetProfileFunctor(name), fn(fn) { } + + const ProfileStats* operator()() override + { return fn(name.c_str()); } + + get_profile_stats_fn fn; +}; + +// ----------------------------------------------------------------------------- +// implementation +// ----------------------------------------------------------------------------- + +template +static void setup_node(ProfilerNode& child, ProfilerNode& parent, Getter g) +{ + assert(!child.is_set()); + child.set(g); + + // don't link parent->parent + if ( child == parent ) + return; + + parent.add_child(&child); +} + +void ProfilerNode::set(Module* m) +{ getter = std::make_shared(name, m); } + +void ProfilerNode::set(get_profile_stats_fn fn) +{ getter = std::make_shared(name, fn); } + +void ProfilerNode::accumulate() +{ + if ( is_set() ) + { + const auto* local_stats = (*getter)(); + + if ( !local_stats ) + return; + + get_stats(); + stats += *local_stats; + } +} + +void ProfilerTree::register_node(std::string n, const char* pn, Module* m) +{ setup_node(get_node(n), get_node(pn ? pn : ROOT_NODE), m); } + +void ProfilerTree::register_node(std::string n, const char* pn, get_profile_stats_fn fn) +{ setup_node(get_node(n), get_node(pn ? pn : ROOT_NODE), fn); } + +void ProfilerTree::accumulate_nodes() +{ + static std::mutex stats_mutex; + std::lock_guard lock(stats_mutex); + + for ( auto it = nodes.begin(); it != nodes.end(); ++it ) + it->second.accumulate(); +} + +void ProfilerTree::reset_nodes() +{ + for ( auto it = nodes.begin(); it != nodes.end(); ++it ) + it->second.reset(); +} + +const ProfilerNode& ProfilerTree::get_root() +{ return get_node(ROOT_NODE); } + +ProfilerNode& ProfilerTree::get_node(std::string key) +{ + auto node = nodes.emplace(key, key); + return node.first->second; +} + +#ifdef UNIT_TEST + +static ProfileStats* s_profiler_stats; +static const char* s_profiler_name; + +static ProfileStats* s_profiler_stats_getter(const char* name) +{ + if ( s_profiler_name && std::string(name) == s_profiler_name ) + return s_profiler_stats; + + return nullptr; +} + +static ProfilerNode find_node(const ProfilerTree& tree, std::string name) +{ + for ( const auto& it : tree ) + if ( it.first == name ) + return it.second; + + return ProfilerNode(""); +} + +namespace +{ + +class SpyModule : public Module +{ +public: + SpyModule(const char* name, ProfileStats* stats, bool multi) : + Module(name, nullptr), stats(stats), multi(multi) { } + + ProfileStats* get_stats() { return stats; } + void set_stats(ProfileStats* ps) { stats = ps; } + bool get_multi() { return multi; } + void set_multi(bool b) { multi = b; } + + ProfileStats* get_profile() const override + { return multi ? nullptr : stats; } + + ProfileStats* get_profile( + unsigned i, const char*& name, const char*&) const override + { + if ( !multi ) + return nullptr; + + if ( i == 0 ) + { + name = "dummy"; + return &dummy_stats; + } + + else if ( i == 1 ) + { + name = get_name(); + return stats; + } + + return nullptr; + } + +private: + ProfileStats* stats; + bool multi; + + mutable ProfileStats dummy_stats; +}; + +} // anonymous namespace + +TEST_CASE( "get profile functor for module", "[profiler]" ) +{ + ProfileStats the_stats; + SpyModule m("foo", &the_stats, false); + GetProfileFromModule functor("foo", &m); + auto& ref = functor; + + SECTION( "one" ) + { + CHECK( functor() == &the_stats ); + } + + SECTION( "many" ) + { + m.set_multi(true); + CHECK( functor() == &the_stats ); + } +} + +TEST_CASE( "get profile functor for function", "[profiler]" ) +{ + ProfileStats the_stats; + s_profiler_stats = &the_stats; + s_profiler_name = "foo"; + + GetProfileFromFunction functor("foo", s_profiler_stats_getter); + auto& ref = functor; + CHECK( functor() == &the_stats ); +} + +TEST_CASE( "profiler node", "[profiler]" ) +{ + ProfileStats the_stats; + SpyModule m("foo", &the_stats, false); + + ProfilerNode node("foo"); + node.set(&m); + + SECTION( "get_stats" ) + { + auto& result = node.get_stats(); + CHECK( result == ProfileStats() ); + } + + SECTION( "set" ) + { + the_stats = { { 5_ticks, 7 } }; + + SECTION( "module" ) + { + node.accumulate(); + CHECK( node.get_stats() == the_stats ); + } + + SECTION( "function" ) + { + ProfilerNode f_node("foo"); + s_profiler_stats = &the_stats; + s_profiler_name = "foo"; + f_node.set(s_profiler_stats_getter); + f_node.accumulate(); + CHECK( f_node.get_stats() == the_stats ); + } + } + + SECTION( "accumulate" ) + { + the_stats = { { 1_ticks, 1 } }; + node.accumulate(); + node.accumulate(); + + auto& result = node.get_stats(); + + CHECK( result.time.elapsed == 2_ticks ); + CHECK( result.time.checks == 2 ); + } + + SECTION( "reset" ) + { + the_stats = { { 1_ticks, 1 } }; + node.accumulate(); + + auto& r1 = node.get_stats(); + CHECK( r1 != ProfileStats() ); + + node.reset(); + auto& r2 = node.get_stats(); + CHECK( r2 == ProfileStats() ); + } +} + +TEST_CASE( "profiler tree", "[profiler]" ) +{ + ProfilerTree tree; + + SECTION( "register" ) + { + ProfileStats stats; + SpyModule m("foo", &stats, false); + + SECTION( "register module" ) + { + tree.register_node("foo", nullptr, &m); + CHECK( find_node(tree, "foo").name != "" ); + } + + SECTION( "register function") + { + tree.register_node("foo", nullptr, s_profiler_stats_getter); + CHECK( find_node(tree, "foo").name != "" ); + } + + SECTION( "register child -> parent" ) + { + tree.register_node("foo", "bar", &m); + auto node = find_node(tree, "bar"); + CHECK( !node.get_children().empty() ); + CHECK( node.get_children().front()->name == "foo" ); + } + + SECTION( "register child -> null" ) + { + tree.register_node("foo", nullptr, &m); + auto root = tree.get_root(); + CHECK( !root.get_children().empty() ); + CHECK( root.get_children().front()->name == "foo" ); + } + + SECTION( "register parent -> parent" ) + { + tree.register_node("foo", "foo", &m); + auto node = find_node(tree, "foo"); + CHECK( node.get_children().empty() ); + } + } + + SECTION( "get root" ) + { + CHECK( tree.get_root().name == ROOT_NODE ); + } +} + +#endif diff --git a/src/profiler/profiler_nodes.h b/src/profiler/profiler_nodes.h new file mode 100644 index 000000000..c0a176786 --- /dev/null +++ b/src/profiler/profiler_nodes.h @@ -0,0 +1,103 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// profiler_nodes.h author Joel Cornett + +#ifndef PROFILER_NODES_H +#define PROFILER_NODES_H + +#include +#include +#include +#include + +#include "profiler_defs.h" + +class Module; +struct GetProfileFunctor; + +class ProfilerNode +{ +public: + ProfilerNode(const std::string& key) : + name { key } { } + + void set(Module* m); + void set(get_profile_stats_fn fn); + + bool is_set() const + { return bool(getter); } + + // thread local call + void accumulate(); + + const ProfileStats& get_stats() const + { return stats; } + + void set_stats(const ProfileStats& ps) + { stats = ps; } + + void reset() + { stats.reset(); } + + void add_child(ProfilerNode* node) + { children.push_back(node); } + + const std::vector get_children() const + { return children; } + + const std::string name; + +private: + std::vector children; + std::shared_ptr getter; + ProfileStats stats; +}; + +inline bool operator==(const ProfilerNode& lhs, const ProfilerNode& rhs) +{ return lhs.name == rhs.name; } + +inline bool operator!=(const ProfilerNode& lhs, const ProfilerNode& rhs) +{ return lhs.name == rhs.name; } + +class ProfilerTree +{ +public: + using map_type = std::unordered_map; + + map_type::const_iterator begin() const + { return nodes.begin(); } + + map_type::const_iterator end() const + { return nodes.end(); } + + void register_node(std::string, const char*, Module*); + void register_node(std::string, const char*, get_profile_stats_fn); + + void accumulate_nodes(); + void reset_nodes(); + + const ProfilerNode& get_root(); + +private: + ProfilerNode& get_node(std::string); + + map_type nodes; +}; + +#endif diff --git a/src/profiler/profiler_stats_table.cc b/src/profiler/profiler_stats_table.cc new file mode 100644 index 000000000..308e7a63a --- /dev/null +++ b/src/profiler/profiler_stats_table.cc @@ -0,0 +1,216 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// profiler_stats_table.cc author Joel Cornett + +#include "profiler_stats_table.h" + +#ifdef HAVE_CONFIG_H +#include "config.h" +#endif + +#include +#include +#include + +#ifdef UNIT_TEST +#include "catch/catch.hpp" +#endif + +static constexpr unsigned WIDTH = 40; +static constexpr char ENDL = '\n'; + +const StatsTable::Header StatsTable::HEADER { '=' }; +const StatsTable::Sep StatsTable::SEP { '-' }; +const StatsTable::Row StatsTable::ROW { }; + +StatsTable::StatsTable(const Field* fields, std::ostream& os) : + fields(fields), os(os), cur(nullptr) +{ assert(fields); } + +StatsTable::~StatsTable() +{ finish(); } + +void StatsTable::header(char c) +{ + os.fill(' '); + + const auto* field = fields; + while ( field->name ) + { + format(*field); + os << field->name; + ++field; + } + + os << ENDL; + + if ( c ) + { + const auto* field = fields; + while ( field->name ) + { + format(*field); + os << std::string(strlen(field->name), c); + ++field; + } + + os << ENDL; + } +} + +void StatsTable::sep(char c) +{ os << std::string(WIDTH, c) << ENDL; } + +void StatsTable::row() +{ + finish(); + cur = fields; +} + +StatsTable& StatsTable::operator<<(StatsTable::Header h) +{ + header(h.c); + return *this; +} + +StatsTable& StatsTable::operator<<(StatsTable::Sep s) +{ + sep(s.c); + return *this; +} + +StatsTable& StatsTable::operator<<(StatsTable::Row) +{ + row(); + return *this; +} + +void StatsTable::finish() +{ + if ( cur ) + { + cur = nullptr; + os << ENDL; + } +} + +void StatsTable::format(const StatsTable::Field& field) +{ + os.flags(field.flags); + os << std::fixed; + + if ( field.fill ) + os << std::setfill(field.fill); + + if ( field.width >= 0 ) + os << std::setw(field.width); + + if ( field.precision >= 0 ) + os << std::setprecision(field.precision); +} + +#ifdef UNIT_TEST + +static const StatsTable::Field s_test_fields[] = +{ + { "foo", 7, ' ', 2, std::ios_base::fmtflags() }, + { "bar", 6, ' ', 0, std::ios_base::fmtflags() }, + { nullptr, 0, '\0', 0, std::ios_base::fmtflags() } +}; + +TEST_CASE( "profiler stats table", "[profiler][profiler_stats_table]" ) +{ + std::ostringstream ss; + StatsTable table(s_test_fields, ss); + + SECTION( "header" ) + { + std::string expected = " foo bar\n"; + + SECTION( "without separator" ) + { + table << StatsTable::Header { '\0' }; + auto result = ss.str(); + CHECK( result == expected ); + } + + SECTION( "with default separator" ) + { + expected += " === ===\n"; + table << StatsTable::HEADER; + auto result = ss.str(); + CHECK( result == expected ); + } + } + + SECTION( "separator" ) + { + SECTION( "default separator" ) + { + std::string expected = std::string(WIDTH, '-') + "\n"; + table << StatsTable::SEP; + auto result = ss.str(); + CHECK( result == expected ); + } + + SECTION( "custom separator" ) + { + std::string expected = std::string(WIDTH, '*') + "\n"; + table << StatsTable::Sep { '*' }; + auto result = ss.str(); + CHECK( result == expected ); + } + } + + SECTION( "row" ) + { + SECTION( "partial row" ) + { + std::string expected = " 12.53\n 13.11\n"; + table << StatsTable::ROW << 12.535f; + CHECK( table.next() == "bar" ); + table << StatsTable::ROW << 13.112f; + CHECK( table.next() == "bar" ); + table.finish(); + auto result = ss.str(); + CHECK( result == expected ); + } + + SECTION( "complete rows" ) + { + std::string expected = " 12.53 1\n 29.33 2\n"; + table << StatsTable::ROW << 12.535f << 1.0f; + CHECK( table.next().empty() ); + table << StatsTable::ROW << 29.333f << 2.0f; + CHECK( table.next().empty() ); + table.finish(); + auto result = ss.str(); + CHECK( result == expected ); + } + } + + SECTION( "templated operator <<" ) + { + table << "buzz"; + auto result = ss.str(); + CHECK( result == "buzz" ); + } +} + +#endif diff --git a/src/profiler/profiler_stats_table.h b/src/profiler/profiler_stats_table.h new file mode 100644 index 000000000..f0e74144b --- /dev/null +++ b/src/profiler/profiler_stats_table.h @@ -0,0 +1,98 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// profiler_stats_table.h author Joel Cornett + +#ifndef PROFILER_STATS_TABLE_H +#define PROFILER_STATS_TABLE_H + +#include +#include + +class StatsTable +{ +public: + struct Field + { + const char* name; + int width; + char fill; + int precision; + std::ios_base::fmtflags flags; + }; + + StatsTable(const Field*, std::ostream&); + ~StatsTable(); + + struct Header + { char c; }; + + struct Sep + { char c; }; + + struct Row {}; + + static const Header HEADER; + static const Sep SEP; + static const Row ROW; + + void header(char); + void sep(char); + void row(); + + template + StatsTable& operator<<(T v) + { + if ( cur ) + { + if ( !cur->name ) + finish(); + + else + format(*cur++); + } + + os << v; + + return *this; + } + + StatsTable& operator<<(Header); + StatsTable& operator<<(Sep); + StatsTable& operator<<(Row); + + void finish(); + + std::string next() + { + if ( !cur || !cur->name ) + return ""; + + return cur->name; + } + +private: + void format(const Field&); + + const Field* fields; + std::ostream& os; + + const Field* cur; +}; + +#endif diff --git a/src/profiler/rule_profiler.cc b/src/profiler/rule_profiler.cc new file mode 100644 index 000000000..491b796f2 --- /dev/null +++ b/src/profiler/rule_profiler.cc @@ -0,0 +1,698 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// rule_profiler.cc author Joel Cornett + +#include "rule_profiler.h" + +#if HAVE_CONFIG_H +#include "config.h" +#endif + +#include +#include +#include +#include +#include + +#include "detection/detection_options.h" +#include "detection/treenodes.h" +#include "hash/sfghash.h" +#include "main/snort_config.h" +#include "parser/parser.h" +#include "target_based/snort_protocols.h" + +#include "profiler_stats_table.h" +#include "rule_profiler_defs.h" + +#ifdef UNIT_TEST +#include "catch/catch.hpp" +#endif + +#define s_rule_table_title "Rule Profile Statistics" + +static const StatsTable::Field rule_fields[] = +{ + { "#", 5, '\0', 0, std::ios_base::left }, + { "gid", 6, '\0', 0, std::ios_base::fmtflags() }, + { "sid", 6, '\0', 0, std::ios_base::fmtflags() }, + { "rev", 4, '\0', 0, std::ios_base::fmtflags() }, + { "checks", 7, '\0', 0, std::ios_base::fmtflags() }, + { "matches", 8, '\0', 0, std::ios_base::fmtflags() }, + { "alerts", 7, '\0', 0, std::ios_base::fmtflags() }, + { "time (us)", 10, '\0', 0, std::ios_base::fmtflags() }, + { "avg/check", 10, '\0', 1, std::ios_base::fmtflags() }, + { "avg/match", 10, '\0', 1, std::ios_base::fmtflags() }, + { "avg/non-match", 14, '\0', 1, std::ios_base::fmtflags() }, +#ifdef PPM_MGR + { "disables", 9, '\0', 0, std::ios_base::fmtflags() }, +#endif + { nullptr, 0, '\0', 0, std::ios_base::fmtflags() } +}; + +struct RuleEntry +{ + OtnState state; + const SigInfo* sig_info; + + hr_duration elapsed() const + { return state.elapsed; } + + hr_duration elapsed_match() const + { return state.elapsed_match; } + + hr_duration elapsed_no_match() const + { return elapsed() - elapsed_match(); } + + uint64_t checks() const + { return state.checks; } + + uint64_t matches() const + { return state.matches; } + + uint64_t no_matches() const + { return checks() - matches(); } + + uint64_t alerts() const + { return state.alerts; } + +#ifdef PPM_MGR + uint64_t ppm_disable_count() const + { return state.ppm_disable_cnt; } +#endif + + hr_duration time_per(hr_duration d, uint64_t v) const + { + if ( v == 0 ) + return 0_ticks; + + return hr_duration(d.count() / v); + } + + hr_duration avg_match() const + { return time_per(elapsed_match(), matches()); } + + hr_duration avg_no_match() const + { return time_per(elapsed_no_match(), no_matches()); } + + hr_duration avg_check() const + { return time_per(elapsed(), checks()); } + + RuleEntry(const OtnState& otn_state, const SigInfo* si = nullptr) : + state(otn_state), sig_info(si) { } +}; + +using RuleEntrySortFn = std::function; + +static inline OtnState& operator+=(OtnState& lhs, const OtnState& rhs) +{ + lhs.elapsed += rhs.elapsed; + lhs.elapsed_match += rhs.elapsed_match; + lhs.checks += rhs.checks; + lhs.matches += rhs.matches; + lhs.alerts += rhs.alerts; + return lhs; +} + +static bool get_rule_sort_fn(RuleProfilerConfig::Sort sort, RuleEntrySortFn& fn) +{ + using Sort = RuleProfilerConfig::Sort; + + switch ( sort ) + { + case Sort::SORT_CHECKS: + fn = [](const RuleEntry& lhs, const RuleEntry& rhs) + { return lhs.checks() >= rhs.checks(); }; + break; + + case Sort::SORT_AVG_CHECK: + fn = [](const RuleEntry& lhs, const RuleEntry& rhs) + { return lhs.avg_check() >= rhs.avg_check(); }; + break; + + case Sort::SORT_TOTAL_TIME: + fn = [](const RuleEntry& lhs, const RuleEntry& rhs) + { return lhs.elapsed() >= rhs.elapsed(); }; + break; + + case Sort::SORT_MATCHES: + fn = [](const RuleEntry& lhs, const RuleEntry& rhs) + { return lhs.matches() >= rhs.matches(); }; + break; + + case Sort::SORT_NO_MATCHES: + fn = [](const RuleEntry& lhs, const RuleEntry& rhs) + { return lhs.no_matches() >= rhs.no_matches(); }; + break; + + case Sort::SORT_AVG_MATCH: + fn = [](const RuleEntry& lhs, const RuleEntry& rhs) + { return lhs.avg_match() >= rhs.avg_match(); }; + break; + + case Sort::SORT_AVG_NO_MATCH: + fn = [](const RuleEntry& lhs, const RuleEntry& rhs) + { return lhs.avg_no_match() >= rhs.avg_no_match(); }; + break; + + default: + return false; + break; + } + + return true; +} + +static void consolidate_otn_states(OtnState* states) +{ + for ( unsigned i = 1; i < get_instance_max(); ++i ) + states[0] += states[i]; +} + +static void build_entries(std::vector& entries) +{ + assert(snort_conf); + + detection_option_tree_update_otn_stats(snort_conf->detection_option_tree_hash_table); + auto* otn_map = snort_conf->otn_map; + + for ( auto* h = sfghash_findfirst(otn_map); h; h = sfghash_findnext(otn_map) ) + { + auto* otn = static_cast(h->data); + assert(otn); + + auto* states = otn->state; + + consolidate_otn_states(states); + auto& state = states[0]; + + if ( !state ) + continue; + + entries.emplace_back(state, &otn->sigInfo); + } +} + +static void print_single_entry(const RuleEntry& entry, unsigned n) +{ + using std::chrono::duration_cast; + using std::chrono::microseconds; + + std::ostringstream ss; + StatsTable table(rule_fields, ss); + + table << StatsTable::ROW; + + table << n; // # + + // FIXIT-L J these should be guaranteed to be non-null + table << (entry.sig_info ? entry.sig_info->generator : 0); // gid + table << (entry.sig_info ? entry.sig_info->id : 0); // sid + table << (entry.sig_info ? entry.sig_info->rev : 0); // rev + + table << entry.checks(); // checks + table << entry.matches(); // matches + table << entry.alerts(); // alerts + + table << duration_cast(entry.elapsed()).count(); // time + table << duration_cast(entry.avg_check()).count(); // avg/check + table << duration_cast(entry.avg_match()).count(); // avg/match + table << duration_cast(entry.avg_no_match()).count(); // avg/non-match + +#ifdef PPM_MGR + table << entry.ppm_disable_count(); // disables +#endif + + table.finish(); + LogMessage("%s", ss.str().c_str()); +} + +static void print_entries(std::vector& entries, unsigned count) +{ + std::ostringstream ss; + StatsTable table(rule_fields, ss); + + table << StatsTable::SEP; + + table << s_rule_table_title; + if ( count ) + table << " (worst " << count << ")\n"; + else + table << " (all)\n"; + + table << StatsTable::HEADER; + table.finish(); + + LogMessage("%s", ss.str().c_str()); + + if ( !count || count > entries.size() ) + count = entries.size(); + + for ( unsigned i = 0; i < count; ++i ) + print_single_entry(entries[i], i + 1); +} + +void show_rule_profiler_stats(const RuleProfilerConfig& config) +{ + if ( !config.show ) + return; + + std::vector entries; + build_entries(entries); + + // if there aren't any eval'd rules, don't sort or print + if ( entries.empty() ) + return; + + RuleEntrySortFn sort_fn; + if ( get_rule_sort_fn(config.sort, sort_fn) ) + { + auto stop = ( !config.count || config.count >= entries.size() ) ? + entries.end() : + entries.begin() + config.count; + + std::partial_sort(entries.begin(), stop, entries.end(), sort_fn); + } + + print_entries(entries, config.count); +} + +void reset_rule_profiler_stats() +{ + assert(snort_conf); + auto* otn_map = snort_conf->otn_map; + + for ( auto* h = sfghash_findfirst(otn_map); h; h = sfghash_findnext(otn_map) ) + { + auto* otn = static_cast(h->data); + assert(otn); + + auto* rtn = getRtnFromOtn(otn); + + if ( !rtn || !is_network_protocol(rtn->proto) ) + continue; + + for ( unsigned i = 0; i < get_instance_max(); ++i ) + { + auto& state = otn->state[i]; + state.reset(); + } + } +} + +void RuleContext::stop(bool match) +{ + if ( finished ) + return; + + finished = true; + stats.update(sw.get(), match); +} + +#ifdef UNIT_TEST + +namespace +{ +using RuleEntryVector = std::vector; +using RuleStatsVector = std::vector; +} // anonymous namespace + +static inline bool operator==(const RuleEntryVector& lhs, const RuleStatsVector& rhs) +{ + if ( lhs.size() != rhs.size() ) + return false; + + for ( unsigned i = 0; i < lhs.size(); ++i ) + if ( lhs[i].state != rhs[i] ) + return false; + + return true; +} + +static inline OtnState make_otn_state( + hr_duration elapsed, hr_duration elapsed_match, + uint64_t checks, uint64_t matches) +{ + return { + elapsed, + elapsed_match, + 0_ticks, + + checks, + matches, + 0, + 0 +#ifdef PPM_MGR + ,0, + 0 +#endif + }; +} + +static inline RuleEntry make_rule_entry( + hr_duration elapsed, hr_duration elapsed_match, + uint64_t checks, uint64_t matches) +{ + return { + make_otn_state(elapsed, elapsed_match, checks, matches), + nullptr + }; +} + +TEST_CASE( "otn state", "[profiler][rule_profiler]" ) +{ + OtnState state_a = { 1_ticks, 2_ticks, 3_ticks, 1, 2, 3, 4, 0, 0}; + + SECTION( "incremental addition" ) + { + OtnState state_b = { 4_ticks, 5_ticks, 6_ticks, 5, 6, 7, 8, 0, 0}; + + state_a += state_b; + + CHECK( state_a.elapsed == 5_ticks ); + CHECK( state_a.elapsed_match == 7_ticks ); + CHECK( state_a.checks == 6 ); + CHECK( state_a.matches == 8 ); + CHECK( state_a.alerts == 12 ); + } + + SECTION( "reset" ) + { + state_a.reset(); + CHECK( state_a.elapsed == 0_ticks ); + CHECK( state_a.elapsed_match == 0_ticks ); + CHECK( state_a.checks == 0 ); + CHECK( state_a.matches == 0 ); + CHECK( state_a.alerts == 0 ); + } + + SECTION( "bool()" ) + { + CHECK( state_a ); + + OtnState state_c = OtnState(); + CHECK_FALSE( state_c ); + + state_c.elapsed = 1_ticks; + CHECK( state_c ); + + state_c.elapsed = 0_ticks; + state_c.checks = 1; + CHECK( state_c ); + } +} + +TEST_CASE( "rule entry", "[profiler][rule_profiler]" ) +{ + SigInfo sig_info; + auto entry = make_rule_entry(3_ticks, 2_ticks, 3, 2); + entry.state.alerts = 77; +#ifdef PPM_MGR + entry.state.ppm_disable_cnt = 5; +#endif + + SECTION( "copy assignment" ) + { + auto copy = entry; + CHECK( copy.sig_info == entry.sig_info ); + CHECK( copy.state == entry.state ); + } + + SECTION( "copy construction" ) + { + RuleEntry copy(entry); + CHECK( copy.sig_info == entry.sig_info ); + CHECK( copy.state == entry.state ); + } + + SECTION( "elapsed" ) + { + CHECK( entry.elapsed() == 3_ticks ); + } + + SECTION( "elapsed_match" ) + { + CHECK( entry.elapsed_match() == 2_ticks ); + } + + SECTION( "elapsed_no_match" ) + { + CHECK( entry.elapsed_no_match() == 1_ticks ); + } + + SECTION( "checks" ) + { + CHECK( entry.checks() == 3 ); + } + + SECTION( "matches" ) + { + CHECK( entry.matches() == 2 ); + } + + SECTION( "no_matches" ) + { + CHECK( entry.no_matches() == 1 ); + } + + SECTION( "alerts" ) + { + CHECK( entry.alerts() == 77 ); + } + +#ifdef PPM_MGR + SECTION( "ppm_disable_count" ) + { + CHECK( entry.ppm_disable_count() == 5 ); + } +#endif + + SECTION( "avg_match" ) + { + auto ticks = entry.avg_match(); + INFO( ticks.count() << " == " << (1_ticks).count() ); + CHECK( ticks == 1_ticks ); + } + + SECTION( "avg_no_match" ) + { + auto ticks = entry.avg_no_match(); + INFO( ticks.count() << " == " << (1_ticks).count() ); + CHECK( ticks == 1_ticks ); + } + + SECTION( "avg_check" ) + { + auto ticks = entry.avg_check(); + INFO( ticks.count() << " == " << (1_ticks).count() ); + CHECK( ticks == 1_ticks ); + } +} + +TEST_CASE( "rule profiler sorting", "[profiler][rule_profiler]" ) +{ + using Sort = RuleProfilerConfig::Sort; + RuleEntrySortFn sort_fn; + + SECTION( "checks" ) + { + RuleEntryVector entries { + make_rule_entry(0_ticks, 0_ticks, 0, 0), + make_rule_entry(0_ticks, 0_ticks, 1, 0), + make_rule_entry(0_ticks, 0_ticks, 2, 0) + }; + + RuleStatsVector expected { + make_otn_state(0_ticks, 0_ticks, 2, 0), + make_otn_state(0_ticks, 0_ticks, 1, 0), + make_otn_state(0_ticks, 0_ticks, 0, 0) + }; + + REQUIRE( get_rule_sort_fn(Sort::SORT_CHECKS, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + CHECK( entries == expected ); + } + + SECTION( "avg_check" ) + { + RuleEntryVector entries { + make_rule_entry(2_ticks, 0_ticks, 2, 0), + make_rule_entry(8_ticks, 0_ticks, 4, 0), + make_rule_entry(4_ticks, 0_ticks, 1, 0) + }; + + RuleStatsVector expected { + make_otn_state(4_ticks, 0_ticks, 1, 0), + make_otn_state(8_ticks, 0_ticks, 4, 0), + make_otn_state(2_ticks, 0_ticks, 2, 0) + }; + + REQUIRE( get_rule_sort_fn(Sort::SORT_AVG_CHECK, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + CHECK( entries == expected ); + } + + SECTION( "total_time" ) + { + RuleEntryVector entries { + make_rule_entry(0_ticks, 0_ticks, 0, 0), + make_rule_entry(1_ticks, 0_ticks, 0, 0), + make_rule_entry(2_ticks, 0_ticks, 0, 0) + }; + + RuleStatsVector expected { + make_otn_state(2_ticks, 0_ticks, 0, 0), + make_otn_state(1_ticks, 0_ticks, 0, 0), + make_otn_state(0_ticks, 0_ticks, 0, 0) + }; + + REQUIRE( get_rule_sort_fn(Sort::SORT_TOTAL_TIME, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + CHECK( entries == expected ); + } + + SECTION( "matches" ) + { + RuleEntryVector entries { + make_rule_entry(0_ticks, 0_ticks, 0, 0), + make_rule_entry(0_ticks, 0_ticks, 0, 1), + make_rule_entry(0_ticks, 0_ticks, 0, 2) + }; + + RuleStatsVector expected { + make_otn_state(0_ticks, 0_ticks, 0, 2), + make_otn_state(0_ticks, 0_ticks, 0, 1), + make_otn_state(0_ticks, 0_ticks, 0, 0) + }; + + REQUIRE( get_rule_sort_fn(Sort::SORT_MATCHES, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + CHECK( entries == expected ); + } + + SECTION( "no matches" ) + { + RuleEntryVector entries { + make_rule_entry(0_ticks, 0_ticks, 4, 3), + make_rule_entry(0_ticks, 0_ticks, 3, 1), + make_rule_entry(0_ticks, 0_ticks, 4, 1) + }; + + RuleStatsVector expected { + make_otn_state(0_ticks, 0_ticks, 4, 1), + make_otn_state(0_ticks, 0_ticks, 3, 1), + make_otn_state(0_ticks, 0_ticks, 4, 3) + }; + + REQUIRE( get_rule_sort_fn(Sort::SORT_NO_MATCHES, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + CHECK( entries == expected ); + } + + SECTION( "avg match" ) + { + RuleEntryVector entries { + make_rule_entry(4_ticks, 0_ticks, 0, 2), + make_rule_entry(6_ticks, 0_ticks, 0, 2), + make_rule_entry(8_ticks, 0_ticks, 0, 2) + }; + + RuleStatsVector expected { + make_otn_state(8_ticks, 0_ticks, 0, 2), + make_otn_state(6_ticks, 0_ticks, 0, 2), + make_otn_state(4_ticks, 0_ticks, 0, 2) + }; + + REQUIRE( get_rule_sort_fn(Sort::SORT_AVG_MATCH, sort_fn) ); + CHECK( entries == expected ); + } + + SECTION( "avg no match" ) + { + RuleEntryVector entries { + make_rule_entry(4_ticks, 0_ticks, 6, 2), + make_rule_entry(6_ticks, 0_ticks, 5, 2), + make_rule_entry(8_ticks, 0_ticks, 2, 0) + }; + + RuleStatsVector expected { + make_otn_state(8_ticks, 0_ticks, 2, 0), + make_otn_state(6_ticks, 0_ticks, 5, 2), + make_otn_state(4_ticks, 0_ticks, 6, 2) + }; + + REQUIRE( get_rule_sort_fn(Sort::SORT_AVG_NO_MATCH, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + CHECK( entries == expected ); + } +} + +TEST_CASE( "rule profiler time context", "[profiler][rule_profiler]" ) +{ + dot_node_state_t stats; + memset(&stats, 0, sizeof(stats)); + + SECTION( "automatically updates stats" ) + { + { + RuleContext ctx(stats); + } + + CHECK( stats.elapsed > 0_ticks ); + CHECK( stats.checks == 1 ); + CHECK( stats.elapsed_match == 0_ticks ); + } + + SECTION( "explicitly calling stop" ) + { + dot_node_state_t save; + + SECTION( "stop(true)" ) + { + { + RuleContext ctx(stats); + ctx.stop(true); + + CHECK( stats.elapsed > 0_ticks ); + CHECK( stats.checks == 1 ); + CHECK( stats.elapsed_match == stats.elapsed ); + save = stats; + } + } + + SECTION( "stop(false)" ) + { + { + RuleContext ctx(stats); + ctx.stop(false); + + CHECK( stats.elapsed > 0_ticks ); + CHECK( stats.checks == 1 ); + CHECK( stats.elapsed_match == 0_ticks ); + save = stats; + } + } + + CHECK( stats.elapsed == save.elapsed ); + CHECK( stats.elapsed_match == save.elapsed_match ); + CHECK( stats.checks == save.checks ); + } +} + + +#endif diff --git a/src/profiler/rule_profiler.h b/src/profiler/rule_profiler.h new file mode 100644 index 000000000..e5efbbd29 --- /dev/null +++ b/src/profiler/rule_profiler.h @@ -0,0 +1,29 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// rule_profiler.h author Joel Cornett + +#ifndef RULE_PROFILER_H +#define RULE_PROFILER_H + +struct RuleProfilerConfig; + +void show_rule_profiler_stats(const RuleProfilerConfig&); +void reset_rule_profiler_stats(); + +#endif diff --git a/src/profiler/rule_profiler_defs.h b/src/profiler/rule_profiler_defs.h new file mode 100644 index 000000000..d8faa327b --- /dev/null +++ b/src/profiler/rule_profiler_defs.h @@ -0,0 +1,62 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// rule_profiler_defs.h author Joel Cornett + +#ifndef RULE_PROFILER_DEFS_H +#define RULE_PROFILER_DEFS_H + +#include "detection/treenodes.h" +#include "time_profiler_defs.h" + +struct dot_node_state_t; + +struct RuleProfilerConfig +{ + enum Sort + { + SORT_NONE = 0, + SORT_CHECKS, + SORT_AVG_CHECK, + SORT_TOTAL_TIME, + SORT_MATCHES, + SORT_NO_MATCHES, + SORT_AVG_MATCH, + SORT_AVG_NO_MATCH + } sort = Sort::SORT_NONE; + + unsigned count = 0; + bool show = true; +}; + +class RuleContext : public TimeContextBase +{ +public: + RuleContext(dot_node_state_t& stats) : + TimeContextBase(), stats(stats) { } + + ~RuleContext() + { stop(); } + + void stop(bool = false); + +private: + dot_node_state_t& stats; +}; + +#endif diff --git a/src/profiler/time_profiler.cc b/src/profiler/time_profiler.cc new file mode 100644 index 000000000..b416d868d --- /dev/null +++ b/src/profiler/time_profiler.cc @@ -0,0 +1,608 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// time_profiler.cc author Joel Cornett + +#include "time_profiler.h" + +#if HAVE_CONFIG_H +#include "config.h" +#endif + +#include +#include +#include +#include +#include +#include +#include + +#include "log/messages.h" + +#include "profiler_builder.h" +#include "profiler_nodes.h" +#include "profiler_stats_table.h" +#include "time_profiler_defs.h" + +#ifdef UNIT_TEST +#include "catch/catch.hpp" +#endif + +#define s_time_table_title "Module Profile Statistics" + +static const StatsTable::Field time_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() }, + { "avg/check", 11, ' ', 1, std::ios_base::fmtflags() }, + { "%/caller", 10, ' ', 2, std::ios_base::fmtflags() }, + { "%/total", 9, ' ', 2, std::ios_base::fmtflags() }, + { nullptr, 0, '\0', 0, std::ios_base::fmtflags() } +}; + +struct TimeEntry +{ + const ProfilerNode* node; + std::string name; + TimeProfilerStats stats; + TimeProfilerStats caller_stats; + std::vector entries; + + auto child_nodes() const -> const decltype(node->get_children()) + { return node->get_children(); } + + auto child_entries() -> decltype(entries)& + { return entries; } + + hr_duration elapsed() const + { return stats.elapsed; } + + uint64_t checks() const + { return stats.checks; } + + hr_duration avg_check() const + { return checks() ? hr_duration(elapsed().count() / checks()) : 0_ticks; } + + double pct_of(const TimeProfilerStats& o) const + { + if ( o.elapsed <= 0_ticks ) + return 0.0; + + return double(elapsed().count()) / double(o.elapsed.count()) * 100.0; + } + + double pct_of(const TimeEntry& o) const + { return pct_of(o.stats); } + + double pct_caller() const + { return pct_of(caller_stats); } + + operator bool() const + { return stats || !entries.empty(); } + + TimeEntry(const ProfilerNode& node, const ProfilerNode* parent = nullptr) : + node(&node), name(node.name), stats(node.get_stats().time) + { + if ( parent ) + caller_stats = parent->get_stats().time; + } +}; + +using TimeSort = TimeProfilerConfig::Sort; +using TimeBuilder = ProfilerBuilder; +using TimeIncludeFn = typename TimeBuilder::IncludeFn; +using TimeSortFn = typename TimeBuilder::SortFn; +using TimeBuilderConfig = typename TimeBuilder::Config; + +static inline bool operator==(const TimeEntry& lhs, const TimeEntry& rhs) +{ return lhs.node == rhs.node; } + +static bool s_time_include_fn(const ProfilerNode& node) +{ return node.get_stats().time; } + +static bool get_time_sort_fn(TimeSort sort, TimeSortFn& sort_fn) +{ + switch ( sort ) + { + case TimeSort::SORT_CHECKS: + sort_fn = [](const TimeEntry& lhs, const TimeEntry& rhs) + { return lhs.checks() >= rhs.checks(); }; + break; + + case TimeSort::SORT_AVG_CHECK: + sort_fn = [](const TimeEntry& lhs, const TimeEntry& rhs) + { return lhs.avg_check() >= rhs.avg_check(); }; + break; + + case TimeSort::SORT_TOTAL_TIME: + sort_fn = [](const TimeEntry& lhs, const TimeEntry& rhs) + { return lhs.elapsed() >= rhs.elapsed(); }; + break; + + default: + return false; + break; + } + + return true; +} + +static void print_single_entry(const TimeEntry& root, const TimeEntry& cur, int layer, int num) +{ + using std::chrono::duration_cast; + using std::chrono::microseconds; + + std::ostringstream ss; + StatsTable table(time_fields, ss); + + table << StatsTable::ROW; + + if ( root == cur ) + { + // if we're printing the root node + table << "--"; + table << root.name; + table << "--"; + } + + else + { + auto indent = std::string(layer, ' ') + std::to_string(num); + table << indent; // num + table << cur.name; // module + table << layer; // layer + } + + + // checks + table << cur.checks(); + + // total time + table << duration_cast(cur.elapsed()).count(); + + // avg/check + table << duration_cast(cur.avg_check()).count(); + + if ( root == cur ) + { + table << "--"; + table << "--"; + } + + else + { + table << cur.pct_caller(); // %/caller + table << cur.pct_of(root); // %/total + } + + table.finish(); + LogMessage("%s", ss.str().c_str()); +} + +static void print_children(const TimeEntry& root, const TimeEntry& cur, int layer, unsigned count) +{ + if ( !count || count > cur.entries.size() ) + count = cur.entries.size(); + + for ( unsigned i = 0; i < count; ++i ) + { + print_single_entry(root, cur.entries[i], layer + 1, i + 1); + print_children(root, cur.entries[i], layer + 1, count); + } +} + +static void print_entries(TimeEntry& root, unsigned count) +{ + std::ostringstream ss; + StatsTable table(time_fields, ss); + + table << StatsTable::SEP; + + table << s_time_table_title; + if ( count ) + table << " (worst " << count << ")\n"; + else + table << " (all)\n"; + + table << StatsTable::HEADER; + table.finish(); + + LogMessage("%s", ss.str().c_str()); + + print_children(root, root, 0, count); + print_single_entry(root, root, 0, 0); +} + +void show_time_profiler_stats(ProfilerTree& nodes, const TimeProfilerConfig& config) +{ + if ( !config.show ) + return; + + TimeIncludeFn include_fn(s_time_include_fn); + TimeSortFn sort_fn; + + TimeBuilderConfig builder_config; + builder_config.include_fn = &include_fn; + builder_config.sort_fn = get_time_sort_fn(config.sort, sort_fn) ? &sort_fn : nullptr; + builder_config.max_entries = config.count; + + TimeBuilder builder(builder_config); + + TimeEntry root(nodes.get_root()); + + builder.build(root); + + if ( root.entries.empty() && !root.stats ) + return; + + print_entries(root, config.count); +} + +#ifdef UNIT_TEST + +namespace +{ +using TimeEntryVector = std::vector; +using TimeStatsVector = std::vector; +} // anonymous namespace + +static inline bool operator==(const TimeEntryVector& lhs, const TimeStatsVector& rhs) +{ + if ( lhs.size() != rhs.size() ) + return false; + + for ( unsigned i = 0; i < lhs.size(); ++i ) + if ( lhs[i].stats != rhs[i] ) + return false; + + return true; +} + +static inline std::ostream& operator<<(std::ostream& os, const TimeProfilerStats& o) +{ + os << "{" << o.elapsed.count() << ", " << o.checks << "}"; + return os; +} + +static inline TimeEntry make_time_entry(hr_duration elapsed, uint64_t checks) +{ + ProfilerNode node(""); + TimeEntry entry(node); + entry.stats = { elapsed, checks }; + entry.node = nullptr; + return entry; +} + +TEST_CASE( "time profiler stats", "[profiler][time_profiler]" ) +{ + TimeProfilerStats stats = { 2_ticks, 3 }; + + SECTION( "equality" ) + { + auto stats_b = stats; + + CHECK( stats == stats_b ); + CHECK( stats != TimeProfilerStats() ); + } + + SECTION( "operator+=" ) + { + TimeProfilerStats stats_b = { 1_ticks, 1 }; + stats += stats_b; + + CHECK( stats.elapsed == 3_ticks ); + CHECK( stats.checks == 4 ); + } + + SECTION( "update" ) + { + stats.update(1_ticks); + + CHECK( stats.elapsed == 3_ticks ); + CHECK( stats.checks == 4 ); + } + + SECTION( "reset" ) + { + stats.reset(); + + CHECK( stats == TimeProfilerStats() ); + } + + SECTION( "bool()" ) + { + CHECK( stats ); + CHECK_FALSE( TimeProfilerStats() ); + } +} + +TEST_CASE( "time profiler entry", "[profiler][time_profiler]" ) +{ + ProfileStats the_stats = { { 12_ticks, 6 } }; + ProfilerNode node("foo"); + node.set_stats(the_stats); + + TimeEntry entry(node); + + SECTION( "constructor sets members" ) + { + CHECK( entry.name == "foo" ); + CHECK( entry.node == &node ); + CHECK( entry.entries.empty() ); + CHECK( entry.stats == the_stats ); + CHECK_FALSE( entry.caller_stats ); + } + + SECTION( "operator bool()" ) + { + REQUIRE( entry.child_entries().empty() ); + REQUIRE( entry.stats ); + + CHECK( entry ); + + entry.stats.reset(); + CHECK_FALSE( entry ); + + entry.child_entries().push_back(entry); + CHECK( entry ); + } + + SECTION( "elapsed" ) + { + CHECK( entry.elapsed() == 12_ticks ); + } + + SECTION( "checks" ) + { + CHECK( entry.checks() == 6 ); + } + + SECTION( "avg_check" ) + { + CHECK( entry.avg_check() == 2_ticks ); + } + + SECTION( "pct_of" ) + { + TimeProfilerStats tps = { 24_ticks, 0 }; + CHECK( entry.pct_of(tps) == 50.0 ); + CHECK( entry.pct_of(entry) == 100.0 ); + + SECTION( "pct_caller" ) + { + entry.caller_stats = tps; + CHECK( entry.pct_caller() == 50.0 ); + } + } +} + +TEST_CASE( "time profiler sorting", "[profiler][time_profiler]" ) +{ + using Sort = TimeProfilerConfig::Sort; + + TimeSortFn sort_fn; + + SECTION( "checks" ) + { + TimeEntryVector entries { + make_time_entry(0_ticks, 0), + make_time_entry(0_ticks, 10), + make_time_entry(1_ticks, 5) + }; + + TimeStatsVector expected { + { 0_ticks, 10 }, + { 1_ticks, 5 }, + { 0_ticks, 0 } + }; + + REQUIRE( get_time_sort_fn(Sort::SORT_CHECKS, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + + CHECK( entries == expected ); + } + + SECTION( "avg_check" ) + { + TimeEntryVector entries { + make_time_entry(0_ticks, 0), + make_time_entry(10_ticks, 10), + make_time_entry(10_ticks, 5) + }; + + TimeStatsVector expected { + { 10_ticks, 5 }, + { 10_ticks, 10 }, + { 0_ticks, 0 } + }; + + REQUIRE( get_time_sort_fn(Sort::SORT_AVG_CHECK, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + + CHECK( entries == expected ); + } + + SECTION( "total_time" ) + { + TimeEntryVector entries { + make_time_entry(0_ticks, 0), + make_time_entry(10_ticks, 10), + make_time_entry(11_ticks, 5) + }; + + TimeStatsVector expected { + { 11_ticks, 5 }, + { 10_ticks, 10 }, + { 0_ticks, 0 } + }; + + REQUIRE( get_time_sort_fn(Sort::SORT_TOTAL_TIME, sort_fn) ); + std::stable_sort(entries.begin(), entries.end(), sort_fn); + + CHECK( entries == expected ); + } +} + +TEST_CASE( "build entries", "[profiler][time_profiler]" ) +{ + // Tree should look like + // + // A -- B -- D + // | + // - C -- E + // | + // - F + // + + ProfileStats stats; + stats.time = { 1_ticks, 1 }; // make non-zero + REQUIRE( stats.time ); + + // Construct the node tree + ProfilerNode a("a"), b("b"), c("c"), d("d"), e("e"), f("f"); + a.add_child(&b); a.add_child(&c); + b.add_child(&d); + c.add_child(&e); c.add_child(&f); + + // Set the stats for each node + a.set_stats(stats); + b.set_stats(stats); + c.set_stats(stats); + d.set_stats(stats); + e.set_stats(stats); + f.set_stats(stats); + + TimeEntry root(a); + + TimeIncludeFn include_fn = s_time_include_fn; + TimeBuilderConfig builder_config; + builder_config.include_fn = &include_fn; + TimeBuilder builder(builder_config); + + builder.build(root); + + CHECK( root.name == "a" ); + CHECK( root.entries.size() == 2 ); + + for ( const auto& child_L1 : root.entries ) + { + if ( child_L1.name == "b" ) + { + REQUIRE( child_L1.entries.size() == 1 ); + auto& child_L2 = child_L1.entries[0]; + CHECK( child_L2.name == "d" ); + CHECK( child_L2.entries.size() == 0 ); + } + + else if ( child_L1.name == "c" ) + { + CHECK( child_L1.entries.size() == 2 ); + for ( const auto& child_L2 : child_L1.entries ) + { + if ( child_L2.name == "e" ) + CHECK( child_L2.entries.size() == 0 ); + + else if ( child_L2.name == "f" ) + CHECK( child_L2.entries.size() == 0 ); + + else + FAIL( + "expected 'e' or 'f' node, instead got '" << + child_L1.name << "'" + ); + + } + } + + else + FAIL( + "expected 'b' or 'c' node, instead got '" << + child_L1.name << "'" + ); + } +} + +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" ) + { + { + TimeContext ctx(stats); + } + + CHECK( stats.elapsed > 0_ticks ); + CHECK( stats.checks == 1 ); + } + + SECTION( "explicitly calling stop updates stats ONCE" ) + { + TimeProfilerStats save; + + { + TimeContext ctx(stats); + ctx.stop(); + + CHECK( stats.elapsed > 0_ticks ); + CHECK( stats.checks == 1 ); + save = stats; + } + + CHECK( stats == save ); + } +} + +TEST_CASE( "time context pause", "[profiler][time_profiler]" ) +{ + TimeContextBase ctx; + + { + TimePause pause(ctx); + CHECK_FALSE( ctx.active() ); + } + + CHECK( ctx.active() ); +} + +#endif diff --git a/src/profiler/time_profiler.h b/src/profiler/time_profiler.h new file mode 100644 index 000000000..e7c8b1631 --- /dev/null +++ b/src/profiler/time_profiler.h @@ -0,0 +1,29 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// time_profiler.h author Joel Cornett + +#ifndef TIME_PROFILER_H +#define TIME_PROFILER_H + +class ProfilerTree; +struct TimeProfilerConfig; + +void show_time_profiler_stats(ProfilerTree&, const TimeProfilerConfig&); + +#endif diff --git a/src/profiler/time_profiler_defs.h b/src/profiler/time_profiler_defs.h new file mode 100644 index 000000000..302e570db --- /dev/null +++ b/src/profiler/time_profiler_defs.h @@ -0,0 +1,133 @@ +//-------------------------------------------------------------------------- +// Copyright (C) 2015-2015 Cisco and/or its affiliates. All rights reserved. +// +// This program is free software; you can redistribute it and/or modify it +// under the terms of the GNU General Public License Version 2 as published +// by the Free Software Foundation. You may not use, modify or distribute +// this program under any other version of the GNU General Public License. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with this program; if not, write to the Free Software Foundation, Inc., +// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. +//-------------------------------------------------------------------------- + +// time_profiler_defs.h author Joel Cornett + +#ifndef TIME_PROFILER_DEFS_H +#define TIME_PROFILER_DEFS_H + +#include "main/snort_types.h" +#include "time/clock_defs.h" +#include "time/stopwatch.h" + +struct TimeProfilerConfig +{ + enum Sort + { + SORT_NONE = 0, + SORT_CHECKS, + SORT_AVG_CHECK, + SORT_TOTAL_TIME + } sort = Sort::SORT_NONE; + + unsigned count = 0; + bool show = true; +}; + +struct SO_PUBLIC TimeProfilerStats +{ + hr_duration elapsed; + uint64_t checks; + + void update(hr_duration delta) + { elapsed += delta; ++checks; } + + void reset() + { elapsed = 0_ticks; checks = 0; } + + operator bool() const + { return ( elapsed > 0_ticks ) || checks; } + + constexpr TimeProfilerStats() : + elapsed(0_ticks), checks(0) { } + + constexpr TimeProfilerStats(hr_duration elapsed, uint64_t checks) : + elapsed(elapsed), checks(checks) { } +}; + +inline bool operator==(const TimeProfilerStats& lhs, const TimeProfilerStats& rhs) +{ return (lhs.elapsed == rhs.elapsed) && (lhs.checks == rhs.checks); } + +inline bool operator!=(const TimeProfilerStats& lhs, const TimeProfilerStats& rhs) +{ return !(lhs == rhs); } + +inline TimeProfilerStats& operator+=(TimeProfilerStats& lhs, const TimeProfilerStats& rhs) +{ + lhs.elapsed += rhs.elapsed; + lhs.checks += rhs.checks; + return lhs; +} + +class TimeContextBase +{ +public: + TimeContextBase() : + finished(false) + { start(); } + + void start() + { sw.start(); } + + void pause() + { sw.stop(); } + + bool active() const + { return sw.active(); } + +protected: + Stopwatch sw; + bool finished; +}; + +class SO_PUBLIC TimeContext : public TimeContextBase +{ +public: + TimeContext(TimeProfilerStats& stats) : + TimeContextBase(), stats(stats) { } + + ~TimeContext() + { stop(); } + + void stop() + { + if ( finished ) + return; + + finished = true; + stats.update(sw.get()); + } + +private: + TimeProfilerStats& stats; +}; + +class SO_PUBLIC TimePause +{ +public: + TimePause(TimeContextBase& ctx) : + ctx(ctx) + { ctx.pause(); } + + ~TimePause() + { ctx.start(); } + +private: + TimeContextBase& ctx; +}; + +#endif diff --git a/src/protocols/packet_manager.cc b/src/protocols/packet_manager.cc index 55ef4b5d7..09e25e487 100644 --- a/src/protocols/packet_manager.cc +++ b/src/protocols/packet_manager.cc @@ -185,7 +185,7 @@ RawData::RawData(const DAQ_PktHdr_t* h, const uint8_t* p) void PacketManager::decode( Packet* p, const DAQ_PktHdr_t* pkthdr, const uint8_t* pkt, bool cooked) { - PERF_PROFILE(decodePerfStats); + Profile profile(decodePerfStats); DecodeData unsure_encap_ptrs; diff --git a/src/service_inspectors/back_orifice/back_orifice.cc b/src/service_inspectors/back_orifice/back_orifice.cc index c4553afaf..4b14ace16 100644 --- a/src/service_inspectors/back_orifice/back_orifice.cc +++ b/src/service_inspectors/back_orifice/back_orifice.cc @@ -466,7 +466,7 @@ void BackOrifice::show(SnortConfig*) void BackOrifice::eval(Packet* p) { - PERF_PROFILE(boPerfStats); + Profile profile(boPerfStats); const char* const magic_cookie = "*!*QWTY?"; diff --git a/src/service_inspectors/dnp3/dnp3.cc b/src/service_inspectors/dnp3/dnp3.cc index a78a225eb..956936d92 100644 --- a/src/service_inspectors/dnp3/dnp3.cc +++ b/src/service_inspectors/dnp3/dnp3.cc @@ -235,7 +235,7 @@ void Dnp3::show(SnortConfig*) void Dnp3::eval(Packet* p) { - PERF_PROFILE(dnp3_perf_stats); + Profile profile(dnp3_perf_stats); assert (p->has_tcp_data() || p->has_udp_data()); assert(p->flow); diff --git a/src/service_inspectors/dnp3/dnp3_reassembly.cc b/src/service_inspectors/dnp3/dnp3_reassembly.cc index 59768b8d7..1ef3265ce 100644 --- a/src/service_inspectors/dnp3/dnp3_reassembly.cc +++ b/src/service_inspectors/dnp3/dnp3_reassembly.cc @@ -407,11 +407,13 @@ bool dnp3_full_reassembly(dnp3ProtoConf& config, dnp3_session_data_t* session, P if ((ret == true) && (packet->is_udp())) { ProfileStats dnp3_detect_perf_stats; - PERF_PROFILE_BLOCK(dnp3_detect_perf_stats) + { + Profile profile(dnp3_detect_perf_stats); snort_detect(packet); } - dnp3_perf_stats.elapsed -= dnp3_detect_perf_stats.elapsed; + + dnp3_perf_stats.time.elapsed -= dnp3_detect_perf_stats.time.elapsed; /* Since detection was done, reset reassembly state to avoid double alerts on the last PDU */ diff --git a/src/service_inspectors/dnp3/ips_dnp3_data.cc b/src/service_inspectors/dnp3/ips_dnp3_data.cc index 0f5add0ce..52f3204ca 100644 --- a/src/service_inspectors/dnp3/ips_dnp3_data.cc +++ b/src/service_inspectors/dnp3/ips_dnp3_data.cc @@ -67,7 +67,7 @@ bool Dnp3DataOption::operator==(const IpsOption& ips) const int Dnp3DataOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(dnp3_data_perf_stats); + Profile profile(dnp3_data_perf_stats); if ((p->has_tcp_data() && !p->is_full_pdu()) || !p->flow || !p->dsize) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/dnp3/ips_dnp3_func.cc b/src/service_inspectors/dnp3/ips_dnp3_func.cc index fb530b5c1..6cf70ee7e 100644 --- a/src/service_inspectors/dnp3/ips_dnp3_func.cc +++ b/src/service_inspectors/dnp3/ips_dnp3_func.cc @@ -74,7 +74,7 @@ bool Dnp3FuncOption::operator==(const IpsOption& ips) const int Dnp3FuncOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(dnp3_func_perf_stats); + Profile profile(dnp3_func_perf_stats); if ((p->has_tcp_data() && !p->is_full_pdu()) || !p->flow || !p->dsize) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/dnp3/ips_dnp3_ind.cc b/src/service_inspectors/dnp3/ips_dnp3_ind.cc index c63d5eae6..0c1949095 100644 --- a/src/service_inspectors/dnp3/ips_dnp3_ind.cc +++ b/src/service_inspectors/dnp3/ips_dnp3_ind.cc @@ -75,7 +75,7 @@ bool Dnp3IndOption::operator==(const IpsOption& ips) const int Dnp3IndOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(dnp3_ind_perf_stats); + Profile profile(dnp3_ind_perf_stats); if ((p->has_tcp_data() && !p->is_full_pdu()) || !p->flow || !p->dsize) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/dnp3/ips_dnp3_obj.cc b/src/service_inspectors/dnp3/ips_dnp3_obj.cc index 98eaa7e25..0c208371d 100644 --- a/src/service_inspectors/dnp3/ips_dnp3_obj.cc +++ b/src/service_inspectors/dnp3/ips_dnp3_obj.cc @@ -105,7 +105,7 @@ bool Dnp3ObjOption::operator==(const IpsOption& ips) const int Dnp3ObjOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(dnp3_obj_perf_stats); + Profile profile(dnp3_obj_perf_stats); size_t header_size; diff --git a/src/service_inspectors/dns/dns.cc b/src/service_inspectors/dns/dns.cc index 3dfa673e3..e78a7c459 100644 --- a/src/service_inspectors/dns/dns.cc +++ b/src/service_inspectors/dns/dns.cc @@ -1022,7 +1022,7 @@ void ParseDNSResponseMessage(Packet* p, DNSData* dnsSessionData) static void snort_dns(Packet* p) { - PERF_PROFILE(dnsPerfStats); + Profile profile(dnsPerfStats); // For TCP, do a few extra checks... if ( p->has_tcp_data() ) diff --git a/src/service_inspectors/ftp_telnet/ft_main.cc b/src/service_inspectors/ftp_telnet/ft_main.cc index d87642d0f..bda129f87 100644 --- a/src/service_inspectors/ftp_telnet/ft_main.cc +++ b/src/service_inspectors/ftp_telnet/ft_main.cc @@ -69,17 +69,18 @@ #include "sfip/sf_ip.h" // FIXIT-M ftp, http, etc. should not be calling snort_detect() -static THREAD_LOCAL int ftppDetectCalled = 0; +static THREAD_LOCAL bool ftppDetectCalled = false; static THREAD_LOCAL ProfileStats ftppDetectPerfStats; +// FIXIT-M J need a better way to "pause" current profiling context, +// see http_inspect void ft_update_perf(ProfileStats& stats) { - if (ftppDetectCalled) + if ( ftppDetectCalled ) { - stats.elapsed -= ftppDetectPerfStats.elapsed; + stats.time.elapsed -= ftppDetectPerfStats.time.elapsed; ftppDetectPerfStats.reset(); - // FIXIT-L J should be a bool - ftppDetectCalled = 0; + ftppDetectCalled = false; } } @@ -245,7 +246,7 @@ int FTPCheckConfigs(SnortConfig* sc, void* pData) */ void do_detection(Packet* p) { - PERF_PROFILE(ftppDetectPerfStats); + Profile profile(ftppDetectPerfStats); // If we get here we either had a client or server request/response. // We do the detection here, because we're starting a new paradigm @@ -259,6 +260,6 @@ void do_detection(Packet* p) get_data_bus().publish(PACKET_EVENT, p); DisableInspection(p); - ftppDetectCalled = 1; + ftppDetectCalled = true; } diff --git a/src/service_inspectors/ftp_telnet/ftp.cc b/src/service_inspectors/ftp_telnet/ftp.cc index a5cec6843..2bb9168b5 100644 --- a/src/service_inspectors/ftp_telnet/ftp.cc +++ b/src/service_inspectors/ftp_telnet/ftp.cc @@ -73,7 +73,7 @@ static inline int InspectClientPacket(Packet* p) static int SnortFTP( FTP_SESSION* FTPsession, Packet* p, int iInspectMode) { - PERF_PROFILE(ftpPerfStats); + Profile profile(ftpPerfStats); if ( !FTPsession || !FTPsession->server_conf || !FTPsession->client_conf ) return FTPP_INVALID_SESSION; diff --git a/src/service_inspectors/ftp_telnet/ftp_data.cc b/src/service_inspectors/ftp_telnet/ftp_data.cc index 7bb0e8976..cabef44f3 100644 --- a/src/service_inspectors/ftp_telnet/ftp_data.cc +++ b/src/service_inspectors/ftp_telnet/ftp_data.cc @@ -251,7 +251,7 @@ ProfileStats* FtpDataModule::get_profile() const void FtpData::eval(Packet* p) { - PERF_PROFILE(ftpdataPerfStats); + Profile profile(ftpdataPerfStats); // precondition - what we registered for assert(p->has_tcp_data()); diff --git a/src/service_inspectors/ftp_telnet/telnet.cc b/src/service_inspectors/ftp_telnet/telnet.cc index 1cf7c0c35..f4084f1f0 100644 --- a/src/service_inspectors/ftp_telnet/telnet.cc +++ b/src/service_inspectors/ftp_telnet/telnet.cc @@ -76,7 +76,7 @@ static int TelnetCheckConfigs(SnortConfig*, void* pData) static int SnortTelnet(TELNET_PROTO_CONF* telnet_config, TELNET_SESSION* Telnetsession, Packet* p, int iInspectMode) { - PERF_PROFILE(telnetPerfStats); + Profile profile(telnetPerfStats); if ( !Telnetsession ) return FTPP_NONFATAL_ERR; diff --git a/src/service_inspectors/gtp/gtp_inspect.cc b/src/service_inspectors/gtp/gtp_inspect.cc index f32c59c6b..377673dce 100644 --- a/src/service_inspectors/gtp/gtp_inspect.cc +++ b/src/service_inspectors/gtp/gtp_inspect.cc @@ -88,7 +88,7 @@ GtpInspect::GtpInspect(std::vector& v) void GtpInspect::eval(Packet* p) { - PERF_PROFILE(gtp_inspect_prof); + Profile profile(gtp_inspect_prof); // preconditions - what we registered for assert(p->has_udp_data()); diff --git a/src/service_inspectors/gtp/ips_gtp_info.cc b/src/service_inspectors/gtp/ips_gtp_info.cc index 07ec4c598..88fae6fba 100644 --- a/src/service_inspectors/gtp/ips_gtp_info.cc +++ b/src/service_inspectors/gtp/ips_gtp_info.cc @@ -100,7 +100,7 @@ bool GtpInfoOption::operator==(const IpsOption& ips) const int GtpInfoOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(gtp_info_prof); + Profile profile(gtp_info_prof); if ( !p or !p->flow ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/gtp/ips_gtp_type.cc b/src/service_inspectors/gtp/ips_gtp_type.cc index 29ee80470..5d891483b 100644 --- a/src/service_inspectors/gtp/ips_gtp_type.cc +++ b/src/service_inspectors/gtp/ips_gtp_type.cc @@ -100,7 +100,7 @@ bool GtpTypeOption::operator==(const IpsOption& ips) const int GtpTypeOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(gtp_type_prof); + Profile profile(gtp_type_prof); if ( !p or !p->flow ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/gtp/ips_gtp_version.cc b/src/service_inspectors/gtp/ips_gtp_version.cc index d81a12647..970f2b3dc 100644 --- a/src/service_inspectors/gtp/ips_gtp_version.cc +++ b/src/service_inspectors/gtp/ips_gtp_version.cc @@ -79,7 +79,7 @@ bool GtpVersionOption::operator==(const IpsOption& ips) const int GtpVersionOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(gtp_ver_prof); + Profile profile(gtp_ver_prof); if ( !p or !p->flow ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/http_inspect/hi_main.cc b/src/service_inspectors/http_inspect/hi_main.cc index 61fdd72b7..ab49fdcff 100644 --- a/src/service_inspectors/http_inspect/hi_main.cc +++ b/src/service_inspectors/http_inspect/hi_main.cc @@ -610,11 +610,10 @@ int HttpInspectMain(HTTPINSPECT_CONF* conf, Packet* p) return 0; } // see comments on call to snort_detect() below - PERF_PROFILE_BLOCK(hiDetectPerfStats) { + Profile profile(hiDetectPerfStats); get_data_bus().publish(PACKET_EVENT, p); - // FIXIT-L J should be a bool - hiDetectCalled = 1; + hiDetectCalled = true; } return 0; @@ -1104,10 +1103,10 @@ int HttpInspectMain(HTTPINSPECT_CONF* conf, Packet* p) ** better than having all these Packet struct field checks in the ** main detection engine for each protocol field. */ - PERF_PROFILE_BLOCK(hiDetectPerfStats) { + Profile profile(hiDetectPerfStats); snort_detect(p); - hiDetectCalled = 1; + hiDetectCalled = true; } /* diff --git a/src/service_inspectors/http_inspect/hi_main.h b/src/service_inspectors/http_inspect/hi_main.h index 089635b9e..bf1a4bab9 100644 --- a/src/service_inspectors/http_inspect/hi_main.h +++ b/src/service_inspectors/http_inspect/hi_main.h @@ -79,7 +79,7 @@ extern SO_PUBLIC THREAD_LOCAL HttpBuffer http_buffer[HTTP_BUFFER_MAX]; extern THREAD_LOCAL DataBuffer HttpDecodeBuf; extern THREAD_LOCAL ProfileStats hiDetectPerfStats; -extern THREAD_LOCAL int hiDetectCalled; +extern THREAD_LOCAL bool hiDetectCalled; typedef enum _HttpRespCompressType { diff --git a/src/service_inspectors/http_inspect/http_inspect.cc b/src/service_inspectors/http_inspect/http_inspect.cc index 1379acbe3..ebd105db6 100644 --- a/src/service_inspectors/http_inspect/http_inspect.cc +++ b/src/service_inspectors/http_inspect/http_inspect.cc @@ -99,7 +99,7 @@ const PegInfo peg_names[] = { nullptr, nullptr } }; -THREAD_LOCAL int hiDetectCalled = 0; +THREAD_LOCAL bool hiDetectCalled = false; /* ** Prototypes @@ -318,7 +318,7 @@ void HttpInspect::show(SnortConfig*) void HttpInspect::eval(Packet* p) { - PERF_PROFILE(hiPerfStats); + Profile profile(hiPerfStats); // preconditions - what we registered for assert(p->has_tcp_data()); @@ -338,11 +338,13 @@ void HttpInspect::eval(Packet* p) * spent in snort_detect(). * Subtract the ticks from this if iCallDetect == 0 */ - if (hiDetectCalled) + // FIXIT-M J need better a way to pause a profiler when the context + // is not visible from the current scope + if ( hiDetectCalled ) { - hiPerfStats.elapsed -= hiDetectPerfStats.elapsed; - hiDetectPerfStats.reset(); - hiDetectCalled = 0; + hiPerfStats.time.elapsed -= hiDetectPerfStats.time.elapsed; + hiDetectPerfStats.time.reset(); + hiDetectCalled = false; } } diff --git a/src/service_inspectors/imap/imap.cc b/src/service_inspectors/imap/imap.cc index 4ab188015..1b6f71849 100644 --- a/src/service_inspectors/imap/imap.cc +++ b/src/service_inspectors/imap/imap.cc @@ -778,7 +778,7 @@ void Imap::show(SnortConfig*) void Imap::eval(Packet* p) { - PERF_PROFILE(imapPerfStats); + Profile profile(imapPerfStats); // precondition - what we registered for assert(p->has_tcp_data()); diff --git a/src/service_inspectors/modbus/ips_modbus_data.cc b/src/service_inspectors/modbus/ips_modbus_data.cc index 4cebf9731..c10983a81 100644 --- a/src/service_inspectors/modbus/ips_modbus_data.cc +++ b/src/service_inspectors/modbus/ips_modbus_data.cc @@ -68,7 +68,7 @@ bool ModbusDataOption::operator==(const IpsOption& ips) const int ModbusDataOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE(modbus_data_prof); + Profile profile(modbus_data_prof); if ( !p->flow ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/modbus/ips_modbus_func.cc b/src/service_inspectors/modbus/ips_modbus_func.cc index b7a36d06e..8462f85a9 100644 --- a/src/service_inspectors/modbus/ips_modbus_func.cc +++ b/src/service_inspectors/modbus/ips_modbus_func.cc @@ -122,7 +122,7 @@ bool ModbusFuncOption::operator==(const IpsOption& ips) const int ModbusFuncOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(modbus_func_prof); + Profile profile(modbus_func_prof); if ( !p->flow ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/modbus/ips_modbus_unit.cc b/src/service_inspectors/modbus/ips_modbus_unit.cc index 988800f3f..0e4057efd 100644 --- a/src/service_inspectors/modbus/ips_modbus_unit.cc +++ b/src/service_inspectors/modbus/ips_modbus_unit.cc @@ -74,7 +74,7 @@ bool ModbusUnitOption::operator==(const IpsOption& ips) const int ModbusUnitOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(modbus_unit_prof); + Profile profile(modbus_unit_prof); if ( !p->flow ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/modbus/modbus.cc b/src/service_inspectors/modbus/modbus.cc index 60416ea22..ad4d6f140 100644 --- a/src/service_inspectors/modbus/modbus.cc +++ b/src/service_inspectors/modbus/modbus.cc @@ -69,7 +69,7 @@ public: void Modbus::eval(Packet* p) { - PERF_PROFILE(modbus_prof); + Profile profile(modbus_prof); // preconditions - what we registered for assert(p->has_tcp_data()); diff --git a/src/service_inspectors/pop/pop.cc b/src/service_inspectors/pop/pop.cc index 44b6908cb..3039133a1 100644 --- a/src/service_inspectors/pop/pop.cc +++ b/src/service_inspectors/pop/pop.cc @@ -714,7 +714,7 @@ void Pop::show(SnortConfig*) void Pop::eval(Packet* p) { - PERF_PROFILE(popPerfStats); + Profile profile(popPerfStats); // precondition - what we registered for assert(p->has_tcp_data()); diff --git a/src/service_inspectors/rpc_decode/rpc_decode.cc b/src/service_inspectors/rpc_decode/rpc_decode.cc index e4fc332da..0af3689c2 100644 --- a/src/service_inspectors/rpc_decode/rpc_decode.cc +++ b/src/service_inspectors/rpc_decode/rpc_decode.cc @@ -988,7 +988,7 @@ void RpcDecode::show(SnortConfig*) */ void RpcDecode::eval(Packet* p) { - PERF_PROFILE(rpcdecodePerfStats); + Profile profile(rpcdecodePerfStats); // preconditions - what we registered for assert(p->has_tcp_data()); diff --git a/src/service_inspectors/sip/ips_sip.cc b/src/service_inspectors/sip/ips_sip.cc index e7bf6863a..330444d54 100644 --- a/src/service_inspectors/sip/ips_sip.cc +++ b/src/service_inspectors/sip/ips_sip.cc @@ -100,7 +100,7 @@ private: int SipIpsOption::eval(Cursor& c, Packet* p) { - PERF_PROFILE_THREAD_LOCAL(sip_ps, idx); + Profile profile(sip_ps[idx]); SIPData* sd; SIP_Roptions* ropts; diff --git a/src/service_inspectors/sip/ips_sip_method.cc b/src/service_inspectors/sip/ips_sip_method.cc index 99888b137..59e581ce3 100644 --- a/src/service_inspectors/sip/ips_sip_method.cc +++ b/src/service_inspectors/sip/ips_sip_method.cc @@ -99,7 +99,7 @@ bool SipMethodOption::operator==(const IpsOption& ips) const int SipMethodOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(sipMethodRuleOptionPerfStats); + Profile profile(sipMethodRuleOptionPerfStats); if ((!p->is_tcp() && !p->is_udp()) || !p->flow || !p->dsize) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/sip/ips_sip_stat_code.cc b/src/service_inspectors/sip/ips_sip_stat_code.cc index 04ad8428d..f10de61ff 100644 --- a/src/service_inspectors/sip/ips_sip_stat_code.cc +++ b/src/service_inspectors/sip/ips_sip_stat_code.cc @@ -61,7 +61,7 @@ private: int SipStatCodeOption::eval(Cursor&, Packet* p) { - PERF_PROFILE(sipStatCodeRuleOptionPerfStats); + Profile profile(sipStatCodeRuleOptionPerfStats); if ((!p->is_tcp() && !p->is_udp()) || !p->flow || !p->dsize) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/sip/sip.cc b/src/service_inspectors/sip/sip.cc index 6ea824ceb..7ea518c8b 100644 --- a/src/service_inspectors/sip/sip.cc +++ b/src/service_inspectors/sip/sip.cc @@ -243,7 +243,7 @@ static inline int SIP_Process(Packet* p, SIPData* sessp, SIP_PROTO_CONF* config) */ static void snort_sip(SIP_PROTO_CONF* config, Packet* p) { - PERF_PROFILE(sipPerfStats); + Profile profile(sipPerfStats); /* Attempt to get a previously allocated SIP block. */ SIPData* sessp = get_sip_session_data(p->flow); diff --git a/src/service_inspectors/smtp/smtp.cc b/src/service_inspectors/smtp/smtp.cc index 7c06c1e96..f9109b0a5 100644 --- a/src/service_inspectors/smtp/smtp.cc +++ b/src/service_inspectors/smtp/smtp.cc @@ -1553,7 +1553,7 @@ void Smtp::show(SnortConfig*) void Smtp::eval(Packet* p) { - PERF_PROFILE(smtpPerfStats); + Profile profile(smtpPerfStats); // precondition - what we registered for assert(p->has_tcp_data()); diff --git a/src/service_inspectors/ssh/ssh.cc b/src/service_inspectors/ssh/ssh.cc index 1976f23c7..a81092b87 100644 --- a/src/service_inspectors/ssh/ssh.cc +++ b/src/service_inspectors/ssh/ssh.cc @@ -141,7 +141,7 @@ static unsigned int SSHPacket_GetLength(SSH2Packet* p, size_t buflen) */ static void snort_ssh(SSH_PROTO_CONF* config, Packet* p) { - PERF_PROFILE(sshPerfStats); + Profile profile(sshPerfStats); // Attempt to get a previously allocated SSH block. SSHData* sessp = get_session_data(p->flow); diff --git a/src/service_inspectors/ssl/ips_ssl_state.cc b/src/service_inspectors/ssl/ips_ssl_state.cc index eb888474c..c208c62fb 100644 --- a/src/service_inspectors/ssl/ips_ssl_state.cc +++ b/src/service_inspectors/ssl/ips_ssl_state.cc @@ -98,7 +98,7 @@ bool SslStateOption::operator==(const IpsOption& ips) const int SslStateOption::eval(Cursor&, Packet* pkt) { - PERF_PROFILE(sslStateRuleOptionPerfStats); + Profile profile(sslStateRuleOptionPerfStats); if ( !(pkt->packet_flags & PKT_REBUILT_STREAM) && !pkt->is_full_pdu() ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/ssl/ips_ssl_version.cc b/src/service_inspectors/ssl/ips_ssl_version.cc index f03bbbf34..5afcf08f8 100644 --- a/src/service_inspectors/ssl/ips_ssl_version.cc +++ b/src/service_inspectors/ssl/ips_ssl_version.cc @@ -98,7 +98,7 @@ bool SslVersionOption::operator==(const IpsOption& ips) const int SslVersionOption::eval(Cursor&, Packet* pkt) { - PERF_PROFILE(sslVersionRuleOptionPerfStats); + Profile profile(sslVersionRuleOptionPerfStats); if ( !(pkt->packet_flags & PKT_REBUILT_STREAM) && !pkt->is_full_pdu() ) return DETECTION_OPTION_NO_MATCH; diff --git a/src/service_inspectors/ssl/ssl_inspector.cc b/src/service_inspectors/ssl/ssl_inspector.cc index f331c4901..273ca4303 100644 --- a/src/service_inspectors/ssl/ssl_inspector.cc +++ b/src/service_inspectors/ssl/ssl_inspector.cc @@ -297,7 +297,7 @@ static inline void SSLPP_process_other(SSL_PROTO_CONF* config, SSLData* sd, uint */ static void snort_ssl(SSL_PROTO_CONF* config, Packet* p) { - PERF_PROFILE(sslPerfStats); + Profile profile(sslPerfStats); /* Attempt to get a previously allocated SSL block. */ SSLData* sd = get_ssl_session_data(p->flow); diff --git a/src/stream/base/stream_base.cc b/src/stream/base/stream_base.cc index 8be1402b0..940680924 100644 --- a/src/stream/base/stream_base.cc +++ b/src/stream/base/stream_base.cc @@ -243,7 +243,7 @@ void StreamBase::show(SnortConfig*) void StreamBase::eval(Packet* p) { - PERF_PROFILE(s5PerfStats); + Profile profile(s5PerfStats); if ( !is_eligible(p) ) return; diff --git a/src/stream/file/file_session.cc b/src/stream/file/file_session.cc index f932ad8c6..90cbdda3a 100644 --- a/src/stream/file/file_session.cc +++ b/src/stream/file/file_session.cc @@ -72,7 +72,7 @@ static FilePosition position(Packet* p) int FileSession::process(Packet* p) { - PERF_PROFILE(file_ssn_stats); + Profile profile(file_ssn_stats); p->flow->ssn_state.application_protocol = SNORT_PROTO_USER; StreamFileConfig* c = get_file_cfg(p->flow->ssn_server); diff --git a/src/stream/ip/ip_defrag.cc b/src/stream/ip/ip_defrag.cc index 4d1faf173..88ed957c6 100644 --- a/src/stream/ip/ip_defrag.cc +++ b/src/stream/ip/ip_defrag.cc @@ -776,7 +776,7 @@ static inline int FragIsComplete(FragTracker* ft) */ static void FragRebuild(FragTracker* ft, Packet* p) { - PERF_PROFILE(fragRebuildPerfStats); + Profile profile(fragRebuildPerfStats); static THREAD_LOCAL uint8_t encap_frag_cnt = 0; uint8_t* rebuild_ptr = NULL; /* ptr to the start of the reassembly buffer */ @@ -1215,7 +1215,7 @@ void Defrag::process(Packet* p, FragTracker* ft) ip_stats.total++; UpdateIPFragStats(&sfBase, p->pkth->caplen); - PERF_PROFILE(fragPerfStats); + Profile profile(fragPerfStats); pkttime = (struct timeval*)&p->pkth->ts; @@ -1390,7 +1390,7 @@ int Defrag::insert(Packet* p, FragTracker* ft, FragEngine* fe) sfBase.iFragInserts++; - PERF_PROFILE(fragInsertPerfStats); + Profile profile(fragInsertPerfStats); if (p->is_ip6() && (net_frag_offset == 0)) { diff --git a/src/stream/ip/ip_session.cc b/src/stream/ip/ip_session.cc index a16cd9052..eaefbd76e 100644 --- a/src/stream/ip/ip_session.cc +++ b/src/stream/ip/ip_session.cc @@ -139,7 +139,7 @@ bool IpSession::setup(Packet*) int IpSession::process(Packet* p) { - PERF_PROFILE(ip_perf_stats); + Profile profile(ip_perf_stats); if ( stream.expired_session(flow, p) ) { diff --git a/src/stream/tcp/ips_stream_reassemble.cc b/src/stream/tcp/ips_stream_reassemble.cc index 15ca79d18..21ccf531f 100644 --- a/src/stream/tcp/ips_stream_reassemble.cc +++ b/src/stream/tcp/ips_stream_reassemble.cc @@ -114,8 +114,8 @@ int ReassembleOption::eval(Cursor&, Packet* pkt) if (!pkt->flow || !pkt->ptrs.tcph) return 0; - PERF_PROFILE_BLOCK(streamReassembleRuleOptionPerfStats) { + Profile profile(streamReassembleRuleOptionPerfStats); Flow* lwssn = (Flow*)pkt->flow; TcpSession* tcpssn = (TcpSession*)lwssn->session; diff --git a/src/stream/tcp/ips_stream_size.cc b/src/stream/tcp/ips_stream_size.cc index 708210f6b..2fff925b1 100644 --- a/src/stream/tcp/ips_stream_size.cc +++ b/src/stream/tcp/ips_stream_size.cc @@ -96,7 +96,7 @@ bool SizeOption::operator==(const IpsOption& ips) const int SizeOption::eval(Cursor&, Packet* pkt) { - PERF_PROFILE(streamSizePerfStats); + Profile profile(streamSizePerfStats); if (!pkt->flow || !pkt->ptrs.tcph) return DETECTION_OPTION_NO_MATCH; diff --git a/src/stream/tcp/tcp_reassembler.cc b/src/stream/tcp/tcp_reassembler.cc index f81a3fe36..628d4f297 100644 --- a/src/stream/tcp/tcp_reassembler.cc +++ b/src/stream/tcp/tcp_reassembler.cc @@ -493,7 +493,7 @@ int TcpReassembler::flush_data_segments( Packet* p, uint32_t toSeq, uint8_t* flu DEBUG_WRAP( uint32_t bytes_queued = seg_bytes_logical; ); assert( seglist.next ); - PERF_PROFILE( s5TcpBuildPacketPerfStats ); + Profile profile( s5TcpBuildPacketPerfStats ); uint32_t total = toSeq - seglist.next->seq; while( SEQ_LT(seglist.next->seq, toSeq ) ) @@ -627,7 +627,7 @@ void TcpReassembler::prep_s5_pkt(Flow* flow, Packet* p, uint32_t pkt_flags) int TcpReassembler::_flush_to_seq( uint32_t bytes, Packet* p, uint32_t pkt_flags) { - PERF_PROFILE(s5TcpFlushPerfStats); + Profile profile(s5TcpFlushPerfStats); uint32_t stop_seq; uint32_t footprint; @@ -711,8 +711,8 @@ int TcpReassembler::_flush_to_seq( uint32_t bytes, Packet* p, uint32_t pkt_flags tcpStats.rebuilt_packets++; UpdateStreamReassStats( &sfBase, flushed_bytes ); - PERF_PAUSE_BLOCK(s5TcpFlushPerfStats) { + ProfilePause profile_pause(profile); Snort::detect_rebuilt_packet(s5_pkt); } } @@ -942,7 +942,7 @@ uint32_t TcpReassembler::get_forward_packet_dir(const Packet* p) // because we don't wait until it is acknowledged uint32_t TcpReassembler::flush_pdu_ips( uint32_t* flags ) { - PERF_PROFILE( s5TcpPAFPerfStats ); + Profile profile( s5TcpPAFPerfStats ); uint32_t total = 0, avail; TcpSegment* seg; @@ -1012,7 +1012,7 @@ void TcpReassembler::fallback( void ) uint32_t TcpReassembler::flush_pdu_ackd( uint32_t* flags ) { - PERF_PROFILE(s5TcpPAFPerfStats); + Profile profile(s5TcpPAFPerfStats); uint32_t total = 0; TcpSegment* seg = SEQ_LT( seglist_base_seq, tracker->r_win_base ) ? seglist.head : nullptr; @@ -1363,7 +1363,7 @@ int TcpReassembler::insert_segment_in_seglist( TcpDataBlock* tdb ) int TcpReassembler::queue_packet_for_reassembly( TcpDataBlock* tdb ) { - PERF_PROFILE( s5TcpInsertPerfStats ); + Profile profile( s5TcpInsertPerfStats ); int rc = STREAM_INSERT_OK; diff --git a/src/stream/tcp/tcp_session.cc b/src/stream/tcp/tcp_session.cc index 0b477f3a2..3fc452b43 100644 --- a/src/stream/tcp/tcp_session.cc +++ b/src/stream/tcp/tcp_session.cc @@ -895,7 +895,7 @@ static void ProcessTcpStream(TcpTracker *rcv, TcpSession *tcpssn, TcpDataBlock * static int ProcessTcpData(TcpTracker *listener, TcpSession *tcpssn, TcpDataBlock *tdb, StreamTcpConfig *config) { - PERF_PROFILE(s5TcpDataPerfStats); + Profile profile(s5TcpDataPerfStats); const tcp::TCPHdr* tcph = tdb->pkt->ptrs.tcph; uint32_t seq = tdb->seq; @@ -1175,7 +1175,7 @@ static void NewTcpSession(Packet* p, Flow* flow, StreamTcpConfig* dstPolicy, Tcp static void NewTcpSessionOnSyn(Flow* flow, TcpDataBlock* tdb, StreamTcpConfig* dstPolicy) { - PERF_PROFILE(s5TcpNewSessPerfStats); + Profile profile(s5TcpNewSessPerfStats); const tcp::TCPHdr* tcph = tdb->pkt->ptrs.tcph; TcpSession* tss; @@ -1228,7 +1228,7 @@ static void NewTcpSessionOnSyn(Flow* flow, TcpDataBlock* tdb, StreamTcpConfig* d static void NewTcpSessionOnSynAck(Flow* flow, TcpDataBlock* tdb, StreamTcpConfig* dstPolicy) { - PERF_PROFILE(s5TcpNewSessPerfStats); + Profile profile(s5TcpNewSessPerfStats); const tcp::TCPHdr* tcph = tdb->pkt->ptrs.tcph; TcpSession* tss; @@ -1280,7 +1280,7 @@ static void NewTcpSessionOnSynAck(Flow* flow, TcpDataBlock* tdb, StreamTcpConfig static void NewTcpSessionOn3Way(Flow* flow, TcpDataBlock* tdb, StreamTcpConfig* dstPolicy) { - PERF_PROFILE(s5TcpNewSessPerfStats); + Profile profile(s5TcpNewSessPerfStats); const tcp::TCPHdr* tcph = tdb->pkt->ptrs.tcph; TcpSession* tss; @@ -1330,7 +1330,7 @@ static void NewTcpSessionOn3Way(Flow* flow, TcpDataBlock* tdb, static void NewTcpSessionOnData(Flow* flow, TcpDataBlock* tdb, StreamTcpConfig* dstPolicy) { - PERF_PROFILE(s5TcpNewSessPerfStats); + Profile profile(s5TcpNewSessPerfStats); const tcp::TCPHdr* tcph = tdb->pkt->ptrs.tcph; TcpSession* tss; @@ -1423,7 +1423,7 @@ static void NewTcpSessionOnData(Flow* flow, TcpDataBlock* tdb, StreamTcpConfig* static int ProcessTcp(Flow* flow, TcpDataBlock* tdb, StreamTcpConfig* config) { - PERF_PROFILE(s5TcpStatePerfStats); + Profile profile(s5TcpStatePerfStats); int retcode = ACTION_NOTHING; int eventcode = 0; @@ -2879,7 +2879,7 @@ void TcpSession::SwapPacketHeaderFoo( void ) */ int TcpSession::process(Packet* p) { - PERF_PROFILE(s5TcpPerfStats); + Profile profile(s5TcpPerfStats); TcpDataBlock tdb; int status; diff --git a/src/stream/udp/udp_session.cc b/src/stream/udp/udp_session.cc index cce10d512..9c23af893 100644 --- a/src/stream/udp/udp_session.cc +++ b/src/stream/udp/udp_session.cc @@ -203,7 +203,7 @@ void UdpSession::update_direction( int UdpSession::process(Packet* p) { - PERF_PROFILE(udp_perf_stats); + Profile profile(udp_perf_stats); StreamUdpConfig* pc = get_udp_cfg(flow->ssn_server); // Check if the session is expired. diff --git a/src/stream/user/user_session.cc b/src/stream/user/user_session.cc index 0b984e7a5..8ae5e7073 100644 --- a/src/stream/user/user_session.cc +++ b/src/stream/user/user_session.cc @@ -464,7 +464,7 @@ StreamSplitter* UserSession::get_splitter(bool c2s) int UserSession::process(Packet* p) { - PERF_PROFILE(user_perf_stats); + Profile profile(user_perf_stats); if ( stream.expired_session(flow, p) ) { diff --git a/src/time/CMakeLists.txt b/src/time/CMakeLists.txt index bb4d7856c..7abebf71f 100644 --- a/src/time/CMakeLists.txt +++ b/src/time/CMakeLists.txt @@ -6,6 +6,10 @@ set ( TIME_INTERNAL_SOURCES timersub.h ) +if ( BUILD_UNIT_TESTS ) + list ( APPEND TIME_INTERNAL_SOURCES stopwatch_test.cc ) +endif ( BUILD_UNIT_TESTS ) + set ( TIME_INCLUDES cpuclock.h clock_defs.h diff --git a/src/time/Makefile.am b/src/time/Makefile.am index ee5ee0cda..3242a9a5b 100644 --- a/src/time/Makefile.am +++ b/src/time/Makefile.am @@ -15,3 +15,7 @@ periodic.h \ timersub.h \ clock_defs.h \ stopwatch.h + +if BUILD_UNIT_TESTS +libtime_a_SOURCES += stopwatch_test.cc +endif diff --git a/src/time/stopwatch.h b/src/time/stopwatch.h index f6d633966..bd6b47eeb 100644 --- a/src/time/stopwatch.h +++ b/src/time/stopwatch.h @@ -22,6 +22,10 @@ #include +#ifdef HAVE_CONFIG_H +#include "config.h" +#endif + #include "clock_defs.h" class Stopwatch @@ -56,7 +60,7 @@ public: return elapsed; } - bool alive() const + bool active() const { return running; } void reset() @@ -66,8 +70,13 @@ public: { running = false; } private: +// Dirty, dirty hack to get Catch unit test visibility +#ifdef UNIT_TEST + hr_duration get_delta() const; +#else hr_duration get_delta() const { return hr_clock::now() - start_time; } +#endif hr_duration elapsed; bool running; diff --git a/src/time/stopwatch_test.cc b/src/time/stopwatch_test.cc new file mode 100644 index 000000000..5644702cc --- /dev/null +++ b/src/time/stopwatch_test.cc @@ -0,0 +1,102 @@ +#include "stopwatch.h" +#include "catch/catch.hpp" + +hr_duration Stopwatch::get_delta() const +{ return hr_clock::now() - start_time; } + +TEST_CASE( "stopwatch", "[stopwatch]" ) +{ + Stopwatch sw; + + REQUIRE_FALSE( sw.active() ); + REQUIRE( sw.get() == 0_ticks ); + + SECTION( "start" ) + { + sw.start(); + + SECTION( "sets clock to active" ) + { + CHECK( sw.active() ); + } + + SECTION( "running elapsed time should be non-zero" ) + { + CHECK( sw.get() > 0_ticks ); + } + + SECTION( "start on running clock has no effect" ) + { + auto val = sw.get(); + sw.start(); + CHECK( sw.active() ); + CHECK( sw.get() > val ); + } + } + + SECTION( "stop" ) + { + sw.start(); + sw.stop(); + + SECTION( "sets clock to be dead" ) + { + CHECK_FALSE( sw.active() ); + } + + SECTION( "ticks should not increase after death" ) + { + auto val = sw.get(); + CHECK( val == sw.get() ); + } + + SECTION( "stop on stopped clock has no effect" ) + { + auto val = sw.get(); + sw.stop(); + CHECK_FALSE( sw.active() ); + CHECK( val == sw.get() ); + } + } + + SECTION( "reset" ) + { + sw.start(); + + SECTION( "reset on running clock" ) + { + sw.reset(); + CHECK_FALSE( sw.active() ); + CHECK( sw.get() == 0_ticks ); + } + + SECTION( "reset on stopped clock" ) + { + sw.stop(); + sw.reset(); + CHECK_FALSE( sw.active() ); + CHECK( sw.get() == 0_ticks ); + } + } + + SECTION( "cancel" ) + { + sw.start(); + SECTION( "cancel on running clock that has no lap time" ) + { + sw.cancel(); + CHECK_FALSE( sw.active() ); + CHECK( sw.get() == 0_ticks ); + } + + SECTION( "cancel on stopped clock that has lap time" ) + { + sw.stop(); + auto val = sw.get(); + sw.cancel(); + + CHECK_FALSE( sw.active() ); + CHECK( val == sw.get() ); + } + } +} diff --git a/src/utils/stats.cc b/src/utils/stats.cc index cfb17477a..fad7864dc 100644 --- a/src/utils/stats.cc +++ b/src/utils/stats.cc @@ -356,7 +356,7 @@ void PrintStatistics(void) snort_conf->logging_flags &= ~LOGGING_FLAG__QUIET; - PerfProfilerManager::show_all_stats(); + Profiler::show_stats(); snort_conf->logging_flags |= save_quiet_flag; } diff --git a/tools/snort2lua/config_states/config_profile.cc b/tools/snort2lua/config_states/config_profile.cc index e68a7b070..f86d3face 100644 --- a/tools/snort2lua/config_states/config_profile.cc +++ b/tools/snort2lua/config_states/config_profile.cc @@ -35,6 +35,31 @@ public: Profilers(Converter& c) : ConversionState(c) { } virtual ~Profilers() { } virtual bool convert(std::istringstream& data_stream); + + template + bool add_or_append(const std::string opt_name, T val) + { + if ( table_api.option_exists(opt_name) ) + { + table_api.append_option(opt_name, val); + return true; + } + + table_api.add_option(opt_name, val); + return false; + } + + template + bool append_if_exists(const std::string opt_name, T val) + { + if ( table_api.option_exists(opt_name) ) + { + table_api.add_option(opt_name, val); + return true; + } + + return false; + } }; } // namespace @@ -44,7 +69,7 @@ bool Profilers::convert(std::istringstream& data_stream) std::string args; bool retval = true; - table_api.open_table("profile"); + table_api.open_table("profiler"); table_api.open_table(*table_name); while (util::get_string(data_stream, args, ",")) @@ -57,9 +82,8 @@ bool Profilers::convert(std::istringstream& data_stream) tmpval = false; else if (!keyword.compare("filename")) - { table_api.add_deleted_comment("profile_*: filename ..."); - } + else if (!keyword.compare("print")) { table_api.add_diff_option_comment("print", "count"); @@ -69,12 +93,37 @@ bool Profilers::convert(std::istringstream& data_stream) tmpval = false; else if (!tmp_string.compare("all")) - tmpval = table_api.add_option("count", -1); + { + // count = 0 is the default, so we don't need + // to specify unless we're overriding a previously + // defined value + if ( append_if_exists("count", 0) ) + // same with show = true + append_if_exists("show", true); + } else if (isdigit(tmp_string[0]) || (tmp_string[0] == '-') || (tmp_string[0] == '+')) - tmpval = table_api.add_option("count", std::stoi(tmp_string)); + { + auto count = std::stoi(tmp_string); + + if ( count > 0 ) + { + if ( add_or_append("count", count) ) + if ( table_api.option_exists("show") ) + table_api.append_option("show", true); + } + + else if ( count < 0 ) + { + if ( append_if_exists("count", 0) ) + append_if_exists("show", true); + } + + else + add_or_append("show", false); + } else tmpval = false; @@ -86,14 +135,36 @@ bool Profilers::convert(std::istringstream& data_stream) if (!(arg_stream >> val)) tmpval = false; + else if (!val.compare("avg_ticks")) + { + table_api.add_diff_option_comment("sort avg_ticks", "sort = avg_check"); + add_or_append("sort", "avg_check"); + } + else if (!val.compare("total_ticks")) + { + table_api.add_diff_option_comment("sort total_ticks", "sort = total_time"); + add_or_append("sort", "total_time"); + } + else if (!val.compare("avg_ticks_per_match")) + { + table_api.add_diff_option_comment("sort avg_ticks_per_match", + "sort = avg_match"); + add_or_append("sort", "avg_match"); + } else if (!val.compare("avg_ticks_per_nomatch")) { table_api.add_diff_option_comment("sort avg_ticks_per_nomatch", - "sort = avg_ticks_per_no_match"); - tmpval = table_api.add_option("sort", "avg_ticks_per_no_match"); + "sort = avg_no_match"); + add_or_append("sort", "avg_no_match"); + } + else if (!val.compare("nomatches")) + { + table_api.add_diff_option_comment("sort nomatches", + "sort = no_matches"); + add_or_append("sort", "no_matches"); } else - tmpval = table_api.add_option("sort", val); + add_or_append("sort", val); } else { @@ -114,7 +185,7 @@ bool Profilers::convert(std::istringstream& data_stream) template static ConversionState* ctor(Converter& c) { - c.get_table_api().open_table("profile"); + c.get_table_api().open_table("profiler"); c.get_table_api().open_table(*table_name); c.get_table_api().close_table(); c.get_table_api().close_table();