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.
pull/1980/head
Victor Julien 9 years ago
parent e310a033be
commit 722e2dbf7c

@ -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 \

@ -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);

@ -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);
}

@ -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 */

@ -381,6 +381,7 @@ TmEcode UnixSocketPcapFilesCheck(void *data)
#ifdef PROFILING
SCProfilingRulesGlobalInit();
SCProfilingKeywordsGlobalInit();
SCProfilingSghsGlobalInit();
SCProfilingInit();
#endif /* PROFILING */
DefragInit();

@ -2167,6 +2167,7 @@ static int PostConfLoadedSetup(SCInstance *suri)
if (suri->run_mode != RUNMODE_UNIX_SOCKET) {
SCProfilingRulesGlobalInit();
SCProfilingKeywordsGlobalInit();
SCProfilingSghsGlobalInit();
SCProfilingInit();
}
#endif /* PROFILING */

@ -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, " ----------------------------------------------"

@ -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 <victor@inliniac.net>
*
* 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 */

@ -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__ */

@ -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:

Loading…
Cancel
Save