1 /*
2 ** $Id$
3 **
4 ** profiler.c
5 **
6 ** Copyright (C) 2014-2021 Cisco and/or its affiliates. All rights reserved.
7 ** Copyright (C) 2005-2013 Sourcefire, Inc.
8 ** Steven Sturges <ssturges@sourcefire.com>
9 **
10 ** This program is free software; you can redistribute it and/or modify
11 ** it under the terms of the GNU General Public License Version 2 as
12 ** published by the Free Software Foundation. You may not use, modify or
13 ** distribute this program under any other version of the GNU General
14 ** Public License.
15 **
16 ** This program is distributed in the hope that it will be useful,
17 ** but WITHOUT ANY WARRANTY; without even the implied warranty of
18 ** MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
19 ** GNU General Public License for more details.
20 **
21 ** You should have received a copy of the GNU General Public License
22 ** along with this program; if not, write to the Free Software
23 ** Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
24 **
25 */
26
27 #include <stdio.h>
28 #include <stdlib.h>
29 #include <string.h>
30 #include <unistd.h>
31
32 #ifdef HAVE_CONFIG_H
33 #include "config.h"
34 #endif
35
36 #include "snort.h"
37 #include "rules.h"
38 #include "treenodes.h"
39 #include "treenodes.h"
40 #include "parser.h"
41 #include "plugin_enum.h"
42 #include "util.h"
43 #include "rules.h"
44 #include "treenodes.h"
45 #include "treenodes.h"
46 #include "profiler.h"
47 #include "sf_types.h"
48 #include "sf_textlog.h"
49 #include "detection_options.h"
50
51 #ifdef PERF_PROFILING
52
53 /* Data types *****************************************************************/
54 typedef struct _OTN_WorstPerformer
55 {
56 OptTreeNode *otn;
57 struct _OTN_WorstPerformer *next;
58 struct _OTN_WorstPerformer *prev;
59 double ticks_per_check;
60 double ticks_per_match;
61 double ticks_per_nomatch;
62
63 } OTN_WorstPerformer;
64
65 typedef struct _Preproc_WorstPerformer
66 {
67 PreprocStatsNode *node;
68 struct _Preproc_WorstPerformer *next;
69 struct _Preproc_WorstPerformer *prev;
70 struct _Preproc_WorstPerformer *children;
71 double ticks_per_check;
72 double pct_of_parent;
73 double pct_of_total;
74 } Preproc_WorstPerformer;
75
76
77 /* Globals ********************************************************************/
78 double ticks_per_microsec = 0.0;
79 OTN_WorstPerformer *worstPerformers = NULL;
80
81 Preproc_WorstPerformer *worstPreprocPerformers = NULL;
82 PreprocStats totalPerfStats;
83 PreprocStats metaPerfStats;
84 static PreprocStatsNode * PreprocStatsNodeList = NULL;
85 int max_layers = 0;
86
87
88 /* Externs ********************************************************************/
89 extern PreprocStats mpsePerfStats, rulePerfStats, ncrulePerfStats;
90
91
getTicksPerMicrosec(void)92 void getTicksPerMicrosec(void)
93 {
94 if (ticks_per_microsec == 0.0)
95 {
96 ticks_per_microsec = get_ticks_per_usec();
97 }
98 }
99
ResetRuleProfiling(void)100 void ResetRuleProfiling(void)
101 {
102 /* Cycle through all Rules, print ticks & check count for each */
103 RuleTreeNode *rtn;
104 SFGHASH_NODE *hashNode;
105 OptTreeNode *otn = NULL;
106 tSfPolicyId policyId = 0;
107 SnortConfig *sc = snort_conf;
108
109 if ((sc == NULL) || (sc->profile_rules.num == 0))
110 return;
111
112 for (hashNode = sfghash_findfirst(sc->otn_map);
113 hashNode;
114 hashNode = sfghash_findnext(sc->otn_map))
115 {
116 otn = (OptTreeNode *)hashNode->data;
117 for ( policyId = 0;
118 policyId < otn->proto_node_num;
119 policyId++ )
120 {
121 rtn = getRtnFromOtn(otn, policyId);
122 if (rtn == NULL)
123 continue;
124
125 if ((rtn->proto == IPPROTO_TCP) || (rtn->proto == IPPROTO_UDP)
126 || (rtn->proto == IPPROTO_ICMP) || (rtn->proto == ETHERNET_TYPE_IP))
127 {
128 //do operation
129 otn->ticks = 0;
130 otn->ticks_match = 0;
131 otn->ticks_no_match = 0;
132 otn->checks = 0;
133 otn->matches = 0;
134 otn->alerts = 0;
135 otn->noalerts = 0;
136 #ifdef PPM_MGR
137 otn->ppm_disable_cnt = 0;
138 #endif
139 }
140 }
141 }
142 }
143
PrintWorstRules(int numToPrint)144 void PrintWorstRules(int numToPrint)
145 {
146 OptTreeNode *otn;
147 OTN_WorstPerformer *node, *tmp;
148 int num = 0;
149 TextLog *log = NULL;
150 time_t cur_time;
151 char fullname[STD_BUF];
152 int ret;
153 SnortConfig *sc = snort_conf;
154
155 if (sc == NULL)
156 return;
157
158 getTicksPerMicrosec();
159
160 cur_time = time(NULL);
161
162 if (sc->profile_rules.filename != NULL)
163 {
164 if (sc->profile_rules.append)
165 {
166 log = TextLog_Init(sc->profile_rules.filename, 512*1024, 512*1024);
167
168 if (log != NULL)
169 TextLog_Print(log, "\ntimestamp: %u\n", cur_time);
170 }
171 else
172 {
173 ret = SnortSnprintf(fullname, STD_BUF, "%s.%u", sc->profile_rules.filename, (uint32_t)cur_time);
174 if(ret != SNORT_SNPRINTF_SUCCESS)
175 FatalError("profiler: file path+name too long\n");
176 log = TextLog_Init(fullname, 512*1024, 512*1024);
177 }
178 }
179
180 if (numToPrint != -1)
181 {
182 if(log)
183 {
184 TextLog_Print(log, "Rule Profile Statistics (worst %d rules)\n", numToPrint);
185 } else {
186 LogMessage("Rule Profile Statistics (worst %d rules)\n", numToPrint);
187 }
188 }
189 else
190 {
191 if(log)
192 {
193 TextLog_Print(log, "Rule Profile Statistics (all rules)\n");
194 } else {
195 LogMessage("Rule Profile Statistics (all rules)\n");
196 }
197 }
198
199 if(log)
200 {
201 TextLog_Print(log, "==========================================================\n");
202 } else {
203 LogMessage("==========================================================\n");
204 }
205
206 if (!worstPerformers)
207 {
208 if(log)
209 {
210 TextLog_Print(log, "No rules were profiled\n");
211 TextLog_Term(log);
212 } else {
213 LogMessage("No rules were profiled\n");
214 }
215 return;
216 }
217
218 if(log)
219 {
220 TextLog_Print(log,
221 #ifdef PPM_MGR
222 "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
223 #else
224 "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
225 #endif
226 6, "Num",
227 9, "SID", 4, "GID", 4, "Rev",
228 11, "Checks",
229 10, "Matches",
230 10, "Alerts",
231 20, "Microsecs",
232 11, "Avg/Check",
233 11, "Avg/Match",
234 13, "Avg/Nonmatch"
235 #ifdef PPM_MGR
236 , 11, "Disabled"
237 #endif
238 );
239 }
240 else
241 {
242 LogMessage(
243 #ifdef PPM_MGR
244 "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
245 #else
246 "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
247 #endif
248 6, "Num",
249 9, "SID", 4, "GID", 4, "Rev",
250 11, "Checks",
251 10, "Matches",
252 10, "Alerts",
253 20, "Microsecs",
254 11, "Avg/Check",
255 11, "Avg/Match",
256 13, "Avg/Nonmatch"
257 #ifdef PPM_MGR
258 , 11, "Disabled"
259 #endif
260 );
261 }
262
263 if(log)
264 {
265 TextLog_Print(log,
266 #ifdef PPM_MGR
267 "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
268 #else
269 "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
270 #endif
271 6, "===",
272 9, "===", 4, "===", 4, "===",
273 11, "======",
274 10, "=======",
275 10, "======",
276 20, "=========",
277 11, "=========",
278 11, "=========",
279 13, "============"
280 #ifdef PPM_MGR
281 , 11, "========"
282 #endif
283 );
284 }
285 else
286 {
287 LogMessage(
288 #ifdef PPM_MGR
289 "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
290 #else
291 "%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
292 #endif
293 6, "===",
294 9, "===", 4, "===", 4, "===",
295 11, "======",
296 10, "=======",
297 10, "======",
298 20, "=========",
299 11, "=========",
300 11, "=========",
301 13, "============"
302 #ifdef PPM_MGR
303 , 11, "========"
304 #endif
305 );
306 }
307
308 for (node = worstPerformers, num=1;
309 node && ((numToPrint < 0) ? 1 : (num <= numToPrint));
310 node= node->next, num++)
311 {
312 //if (!node)
313 // break;
314 otn = node->otn;
315
316 if(log)
317 {
318 TextLog_Print(log,
319 #ifdef PPM_MGR
320 "%*d%*d%*d%*d" FMTu64("*") FMTu64("*") FMTu64("*") FMTu64("*") "%*.1f%*.1f%*.1f" FMTu64("*") "\n",
321 #else
322 "%*d%*d%*d%*d" FMTu64("*") FMTu64("*") FMTu64("*") FMTu64("*") "%*.1f%*.1f%*.1f" "\n",
323 #endif
324 6, num, 9, otn->sigInfo.id, 4, otn->sigInfo.generator, 4, otn->sigInfo.rev,
325 11, otn->checks,
326 10, otn->matches,
327 10, otn->alerts,
328 20, (uint64_t)(otn->ticks/ticks_per_microsec),
329 11, node->ticks_per_check/ticks_per_microsec,
330 11, node->ticks_per_match/ticks_per_microsec,
331 13, node->ticks_per_nomatch/ticks_per_microsec
332 #ifdef PPM_MGR
333 , 11, otn->ppm_disable_cnt
334 #endif
335 );
336 }
337 else
338 {
339 LogMessage(
340 #ifdef PPM_MGR
341 "%*d%*d%*d%*d" FMTu64("*") FMTu64("*") FMTu64("*") FMTu64("*") "%*.1f%*.1f%*.1f" FMTu64("*") "\n",
342 #else
343 "%*d%*d%*d%*d" FMTu64("*") FMTu64("*") FMTu64("*") FMTu64("*") "%*.1f%*.1f%*.1f" "\n",
344 #endif
345 6, num, 9, otn->sigInfo.id, 4, otn->sigInfo.generator, 4, otn->sigInfo.rev,
346 11, otn->checks,
347 10, otn->matches,
348 10, otn->alerts,
349 20, (uint64_t)(otn->ticks/ticks_per_microsec),
350 11, node->ticks_per_check/ticks_per_microsec,
351 11, node->ticks_per_match/ticks_per_microsec,
352 13, node->ticks_per_nomatch/ticks_per_microsec
353 #ifdef PPM_MGR
354 , 11, otn->ppm_disable_cnt
355 #endif
356 );
357 }
358 }
359
360 /* Do some cleanup */
361 for (node = worstPerformers; node; )
362 {
363 tmp = node->next;
364 free(node);
365 node = tmp;
366 }
367
368 if(log)
369 TextLog_Term(log);
370 worstPerformers = NULL;
371 }
372
CollectRTNProfile(void)373 void CollectRTNProfile(void)
374 {
375 OptTreeNode *otn;
376 OTN_WorstPerformer *new, *node, *last = NULL;
377 char got_position;
378 SFGHASH_NODE *hashNode;
379 SnortConfig *sc = snort_conf;
380
381 if (sc == NULL)
382 return;
383
384 for (hashNode = sfghash_findfirst(sc->otn_map);
385 hashNode;
386 hashNode = sfghash_findnext(sc->otn_map))
387 {
388 otn = (OptTreeNode *)hashNode->data;
389
390 /* Only log info if OTN has actually been eval'd */
391 if (otn->checks > 0 && otn->ticks > 0)
392 {
393 double ticks_per_check = (double)otn->ticks/(double)otn->checks;
394 double ticks_per_nomatch;
395 double ticks_per_match;
396
397 if (otn->matches > otn->checks)
398 otn->checks = otn->matches;
399
400 if (otn->matches)
401 ticks_per_match = (double)otn->ticks_match/(double)otn->matches;
402 else
403 ticks_per_match = 0.0;
404
405 if (otn->checks == otn->matches)
406 ticks_per_nomatch = 0.0;
407 else
408 ticks_per_nomatch = (double)otn->ticks_no_match/(double)(otn->checks - otn->matches);
409
410 /* Find where he goes in the list
411 * Cycle through the list and add
412 * this where it goes
413 */
414 new = (OTN_WorstPerformer *)SnortAlloc(sizeof(OTN_WorstPerformer));
415 new->otn = otn;
416 new->ticks_per_check = ticks_per_check;
417 new->ticks_per_match = ticks_per_match;
418 new->ticks_per_nomatch = ticks_per_nomatch;
419
420 got_position = 0;
421
422 for (node = worstPerformers; node && !got_position; node = node->next)
423 {
424 last = node;
425 switch (sc->profile_rules.sort)
426 {
427 case PROFILE_SORT_CHECKS:
428 if (otn->checks >= node->otn->checks)
429 {
430 got_position = 1;
431 }
432 break;
433 case PROFILE_SORT_MATCHES:
434 if (otn->matches >= node->otn->matches)
435 {
436 got_position = 1;
437 }
438 break;
439 case PROFILE_SORT_NOMATCHES:
440 if (otn->checks - otn->matches >
441 node->otn->checks - node->otn->matches)
442 {
443 got_position = 1;
444 }
445 break;
446 case PROFILE_SORT_AVG_TICKS_PER_MATCH:
447 if (ticks_per_match >= node->ticks_per_match)
448 {
449 got_position = 1;
450 }
451 break;
452 case PROFILE_SORT_AVG_TICKS_PER_NOMATCH:
453 if (ticks_per_nomatch >= node->ticks_per_nomatch)
454 {
455 got_position = 1;
456 }
457 break;
458 case PROFILE_SORT_TOTAL_TICKS:
459 if (otn->ticks >= node->otn->ticks)
460 {
461 got_position = 1;
462 }
463 break;
464 default:
465 case PROFILE_SORT_AVG_TICKS:
466 if (ticks_per_check >= node->ticks_per_check)
467 {
468 got_position = 1;
469 }
470 break;
471 }
472 if (got_position)
473 break;
474 }
475
476 if (node)
477 {
478 new->next = node;
479 new->prev = node->prev;
480 node->prev = new;
481 if (new->prev)
482 new->prev->next = new;
483 /* Reset the head of list */
484 if (node == worstPerformers)
485 worstPerformers = new;
486 }
487 else
488 {
489 if (!last)
490 {
491 worstPerformers = new;
492 }
493 else
494 {
495 new->prev = last;
496 last->next = new;
497 }
498 }
499 }
500 }
501 }
502
503
ShowRuleProfiles(void)504 void ShowRuleProfiles(void)
505 {
506 /* Cycle through all Rules, print ticks & check count for each */
507 SnortConfig *sc = snort_conf;
508
509 if ((sc == NULL) || (sc->profile_rules.num == 0))
510 return;
511
512 detection_option_tree_update_otn_stats(sc->detection_option_tree_hash_table);
513
514 CollectRTNProfile();
515
516 /* Specifically call out a top xxx or something? */
517 PrintWorstRules(sc->profile_rules.num);
518 return;
519 }
520
521 /* The preprocessor profile list is only accessed for printing stats when
522 * Snort shuts down, so adding new nodes during a reload shouldn't be a
523 * problem. */
RegisterPreprocessorProfile(const char * keyword,PreprocStats * stats,int layer,PreprocStats * parent,StatsNodeFreeFunc freefn)524 void RegisterPreprocessorProfile(const char *keyword, PreprocStats *stats, int layer, PreprocStats *parent, StatsNodeFreeFunc freefn)
525 {
526 PreprocStatsNode *node;
527
528 if (stats == NULL)
529 return;
530
531 node = (PreprocStatsNode *)SnortAlloc(sizeof(PreprocStatsNode));
532
533 if (PreprocStatsNodeList == NULL)
534 {
535 PreprocStatsNodeList = node;
536 }
537 else
538 {
539 PreprocStatsNode *tmp = PreprocStatsNodeList;
540 PreprocStatsNode *last;
541
542 do
543 {
544 if (strcasecmp(tmp->name, keyword) == 0)
545 {
546 //FatalError("Duplicate Preprocessor Stats Name (%s)\n", keyword);
547 /* Don't fatal error here since during a reload there are
548 * probably going to be dups - just return */
549 //multiple policy support
550 free(node);
551 return;
552 }
553
554 last = tmp;
555 tmp = tmp->next;
556
557 } while (tmp != NULL);
558
559 last->next = node;
560 }
561
562 node->name = SnortStrdup(keyword);
563 node->stats = stats; /* Set the stats reference */
564 node->parent = parent;
565 node->layer = layer;
566 node->freefn = freefn;
567
568 if (layer > max_layers)
569 max_layers = layer;
570 }
571
FreePreprocPerformance(Preproc_WorstPerformer * idx)572 void FreePreprocPerformance(Preproc_WorstPerformer *idx)
573 {
574 Preproc_WorstPerformer *child, *tmp;
575 child = idx->children;
576 while (child)
577 {
578 FreePreprocPerformance(child);
579 tmp = child;
580 child = child->next;
581 free(tmp);
582 }
583 }
584
PrintPreprocPerformance(TextLog * log,int num,Preproc_WorstPerformer * idx)585 void PrintPreprocPerformance(TextLog *log, int num, Preproc_WorstPerformer *idx)
586 {
587 Preproc_WorstPerformer *child;
588 int i;
589 /* indent 'Num' based on the layer */
590 unsigned int indent = 6 - (5 - idx->node->layer);
591
592 if (num != 0)
593 {
594 indent += 2;
595 if(log)
596 {
597 TextLog_Print(log, "%*d%*s%*d" FMTu64("*") FMTu64("*") FMTu64("*") "%*.2f%*.2f%*.2f\n",
598 indent, num,
599 28 - indent, idx->node->name, 6, idx->node->layer,
600 11, idx->node->stats->checks,
601 11, idx->node->stats->exits,
602 20, (uint64_t)(idx->node->stats->ticks/ticks_per_microsec),
603 11, idx->ticks_per_check/ticks_per_microsec,
604 14, idx->pct_of_parent,
605 13, idx->pct_of_total);
606 }
607 else
608 {
609 LogMessage("%*d%*s%*d" FMTu64("*") FMTu64("*") FMTu64("*") "%*.2f%*.2f%*.2f\n",
610 indent, num,
611 28 - indent, idx->node->name, 6, idx->node->layer,
612 11, idx->node->stats->checks,
613 11, idx->node->stats->exits,
614 20, (uint64_t)(idx->node->stats->ticks/ticks_per_microsec),
615 11, idx->ticks_per_check/ticks_per_microsec,
616 14, idx->pct_of_parent,
617 13, idx->pct_of_total);
618 }
619 }
620 else
621 {
622 /* The totals */
623 indent += strlen(idx->node->name);
624
625 if(log)
626 {
627 TextLog_Print(log, "%*s%*s%*d" FMTu64("*") FMTu64("*") FMTu64("*") "%*.2f%*.2f%*.2f\n",
628 indent, idx->node->name,
629 28 - indent, idx->node->name, 6, idx->node->layer,
630 11, idx->node->stats->checks,
631 11, idx->node->stats->exits,
632 20, (uint64_t)(idx->node->stats->ticks/ticks_per_microsec),
633 11, idx->ticks_per_check/ticks_per_microsec,
634 14, idx->pct_of_parent,
635 13, idx->pct_of_parent);
636 }
637 else
638 {
639 LogMessage("%*s%*s%*d" FMTu64("*") FMTu64("*") FMTu64("*") "%*.2f%*.2f%*.2f\n",
640 indent, idx->node->name,
641 28 - indent, idx->node->name, 6, idx->node->layer,
642 11, idx->node->stats->checks,
643 11, idx->node->stats->exits,
644 20, (uint64_t)(idx->node->stats->ticks/ticks_per_microsec),
645 11, idx->ticks_per_check/ticks_per_microsec,
646 14, idx->pct_of_parent,
647 13, idx->pct_of_parent);
648 }
649 }
650
651 child = idx->children;
652
653 i = 1;
654 while (child)
655 {
656 PrintPreprocPerformance(log, i++, child);
657 child = child->next;
658 }
659 }
660
CleanupPreprocStatsNodeList(void)661 void CleanupPreprocStatsNodeList(void)
662 {
663 PreprocStatsNode *node, *nxt;
664
665 node = PreprocStatsNodeList;
666 while (node)
667 {
668 nxt = node->next;
669 if (node->freefn)
670 node->freefn(node->stats);
671 free(node->name);
672 free(node);
673 node = nxt;
674 }
675 PreprocStatsNodeList = NULL;
676 }
677
CleanupPreprocPerformance(Preproc_WorstPerformer * worst)678 void CleanupPreprocPerformance(Preproc_WorstPerformer *worst)
679 {
680 Preproc_WorstPerformer *idx, *child, *tmp;
681
682 idx = worst;
683 while (idx)
684 {
685 tmp = idx->next;
686 child = idx->children;
687 CleanupPreprocPerformance(child);
688
689 free(idx);
690 idx = tmp;
691 }
692 }
693
PrintWorstPreprocs(int numToPrint)694 void PrintWorstPreprocs(int numToPrint)
695 {
696 Preproc_WorstPerformer *idx;
697 Preproc_WorstPerformer *total = NULL;
698 int num = 0;
699 TextLog *log = NULL;
700 time_t cur_time;
701 char fullname[STD_BUF];
702 int ret;
703 SnortConfig *sc = snort_conf;
704
705 getTicksPerMicrosec();
706
707 cur_time = time(NULL);
708 if (sc->profile_preprocs.filename != NULL)
709 {
710 if (sc->profile_preprocs.append)
711 {
712 log = TextLog_Init(sc->profile_preprocs.filename, 512*1024, 512*1024);
713
714 if (log != NULL)
715 TextLog_Print(log, "\ntimestamp: %u\n", cur_time);
716 }
717 else
718 {
719 ret = SnortSnprintf(fullname, STD_BUF, "%s.%u", sc->profile_preprocs.filename, (uint32_t)cur_time);
720 if(ret != SNORT_SNPRINTF_SUCCESS)
721 FatalError("profiler: file path+name too long\n");
722 log = TextLog_Init(fullname, 512*1024, 512*1024);
723 }
724 }
725
726 if (numToPrint != -1)
727 {
728 if(log)
729 {
730 TextLog_Print(log, "Preprocessor Profile Statistics (worst %d)\n", numToPrint);
731 }
732 else
733 {
734 LogMessage("Preprocessor Profile Statistics (worst %d)\n", numToPrint);
735 }
736 }
737 else
738 {
739 if(log)
740 {
741 TextLog_Print(log, "Preprocessor Profile Statistics (all)\n");
742 }
743 else
744 {
745 LogMessage("Preprocessor Profile Statistics (all)\n");
746 }
747 }
748
749 if(log)
750 {
751 TextLog_Print(log, "==========================================================\n");
752 }
753 else
754 {
755 LogMessage("==========================================================\n");
756 }
757
758 if (!worstPreprocPerformers)
759 {
760 if(log)
761 {
762 TextLog_Print(log, "No Preprocessors were profiled\n");
763 TextLog_Term(log);
764 }
765 else
766 {
767 LogMessage("No Preprocessors were profiled\n");
768 }
769 CleanupPreprocPerformance(worstPreprocPerformers);
770 worstPreprocPerformers = NULL;
771 return;
772 }
773
774 if(log)
775 {
776 TextLog_Print(log, "%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
777 4, "Num",
778 24, "Preprocessor",
779 6, "Layer",
780 11, "Checks",
781 11, "Exits",
782 20, "Microsecs",
783 11, "Avg/Check",
784 14, "Pct of Caller",
785 13, "Pct of Total");
786 }
787 else
788 {
789 LogMessage("%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
790 4, "Num",
791 24, "Preprocessor",
792 6, "Layer",
793 11, "Checks",
794 11, "Exits",
795 20, "Microsecs",
796 11, "Avg/Check",
797 14, "Pct of Caller",
798 13, "Pct of Total");
799 }
800
801 if(log)
802 {
803 TextLog_Print(log, "%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
804 4, "===",
805 24, "============",
806 6, "=====",
807 11, "======",
808 11, "=====",
809 20, "=========",
810 11, "=========",
811 14, "=============",
812 13, "============");
813 }
814 else
815 {
816 LogMessage("%*s%*s%*s%*s%*s%*s%*s%*s%*s\n",
817 4, "===",
818 24, "============",
819 6, "=====",
820 11, "======",
821 11, "=====",
822 20, "=========",
823 11, "=========",
824 14, "=============",
825 13, "============");
826 }
827
828 for (idx = worstPreprocPerformers, num=1;
829 idx && ((numToPrint < 0) ? 1 : (num <= numToPrint));
830 idx= idx->next, num++)
831 {
832 /* Skip the total counter */
833 if (idx->node->stats == &totalPerfStats)
834 {
835 num--;
836 total = idx;
837 continue;
838 }
839 //if (!idx)
840 // break;
841 PrintPreprocPerformance(log, num, idx);
842 //LogMessage("%*d%*s%*d%*d" FMTu64("*") "%*.1f%*.1f\n",
843 // 6, num, 20, idx->node->name, 6, idx->node->layer,
844 // 11, idx->node->stats->checks,
845 // 11, idx->node->stats->exits,
846 // 20, idx->node->stats->ticks,
847 // 11, idx->ticks_per_check,
848 // 14, idx->pct_of_parent,
849 // 14, idx->pct_of_total);
850 }
851 if (total)
852 PrintPreprocPerformance(log, 0, total);
853
854 if(log)
855 TextLog_Term(log);
856 CleanupPreprocPerformance(worstPreprocPerformers);
857 worstPreprocPerformers = NULL;
858 }
859
findPerfParent(PreprocStatsNode * node,Preproc_WorstPerformer * top)860 Preproc_WorstPerformer *findPerfParent(PreprocStatsNode *node,
861 Preproc_WorstPerformer *top)
862 {
863 Preproc_WorstPerformer *list = top;
864 Preproc_WorstPerformer *parent;
865
866 if (!list)
867 return NULL;
868
869 if (list->node->layer > node->layer)
870 return NULL;
871
872 while (list)
873 {
874 if (list->node->stats == node->parent)
875 {
876 parent = list;
877 return parent;
878 }
879
880 parent = findPerfParent(node, list->children);
881
882 if (parent)
883 return parent;
884
885 list = list->next;
886 }
887
888 return NULL;
889 }
890
ResetPreprocProfiling(void)891 void ResetPreprocProfiling(void)
892 {
893 PreprocStatsNode *idx = NULL;
894 SnortConfig *sc = snort_conf;
895
896 if ((sc == NULL) || (sc->profile_preprocs.num == 0))
897 return;
898
899 for (idx = PreprocStatsNodeList; idx != NULL; idx = idx->next)
900 {
901 idx->stats->ticks = 0;
902 idx->stats->ticks_start = 0;
903 idx->stats->checks = 0;
904 idx->stats->exits = 0;
905 }
906 }
907
ShowPreprocProfiles(void)908 void ShowPreprocProfiles(void)
909 {
910 /* Cycle through all Rules, print ticks & check count for each */
911 PreprocStatsNode *idx;
912 int layer;
913 Preproc_WorstPerformer *parent, *new, *this = NULL, *last = NULL;
914 char got_position;
915 Preproc_WorstPerformer *listhead;
916 double ticks_per_check;
917 SnortConfig *sc = snort_conf;
918
919 if ((sc == NULL) || (sc->profile_preprocs.num == 0))
920 return;
921
922 /* Adjust mpse stats to not include rule evaluation */
923 mpsePerfStats.ticks -= rulePerfStats.ticks;
924 /* And adjust the rules to include the NC rules */
925 rulePerfStats.ticks += ncrulePerfStats.ticks;
926
927 for (layer=0;layer<=max_layers;layer++)
928 {
929
930 for (idx = PreprocStatsNodeList; idx; idx = idx->next)
931 {
932 if (idx->stats->checks == 0 || idx->stats->ticks == 0)
933 continue;
934
935 if (idx->layer != layer)
936 continue;
937
938 last = NULL;
939
940 ticks_per_check = (double)idx->stats->ticks/(double)idx->stats->checks;
941
942 new = (Preproc_WorstPerformer *)SnortAlloc(sizeof(Preproc_WorstPerformer));
943 new->node = idx;
944 new->ticks_per_check = ticks_per_check;
945
946 if (idx->parent)
947 {
948 /* Find this idx's parent in the list */
949 parent = findPerfParent(idx, worstPreprocPerformers);
950 if (parent && (parent->node->stats != &totalPerfStats))
951 {
952 listhead = parent->children;
953 }
954 else
955 {
956 listhead = worstPreprocPerformers;
957 parent = NULL;
958 }
959 new->pct_of_parent = (double)idx->stats->ticks/idx->parent->ticks*100.0;
960 new->pct_of_total = (double)idx->stats->ticks/totalPerfStats.ticks*100.0;
961 }
962 else
963 {
964 parent = NULL;
965 new->pct_of_parent = 0.0;
966 new->pct_of_total = 100.0;
967 listhead = worstPreprocPerformers;
968 }
969
970 got_position = 0;
971
972 for (this = listhead; this && !got_position; this = this->next)
973 {
974 last = this;
975 switch (sc->profile_preprocs.sort)
976 {
977 case PROFILE_SORT_CHECKS:
978 if (new->node->stats->checks >= this->node->stats->checks)
979 {
980 got_position = 1;
981 }
982 break;
983 case PROFILE_SORT_TOTAL_TICKS:
984 if (new->node->stats->ticks >= this->node->stats->ticks)
985 {
986 got_position = 1;
987 }
988 break;
989 default:
990 case PROFILE_SORT_AVG_TICKS:
991 if (new->ticks_per_check >= this->ticks_per_check)
992 {
993 got_position = 1;
994 }
995 break;
996 }
997 if (got_position)
998 break;
999 }
1000 if (this)
1001 {
1002 new->next = this;
1003 new->prev = this->prev;
1004 this->prev = new;
1005 if (new->prev)
1006 new->prev->next = new;
1007 /* Reset the head of the list */
1008 if (this == listhead)
1009 {
1010 if (parent)
1011 {
1012 parent->children = new;
1013 }
1014 else
1015 {
1016 worstPreprocPerformers = new;
1017 }
1018 }
1019 }
1020 else
1021 {
1022 if (!last)
1023 {
1024 if (parent)
1025 {
1026 parent->children = new;
1027 }
1028 else
1029 {
1030 worstPreprocPerformers = new;
1031 }
1032 }
1033 else
1034 {
1035 new->prev = last;
1036 last->next = new;
1037 }
1038 }
1039 }
1040 }
1041 PrintWorstPreprocs(sc->profile_preprocs.num);
1042 CleanupPreprocStatsNodeList();
1043 }
1044
1045 #endif
1046