Subsections

2.5 Performance Profiling

Snort can provide statistics on rule and preprocessor performance. Each require only a simple config option to snort.conf and Snort will print statistics on the worst (or all) performers on exit. When a file name is provided in profile_rules or profile_preprocs, the statistics will be saved in these files. If append is not specified, a new file will be created each time Snort is run. The filenames will have timestamps appended to them. These files will be found in the logging directory.

To use this feature, you must build snort with the -enable-perfprofiling option to the configure script.

2.5.1 Rule Profiling

2.5.1.1 Format

    config profile_rules: \
        print [all | <num>], \
        sort <sort_option> \
        [,filename <filename> [append]]

<num> is the number of rules to print
<sort_option> is one of:
checks matches nomatches avg_ticks avg_ticks_per_match avg_ticks_per_nomatch total_ticks
<filename> is the output filename
[append] dictates that the output will go to the same file each time (optional)

2.5.1.2 Examples

Print all rules, sort by avg_ticks (default configuration if option is turned on) config profile_rules
Print all rules, sort by avg_ticks, and append to file rules_stats.txt config profile_rules: filename rules_stats.txt append
Print the top 10 rules, based on highest average time config profile_rules: print 10, sort avg_ticks
Print all rules, sorted by number of checks config profile_rules: print all, sort checks
Print top 100 rules, based on total time config profile_rules: print 100, sort total_ticks
Print with default options, save results to performance.txt each time config profile_rules: filename performance.txt append
Print top 20 rules, save results to perf.txt with timestamp in filename config profile_rules: print 20, filename perf.txt

2.5.1.3 Output

Snort will print a table much like the following at exit.

