diff --git a/qa/gnuplot/plot-csv-large-all.sh b/qa/gnuplot/plot-csv-large-all.sh index 85b6c6a2ba..f3484fd723 100755 --- a/qa/gnuplot/plot-csv-large-all.sh +++ b/qa/gnuplot/plot-csv-large-all.sh @@ -14,7 +14,8 @@ set title "$1 ticks" set key autotitle columnhead set yrange [:] set xrange [:] -#set logscale y +set logscale y +#set pointsize 4 plot "$1" using $2 with $4, for [i in $3] '' using i with $4 EOF RESULT=$? diff --git a/src/decode.h b/src/decode.h index 27b5fe466d..345240865c 100644 --- a/src/decode.h +++ b/src/decode.h @@ -274,6 +274,12 @@ typedef struct PktProfilingTmmData_ { uint64_t ticks_end; } PktProfilingTmmData; +typedef struct PktProfilingDetectData_ { + uint64_t ticks_start; + uint64_t ticks_end; + uint32_t ticks_spent; +} PktProfilingDetectData; + typedef struct PktProfilingAppData_ { uint64_t ticks_spent; } PktProfilingAppData; @@ -285,6 +291,7 @@ typedef struct PktProfiling_ { PktProfilingTmmData tmm[TMM_SIZE]; PktProfilingAppData app[ALPROTO_MAX]; + PktProfilingDetectData detect[PROF_DETECT_SIZE]; uint32_t proto_detect; } PktProfiling; diff --git a/src/detect.c b/src/detect.c index 83a1b505ed..f30b3908ab 100644 --- a/src/detect.c +++ b/src/detect.c @@ -1200,7 +1200,11 @@ static inline void DetectMpmPrefilter(DetectEngineCtx *de_ctx, } else { SCLogDebug("search: (%p, maxlen %" PRIu32 ", sgh->sig_cnt %" PRIu32 ")", det_ctx->sgh, det_ctx->sgh->mpm_content_maxlen, det_ctx->sgh->sig_cnt); + + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_MPM_PACKET); cnt = PacketPatternSearch(det_ctx, p); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_MPM_PACKET); + SCLogDebug("post search: cnt %" PRIu32, cnt); *sms_runflags |= SMS_USED_PM; } @@ -1210,7 +1214,10 @@ static inline void DetectMpmPrefilter(DetectEngineCtx *de_ctx, if (p->flowflags & FLOW_PKT_ESTABLISHED) { SCLogDebug("p->flowflags & FLOW_PKT_ESTABLISHED"); if (smsg != NULL && det_ctx->sgh->mpm_stream_ctx != NULL) { + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_MPM_STREAM); cnt = StreamPatternSearch(det_ctx, p, smsg, flags); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_MPM_STREAM); + SCLogDebug("Stream Mpm cnt %u", cnt); *sms_runflags |= SMS_USED_STREAM_PM; } else { @@ -1302,6 +1309,7 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh /* Get the stored sgh from the flow (if any). Make sure we're not using * the sgh for icmp error packets part of the same stream. */ if (IP_GET_IPPROTO(p) == p->flow->proto) { /* filter out icmp */ + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_GETSGH); if (p->flowflags & FLOW_PKT_TOSERVER && p->flow->flags & FLOW_SGH_TOSERVER) { det_ctx->sgh = p->flow->sgh_toserver; sms_runflags |= SMS_USE_FLOW_SGH; @@ -1309,6 +1317,7 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh det_ctx->sgh = p->flow->sgh_toclient; sms_runflags |= SMS_USE_FLOW_SGH; } + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_GETSGH); smsg = SigMatchSignaturesGetSmsg(p->flow, p, flags); #if 0 @@ -1352,7 +1361,10 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh { SCLogDebug("testing against \"ip-only\" signatures"); + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_IPONLY); IPOnlyMatchPacket(th_v, de_ctx, det_ctx, &de_ctx->io_ctx, &det_ctx->io_ctx, p); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_IPONLY); + /* save in the flow that we scanned this direction... locking is * done in the FlowSetIPOnlyFlag function. */ FlowSetIPOnlyFlag(p->flow, p->flowflags & FLOW_PKT_TOSERVER ? 1 : 0); @@ -1378,15 +1390,22 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh } if (!(sms_runflags & SMS_USE_FLOW_SGH)) { + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_GETSGH); det_ctx->sgh = SigMatchSignaturesGetSgh(de_ctx, det_ctx, p); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_GETSGH); } } else { /* no flow */ + /* Even without flow we should match the packet src/dst */ + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_IPONLY); IPOnlyMatchPacket(th_v, de_ctx, det_ctx, &de_ctx->io_ctx, &det_ctx->io_ctx, p); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_IPONLY); + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_GETSGH); det_ctx->sgh = SigMatchSignaturesGetSgh(de_ctx, det_ctx, p); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_GETSGH); } /* if we didn't get a sig group head, we @@ -1397,9 +1416,12 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh } /* run the mpm for each type */ + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_MPM); DetectMpmPrefilter(de_ctx, det_ctx, smsg, p, flags, alproto, alstate, &sms_runflags); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_MPM); + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_STATEFUL); /* stateful app layer detection */ if (p->flags & PKT_HAS_FLOW && alstate != NULL) { /* initialize to 0 (DE_STATE_MATCH_NOSTATE) */ @@ -1414,14 +1436,18 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh alstate = NULL; } } + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_STATEFUL); /* create our prefilter mask */ SignatureMask mask = 0; PacketCreateMask(p, &mask, alproto, alstate, smsg); + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_PREFILTER); /* build the match array */ SigMatchSignaturesBuildMatchArray(det_ctx, p, mask, alproto); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_PREFILTER); + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_RULES); /* inspect the sigs against the packet */ for (idx = 0; idx < det_ctx->match_array_cnt; idx++) { StreamMsg *alert_msg = NULL; @@ -1592,8 +1618,13 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh if (det_ctx->de_state_sig_array[s->num] == DE_STATE_MATCH_NOSTATE) { SCLogDebug("stateful app layer match inspection starting"); - if (DeStateDetectStartDetection(th_v, de_ctx, det_ctx, s, - p->flow, flags, alstate, alproto, alversion) != 1) { + + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_STATEFUL); + int de_r = DeStateDetectStartDetection(th_v, de_ctx, det_ctx, s, + p->flow, flags, alstate, alproto, alversion); + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_STATEFUL); + + if (de_r != 1) { goto next; } else { if (s->action == ACTION_DROP) @@ -1692,9 +1723,11 @@ int SigMatchSignatures(ThreadVars *th_v, DetectEngineCtx *de_ctx, DetectEngineTh RULE_PROFILING_END(s, match); break; } + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_RULES); end: if (alstate != NULL) { + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_STATEFUL); SCLogDebug("getting de_state_status"); int de_state_status = DeStateUpdateInspectTransactionId(p->flow, (flags & STREAM_TOSERVER) ? STREAM_TOSERVER : STREAM_TOCLIENT); @@ -1705,17 +1738,21 @@ end: DetectEngineStateReset(p->flow->de_state); SCMutexUnlock(&p->flow->de_state_m); } + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_STATEFUL); } /* so now let's iterate the alerts and remove the ones after a pass rule * matched (if any). This is done inside PacketAlertFinalize() */ /* PR: installed "tag" keywords are handled after the threshold inspection */ + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_ALERT); PacketAlertFinalize(de_ctx, det_ctx, p); if (p->alerts.cnt > 0) { SCPerfCounterAddUI64(det_ctx->counter_alerts, det_ctx->tv->sc_perf_pca, (uint64_t)p->alerts.cnt); } + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_ALERT); + PACKET_PROFILING_DETECT_START(p, PROF_DETECT_CLEANUP); /* cleanup pkt specific part of the patternmatcher */ PacketPatternCleanup(th_v, det_ctx); @@ -1752,6 +1789,7 @@ end: FlowDecrUsecnt(p->flow); } + PACKET_PROFILING_DETECT_END(p, PROF_DETECT_CLEANUP); SCReturnInt(fmatch); } diff --git a/src/suricata-common.h b/src/suricata-common.h index a6c024abf7..f2421a5164 100644 --- a/src/suricata-common.h +++ b/src/suricata-common.h @@ -160,6 +160,21 @@ #endif #endif +typedef enum PacketProfileDetectId_ { + PROF_DETECT_MPM, + PROF_DETECT_MPM_PACKET, + PROF_DETECT_MPM_STREAM, + PROF_DETECT_IPONLY, + PROF_DETECT_RULES, + PROF_DETECT_STATEFUL, + PROF_DETECT_PREFILTER, + PROF_DETECT_ALERT, + PROF_DETECT_CLEANUP, + PROF_DETECT_GETSGH, + + PROF_DETECT_SIZE, +} PacketProfileDetectId; + #include #include "threads.h" #include "tm-threads-common.h" diff --git a/src/util-profiling.c b/src/util-profiling.c index 8a075f252e..89bbe61970 100644 --- a/src/util-profiling.c +++ b/src/util-profiling.c @@ -101,6 +101,9 @@ SCProfilePacketData packet_profile_app_data6[TMM_SIZE][257]; SCProfilePacketData packet_profile_app_pd_data4[257]; 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. */ @@ -137,6 +140,7 @@ const char *profiling_packets_file_mode; __thread int profiling_rules_entered = 0; void SCProfilingDumpPacketStats(void); +const char * PacketProfileDetectIdToString(PacketProfileDetectId id); /** * \brief Initialize profiling. @@ -242,6 +246,8 @@ SCProfilingInit(void) memset(&packet_profile_app_data6, 0, sizeof(packet_profile_app_data6)); memset(&packet_profile_app_pd_data4, 0, sizeof(packet_profile_app_pd_data4)); memset(&packet_profile_app_pd_data6, 0, sizeof(packet_profile_app_pd_data6)); + memset(&packet_profile_detect_data4, 0, sizeof(packet_profile_detect_data4)); + memset(&packet_profile_detect_data6, 0, sizeof(packet_profile_detect_data6)); const char *filename = ConfNodeLookupChildValue(conf, "filename"); if (filename != NULL) { @@ -294,7 +300,11 @@ SCProfilingInit(void) for (i = 0; i < ALPROTO_MAX; i++) { fprintf(packet_profile_csv_fp, "%s,", TmModuleAlprotoToString(i)); } - fprintf(packet_profile_csv_fp, "STREAM (no app),proto detect,\n"); + fprintf(packet_profile_csv_fp, "STREAM (no app),proto detect,"); + for (i = 0; i < PROF_DETECT_SIZE; i++) { + fprintf(packet_profile_csv_fp, "%s,", PacketProfileDetectIdToString(i)); + } + fprintf(packet_profile_csv_fp, "\n"); profiling_packets_csv_enabled = 1; } @@ -794,6 +804,38 @@ void SCProfilingDumpPacketStats(void) { } } + fprintf(fp, "\nGeneral detection engine stats:\n"); + + fprintf(fp, "\n%-24s %-6s %-5s %-8s %-6s %-10s %-8s\n", + "Detection phase", "IP ver", "Proto", "cnt", "min", "max", "avg"); + fprintf(fp, "%-24s %-6s %-5s %-8s %-6s %-10s %-8s\n", + "-------------------------", "------", "-----", "------", "------", "----------", "-------"); + for (m = 0; m < PROF_DETECT_SIZE; m++) { + int p; + for (p = 0; p < 257; p++) { + SCProfilePacketData *pd = &packet_profile_detect_data4[m][p]; + + if (pd->cnt == 0) { + continue; + } + + fprintf(fp, "%-24s IPv4 %3d %8u %6u %10u %8"PRIu64"\n", + PacketProfileDetectIdToString(m), p, pd->cnt, pd->min, pd->max, pd->tot / pd->cnt); + } + } + for (m = 0; m < PROF_DETECT_SIZE; m++) { + int p; + for (p = 0; p < 257; p++) { + SCProfilePacketData *pd = &packet_profile_detect_data6[m][p]; + + if (pd->cnt == 0) { + continue; + } + + fprintf(fp, "%-24s IPv6 %3d %8u %6u %10u %8"PRIu64"\n", + PacketProfileDetectIdToString(m), p, pd->cnt, pd->min, pd->max, pd->tot / pd->cnt); + } + } fclose(fp); } @@ -843,9 +885,52 @@ void SCProfilingPrintPacketProfile(Packet *p) { fprintf(packet_profile_csv_fp, "%"PRIu32",", real_tcp); fprintf(packet_profile_csv_fp, "%"PRIu32",", p->profile.proto_detect); + + for (i = 0; i < PROF_DETECT_SIZE; i++) { + PktProfilingDetectData *pdt = &p->profile.detect[i]; + + fprintf(packet_profile_csv_fp,"%"PRIu32",", pdt->ticks_spent); + } fprintf(packet_profile_csv_fp,"\n"); } +void SCProfilingUpdatePacketDetectRecord(PacketProfileDetectId id, uint8_t ipproto, PktProfilingDetectData *pdt, int ipver) { + if (pdt == NULL) { + return; + } + + SCProfilePacketData *pd; + if (ipver == 4) + pd = &packet_profile_detect_data4[id][ipproto]; + else + pd = &packet_profile_detect_data6[id][ipproto]; + + if (pd->min == 0 || pdt->ticks_spent < pd->min) { + pd->min = pdt->ticks_spent; + } + if (pd->max < pdt->ticks_spent) { + pd->max = pdt->ticks_spent; + } + + pd->tot += pdt->ticks_spent; + pd->cnt ++; +} + +void SCProfilingUpdatePacketDetectRecords(Packet *p) { + PacketProfileDetectId i; + for (i = 0; i < PROF_DETECT_SIZE; i++) { + PktProfilingDetectData *pdt = &p->profile.detect[i]; + + if (pdt->ticks_spent > 0) { + if (PKT_IS_IPV4(p)) { + SCProfilingUpdatePacketDetectRecord(i, p->proto, pdt, 4); + } else { + SCProfilingUpdatePacketDetectRecord(i, p->proto, pdt, 6); + } + } + } +} + void SCProfilingUpdatePacketAppPdRecord(uint8_t ipproto, uint32_t ticks_spent, int ipver) { SCProfilePacketData *pd; if (ipver == 4) @@ -985,6 +1070,7 @@ void SCProfilingAddPacket(Packet *p) { SCProfilingUpdatePacketTmmRecords(p); SCProfilingUpdatePacketAppRecords(p); + SCProfilingUpdatePacketDetectRecords(p); } else if (PKT_IS_IPV6(p)) { SCProfilePacketData *pd = &packet_profile_data6[p->proto]; @@ -1016,11 +1102,39 @@ void SCProfilingAddPacket(Packet *p) { SCProfilingUpdatePacketTmmRecords(p); SCProfilingUpdatePacketAppRecords(p); + SCProfilingUpdatePacketDetectRecords(p); } } SCMutexUnlock(&packet_profile_lock); } +#define CASE_CODE(E) case E: return #E + +/** + * \brief Maps the PacketProfileDetectId, to its string equivalent + * + * \param id PacketProfileDetectId id + * + * \retval string equivalent for the PacketProfileDetectId id + */ +const char * PacketProfileDetectIdToString(PacketProfileDetectId id) +{ + switch (id) { + CASE_CODE (PROF_DETECT_MPM); + CASE_CODE (PROF_DETECT_MPM_PACKET); + CASE_CODE (PROF_DETECT_MPM_STREAM); + CASE_CODE (PROF_DETECT_IPONLY); + CASE_CODE (PROF_DETECT_RULES); + CASE_CODE (PROF_DETECT_PREFILTER); + CASE_CODE (PROF_DETECT_STATEFUL); + CASE_CODE (PROF_DETECT_ALERT); + CASE_CODE (PROF_DETECT_CLEANUP); + CASE_CODE (PROF_DETECT_GETSGH); + + default: + return "UNKNOWN"; + } +} #ifdef UNITTESTS static int diff --git a/src/util-profiling.h b/src/util-profiling.h index ef5044a410..aba9a42273 100644 --- a/src/util-profiling.h +++ b/src/util-profiling.h @@ -130,6 +130,21 @@ void SCProfilingAddPacket(Packet *); } \ } +#define PACKET_PROFILING_DETECT_START(p, id) \ + if (profiling_packets_enabled) { \ + if ((id) < PROF_DETECT_SIZE) { \ + (p)->profile.detect[(id)].ticks_start = UtilCpuGetTicks(); \ + } \ + } + +#define PACKET_PROFILING_DETECT_END(p, id) \ + if (profiling_packets_enabled) { \ + if ((id) < TMM_SIZE) { \ + (p)->profile.detect[(id)].ticks_end = UtilCpuGetTicks();\ + (p)->profile.detect[(id)].ticks_spent += \ + ((p)->profile.detect[(id)].ticks_end - (p)->profile.detect[(id)].ticks_start); \ + } \ + } void SCProfilingInit(void); void SCProfilingDestroy(void); @@ -157,6 +172,12 @@ void SCProfilingUpdateRuleCounter(uint16_t, uint64_t, int); #define PACKET_PROFILING_APP_RESET(dp) #define PACKET_PROFILING_APP_STORE(dp, p) +#define PACKET_PROFILING_APP_PD_START(dp) +#define PACKET_PROFILING_APP_PD_END(dp) + +#define PACKET_PROFILING_DETECT_START(p, id) +#define PACKET_PROFILING_DETECT_END(p, id) + #endif /* PROFILING */ #endif /* ! __UTIL_PROFILE_H__ */