From: Victor Julien Date: Fri, 16 Oct 2015 22:21:00 +0000 (+0200) Subject: profiling: initial rulegroup tracking X-Git-Tag: suricata-3.1RC1~329 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=722e2dbf7cb916845fc50d5408000dcc6da9eabc;p=thirdparty%2Fsuricata.git profiling: initial rulegroup tracking Per rule group tracking of checks, use of lists, mpm matches, post filter counts. Logs SGH id so it can be compared with the rule_group.json output. Implemented both in a human readable text format and a JSON format. --- diff --git a/src/Makefile.am b/src/Makefile.am index ec936181d2..c3c7c679c1 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -382,6 +382,7 @@ util-profiling.c util-profiling.h \ util-profiling-locks.c util-profiling-locks.h \ util-profiling-rules.c \ util-profiling-keywords.c \ +util-profiling-rulegroups.c \ util-proto-name.c util-proto-name.h \ util-radix-tree.c util-radix-tree.h \ util-random.c util-random.h \ diff --git a/src/detect-engine.c b/src/detect-engine.c index 5827af8900..c293a2ea81 100644 --- a/src/detect-engine.c +++ b/src/detect-engine.c @@ -949,6 +949,9 @@ void DetectEngineCtxFree(DetectEngineCtx *de_ctx) SCProfilingKeywordDestroyCtx(de_ctx);//->profile_keyword_ctx); // de_ctx->profile_keyword_ctx = NULL; } + if (de_ctx->profile_sgh_ctx != NULL) { + SCProfilingSghDestroyCtx(de_ctx); + } #endif /* Normally the hashes are freed elsewhere, but @@ -1380,6 +1383,7 @@ static TmEcode ThreadCtxDoInit (DetectEngineCtx *de_ctx, DetectEngineThreadCtx * #ifdef PROFILING SCProfilingRuleThreadSetup(de_ctx->profile_ctx, det_ctx); SCProfilingKeywordThreadSetup(de_ctx->profile_keyword_ctx, det_ctx); + SCProfilingSghThreadSetup(de_ctx->profile_sgh_ctx, det_ctx); #endif SC_ATOMIC_INIT(det_ctx->so_far_used_by_detect); @@ -1530,6 +1534,7 @@ void DetectEngineThreadCtxFree(DetectEngineThreadCtx *det_ctx) #ifdef PROFILING SCProfilingRuleThreadCleanup(det_ctx); SCProfilingKeywordThreadCleanup(det_ctx); + SCProfilingSghThreadCleanup(det_ctx); #endif DetectEngineIPOnlyThreadDeinit(&det_ctx->io_ctx); diff --git a/src/detect.c b/src/detect.c index 2293f69b11..90699debd4 100644 --- a/src/detect.c +++ b/src/detect.c @@ -1538,6 +1538,8 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh #endif Signature **match_array = det_ctx->match_array; + SGH_PROFILING_RECORD(det_ctx, det_ctx->sgh); + uint32_t sflags, next_sflags = 0; if (match_cnt) { next_s = *match_array++; @@ -4091,6 +4093,9 @@ int SigAddressPrepareStage4(DetectEngineCtx *de_ctx) RulesDumpGrouping(de_ctx); +#ifdef PROFILING + SCProfilingSghInitCounters(de_ctx); +#endif SCReturnInt(0); } diff --git a/src/detect.h b/src/detect.h index 02728200c1..f70493f3cb 100644 --- a/src/detect.h +++ b/src/detect.h @@ -660,6 +660,7 @@ typedef struct DetectEngineCtx_ { struct SCProfileDetectCtx_ *profile_ctx; struct SCProfileKeywordDetectCtx_ *profile_keyword_ctx; struct SCProfileKeywordDetectCtx_ *profile_keyword_ctx_per_list[DETECT_SM_LIST_MAX]; + struct SCProfileSghDetectCtx_ *profile_sgh_ctx; #endif char config_prefix[64]; @@ -858,6 +859,7 @@ typedef struct DetectEngineThreadCtx_ { struct SCProfileKeywordData_ *keyword_perf_data; struct SCProfileKeywordData_ *keyword_perf_data_per_list[DETECT_SM_LIST_MAX]; int keyword_perf_list; /**< list we're currently inspecting, DETECT_SM_LIST_* */ + struct SCProfileSghData_ *sgh_perf_data; #endif } DetectEngineThreadCtx; @@ -1030,6 +1032,7 @@ typedef struct SigGroupHead_ { /* ptr to our init data we only use at... init :) */ SigGroupHeadInitData *init; + } SigGroupHead; /** sigmatch has no options, so the parser shouldn't expect any */ diff --git a/src/runmode-unix-socket.c b/src/runmode-unix-socket.c index 09edb610d8..3ccf89b98d 100644 --- a/src/runmode-unix-socket.c +++ b/src/runmode-unix-socket.c @@ -381,6 +381,7 @@ TmEcode UnixSocketPcapFilesCheck(void *data) #ifdef PROFILING SCProfilingRulesGlobalInit(); SCProfilingKeywordsGlobalInit(); + SCProfilingSghsGlobalInit(); SCProfilingInit(); #endif /* PROFILING */ DefragInit(); diff --git a/src/suricata.c b/src/suricata.c index dbe1b139c3..5eb6482be7 100644 --- a/src/suricata.c +++ b/src/suricata.c @@ -2167,6 +2167,7 @@ static int PostConfLoadedSetup(SCInstance *suri) if (suri->run_mode != RUNMODE_UNIX_SOCKET) { SCProfilingRulesGlobalInit(); SCProfilingKeywordsGlobalInit(); + SCProfilingSghsGlobalInit(); SCProfilingInit(); } #endif /* PROFILING */ diff --git a/src/util-profiling-keywords.c b/src/util-profiling-keywords.c index 9f3019aa5d..444406c127 100644 --- a/src/util-profiling-keywords.c +++ b/src/util-profiling-keywords.c @@ -100,7 +100,7 @@ void SCProfilingKeywordsGlobalInit(void) } } -void DoDump(SCProfileKeywordDetectCtx *rules_ctx, FILE *fp, const char *name) +static void DoDump(SCProfileKeywordDetectCtx *rules_ctx, FILE *fp, const char *name) { int i; fprintf(fp, " ----------------------------------------------" diff --git a/src/util-profiling-rulegroups.c b/src/util-profiling-rulegroups.c new file mode 100644 index 0000000000..e4112ccc13 --- /dev/null +++ b/src/util-profiling-rulegroups.c @@ -0,0 +1,407 @@ +/* Copyright (C) 2007-2015 Open Information Security Foundation + * + * You can copy, redistribute or modify this Program under the terms of + * the GNU General Public License version 2 as published by the Free + * Software Foundation. + * + * 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 + * version 2 along with this program; if not, write to the Free Software + * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA + * 02110-1301, USA. + */ + +/** + * \file + * + * \author Endace Technology Limited. + * \author Victor Julien + * + * An API for rule profiling operations. + */ + +#include "suricata-common.h" +#include "decode.h" +#include "detect.h" +#include "detect-engine.h" +#include "conf.h" + +#include "tm-threads.h" + +#include "util-unittest.h" +#include "util-byte.h" +#include "util-profiling.h" +#include "util-profiling-locks.h" + +#ifdef PROFILING + +/** + * Extra data for rule profiling. + */ +typedef struct SCProfileSghData_ { + uint64_t checks; + + uint64_t non_mpm_generic; + uint64_t non_mpm_syn; + + uint64_t post_prefilter_sigs_total; + uint64_t post_prefilter_sigs_max; + + uint64_t mpm_match_cnt_total; + uint64_t mpm_match_cnt_max; + +} SCProfileSghData; + +typedef struct SCProfileSghDetectCtx_ { + uint32_t cnt; + SCProfileSghData *data; + pthread_mutex_t data_m; +} SCProfileSghDetectCtx; + +static int profiling_sghs_output_to_file = 0; +int profiling_sghs_enabled = 0; +static char *profiling_file_name = ""; +static const char *profiling_file_mode = "a"; +static int profiling_rulegroup_json = 0; + +void SCProfilingSghsGlobalInit(void) +{ + ConfNode *conf; + + conf = ConfGetNode("profiling.rulegroups"); + if (conf != NULL) { + if (ConfNodeChildValueIsTrue(conf, "enabled")) { + profiling_sghs_enabled = 1; + const char *filename = ConfNodeLookupChildValue(conf, "filename"); + if (filename != NULL) { + + char *log_dir; + log_dir = ConfigGetLogDirectory(); + + profiling_file_name = SCMalloc(PATH_MAX); + if (unlikely(profiling_file_name == NULL)) { + SCLogError(SC_ERR_MEM_ALLOC, "can't duplicate file name"); + exit(EXIT_FAILURE); + } + snprintf(profiling_file_name, PATH_MAX, "%s/%s", log_dir, filename); + + const char *v = ConfNodeLookupChildValue(conf, "append"); + if (v == NULL || ConfValIsTrue(v)) { + profiling_file_mode = "a"; + } else { + profiling_file_mode = "w"; + } + + profiling_sghs_output_to_file = 1; + } + if (ConfNodeChildValueIsTrue(conf, "json")) { +#ifdef HAVE_LIBJANSSON + profiling_rulegroup_json = 1; +#else + SCLogWarning(SC_ERR_NO_JSON_SUPPORT, "no json support compiled in, using plain output"); +#endif + } + } + } +} + +#ifdef HAVE_LIBJANSSON +static void DoDumpJSON(SCProfileSghDetectCtx *rules_ctx, FILE *fp, const char *name) +{ + char timebuf[64]; + uint32_t i; + struct timeval tval; + + json_t *js = json_object(); + if (js == NULL) + return; + json_t *jsa = json_array(); + if (jsa == NULL) { + json_decref(js); + return; + } + + gettimeofday(&tval, NULL); + CreateIsoTimeString(&tval, timebuf, sizeof(timebuf)); + json_object_set_new(js, "timestamp", json_string(timebuf)); + + for (i = 0; i < rules_ctx->cnt; i++) { + SCProfileSghData *d = &rules_ctx->data[i]; + if (d == NULL || d->checks == 0) + continue; + + double avgsigs = 0; + double avgmpms = 0; + + if (d->post_prefilter_sigs_total && d->checks) { + avgsigs = (double)((double)d->post_prefilter_sigs_total / (double)d->checks); + } + if (d->mpm_match_cnt_total && d->checks) { + avgmpms = (double)((double)d->mpm_match_cnt_total / (double)d->checks); + } + + json_t *jsm = json_object(); + if (jsm) { + json_object_set_new(jsm, "id", json_integer(i)); + json_object_set_new(jsm, "checks", json_integer(d->checks)); + json_object_set_new(jsm, "non_mpm_generic", json_integer(d->non_mpm_generic)); + json_object_set_new(jsm, "non_mpm_syn", json_integer(d->non_mpm_syn)); + json_object_set_new(jsm, "avgmpms", json_real(avgmpms)); + json_object_set_new(jsm, "mpm_match_cnt_max", json_integer(d->mpm_match_cnt_max)); + json_object_set_new(jsm, "avgsigs", json_real(avgsigs)); + json_object_set_new(jsm, "post_prefilter_sigs_max", json_integer(d->post_prefilter_sigs_max)); + json_array_append_new(jsa, jsm); + } + } + json_object_set_new(js, "rule_groups", jsa); + + char *js_s = json_dumps(js, + JSON_PRESERVE_ORDER|JSON_COMPACT|JSON_ENSURE_ASCII| + JSON_ESCAPE_SLASH); + if (likely(js_s != NULL)) { + fprintf(fp, "%s", js_s); + free(js_s); + } + json_decref(js); +} +#endif /* HAVE_LIBJANSSON */ + +static void DoDump(SCProfileSghDetectCtx *rules_ctx, FILE *fp, const char *name) +{ + uint32_t i; + struct timeval tval; + struct tm *tms; + struct tm local_tm; + + gettimeofday(&tval, NULL); + tms = SCLocalTime(tval.tv_sec, &local_tm); + + fprintf(fp, " ----------------------------------------------" + "------------------------------------------------------" + "----------------------------\n"); + fprintf(fp, " Date: %" PRId32 "/%" PRId32 "/%04d -- " + "%02d:%02d:%02d\n", tms->tm_mon + 1, tms->tm_mday, tms->tm_year + 1900, + tms->tm_hour,tms->tm_min, tms->tm_sec); + + fprintf(fp, " ----------------------------------------------" + "------------------------------------------------------" + "----------------------------\n"); + fprintf(fp, " Stats for: %s %u\n", name, rules_ctx->cnt); + fprintf(fp, " ----------------------------------------------" + "------------------------------------------------------" + "----------------------------\n"); + fprintf(fp, " %-16s %-15s %-15s %-15s %-15s %-15s %-15s %-15s\n", "Sgh", "Checks", "Non-MPM(gen)", "Non-Mpm(syn)", "MPM Matches", "MPM Match Max", "Post-Filter", "Post-Filter Max"); + fprintf(fp, " ---------------- " + "--------------- " + "--------------- " + "--------------- " + "--------------- " + "--------------- " + "--------------- " + "--------------- " + "\n"); + for (i = 0; i < rules_ctx->cnt; i++) { + SCProfileSghData *d = &rules_ctx->data[i]; + if (d == NULL || d->checks == 0) + continue; + + double avgsigs = 0; + double avgmpms = 0; + + if (d->post_prefilter_sigs_total && d->checks) { + avgsigs = (double)((double)d->post_prefilter_sigs_total / (double)d->checks); + } + if (d->mpm_match_cnt_total && d->checks) { + avgmpms = (double)((double)d->mpm_match_cnt_total / (double)d->checks); + } + + fprintf(fp, + " %-16u %-15"PRIu64" %-15"PRIu64" %-15"PRIu64" %-15.2f %-15"PRIu64" %-15.2f %-15"PRIu64"\n", + i, + d->checks, + d->non_mpm_generic, + d->non_mpm_syn, + avgmpms, + d->mpm_match_cnt_max, + avgsigs, + d->post_prefilter_sigs_max); + } + fprintf(fp,"\n"); +} + +void +SCProfilingSghDump(DetectEngineCtx *de_ctx) +{ + FILE *fp; + + if (profiling_sghs_enabled == 0) + return; + + if (profiling_sghs_output_to_file == 1) { + SCLogDebug("file %s mode %s", profiling_file_name, profiling_file_mode); + + fp = fopen(profiling_file_name, profiling_file_mode); + + if (fp == NULL) { + SCLogError(SC_ERR_FOPEN, "failed to open %s: %s", profiling_file_name, + strerror(errno)); + return; + } + } else { + fp = stdout; + } + +#ifdef HAVE_LIBJANSSON + if (profiling_rulegroup_json) { + DoDumpJSON(de_ctx->profile_sgh_ctx, fp, "rule groups"); + } else +#endif + { + DoDump(de_ctx->profile_sgh_ctx, fp, "rule groups"); + } + + if (fp != stdout) + fclose(fp); + + SCLogInfo("Done dumping rulegroup profiling data."); +} + +/** + * \brief Update a rule counter. + * + * \param id The ID of this counter. + * \param ticks Number of CPU ticks for this rule. + * \param match Did the rule match? + */ +void +SCProfilingSghUpdateCounter(DetectEngineThreadCtx *det_ctx, const SigGroupHead *sgh) +{ + if (det_ctx != NULL && det_ctx->sgh_perf_data != NULL && sgh->id < det_ctx->de_ctx->sgh_array_cnt) { + SCProfileSghData *p = &det_ctx->sgh_perf_data[sgh->id]; + p->checks++; + + if (det_ctx->non_mpm_store_cnt > 0) { + if (det_ctx->non_mpm_store_ptr == sgh->non_mpm_syn_store_array) + p->non_mpm_syn++; + else + p->non_mpm_generic++; + } + p->post_prefilter_sigs_total += det_ctx->match_array_cnt; + if (det_ctx->match_array_cnt > p->post_prefilter_sigs_max) + p->post_prefilter_sigs_max = det_ctx->match_array_cnt; + p->mpm_match_cnt_total += det_ctx->pmq.rule_id_array_cnt; + if (det_ctx->pmq.rule_id_array_cnt > p->mpm_match_cnt_max) + p->mpm_match_cnt_max = det_ctx->pmq.rule_id_array_cnt; + } +} + +SCProfileSghDetectCtx *SCProfilingSghInitCtx(void) +{ + SCProfileSghDetectCtx *ctx = SCCalloc(1, sizeof(SCProfileSghDetectCtx)); + if (ctx != NULL) { + if (pthread_mutex_init(&ctx->data_m, NULL) != 0) { + SCLogError(SC_ERR_MUTEX, + "Failed to initialize mutex."); + exit(EXIT_FAILURE); + } + } + + return ctx; +} + +static void DetroyCtx(SCProfileSghDetectCtx *ctx) +{ + if (ctx) { + if (ctx->data != NULL) + SCFree(ctx->data); + pthread_mutex_destroy(&ctx->data_m); + SCFree(ctx); + } +} + +void SCProfilingSghDestroyCtx(DetectEngineCtx *de_ctx) +{ + if (de_ctx != NULL) { + SCProfilingSghDump(de_ctx); + + DetroyCtx(de_ctx->profile_sgh_ctx); + } +} + +void SCProfilingSghThreadSetup(SCProfileSghDetectCtx *ctx, DetectEngineThreadCtx *det_ctx) +{ + if (ctx == NULL) + return; + + uint32_t array_size = det_ctx->de_ctx->sgh_array_cnt; + + SCProfileSghData *a = SCCalloc(array_size, sizeof(SCProfileSghData)); + if (a != NULL) { + det_ctx->sgh_perf_data = a; + } +} + +static void SCProfilingSghThreadMerge(DetectEngineCtx *de_ctx, const DetectEngineThreadCtx *det_ctx) +{ + if (de_ctx == NULL || de_ctx->profile_sgh_ctx == NULL || + de_ctx->profile_sgh_ctx->data == NULL || det_ctx == NULL || + det_ctx->sgh_perf_data == NULL) + return; + +#define ADD(name) de_ctx->profile_sgh_ctx->data[i].name += det_ctx->sgh_perf_data[i].name + uint32_t i; + for (i = 0; i < de_ctx->sgh_array_cnt; i++) { + ADD(checks); + ADD(non_mpm_generic); + ADD(non_mpm_syn); + ADD(post_prefilter_sigs_total); + ADD(mpm_match_cnt_total); + + if (det_ctx->sgh_perf_data[i].mpm_match_cnt_max > de_ctx->profile_sgh_ctx->data[i].mpm_match_cnt_max) + de_ctx->profile_sgh_ctx->data[i].mpm_match_cnt_max = det_ctx->sgh_perf_data[i].mpm_match_cnt_max; + if (det_ctx->sgh_perf_data[i].post_prefilter_sigs_max > de_ctx->profile_sgh_ctx->data[i].post_prefilter_sigs_max) + de_ctx->profile_sgh_ctx->data[i].post_prefilter_sigs_max = det_ctx->sgh_perf_data[i].post_prefilter_sigs_max; + } +#undef ADD +} + +void SCProfilingSghThreadCleanup(DetectEngineThreadCtx *det_ctx) +{ + if (det_ctx == NULL || det_ctx->de_ctx == NULL || det_ctx->sgh_perf_data == NULL) + return; + + pthread_mutex_lock(&det_ctx->de_ctx->profile_sgh_ctx->data_m); + SCProfilingSghThreadMerge(det_ctx->de_ctx, det_ctx); + pthread_mutex_unlock(&det_ctx->de_ctx->profile_sgh_ctx->data_m); + + SCFree(det_ctx->sgh_perf_data); + det_ctx->sgh_perf_data = NULL; +} + +/** + * \brief Register the keyword profiling counters. + * + * \param de_ctx The active DetectEngineCtx, used to get at the loaded rules. + */ +void +SCProfilingSghInitCounters(DetectEngineCtx *de_ctx) +{ + if (profiling_sghs_enabled == 0) + return; + + de_ctx->profile_sgh_ctx = SCProfilingSghInitCtx(); + BUG_ON(de_ctx->profile_sgh_ctx == NULL); + + de_ctx->profile_sgh_ctx->data = SCCalloc(de_ctx->sgh_array_cnt, sizeof(SCProfileSghData)); + BUG_ON(de_ctx->profile_sgh_ctx->data == NULL); + + de_ctx->profile_sgh_ctx->cnt = de_ctx->sgh_array_cnt; + + SCLogInfo("Registered %"PRIu32" rulegroup profiling counters.", de_ctx->sgh_array_cnt); +} + +#endif /* PROFILING */ diff --git a/src/util-profiling.h b/src/util-profiling.h index 763d8414ae..cc7ea02700 100644 --- a/src/util-profiling.h +++ b/src/util-profiling.h @@ -32,6 +32,7 @@ extern int profiling_rules_enabled; extern int profiling_packets_enabled; +extern int profiling_sghs_enabled; extern __thread int profiling_rules_entered; void SCProfilingPrintPacketProfile(Packet *); @@ -229,6 +230,11 @@ PktProfiling *SCProfilePacketStart(void); } \ } +#define SGH_PROFILING_RECORD(det_ctx, sgh) \ + if (profiling_sghs_enabled) { \ + SCProfilingSghUpdateCounter((det_ctx), (sgh)); \ + } + void SCProfilingRulesGlobalInit(void); void SCProfilingRuleDestroyCtx(struct SCProfileDetectCtx_ *); @@ -244,6 +250,13 @@ void SCProfilingKeywordUpdateCounter(DetectEngineThreadCtx *det_ctx, int id, uin void SCProfilingKeywordThreadSetup(struct SCProfileKeywordDetectCtx_ *, DetectEngineThreadCtx *); void SCProfilingKeywordThreadCleanup(DetectEngineThreadCtx *); +void SCProfilingSghsGlobalInit(void); +void SCProfilingSghDestroyCtx(DetectEngineCtx *); +void SCProfilingSghInitCounters(DetectEngineCtx *); +void SCProfilingSghUpdateCounter(DetectEngineThreadCtx *det_ctx, const SigGroupHead *sgh); +void SCProfilingSghThreadSetup(struct SCProfileSghDetectCtx_ *, DetectEngineThreadCtx *); +void SCProfilingSghThreadCleanup(DetectEngineThreadCtx *); + void SCProfilingInit(void); void SCProfilingDestroy(void); void SCProfilingRegisterTests(void); @@ -277,6 +290,8 @@ void SCProfilingDump(void); #define PACKET_PROFILING_DETECT_START(p, id) #define PACKET_PROFILING_DETECT_END(p, id) +#define SGH_PROFILING_RECORD(det_ctx, sgh) + #endif /* PROFILING */ #endif /* ! __UTIL_PROFILE_H__ */ diff --git a/suricata.yaml.in b/suricata.yaml.in index 152f2e757d..368ee3408c 100644 --- a/suricata.yaml.in +++ b/suricata.yaml.in @@ -1497,6 +1497,12 @@ profiling: filename: keyword_perf.log append: yes + # per rulegroup profiling + rulegroups: + enabled: yes + filename: rule_group_perf.log + append: yes + # packet profiling packets: