diff --git a/src/Makefile.am b/src/Makefile.am index 385faa6059..bcc2650b44 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -307,6 +307,7 @@ win32-service.c win32-service.h \ util-action.c util-action.h \ win32-syslog.h \ util-profiling.c util-profiling.h \ +util-profiling-rules.c util-profiling-rules.h \ util-profiling-locks.c util-profiling-locks.h \ cuda-packet-batcher.c cuda-packet-batcher.h \ util-ioctl.h util-ioctl.c \ diff --git a/src/detect-engine-state.c b/src/detect-engine-state.c index de7ae7de90..5bf178cb66 100644 --- a/src/detect-engine-state.c +++ b/src/detect-engine-state.c @@ -1162,7 +1162,7 @@ int DeStateDetectContinueDetection(ThreadVars *tv, DetectEngineCtx *de_ctx, Dete SCLogDebug("signature %"PRIu32" match state %s", s->id, DeStateMatchResultToString(det_ctx->de_state_sig_array[item->sid])); - RULE_PROFILING_END(s, match); + RULE_PROFILING_END(det_ctx, s, match); } } diff --git a/src/detect-engine.c b/src/detect-engine.c index 4c5abdc78d..8adf3f964f 100644 --- a/src/detect-engine.c +++ b/src/detect-engine.c @@ -65,6 +65,10 @@ #include "tm-threads.h" +#ifdef PROFILING +#include "util-profiling.h" +#endif + #define DETECT_ENGINE_DEFAULT_INSPECTION_RECURSION_LIMIT 3000 static uint32_t detect_engine_ctx_id = 1; @@ -428,6 +432,12 @@ void DetectEngineCtxFree(DetectEngineCtx *de_ctx) { if (de_ctx == NULL) return; +#ifdef PROFILING + if (de_ctx->profile_ctx != NULL) { + SCProfilingRuleDestroyCtx(de_ctx->profile_ctx); + de_ctx->profile_ctx = NULL; + } +#endif /* Normally the hashes are freed elsewhere, but * to be sure look at them again here. @@ -791,6 +801,9 @@ TmEcode DetectEngineThreadCtxInit(ThreadVars *tv, void *initdata, void **data) { } DetectEngineThreadCtxInitKeywords(de_ctx, det_ctx); +#ifdef PROFILING + SCProfilingRuleThreadSetup(de_ctx->profile_ctx, det_ctx); +#endif SC_ATOMIC_INIT(det_ctx->so_far_used_by_detect); @@ -873,6 +886,9 @@ static TmEcode DetectEngineThreadCtxInitForLiveRuleSwap(ThreadVars *tv, void *in } DetectEngineThreadCtxInitKeywords(de_ctx, det_ctx); +#ifdef PROFILING + SCProfilingRuleThreadSetup(de_ctx->profile_ctx, det_ctx); +#endif SC_ATOMIC_INIT(det_ctx->so_far_used_by_detect); @@ -889,6 +905,10 @@ TmEcode DetectEngineThreadCtxDeinit(ThreadVars *tv, void *data) { return TM_ECODE_OK; } +#ifdef PROFILING + SCProfilingRuleThreadCleanup(det_ctx); +#endif + DetectEngineIPOnlyThreadDeinit(&det_ctx->io_ctx); /** \todo get rid of this static */ diff --git a/src/detect.c b/src/detect.c index 1640b1d63a..09492086a2 100644 --- a/src/detect.c +++ b/src/detect.c @@ -1843,7 +1843,7 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh next: DetectReplaceFree(det_ctx->replist); det_ctx->replist = NULL; - RULE_PROFILING_END(s, smatch); + RULE_PROFILING_END(det_ctx, s, smatch); det_ctx->flags = 0; continue; @@ -4681,7 +4681,9 @@ int SigGroupBuild (DetectEngineCtx *de_ctx) { // DetectAddressPrintMemory(); // DetectSigGroupPrintMemory(); // DetectPortPrintMemory(); - +#ifdef PROFILING + SCProfilingRuleInitCounters(de_ctx); +#endif return 0; } diff --git a/src/detect.h b/src/detect.h index ed4dae0733..627d12d5a4 100644 --- a/src/detect.h +++ b/src/detect.h @@ -42,6 +42,11 @@ #include "detect-mark.h" +#ifdef PROFILING +typedef struct SCProfileData_ SCProfileData; +typedef struct SCProfileDetectCtx_ SCProfileDetectCtx; +#endif + #define COUNTER_DETECT_ALERTS 1 /* forward declarations for the structures from detect-engine-sigorder.h */ @@ -689,6 +694,10 @@ typedef struct DetectEngineCtx_ { /** list of keywords that need thread local ctxs */ DetectEngineThreadKeywordCtxItem *keyword_list; int keyword_id; + +#ifdef PROFILING + SCProfileDetectCtx *profile_ctx; +#endif } DetectEngineCtx; /* Engine groups profiles (low, medium, high, custom) */ @@ -813,6 +822,11 @@ typedef struct DetectionEngineThreadCtx_ { * thread safety issues */ void **keyword_ctxs_array; int keyword_ctxs_size; + +#ifdef PROFILING + SCProfileData *rule_perf_data; + int rule_perf_data_size; +#endif } DetectEngineThreadCtx; /** \brief element in sigmatch type table. diff --git a/src/suricata.c b/src/suricata.c index fe89968c44..3b2a82979f 100644 --- a/src/suricata.c +++ b/src/suricata.c @@ -1424,6 +1424,7 @@ int main(int argc, char **argv) //PatternMatchPrepare(mpm_ctx, MPM_B2G); SCPerfInitCounterApi(); #ifdef PROFILING + SCProfilingRulesGlobalInit(); SCProfilingInit(); #endif /* PROFILING */ SCReputationInitCtx(); @@ -1777,10 +1778,6 @@ int main(int argc, char **argv) if (sig_file == NULL && rule_reload == 1) UtilSignalHandlerSetup(SIGUSR2, SignalHandlerSigusr2); -#ifdef PROFILING - SCProfilingInitRuleCounters(de_ctx); -#endif /* PROFILING */ - #ifdef __SC_CUDA_SUPPORT__ SCCudaPBSetUpQueuesAndBuffers(); #endif /* __SC_CUDA_SUPPORT__ */ diff --git a/src/util-profiling-rules.c b/src/util-profiling-rules.c new file mode 100644 index 0000000000..20cd4a6a42 --- /dev/null +++ b/src/util-profiling-rules.c @@ -0,0 +1,540 @@ +/* Copyright (C) 2007-2012 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 "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 + +#ifndef MIN +#define MIN(a, b) (((a) < (b)) ? (a) : (b)) +#endif + +#define DEFAULT_LOG_FILENAME "profile.log" +#define DEFAULT_LOG_MODE_APPEND "yes" + +typedef struct SCProfileDetectCtx_ { + uint32_t size; + uint32_t id; +} SCProfileDetectCtx; + +/** + * Extra data for rule profiling. + */ +typedef struct SCProfileData_ { + uint32_t sid; + uint32_t gid; + uint32_t rev; + uint64_t checks; + uint64_t matches; + uint64_t max; + uint64_t ticks_match; + uint64_t ticks_no_match; +} SCProfileData; + +/** + * Used for generating the summary data to print. + */ +typedef struct SCProfileSummary_ { + uint32_t sid; + uint32_t gid; + uint32_t rev; + uint64_t ticks; + double avgticks; + double avgticks_match; + double avgticks_no_match; + uint64_t checks; + uint64_t matches; + uint64_t max; + uint64_t ticks_match; + uint64_t ticks_no_match; +} SCProfileSummary; + +extern int profiling_output_to_file; +static SCProfileData rules_profile_data[0xffff]; +static pthread_mutex_t rules_profile_data_m; +int profiling_rules_enabled = 0; +static char *profiling_file_name = ""; +static const char *profiling_file_mode = ""; + +/** + * Sort orders for dumping profiled rules. + */ +enum { + SC_PROFILING_RULES_SORT_BY_TICKS = 0, + SC_PROFILING_RULES_SORT_BY_AVG_TICKS, + SC_PROFILING_RULES_SORT_BY_CHECKS, + SC_PROFILING_RULES_SORT_BY_MATCHES, + SC_PROFILING_RULES_SORT_BY_MAX_TICKS, + SC_PROFILING_RULES_SORT_BY_AVG_TICKS_MATCH, + SC_PROFILING_RULES_SORT_BY_AVG_TICKS_NO_MATCH, +}; +static int profiling_rules_sort_order = SC_PROFILING_RULES_SORT_BY_TICKS; + +/** + * Maximum number of rules to dump. + */ +static uint32_t profiling_rules_limit = UINT32_MAX; + +void SCProfilingRulesGlobalInit(void) { + ConfNode *conf; + const char *val; + + conf = ConfGetNode("profiling.rules"); + if (conf != NULL) { + if (ConfNodeChildValueIsTrue(conf, "enabled")) { + memset(rules_profile_data, 0, sizeof(rules_profile_data)); + profiling_rules_enabled = 1; + + val = ConfNodeLookupChildValue(conf, "sort"); + if (val != NULL) { + if (strcmp(val, "ticks") == 0) { + profiling_rules_sort_order = + SC_PROFILING_RULES_SORT_BY_TICKS; + } + else if (strcmp(val, "avgticks") == 0) { + profiling_rules_sort_order = + SC_PROFILING_RULES_SORT_BY_AVG_TICKS; + } + else if (strcmp(val, "avgticks_match") == 0) { + profiling_rules_sort_order = + SC_PROFILING_RULES_SORT_BY_AVG_TICKS_MATCH; + } + else if (strcmp(val, "avgticks_no_match") == 0) { + profiling_rules_sort_order = + SC_PROFILING_RULES_SORT_BY_AVG_TICKS_NO_MATCH; + } + else if (strcmp(val, "checks") == 0) { + profiling_rules_sort_order = + SC_PROFILING_RULES_SORT_BY_CHECKS; + } + else if (strcmp(val, "matches") == 0) { + profiling_rules_sort_order = + SC_PROFILING_RULES_SORT_BY_MATCHES; + } + else if (strcmp(val, "maxticks") == 0) { + profiling_rules_sort_order = + SC_PROFILING_RULES_SORT_BY_MAX_TICKS; + } + else { + SCLogError(SC_ERR_INVALID_ARGUMENT, + "Invalid profiling sort order: %s", val); + exit(EXIT_FAILURE); + } + } + + val = ConfNodeLookupChildValue(conf, "limit"); + if (val != NULL) { + if (ByteExtractStringUint32(&profiling_rules_limit, 10, + (uint16_t)strlen(val), val) <= 0) { + SCLogError(SC_ERR_INVALID_ARGUMENT, "Invalid limit: %s", val); + exit(EXIT_FAILURE); + } + } + const char *filename = ConfNodeLookupChildValue(conf, "filename"); + if (filename != NULL) { + + char *log_dir; + if (ConfGet("default-log-dir", &log_dir) != 1) + log_dir = DEFAULT_LOG_DIR; + + profiling_file_name = SCMalloc(PATH_MAX); + snprintf(profiling_file_name, PATH_MAX, "%s/%s", log_dir, filename); + + profiling_file_mode = ConfNodeLookupChildValue(conf, "append"); + if (profiling_file_mode == NULL) + profiling_file_mode = DEFAULT_LOG_MODE_APPEND; + + profiling_output_to_file = 1; + } + } + } +} + +/** + * \brief Qsort comparison function to sort by ticks. + */ +static int +SCProfileSummarySortByTicks(const void *a, const void *b) +{ + const SCProfileSummary *s0 = a; + const SCProfileSummary *s1 = b; + return s1->ticks - s0->ticks; +} + +/** + * \brief Qsort comparison function to sort by average ticks per match. + */ +static int +SCProfileSummarySortByAvgTicksMatch(const void *a, const void *b) +{ + const SCProfileSummary *s0 = a; + const SCProfileSummary *s1 = b; + return s1->avgticks_match - s0->avgticks_match; +} + +/** + * \brief Qsort comparison function to sort by average ticks per non match. + */ +static int +SCProfileSummarySortByAvgTicksNoMatch(const void *a, const void *b) +{ + const SCProfileSummary *s0 = a; + const SCProfileSummary *s1 = b; + return s1->avgticks_no_match - s0->avgticks_no_match; +} + +/** + * \brief Qsort comparison function to sort by average ticks. + */ +static int +SCProfileSummarySortByAvgTicks(const void *a, const void *b) +{ + const SCProfileSummary *s0 = a; + const SCProfileSummary *s1 = b; + return s1->avgticks - s0->avgticks; +} + +/** + * \brief Qsort comparison function to sort by checks. + */ +static int +SCProfileSummarySortByChecks(const void *a, const void *b) +{ + const SCProfileSummary *s0 = a; + const SCProfileSummary *s1 = b; + return s1->checks - s0->checks; +} + +/** + * \brief Qsort comparison function to sort by matches. + */ +static int +SCProfileSummarySortByMatches(const void *a, const void *b) +{ + const SCProfileSummary *s0 = a; + const SCProfileSummary *s1 = b; + return s1->matches - s0->matches; +} + +/** + * \brief Qsort comparison function to sort by max ticks. + */ +static int +SCProfileSummarySortByMaxTicks(const void *a, const void *b) +{ + const SCProfileSummary *s0 = a; + const SCProfileSummary *s1 = b; + return s1->max - s0->max; +} + +void +SCProfilingRuleDump(SCProfileDetectCtx *rules_ctx) +{ + uint32_t i; + FILE *fp; + + if (rules_ctx == NULL) + return; + + struct timeval tval; + struct tm *tms; + if (profiling_output_to_file == 1) { + if (ConfValIsTrue(profiling_file_mode)) { + fp = fopen(profiling_file_name, "a"); + } else { + fp = fopen(profiling_file_name, "w"); + } + + if (fp == NULL) { + SCLogError(SC_ERR_FOPEN, "failed to open %s: %s", profiling_file_name, + strerror(errno)); + return; + } + } else { + fp = stdout; + } + + int summary_size = sizeof(SCProfileSummary) * rules_ctx->size; + SCProfileSummary *summary = SCMalloc(summary_size); + if (summary == NULL) { + SCLogError(SC_ERR_MEM_ALLOC, "Error allocating memory for profiling summary"); + return; + } + + uint32_t count = rules_ctx->size; + uint64_t total_ticks = 0; + + SCLogInfo("Dumping profiling data for %u rules.", count); + + memset(summary, 0, summary_size); + for (i = 1; i < count + 1; i++) { + summary[i - 1].sid = rules_profile_data[i].sid; + summary[i - 1].rev = rules_profile_data[i].rev; + summary[i - 1].gid = rules_profile_data[i].gid; + + summary[i - 1].ticks = rules_profile_data[i].ticks_match + rules_profile_data[i].ticks_no_match; + summary[i - 1].checks = rules_profile_data[i].checks; + + if (summary[i - 1].ticks > 0) { + summary[i - 1].avgticks = (long double)summary[i - 1].ticks / (long double)rules_profile_data[i].checks; + } + + summary[i - 1].matches = rules_profile_data[i].matches; + summary[i - 1].max = rules_profile_data[i].max; + summary[i - 1].ticks_match = rules_profile_data[i].ticks_match; + summary[i - 1].ticks_no_match = rules_profile_data[i].ticks_no_match; + if (rules_profile_data[i].ticks_match > 0) { + summary[i - 1].avgticks_match = (long double)rules_profile_data[i].ticks_match / + (long double)rules_profile_data[i].matches; + } + + if (rules_profile_data[i].ticks_no_match > 0) { + summary[i - 1].avgticks_no_match = (long double)rules_profile_data[i].ticks_no_match / + ((long double)rules_profile_data[i].checks - (long double)rules_profile_data[i].matches); + } + total_ticks += summary[i - 1].ticks; + } + + switch (profiling_rules_sort_order) { + case SC_PROFILING_RULES_SORT_BY_TICKS: + qsort(summary, count, sizeof(SCProfileSummary), + SCProfileSummarySortByTicks); + break; + case SC_PROFILING_RULES_SORT_BY_AVG_TICKS: + qsort(summary, count, sizeof(SCProfileSummary), + SCProfileSummarySortByAvgTicks); + break; + case SC_PROFILING_RULES_SORT_BY_CHECKS: + qsort(summary, count, sizeof(SCProfileSummary), + SCProfileSummarySortByChecks); + break; + case SC_PROFILING_RULES_SORT_BY_MATCHES: + qsort(summary, count, sizeof(SCProfileSummary), + SCProfileSummarySortByMatches); + break; + case SC_PROFILING_RULES_SORT_BY_MAX_TICKS: + qsort(summary, count, sizeof(SCProfileSummary), + SCProfileSummarySortByMaxTicks); + break; + case SC_PROFILING_RULES_SORT_BY_AVG_TICKS_MATCH: + qsort(summary, count, sizeof(SCProfileSummary), + SCProfileSummarySortByAvgTicksMatch); + break; + case SC_PROFILING_RULES_SORT_BY_AVG_TICKS_NO_MATCH: + qsort(summary, count, sizeof(SCProfileSummary), + SCProfileSummarySortByAvgTicksNoMatch); + break; + } + + gettimeofday(&tval, NULL); + struct tm local_tm; + tms = (struct tm *)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, " %-8s %-12s %-8s %-8s %-12s %-6s %-8s %-8s %-11s %-11s %-11s %-11s\n", "Num", "Rule", "Gid", "Rev", "Ticks", "%", "Checks", "Matches", "Max Ticks", "Avg Ticks", "Avg Match", "Avg No Match"); + fprintf(fp, " -------- " + "------------ " + "-------- " + "-------- " + "------------ " + "------ " + "-------- " + "-------- " + "----------- " + "----------- " + "----------- " + "-------------- " + "\n"); + for (i = 0; i < MIN(count, profiling_rules_limit); i++) { + + /* Stop dumping when we hit our first rule with 0 checks. Due + * to sorting this will be the beginning of all the rules with + * 0 checks. */ + if (summary[i].checks == 0) + break; + + double percent = (long double)summary[i].ticks / + (long double)total_ticks * 100; + fprintf(fp, + " %-8"PRIu32" %-12u %-8"PRIu32" %-8"PRIu32" %-12"PRIu64" %-6.2f %-8"PRIu64" %-8"PRIu64" %-11"PRIu64" %-11.2f %-11.2f %-11.2f\n", + i + 1, + summary[i].sid, + summary[i].gid, + summary[i].rev, + summary[i].ticks, + percent, + summary[i].checks, + summary[i].matches, + summary[i].max, + summary[i].avgticks, + summary[i].avgticks_match, + summary[i].avgticks_no_match); + } + + fprintf(fp,"\n"); + if (fp != stdout) + fclose(fp); + SCLogInfo("Done dumping profiling data."); +} + +/** + * \brief Register a rule profiling counter. + * + * \retval Returns the ID of the counter on success, 0 on failure. + */ +static uint16_t +SCProfilingRegisterRuleCounter(SCProfileDetectCtx *ctx) +{ + ctx->size++; + return ctx->id++; +} + +/** + * \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 +SCProfilingUpdateRuleCounter(DetectEngineThreadCtx *det_ctx, uint16_t id, uint64_t ticks, int match) +{ + if (det_ctx != NULL && det_ctx->rule_perf_data != NULL && det_ctx->rule_perf_data_size >= id) { + SCProfileData *p = &det_ctx->rule_perf_data[id]; + + p->checks++; + p->matches += match; + if (ticks > p->max) + p->max = ticks; + if (match == 1) + p->ticks_match += ticks; + else + p->ticks_no_match += ticks; + } +} + +SCProfileDetectCtx *SCProfilingRuleInitCtx(void) { + SCProfileDetectCtx *ctx = SCMalloc(sizeof(SCProfileDetectCtx)); + if (ctx != NULL) { + memset(ctx, 0x00, sizeof(SCProfileDetectCtx)); + + if (pthread_mutex_init(&rules_profile_data_m, NULL) != 0) { + SCLogError(SC_ERR_MUTEX, + "Failed to initialize hash table mutex."); + exit(EXIT_FAILURE); + } + } + + return ctx; +} + +void SCProfilingRuleDestroyCtx(SCProfileDetectCtx *ctx) { + if (ctx != NULL) { + SCProfilingRuleDump(ctx); + pthread_mutex_destroy(&rules_profile_data_m); + SCFree(ctx); + } +} + +void SCProfilingRuleThreadSetup(SCProfileDetectCtx *ctx, DetectEngineThreadCtx *det_ctx) { + if (ctx == NULL) + return; + + SCProfileData *a = SCMalloc(sizeof(SCProfileData) * ctx->size); + if (a != NULL) { + memset(a, 0x00, sizeof(SCProfileData) * ctx->size); + + det_ctx->rule_perf_data = a; + det_ctx->rule_perf_data_size = ctx->size; + } +} + +static void SCProfilingRuleThreadMerge(DetectEngineThreadCtx *det_ctx) { + if (det_ctx == NULL || det_ctx->rule_perf_data == NULL) + return; + + int i; + for (i = 0; i < det_ctx->rule_perf_data_size; i++) { + rules_profile_data[i].checks += det_ctx->rule_perf_data[i].checks; + rules_profile_data[i].matches += det_ctx->rule_perf_data[i].matches; + rules_profile_data[i].ticks_match += det_ctx->rule_perf_data[i].ticks_match; + rules_profile_data[i].ticks_no_match += det_ctx->rule_perf_data[i].ticks_no_match; + if (det_ctx->rule_perf_data[i].max > rules_profile_data[i].max) + rules_profile_data[i].max = det_ctx->rule_perf_data[i].max; + } +} + +void SCProfilingRuleThreadCleanup(DetectEngineThreadCtx *det_ctx) { + if (det_ctx == NULL || det_ctx->rule_perf_data == NULL) + return; + + pthread_mutex_lock(&rules_profile_data_m); + SCProfilingRuleThreadMerge(det_ctx); + pthread_mutex_unlock(&rules_profile_data_m); +} + +/** + * \brief Register the rule profiling counters. + * + * \param de_ctx The active DetectEngineCtx, used to get at the loaded rules. + */ +void +SCProfilingRuleInitCounters(DetectEngineCtx *de_ctx) +{ + de_ctx->profile_ctx = SCProfilingRuleInitCtx(); + BUG_ON(de_ctx->profile_ctx == NULL); + + Signature *sig = de_ctx->sig_list; + uint32_t count = 0; + while (sig != NULL) { + sig->profiling_id = SCProfilingRegisterRuleCounter(de_ctx->profile_ctx); + rules_profile_data[sig->profiling_id].sid = sig->id; + rules_profile_data[sig->profiling_id].gid = sig->gid; + rules_profile_data[sig->profiling_id].rev = sig->rev; + sig = sig->next; + count++; + } + SCLogInfo("Registered %"PRIu32" rule profiling counters.", count); +} + +#endif /* PROFILING */ + diff --git a/src/util-profiling.c b/src/util-profiling.c index 23ffe41671..92ef3f2387 100644 --- a/src/util-profiling.c +++ b/src/util-profiling.c @@ -29,7 +29,6 @@ #include "suricata-common.h" #include "decode.h" #include "detect.h" -#include "counters.h" #include "conf.h" #include "tm-threads.h" @@ -48,28 +47,6 @@ #define DEFAULT_LOG_FILENAME "profile.log" #define DEFAULT_LOG_MODE_APPEND "yes" -/** - * Sort orders for dumping profiled rules. - */ -enum { - SC_PROFILING_RULES_SORT_BY_TICKS = 0, - SC_PROFILING_RULES_SORT_BY_AVG_TICKS, - SC_PROFILING_RULES_SORT_BY_CHECKS, - SC_PROFILING_RULES_SORT_BY_MATCHES, - SC_PROFILING_RULES_SORT_BY_MAX_TICKS, - SC_PROFILING_RULES_SORT_BY_AVG_TICKS_MATCH, - SC_PROFILING_RULES_SORT_BY_AVG_TICKS_NO_MATCH, -}; -static int profiling_rules_sort_order = SC_PROFILING_RULES_SORT_BY_TICKS; - -/** - * Maximum number of rules to dump. - */ -static uint32_t profiling_rules_limit = UINT32_MAX; - -static SCPerfContext rules_ctx; -static SCPerfCounterArray *rules_pca; - static pthread_mutex_t packet_profile_lock; static FILE *packet_profile_csv_fp = NULL; @@ -78,19 +55,6 @@ extern int profiling_locks_output_to_file; extern char *profiling_locks_file_name; extern char *profiling_locks_file_mode; -/** - * Extra data for rule profiling. - */ -typedef struct SCProfileData_ { - uint32_t gid; - uint8_t rev; - uint64_t matches; - uint64_t max; - uint64_t ticks_match; - uint64_t ticks_no_match; -} SCProfileData; -SCProfileData rules_profile_data[0xffff]; - typedef struct SCProfilePacketData_ { uint64_t min; uint64_t max; @@ -122,25 +86,6 @@ SCProfilePacketData packet_profile_app_pd_data6[257]; SCProfilePacketData packet_profile_detect_data4[PROF_DETECT_SIZE][257]; SCProfilePacketData packet_profile_detect_data6[PROF_DETECT_SIZE][257]; -/** - * Used for generating the summary data to print. - */ -typedef struct SCProfileSummary_ { - char *name; - uint32_t gid; - uint8_t rev; - uint64_t ticks; - double avgticks; - double avgticks_match; - double avgticks_no_match; - uint64_t checks; - uint64_t matches; - uint64_t max; - uint64_t ticks_match; - uint64_t ticks_no_match; -} SCProfileSummary; - -int profiling_rules_enabled = 0; int profiling_packets_enabled = 0; int profiling_packets_csv_enabled = 0; @@ -149,7 +94,6 @@ int profiling_packets_output_to_file = 0; char *profiling_file_name; char *profiling_packets_file_name; char *profiling_csv_file_name; -const char *profiling_file_mode; const char *profiling_packets_file_mode; /** @@ -167,84 +111,6 @@ void SCProfilingInit(void) { ConfNode *conf; - const char *val; - - conf = ConfGetNode("profiling.rules"); - if (conf != NULL) { - if (ConfNodeChildValueIsTrue(conf, "enabled")) { - memset(rules_profile_data, 0, sizeof(rules_profile_data)); - memset(&rules_ctx, 0, sizeof(rules_ctx)); - rules_pca = SCPerfGetAllCountersArray(NULL); - if (pthread_mutex_init(&rules_ctx.m, NULL) != 0) { - SCLogError(SC_ERR_MUTEX, - "Failed to initialize hash table mutex."); - exit(EXIT_FAILURE); - } - profiling_rules_enabled = 1; - - val = ConfNodeLookupChildValue(conf, "sort"); - if (val != NULL) { - if (strcmp(val, "ticks") == 0) { - profiling_rules_sort_order = - SC_PROFILING_RULES_SORT_BY_TICKS; - } - else if (strcmp(val, "avgticks") == 0) { - profiling_rules_sort_order = - SC_PROFILING_RULES_SORT_BY_AVG_TICKS; - } - else if (strcmp(val, "avgticks_match") == 0) { - profiling_rules_sort_order = - SC_PROFILING_RULES_SORT_BY_AVG_TICKS_MATCH; - } - else if (strcmp(val, "avgticks_no_match") == 0) { - profiling_rules_sort_order = - SC_PROFILING_RULES_SORT_BY_AVG_TICKS_NO_MATCH; - } - else if (strcmp(val, "checks") == 0) { - profiling_rules_sort_order = - SC_PROFILING_RULES_SORT_BY_CHECKS; - } - else if (strcmp(val, "matches") == 0) { - profiling_rules_sort_order = - SC_PROFILING_RULES_SORT_BY_MATCHES; - } - else if (strcmp(val, "maxticks") == 0) { - profiling_rules_sort_order = - SC_PROFILING_RULES_SORT_BY_MAX_TICKS; - } - else { - SCLogError(SC_ERR_INVALID_ARGUMENT, - "Invalid profiling sort order: %s", val); - exit(EXIT_FAILURE); - } - } - - val = ConfNodeLookupChildValue(conf, "limit"); - if (val != NULL) { - if (ByteExtractStringUint32(&profiling_rules_limit, 10, - (uint16_t)strlen(val), val) <= 0) { - SCLogError(SC_ERR_INVALID_ARGUMENT, "Invalid limit: %s", val); - exit(EXIT_FAILURE); - } - } - const char *filename = ConfNodeLookupChildValue(conf, "filename"); - if (filename != NULL) { - - char *log_dir; - if (ConfGet("default-log-dir", &log_dir) != 1) - log_dir = DEFAULT_LOG_DIR; - - profiling_file_name = SCMalloc(PATH_MAX); - snprintf(profiling_file_name, PATH_MAX, "%s/%s", log_dir, filename); - - profiling_file_mode = ConfNodeLookupChildValue(conf, "append"); - if (profiling_file_mode == NULL) - profiling_file_mode = DEFAULT_LOG_MODE_APPEND; - - profiling_output_to_file = 1; - } - } - } conf = ConfGetNode("profiling.packets"); if (conf != NULL) { @@ -366,12 +232,6 @@ SCProfilingInit(void) void SCProfilingDestroy(void) { - if (profiling_rules_enabled) { - SCPerfReleasePerfCounterS(rules_ctx.head); - SCPerfReleasePCA(rules_pca); - pthread_mutex_destroy(&rules_ctx.m); - } - if (profiling_packets_enabled) { pthread_mutex_destroy(&packet_profile_lock); } @@ -392,321 +252,13 @@ SCProfilingDestroy(void) #endif } -/** - * \brief Qsort comparison function to sort by ticks. - */ -static int -SCProfileSummarySortByTicks(const void *a, const void *b) -{ - const SCProfileSummary *s0 = a; - const SCProfileSummary *s1 = b; - return s1->ticks - s0->ticks; -} - -/** - * \brief Qsort comparison function to sort by average ticks per match. - */ -static int -SCProfileSummarySortByAvgTicksMatch(const void *a, const void *b) -{ - const SCProfileSummary *s0 = a; - const SCProfileSummary *s1 = b; - return s1->avgticks_match - s0->avgticks_match; -} - -/** - * \brief Qsort comparison function to sort by average ticks per non match. - */ -static int -SCProfileSummarySortByAvgTicksNoMatch(const void *a, const void *b) -{ - const SCProfileSummary *s0 = a; - const SCProfileSummary *s1 = b; - return s1->avgticks_no_match - s0->avgticks_no_match; -} - -/** - * \brief Qsort comparison function to sort by average ticks. - */ -static int -SCProfileSummarySortByAvgTicks(const void *a, const void *b) -{ - const SCProfileSummary *s0 = a; - const SCProfileSummary *s1 = b; - return s1->avgticks - s0->avgticks; -} - -/** - * \brief Qsort comparison function to sort by checks. - */ -static int -SCProfileSummarySortByChecks(const void *a, const void *b) -{ - const SCProfileSummary *s0 = a; - const SCProfileSummary *s1 = b; - return s1->checks - s0->checks; -} - -/** - * \brief Qsort comparison function to sort by matches. - */ -static int -SCProfileSummarySortByMatches(const void *a, const void *b) -{ - const SCProfileSummary *s0 = a; - const SCProfileSummary *s1 = b; - return s1->matches - s0->matches; -} - -/** - * \brief Qsort comparison function to sort by max ticks. - */ -static int -SCProfileSummarySortByMaxTicks(const void *a, const void *b) -{ - const SCProfileSummary *s0 = a; - const SCProfileSummary *s1 = b; - return s1->max - s0->max; -} - void SCProfilingDump(void) { - uint32_t i; - FILE *fp; - SCProfilingDumpPacketStats(); - - struct timeval tval; - struct tm *tms; - if (profiling_output_to_file == 1) { - if (ConfValIsTrue(profiling_file_mode)) { - fp = fopen(profiling_file_name, "a"); - } else { - fp = fopen(profiling_file_name, "w"); - } - - if (fp == NULL) { - SCLogError(SC_ERR_FOPEN, "failed to open %s: %s", profiling_file_name, - strerror(errno)); - return; - } - } else { - fp = stdout; - } - - if (rules_pca == NULL) { - SCLogDebug("No rules specified to provide a profiling summary"); - return; - } - - int summary_size = sizeof(SCProfileSummary) * rules_pca->size; - SCProfileSummary *summary = SCMalloc(summary_size); - if (summary == NULL) { - SCLogError(SC_ERR_MEM_ALLOC, "Error allocating memory for profiling summary"); - return; - } - - uint32_t count = rules_pca->size; - uint64_t total_ticks = 0; - - SCLogInfo("Dumping profiling data."); - - memset(summary, 0, summary_size); - for (i = 1; i < count + 1; i++) { - summary[i - 1].name = rules_pca->head[i].pc->name->cname; - summary[i - 1].rev = rules_profile_data[i].rev; - summary[i - 1].gid = rules_profile_data[i].gid; - summary[i - 1].ticks = rules_pca->head[i].ui64_cnt; - if (rules_pca->head[i].ui64_cnt) { - summary[i - 1].avgticks = (long double)rules_pca->head[i].ui64_cnt / - (long double)rules_pca->head[i].syncs; - } - summary[i - 1].checks = rules_pca->head[i].syncs; - summary[i - 1].matches = rules_profile_data[i].matches; - summary[i - 1].max = rules_profile_data[i].max; - summary[i - 1].ticks_match = rules_profile_data[i].ticks_match; - summary[i - 1].ticks_no_match = rules_profile_data[i].ticks_no_match; - if (rules_profile_data[i].ticks_match > 0) { - summary[i - 1].avgticks_match = (long double)rules_profile_data[i].ticks_match / - (long double)rules_profile_data[i].matches; - } - - if (rules_profile_data[i].ticks_no_match > 0) { - summary[i - 1].avgticks_no_match = (long double)rules_profile_data[i].ticks_no_match / - ((long double)rules_pca->head[i].syncs - (long double)rules_profile_data[i].matches); - } - total_ticks += summary[i - 1].ticks; - } - - switch (profiling_rules_sort_order) { - case SC_PROFILING_RULES_SORT_BY_TICKS: - qsort(summary, count, sizeof(SCProfileSummary), - SCProfileSummarySortByTicks); - break; - case SC_PROFILING_RULES_SORT_BY_AVG_TICKS: - qsort(summary, count, sizeof(SCProfileSummary), - SCProfileSummarySortByAvgTicks); - break; - case SC_PROFILING_RULES_SORT_BY_CHECKS: - qsort(summary, count, sizeof(SCProfileSummary), - SCProfileSummarySortByChecks); - break; - case SC_PROFILING_RULES_SORT_BY_MATCHES: - qsort(summary, count, sizeof(SCProfileSummary), - SCProfileSummarySortByMatches); - break; - case SC_PROFILING_RULES_SORT_BY_MAX_TICKS: - qsort(summary, count, sizeof(SCProfileSummary), - SCProfileSummarySortByMaxTicks); - break; - case SC_PROFILING_RULES_SORT_BY_AVG_TICKS_MATCH: - qsort(summary, count, sizeof(SCProfileSummary), - SCProfileSummarySortByAvgTicksMatch); - break; - case SC_PROFILING_RULES_SORT_BY_AVG_TICKS_NO_MATCH: - qsort(summary, count, sizeof(SCProfileSummary), - SCProfileSummarySortByAvgTicksNoMatch); - break; - } - - gettimeofday(&tval, NULL); - struct tm local_tm; - tms = (struct tm *)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, " %-8s %-12s %-8s %-8s %-12s %-6s %-8s %-8s %-11s %-11s %-11s %-11s\n", "Num", "Rule", "Gid", "Rev", "Ticks", "%", "Checks", "Matches", "Max Ticks", "Avg Ticks", "Avg Match", "Avg No Match"); - fprintf(fp, " -------- " - "------------ " - "-------- " - "-------- " - "------------ " - "------ " - "-------- " - "-------- " - "----------- " - "----------- " - "----------- " - "-------------- " - "\n"); - for (i = 0; i < MIN(count, profiling_rules_limit); i++) { - - /* Stop dumping when we hit our first rule with 0 checks. Due - * to sorting this will be the beginning of all the rules with - * 0 checks. */ - if (summary[i].checks == 0) - break; - - double percent = (long double)summary[i].ticks / - (long double)total_ticks * 100; - fprintf(fp, - " %-8"PRIu32" %-12s %-8"PRIu32" %-8"PRIu32" %-12"PRIu64" %-6.2f %-8"PRIu64" %-8"PRIu64" %-11"PRIu64" %-11.2f %-11.2f %-11.2f\n", - i + 1, - summary[i].name, - summary[i].gid, - summary[i].rev, - summary[i].ticks, - percent, - summary[i].checks, - summary[i].matches, - summary[i].max, - summary[i].avgticks, - summary[i].avgticks_match, - summary[i].avgticks_no_match); - } - - fprintf(fp,"\n"); - if (fp != stdout) - fclose(fp); SCLogInfo("Done dumping profiling data."); } -/** - * \brief Register a rule profiling counter. - * - * \param gid The GID of the rule. - * \param sid The SID of the rule. - * - * \retval Returns the ID of the counter on success, 0 on failure. - */ -static uint16_t -SCProfilingRegisterRuleCounter(Signature *sig) -{ - char name[12]; - uint16_t id; - - /* Don't use GID right now... */ - //snprintf(name, sizeof(name), "%"PRIu32":%"PRIu32, gid, sid); - snprintf(name, sizeof(name), "%"PRIu32, sig->id); - - id = SCPerfRegisterCounter(name, "profiler", SC_PERF_TYPE_UINT64, NULL, - &rules_ctx); - return id; -} - -/** - * \brief Register the rule profiling counters. - * - * \param de_ctx The active DetectEngineCtx, used to get at the loaded rules. - */ -void -SCProfilingInitRuleCounters(DetectEngineCtx *de_ctx) -{ - Signature *sig = de_ctx->sig_list; - uint32_t count = 0; - while (sig != NULL) { - sig->profiling_id = SCProfilingRegisterRuleCounter(sig); - rules_profile_data[sig->profiling_id].rev = sig->rev; - rules_profile_data[sig->profiling_id].gid = sig->gid; - sig = sig->next; - count++; - } - rules_pca = SCPerfGetAllCountersArray(&rules_ctx); - SCLogInfo("Registered %"PRIu32" rule profiling counters.", count); -} - -/** - * \brief Add a uint64_t value to the current value of the rule - * counter ID. - * - * \param id The ID of the rule profiling counter. - * \paral val The value to add to the counter. - */ -void -SCProfilingCounterAddUI64(uint16_t id, uint64_t val) -{ - SCPerfCounterAddUI64(id, rules_pca, val); -} - -/** - * \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 -SCProfilingUpdateRuleCounter(uint16_t id, uint64_t ticks, int match) -{ - pthread_mutex_lock(&rules_ctx.m); - SCProfilingCounterAddUI64(id, ticks); - rules_profile_data[id].matches += match; - if (ticks > rules_profile_data[id].max) - rules_profile_data[id].max = ticks; - if (match == 1) - rules_profile_data[id].ticks_match += ticks; - else - rules_profile_data[id].ticks_no_match += ticks; - - pthread_mutex_unlock(&rules_ctx.m); -} - void SCProfilingDumpPacketStats(void) { int i; FILE *fp; @@ -1235,6 +787,7 @@ const char * PacketProfileDetectIdToString(PacketProfileDetectId id) static int ProfilingTest01(void) { +#if 0 uint16_t counter1; Signature sig; @@ -1264,7 +817,7 @@ ProfilingTest01(void) SCProfilingDump(); SCProfilingDestroy(); - +#endif return 1; } diff --git a/src/util-profiling.h b/src/util-profiling.h index 1bc64ace5e..274a1d97f1 100644 --- a/src/util-profiling.h +++ b/src/util-profiling.h @@ -49,10 +49,10 @@ void SCProfilingAddPacket(Packet *); profile_rule_start_ = UtilCpuGetTicks(); \ } -#define RULE_PROFILING_END(r, m) \ +#define RULE_PROFILING_END(ctx, r, m) \ if (profiling_rules_enabled) { \ profile_rule_end_ = UtilCpuGetTicks(); \ - SCProfilingUpdateRuleCounter(r->profiling_id, \ + SCProfilingUpdateRuleCounter(ctx, r->profiling_id, \ profile_rule_end_ - profile_rule_start_, m); \ profiling_rules_entered--; \ } @@ -195,18 +195,24 @@ void SCProfilingAddPacket(Packet *); } \ } + +void SCProfilingRulesGlobalInit(void); +void SCProfilingRuleDestroyCtx(SCProfileDetectCtx *); +void SCProfilingRuleInitCounters(DetectEngineCtx *); +void SCProfilingUpdateRuleCounter(DetectEngineThreadCtx *, uint16_t, uint64_t, int); + +void SCProfilingRuleThreadSetup(SCProfileDetectCtx *, DetectEngineThreadCtx *); +void SCProfilingRuleThreadCleanup(DetectEngineThreadCtx *); + void SCProfilingInit(void); void SCProfilingDestroy(void); -void SCProfilingInitRuleCounters(DetectEngineCtx *); -void SCProfilingCounterAddUI64(uint16_t, uint64_t); void SCProfilingRegisterTests(void); void SCProfilingDump(void); -void SCProfilingUpdateRuleCounter(uint16_t, uint64_t, int); #else #define RULE_PROFILING_START -#define RULE_PROFILING_END(r, m) +#define RULE_PROFILING_END(a,b,c) #define PACKET_PROFILING_START(p) #define PACKET_PROFILING_END(p)