cipherdyne.org

19 February, 2007

The Devel::DProf perl module is a code profiler that builds detailed information about a piece of perl code at run time. This handy tool allows the relative time perl devotes to each subroutine to be recorded, and this information is valuable in the optimization process. Using Devel::DProf it is easy to determine the sections of code where psad spends most of its time. Because psad is written to detect as many network attacks as possible via iptables log messages, one might expect that psad devotes significant processing time to signature matching. Let us verify this by using the --Benchmark mode, which creates and sends 10,000 iptables log messages through the psad parsing and signature matching routines like so (note that this is against psad-2.0.4): # perl -d:DProf psad --Benchmark
Mon Feb 19 00:38:06 2007 [+] Entering benchmark mode.
Mon Feb 19 00:38:06 2007 [+] The --packets command line option was not specified.
Mon Feb 19 00:38:06 2007 [+] Defaulting to a 10,000 packet test.
Mon Feb 19 00:38:06 2007 [+] Creating packet array.
Mon Feb 19 00:38:06 2007 [+] check_scan()
Mon Feb 19 00:38:24 2007 [+] Err packets: -1.
Mon Feb 19 00:38:24 2007 [+] Packet creation and processing time: 18 sec.
Mon Feb 19 00:38:24 2007 [+] Exiting benchmark mode. Now, a new file tmon.out is created in the local directory, and it can be examined using the dprofpp utility which displays perl code profile data:

# dprofpp tmon.out
Total Elapsed Time = 12.98063 Seconds
  User+System Time = 11.83063 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 24.9   2.950 10.806  10001   0.0003 0.0011  main::match_sigs
 11.2   1.329  1.329 501050   0.0000 0.0000  main::check_sig_int_range
 11.1   1.320  1.320 160016   0.0000 0.0000  Net::IPv4Addr::ipv4_chkip
 9.13   1.080  1.110  10001   0.0001 0.0001  main::parse_NF_pkt_str
 9.04   1.070  2.390 160016   0.0000 0.0000  Net::IPv4Addr::ipv4_parse
 8.71   1.030  1.960  80008   0.0000 0.0000  Net::IPv4Addr::ipv4_network
 8.28   0.980 13.104      1   0.9799 13.104  main::check_scan
 6.25   0.740  4.470 110011   0.0000 0.0000  main::check_sig_ip
 6.09   0.720  3.387  20127   0.0000 0.0002  main::match_snort_keywords
 5.91   0.699  1.929 150140   0.0000 0.0000  \
main::match_snort_ip_keywords
 3.71   0.439  0.738  80133   0.0000 0.0000  \
main::match_snort_tcp_keywords
 2.62   0.310  3.730  40004   0.0000 0.0001  \
Net::IPv4Addr::ipv4_in_network
 1.69   0.200  0.200 110136   0.0000 0.0000  main::check_sig_ipopts
 1.44   0.170  0.180      1   0.1700 0.1799  main::import_snort_rules
 1.18   0.140  0.140  20002   0.0000 0.0000  main::check_range

From the above output it is easy to see that the match_sigs() function takes the largest percentage of processing time (24.9%) of any psad function. This function makes a good candidate for any optimization efforts. The next two functions check_sig_int_range() and Net::IPv4Addr::ipv4_chkip() (from the Net::IPv4Addr perl module) are dedicated to checking signature port numbers and IP address against iptables log messages. The parse_NF_pkt_str() is the main routine for parsing iptables log messages and building a hash that describes each log message field. This routine takes over 9% of psad's processing time, so optimizing the regular expressions psad uses to parse iptables log messages might provide a significant additional speedup.