Profiling: add accounting for several detection phases.

remotes/origin/master-1.1.x
Victor Julien 14 years ago
parent e8e392fb1f
commit 3693a7a9ee

@ -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=$?

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

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

@ -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 <htp/htp.h>
#include "threads.h"
#include "tm-threads-common.h"

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

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

Loading…
Cancel
Save