**Figure:** Rule Profiling Example Output
$\begin{figure}\footnotesize { \begin{verbatim}Rule Profile Statistics (worst 4... ...229.0 4 1734 1 37 2 0 0 90054 45027.0 0.0 45027.0\end{verbatim} }\end{figure}$

Configuration line used to print the above table:

config profile_rules: print 4, sort total_ticks

The columns represent:

Number (rank)
Sig ID
Generator ID
Checks (number of times rule was evaluated after fast pattern match within portgroup or any-any rules)
Matches (number of times ALL rule options matched, will be high for rules that have no options)
Alerts (number of alerts generated from this rule)
CPU Ticks
Avg Ticks per Check
Avg Ticks per Match
Avg Ticks per Nonmatch

Interpreting this info is the key. The Microsecs (or Ticks) column is important because that is the total time spent evaluating a given rule. But, if that rule is causing alerts, it makes sense to leave it alone.

A high Avg/Check is a poor performing rule, that most likely contains PCRE. High Checks and low Avg/Check is usually an any-any rule with few rule options and no content. Quick to check, the few options may or may not match. We are looking at moving some of these into code, especially those with low SIDs.

By default, this information will be printed to the console when Snort exits. You can use the "filename" option in snort.conf to specify a file where this will be written. If "append" is not specified, a new file will be created each time Snort is run. The filenames will have timestamps appended to them. These files will be found in the logging directory.

2.5.2 Preprocessor Profiling

2.5.2.1 Format

    config profile_preprocs: \
        print [all | <num>], \
        sort <sort_option> \
        [, filename <filename> [append]]

<num> is the number of preprocessors to print
<sort_option> is one of: checks avg_ticks total_ticks
<filename> is the output filename
[append] dictates that the output will go to the same file each time (optional)

2.5.2.2 Examples

Print all preprocessors, sort by avg_ticks (default configuration if option is turned on) config profile_preprocs
Print all preprocessors, sort by avg_ticks, and append to file preprocs_stats.txt config profile_preprocs: filename preprocs_stats.txt append
Print the top 10 preprocessors, based on highest average time config profile_preprocs: print 10, sort avg_ticks
Print all preprocessors, sorted by number of checks config profile_preprocs: print all, sort checks

2.5.2.3 Output

Snort will print a table much like the following at exit.

**Figure:** Preprocessor Profiling Example Output
$\begin{figure}\footnotesize { \begin{verbatim}Preprocessor Profile Statistics ... ...tal total 0 311202 311202 14011946 45.03 0.00 0.00\end{verbatim} }\end{figure}$

Configuration line used to print the above table:

    config profile_preprocs: \
        print 10, sort total_ticks

The columns represent:

Number (rank) - The number is indented for each layer. Layer 1 preprocessors are listed under their respective caller (and sorted similarly).
Preprocessor Name
Layer - When printing a specific number of preprocessors all subtasks info for a particular preprocessor is printed for each layer 0 preprocessor stat.
Checks (number of times preprocessor decided to look at a packet, ports matched, app layer header was correct, etc)
Exits (number of corresponding exits - just to verify code is instrumented correctly, should ALWAYS match Checks, unless an exception was trapped)
CPU Ticks
Avg Ticks per Check
Percent of caller - For non layer 0 preprocessors, i.e. subroutines within preprocessors, this identifies the percent of the caller's ticks that is spent for this subtask.

Because of task swapping, non-instrumented code, and other factors, the Pct of Caller field will not add up to 100% of the caller's time. It does give a reasonable indication of how much relative time is spent within each subtask.

2.5.3 Packet Performance Monitoring (PPM)

PPM provides thresholding mechanisms that can be used to provide a basic level of latency control for snort. It does not provide a hard and fast latency guarantee but should in effect provide a good average latency control. Both rules and packets can be checked for latency. The action taken upon detection of excessive latency is configurable. The following sections describe configuration, sample output, and some implementation details worth noting.

To use PPM, you must build with the -enable-ppm or the -enable-sourcefire option to configure.

PPM is configured as follows:

    # Packet configuration:
    config ppm: max-pkt-time <micro-secs>, \
        fastpath-expensive-packets, \
        pkt-log, \
        debug-pkts
    
    # Rule configuration:
    config ppm: max-rule-time <micro-secs>, \
        threshold count, \
        suspend-expensive-rules, \
        suspend-timeout <seconds>, \
        rule-log [log] [alert]

Packets and rules can be configured separately, as above, or together in just one config ppm statement. Packet and rule monitoring is independent, so one or both or neither may be enabled.

2.5.3.1 Configuration

Packet Configuration Options

max-pkt-time <micro-secs>

enables packet latency thresholding using 'micros-secs' as the limit.
default is 0 (packet latency thresholding disabled)
reasonable starting defaults: 100/250/1000 for 1G/100M/5M nets

fastpath-expensive-packets

enables stopping further inspection of a packet if the max time is exceeded
default is off

pkt-log

enables logging packet event if packet exceeds max-pkt-time
default is no logging
if no option is given for 'pkt-log', 'pkt-log log' is implied
the log option enables output to syslog or console depending upon snort configuration

debug-pkts

must build with the -enable-debug option to configure
enables per packet timing stats to be printed after each packet
default is off

Rule Configuration Options

max-rule-time <micro-secs>

enables rule latency thresholding using 'micros-secs' as the limit.
default is 0 (rule latency thresholding disabled)
reasonable starting defaults: 100/250/1000 for 1G/100M/5M nets

threshold <count>

sets the number of cumulative rule time excesses before disabling a rule
default is 5

suspend-expensive-rules

enables suspending rule inspection if the max rule time is exceeded
default is off

suspend-timeout <seconds>

rule suspension time in seconds
default is 60 seconds
set to zero to permanently disable expensive rules

rule-log [log] [alert]

enables event logging output for rules
default is no logging
one or both of the options 'log' and 'alert' must be used with 'rule-log'
the log option enables output to syslog or console depending upon snort configuration

2.5.3.2 Examples

Example 1: The following enables packet tracking:

    config ppm: max-pkt-time 100

The following enables rule tracking:

    config ppm: max-rule-time 50, threshold 5

If fastpath-expensive-packets or suspend-expensive-rules is not used, then no action is taken other than to increment the count of the number of packets that should be fastpath'd or the rules that should be suspended. A summary of this information is printed out when snort exits.

Example 2:

The following suspends rules and aborts packet inspection. These rules were used to generate the sample output that follows.

    config ppm: \
        max-pkt-time 50, fastpath-expensive-packets, \
        pkt-log, debug-pkts
    
    config ppm: \
        max-rule-time 50, threshold 5, suspend-expensive-rules, \
        suspend-timeout 300, rule-log log alert

2.5.3.3 Sample Snort Output

Sample Snort Startup Output

    Packet Performance Monitor Config:
      ticks per usec  : 1600 ticks
      max packet time : 50 usecs
      packet action   : fastpath-expensive-packets
      packet logging  : log
      debug-pkts      : disabled
    
    Rule Performance Monitor Config:
      ticks per usec  : 1600 ticks
      max rule time   : 50 usecs
      rule action     : suspend-expensive-rules
      rule threshold  : 5 
      suspend timeout : 300 secs
      rule logging    : alert log

Sample Snort Run-time Output

    ...
    PPM: Process-BeginPkt[61] caplen=60
    PPM: Pkt[61] Used= 8.15385 usecs
    PPM: Process-EndPkt[61]
    
    PPM: Process-BeginPkt[62] caplen=342
    PPM: Pkt[62] Used= 65.3659 usecs
    PPM: Process-EndPkt[62]
    
    PPM: Pkt-Event Pkt[63] used=56.0438 usecs, 0 rules, 1 nc-rules tested, packet fastpathed
         (10.4.12.224:0 -> 10.4.14.108:54321).
    PPM: Process-BeginPkt[63] caplen=60
    PPM: Pkt[63] Used= 8.394 usecs
    PPM: Process-EndPkt[63]
    
    PPM: Process-BeginPkt[64] caplen=60
    PPM: Pkt[64] Used= 8.21764 usecs
    PPM: Process-EndPkt[64]
    ...

Sample Snort Exit Output

    Packet Performance Summary:
       max packet time       : 50 usecs
       packet events         : 1
       avg pkt time          : 0.633125 usecs
    Rule Performance Summary:
       max rule time         : 50 usecs
       rule events           : 0
       avg nc-rule time      : 0.2675 usecs

2.5.3.4 Implementation Details

Enforcement of packet and rule processing times is done after processing each rule. Latency control is not enforced after each preprocessor.
This implementation is software based and does not use an interrupt driven timing mechanism and is therefore subject to the granularity of the software based timing tests. Due to the granularity of the timing measurements any individual packet may exceed the user specified packet or rule processing time limit. Therefore this implementation cannot implement a precise latency guarantee with strict timing guarantees. Hence the reason this is considered a best effort approach.
Since this implementation depends on hardware based high performance frequency counters, latency thresholding is presently only available on Intel and PPC platforms.
Time checks are made based on the total system time, not processor usage by Snort. This was a conscious design decision because when a system is loaded, the latency for a packet is based on the total system time, not just the processor time the Snort application receives. Therefore, it is recommended that you tune your thresholding to operate optimally when your system is under load.