It is abit quicker ... but I don't think profiling is the problem :
root@suricata:~# suricata --build-info
This is Suricata version 2.0dev (rev 106e38d)
Features: PCAP_SET_BUFF LIBPCAP_VERSION_MAJOR=1 PF_RING AF_PACKET HAVE_PACKET_FANOUT LIBCAP_NG LIBNET1.1 HAVE_HTP_URI_NORMALIZE_HOOK HAVE_HTP_TX_GET_RESPONSE_HEADERS_RAW HAVE_NSS HAVE_LUAJIT HAVE_LIBJANSSON
64-bits, Little-endian architecture
GCC version 4.6.3, C version 199901
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_1
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_2
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_4
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_8
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_16
compiled with -fstack-protector
compiled with _FORTIFY_SOURCE=2
compiled with libhtp 0.2.12, linked against 0.2.12
Suricata Configuration:
AF_PACKET support: yes
PF_RING support: yes
NFQueue support: no
IPFW support: no
DAG enabled: no
Napatech enabled: no
Unix socket enabled: yes
libnss support: yes
libnspr support: yes
libjansson support: yes
Prelude support: no
PCRE jit: no
libluajit: yes
libgeoip: no
Non-bundled htp: no
Old barnyard2 support: no
CUDA enabled: no
Suricatasc install: yes
Unit tests enabled: no
Debug output enabled: no
Debug validation enabled: no
Profiling enabled: no
Profiling locks enabled: no
Generic build parameters:
Installation prefix (--prefix): /usr/local
Configuration directory (--sysconfdir): /usr/local/etc/suricata/
Log directory (--localstatedir) : /usr/local/var/log/suricata/
Host: x86_64-unknown-linux-gnu
GCC binary: gcc
GCC Protect enabled: no
GCC march native enabled: yes
GCC Profile enabled: no
root@suricata:~#
[16639] 27/3/2013 -- 03:47:52 - (defrag-hash.c:203) <Info> (DefragInitConfig) -- allocated 229376 bytes of memory for the defrag hash... 4096 buckets of size 56
[16639] 27/3/2013 -- 03:47:52 - (defrag-hash.c:228) <Info> (DefragInitConfig) -- preallocated 65535 defrag trackers of size 144
[16639] 27/3/2013 -- 03:47:52 - (defrag-hash.c:235) <Info> (DefragInitConfig) -- defrag memory usage: 9666416 bytes, maximum: 16777216
[16639] 27/3/2013 -- 03:47:52 - (tmqh-flow.c:76) <Info> (TmqhFlowRegister) -- AutoFP mode using default "Active Packets" flow load balancer
[16640] 27/3/2013 -- 03:47:52 - (tmqh-packetpool.c:130) <Info> (PacketPoolInit) -- preallocated 512 packets. Total memory 2181120
[16640] 27/3/2013 -- 03:47:52 - (host.c:204) <Info> (HostInitConfig) -- allocated 229376 bytes of memory for the host hash... 4096 buckets of size 56
[16640] 27/3/2013 -- 03:47:52 - (host.c:227) <Info> (HostInitConfig) -- preallocated 1000 hosts of size 120
[16640] 27/3/2013 -- 03:47:52 - (host.c:229) <Info> (HostInitConfig) -- host memory usage: 349376 bytes, maximum: 16777216
[16640] 27/3/2013 -- 03:47:52 - (flow.c:412) <Info> (FlowInitConfig) -- allocated 58720256 bytes of memory for the flow hash... 1048576 buckets of size 56
[16640] 27/3/2013 -- 03:47:52 - (flow.c:436) <Info> (FlowInitConfig) -- preallocated 1048576 flows of size 272
[16640] 27/3/2013 -- 03:47:52 - (flow.c:438) <Info> (FlowInitConfig) -- flow memory usage: 343932928 bytes, maximum: 17179869184
[16640] 27/3/2013 -- 03:47:52 - (reputation.c:442) <Info> (SRepInit) -- IP reputation disabled
[16640] 27/3/2013 -- 03:47:52 - (util-magic.c:61) <Info> (MagicInit) -- using magic-file /usr/share/file/magic
[16640] 27/3/2013 -- 03:47:52 - (suricata.c:1865) <Info> (main) -- Delayed detect disabled
[16640] 27/3/2013 -- 03:47:54 - (detect.c:454) <Info> (SigLoadSignatures) -- 7 rule files processed. 6473 rules successfully loaded, 0 rules failed
[16640] 27/3/2013 -- 03:47:58 - (detect.c:2661) <Info> (SigAddressPrepareStage1) -- 6473 signatures processed. 1 are IP-only rules, 1693 are inspecting packet payload, 5454 inspect application layer, 0 are decoder event only
[16640] 27/3/2013 -- 03:47:58 - (detect.c:2664) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete
[16640] 27/3/2013 -- 03:47:58 - (detect.c:3290) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete
[16640] 27/3/2013 -- 03:48:19 - (detect.c:3950) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete
[16640] 27/3/2013 -- 03:48:19 - (util-threshold-config.c:983) <Info> (SCThresholdConfParseFile) -- Threshold config parsed: 0 rule(s) found
[16640] 27/3/2013 -- 03:48:19 - (util-coredump-config.c:122) <Info> (CoredumpLoadConfig) -- Core dump size set to unlimited.
[16640] 27/3/2013 -- 03:48:19 - (util-logopenfile.c:169) <Info> (SCConfLogOpenGeneric) -- fast output device (regular) initialized: fast.log
[16640] 27/3/2013 -- 03:48:19 - (util-logopenfile.c:169) <Info> (SCConfLogOpenGeneric) -- http-log output device (regular) initialized: http.log
[16640] 27/3/2013 -- 03:48:19 - (util-logopenfile.c:169) <Info> (SCConfLogOpenGeneric) -- tls-log output device (regular) initialized: tls.log
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:217) <Info> (AffinitySetupLoadFromConfig) -- Found affinity definition for "management-cpu-set"
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:265) <Info> (AffinitySetupLoadFromConfig) -- Using default prio 'low'
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:217) <Info> (AffinitySetupLoadFromConfig) -- Found affinity definition for "receive-cpu-set"
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:217) <Info> (AffinitySetupLoadFromConfig) -- Found affinity definition for "decode-cpu-set"
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:217) <Info> (AffinitySetupLoadFromConfig) -- Found affinity definition for "stream-cpu-set"
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:217) <Info> (AffinitySetupLoadFromConfig) -- Found affinity definition for "detect-cpu-set"
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:265) <Info> (AffinitySetupLoadFromConfig) -- Using default prio 'high'
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:217) <Info> (AffinitySetupLoadFromConfig) -- Found affinity definition for "verdict-cpu-set"
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:265) <Info> (AffinitySetupLoadFromConfig) -- Using default prio 'high'
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:217) <Info> (AffinitySetupLoadFromConfig) -- Found affinity definition for "reject-cpu-set"
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:265) <Info> (AffinitySetupLoadFromConfig) -- Using default prio 'low'
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:217) <Info> (AffinitySetupLoadFromConfig) -- Found affinity definition for "output-cpu-set"
[16640] 27/3/2013 -- 03:48:19 - (util-affinity.c:265) <Info> (AffinitySetupLoadFromConfig) -- Using default prio 'medium'
[16640] 27/3/2013 -- 03:48:19 - (runmode-pfring.c:324) <Info> (ParsePfringConfig) -- Using flow cluster mode for PF_RING (iface eth3)
[16640] 27/3/2013 -- 03:48:19 - (util-runmodes.c:623) <Info> (RunModeSetLiveCaptureWorkersForDevice) -- Going to use 16 thread(s)
[16642] 27/3/2013 -- 03:48:19 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 0
[16642] 27/3/2013 -- 03:48:19 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth31" Module to cpu/core 0, thread id 16642
[16642] 27/3/2013 -- 03:48:19 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth31) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16643] 27/3/2013 -- 03:48:19 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 1
[16643] 27/3/2013 -- 03:48:19 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth32" Module to cpu/core 1, thread id 16643
[16643] 27/3/2013 -- 03:48:19 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth32) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16644] 27/3/2013 -- 03:48:19 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 2
[16644] 27/3/2013 -- 03:48:19 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth33" Module to cpu/core 2, thread id 16644
[16644] 27/3/2013 -- 03:48:19 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth33) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16645] 27/3/2013 -- 03:48:19 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 3
[16645] 27/3/2013 -- 03:48:19 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth34" Module to cpu/core 3, thread id 16645
[16645] 27/3/2013 -- 03:48:19 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth34) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16646] 27/3/2013 -- 03:48:19 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 4
[16646] 27/3/2013 -- 03:48:19 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth35" Module to cpu/core 4, thread id 16646
[16646] 27/3/2013 -- 03:48:20 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth35) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16647] 27/3/2013 -- 03:48:20 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 5
[16647] 27/3/2013 -- 03:48:20 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth36" Module to cpu/core 5, thread id 16647
[16647] 27/3/2013 -- 03:48:20 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth36) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16648] 27/3/2013 -- 03:48:20 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 6
[16648] 27/3/2013 -- 03:48:20 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth37" Module to cpu/core 6, thread id 16648
[16648] 27/3/2013 -- 03:48:20 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth37) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16649] 27/3/2013 -- 03:48:20 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 7
[16649] 27/3/2013 -- 03:48:20 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth38" Module to cpu/core 7, thread id 16649
[16649] 27/3/2013 -- 03:48:20 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth38) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16650] 27/3/2013 -- 03:48:20 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 8
[16650] 27/3/2013 -- 03:48:20 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth39" Module to cpu/core 8, thread id 16650
[16650] 27/3/2013 -- 03:48:20 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth39) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16651] 27/3/2013 -- 03:48:20 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 9
[16651] 27/3/2013 -- 03:48:20 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth310" Module to cpu/core 9, thread id 16651
[16651] 27/3/2013 -- 03:48:20 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth310) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16652] 27/3/2013 -- 03:48:20 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 10
[16652] 27/3/2013 -- 03:48:20 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth311" Module to cpu/core 10, thread id 16652
[16652] 27/3/2013 -- 03:48:20 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth311) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16653] 27/3/2013 -- 03:48:20 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 11
[16653] 27/3/2013 -- 03:48:20 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth312" Module to cpu/core 11, thread id 16653
[16653] 27/3/2013 -- 03:48:20 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth312) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16654] 27/3/2013 -- 03:48:20 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 12
[16654] 27/3/2013 -- 03:48:20 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth313" Module to cpu/core 12, thread id 16654
[16654] 27/3/2013 -- 03:48:21 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth313) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16655] 27/3/2013 -- 03:48:21 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 13
[16655] 27/3/2013 -- 03:48:21 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth314" Module to cpu/core 13, thread id 16655
[16655] 27/3/2013 -- 03:48:21 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth314) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16656] 27/3/2013 -- 03:48:21 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 14
[16656] 27/3/2013 -- 03:48:21 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth315" Module to cpu/core 14, thread id 16656
[16656] 27/3/2013 -- 03:48:21 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth315) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16657] 27/3/2013 -- 03:48:21 - (util-affinity.c:319) <Info> (AffinityGetNextCPU) -- Setting affinity on CPU 15
[16657] 27/3/2013 -- 03:48:21 - (tm-threads.c:1308) <Info> (TmThreadSetupOptions) -- Setting prio -2 for "RxPFReth316" Module to cpu/core 15, thread id 16657
[16657] 27/3/2013 -- 03:48:21 - (source-pfring.c:418) <Info> (ReceivePfringThreadInit) -- (RxPFReth316) Using PF_RING v.5.5.3, interface eth3, cluster-id 99
[16640] 27/3/2013 -- 03:48:21 - (runmode-pfring.c:556) <Info> (RunModeIdsPfringWorkers) -- RunModeIdsPfringWorkers initialised
[16658] 27/3/2013 -- 03:48:21 - (tm-threads.c:1314) <Info> (TmThreadSetupOptions) -- Setting prio 2 for "FlowManagerThread" thread , thread id 16658
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:337) <Info> (StreamTcpInitConfig) -- stream "max-sessions": 20000000
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:349) <Info> (StreamTcpInitConfig) -- stream "prealloc-sessions": 10000000
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:365) <Info> (StreamTcpInitConfig) -- stream "memcap": 21474836480
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:371) <Info> (StreamTcpInitConfig) -- stream "midstream" session pickups: enabled
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:377) <Info> (StreamTcpInitConfig) -- stream "async-oneside": enabled
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:394) <Info> (StreamTcpInitConfig) -- stream "checksum-validation": disabled
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:416) <Info> (StreamTcpInitConfig) -- stream."inline": disabled
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:434) <Info> (StreamTcpInitConfig) -- stream.reassembly "memcap": 12884901888
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:452) <Info> (StreamTcpInitConfig) -- stream.reassembly "depth": 12582912
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:493) <Info> (StreamTcpInitConfig) -- stream.reassembly "toserver-chunk-size": 2560
[16640] 27/3/2013 -- 03:48:21 - (stream-tcp.c:495) <Info> (StreamTcpInitConfig) -- stream.reassembly "toclient-chunk-size": 2560
[16659] 27/3/2013 -- 03:48:23 - (tm-threads.c:1314) <Info> (TmThreadSetupOptions) -- Setting prio 2 for "SCPerfWakeupThread" thread , thread id 16659
[16660] 27/3/2013 -- 03:48:23 - (tm-threads.c:1314) <Info> (TmThreadSetupOptions) -- Setting prio 2 for "SCPerfMgmtThread" thread , thread id 16660
[16640] 27/3/2013 -- 03:48:23 - (tm-threads.c:2166) <Info> (TmThreadWaitOnThreadInit) -- all 16 packet processing threads, 3 management threads initialized, engine started.
[16640] 28/3/2013 -- 03:45:32 - (suricata.c:2030) <Info> (main) -- Signal Received. Stopping engine.
[16658] 28/3/2013 -- 03:45:33 - (flow-manager.c:558) <Info> (FlowManagerThread) -- 0 new flows, 0 established flows were timed out, 0 flows in closed state
[16640] 28/3/2013 -- 03:47:05 - (tm-threads.c:1752) <Error> (TmThreadDisableThreadsWithTMS) -- [ERRCODE: SC_ERR_FATAL(171)] - Engine unable to disable detect thread - "RxPFReth36". Killing engine
[16640] 28/3/2013 -- 03:47:05 - (tm-threads.c:1752) <Error> (TmThreadDisableThreadsWithTMS) -- [ERRCODE: SC_ERR_FATAL(171)] - Engine unable to disable detect thread - "RxPFReth36". Killing engine
The above is in daemon mode - started as previously explained in the bug report.
In this case the problem is with thread number 6 ...but that is just in this case. I think pfring has that problem in general under high traffic.
So the problem might be (my wild speculation), that when profiling is enabled , we have high traffic and pfring is used - it is "killing" the engine but the "profiling" still waiting for feedback and that could take a while before the whole process is done/finished/killed.