[Oisf-devel] Extremely long startup times on latest git

Sun Sep 18 19:51:20 UTC 2011

Hi Martin,

I am not sure why would it take 28 min to start Suricata if you use all the
default config and options.
Could you please elaborate a bit more on you set-up? /Sur ver/platform/HW../

Please find below my output which uses about 3 times bigger rule set and it
loads for about 4 min:
""
[2034] 18/9/2011 -- 17:05:07 - (detect.c:2440) <Info>
(SigAddressPrepareStage1) -- 29875 signatures processed. 1285 are IP-only
rules, 19921 are inspecting packet payload, 8883 inspect application layer,
72 are decoder/engine/stream event only
[2034] 18/9/2011 -- 17:05:07 - (detect.c:2443) <Info>
(SigAddressPrepareStage1) -- building signature grouping structure, stage 1:
adding signatures to signature source addresses... complete
[2034] 18/9/2011 -- 17:05:36 - (detect.c:3085) <Info>
(SigAddressPrepareStage2) -- building signature grouping structure, stage 2:
building source address list... complete
[2034] 18/9/2011 -- 17:07:20 - (detect.c:3642) <Info>
(SigAddressPrepareStage3) -- MPM memory 2119838502 (dynamic 2119838502, ctxs
0, avg per ctx 0)
[2034] 18/9/2011 -- 17:07:20 - (detect.c:3644) <Info>
(SigAddressPrepareStage3) -- max sig id 29876, array size 3735
[2034] 18/9/2011 -- 17:07:20 - (detect.c:3655) <Info>
(SigAddressPrepareStage3) -- building signature grouping structure, stage 3:
building destination address lists... complete
[2034] 18/9/2011 -- 17:07:46 - (util-threshold-config.c:135) <Warning>
(SCThresholdConfInitContext) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening
file: "threshold.config": No such file or directory
[2034] 18/9/2011 -- 17:07:46 - (alert-fastlog.c:366) <Info>
(AlertFastLogInitCtx) -- Fast log output initialized, filename: fast.log
[2034] 18/9/2011 -- 17:07:46 - (alert-unified2-alert.c:897) <Info>
(Unified2AlertInitCtx) -- Unified2-alert initialized: filename
unified2.alert, limit 32 MB
[2034] 18/9/2011 -- 17:07:46 - (runmodes.c:342) <Warning>
(RunModeInitializeOutputs) -- [ERRCODE: SC_ERR_INVALID_ARGUMENT(13)] - No
output module named alert-prelude, ignoring
[2034] 18/9/2011 -- 17:07:46 - (log-droplog.c:181) <Info>
(LogDropLogInitCtx) -- Drop log output initialized, filename: drop.log
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:356) <Info>
(StreamTcpInitConfig) -- stream "max_sessions": 262144
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:368) <Info>
(StreamTcpInitConfig) -- stream "prealloc_sessions": 32768
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:378) <Info>
(StreamTcpInitConfig) -- stream "memcap": 567554432
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:385) <Info>
(StreamTcpInitConfig) -- stream "midstream" session pickups: enabled
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:393) <Info>
(StreamTcpInitConfig) -- stream "async_oneside": enabled
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:409) <Info>
(StreamTcpInitConfig) -- stream "checksum_validation": disabled
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:420) <Info>
(StreamTcpInitConfig) -- stream."inline": enabled
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:429) <Info>
(StreamTcpInitConfig) -- stream.reassembly "memcap": 67108864
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:439) <Info>
(StreamTcpInitConfig) -- stream.reassembly "depth": 1048576
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:462) <Info>
(StreamTcpInitConfig) -- stream.reassembly "toserver_chunk_size": 2560
[2034] 18/9/2011 -- 17:07:46 - (stream-tcp.c:464) <Info>
(StreamTcpInitConfig) -- stream.reassembly "toclient_chunk_size": 2560
[2044] 18/9/2011 -- 17:07:46 - (source-pcap.c:379) <Info>
(ReceivePcapThreadInit) -- using interface eth0
[2034] 18/9/2011 -- 17:07:47 - (tm-threads.c:1693) <Info>
(TmThreadWaitOnThreadInit) -- all 5 packet processing threads, 3 management
threads initialized, engine started.
^C[2034] 18/9/2011 -- 17:08:21 - (suricata.c:1497) <Info> (main) -- signal
received
[2034] 18/9/2011 -- 17:08:21 - (suricata.c:1506) <Info> (main) -- EngineStop
received
[2044] 18/9/2011 -- 17:08:21 - (source-pcap.c:551) <Info>
(ReceivePcapThreadExitStats) -- (ReceivePcap) Packets 73, bytes 24531
[2044] 18/9/2011 -- 17:08:21 - (source-pcap.c:562) <Info>
(ReceivePcapThreadExitStats) -- (ReceivePcap) Pcap Total:75 Recv:75 Drop:0
(0.0%).
[2034] 18/9/2011 -- 17:08:21 - (suricata.c:1541) <Info> (main) -- all
packets processed by threads, stopping engine
[2034] 18/9/2011 -- 17:08:21 - (suricata.c:1548) <Info> (main) -- time
elapsed 35s
[2045] 18/9/2011 -- 17:08:21 - (stream-tcp.c:3849) <Info>
(StreamTcpExitPrintStats) -- (Decode & Stream) Packets 53
[2048] 18/9/2011 -- 17:08:21 - (alert-fastlog.c:331) <Info>
(AlertFastLogExitPrintStats) -- (Outputs) Alerts 13
[2048] 18/9/2011 -- 17:08:21 - (alert-unified2-alert.c:821) <Info>
(Unified2AlertThreadDeinit) -- Alert unified2 module wrote 13 alerts
[2048] 18/9/2011 -- 17:08:21 - (log-httplog.c:404) <Info>
(LogHttpLogExitPrintStats) -- (Outputs) HTTP requests 2
[2048] 18/9/2011 -- 17:08:21 - (alert-debuglog.c:451) <Info>
(AlertDebugLogExitPrintStats) -- (Outputs) Alerts 13
[2048] 18/9/2011 -- 17:08:21 - (log-droplog.c:388) <Info>
(LogDropLogExitPrintStats) -- (Outputs) Dropped Packets 0
[2049] 18/9/2011 -- 17:08:21 - (flow.c:1148) <Info> (FlowManagerThread) -- 0
new flows, 0 established flows were timed out, 0 flows in closed state
[2034] 18/9/2011 -- 17:08:21 - (stream-tcp-reassemble.c:355) <Info>
(StreamTcpReassembleFree) -- Max memuse of the stream reassembly engine
11220864 (in use 0)
[2034] 18/9/2011 -- 17:08:21 - (stream-tcp.c:509) <Info>
(StreamTcpFreeConfig) -- Max memuse of stream engine 4587520 (in use 0)
[2034] 18/9/2011 -- 17:08:21 - (detect.c:3682) <Info>
(SigAddressCleanupStage1) -- cleaning up signature grouping structure...
complete

real    4m18.090s
user    3m3.455s
sys    0m21.833s
root at ubuntu32:~#

""

Thanks

On Sun, Sep 18, 2011 at 8:06 PM, Martin Holste <mcholste at gmail.com> wrote:

> I'm seeing load times of greater than a half hour with a standard
> setup, using default config values:
>
> [25718] 18/9/2011 -- 11:25:53 - (detect.c:2440) <Info>
> (SigAddressPrepareStage1) -- 9301 signatures processed. 2013 are
> IP-only rules, 2796 are inspecting packet payload, 2739 inspect
> application layer, 0 are decoder/engine/stream event only
> [25718] 18/9/2011 -- 11:25:53 - (detect.c:2443) <Info>
> (SigAddressPrepareStage1) -- building signature grouping structure,
> stage 1: adding signatures to signature source addresses... complete
> [25718] 18/9/2011 -- 11:31:53 - (detect.c:3085) <Info>
> (SigAddressPrepareStage2) -- building signature grouping structure,
> stage 2: building source address list... complete
> [25718] 18/9/2011 -- 11:59:07 - (detect.c:3642) <Info>
> (SigAddressPrepareStage3) -- MPM memory 330428951 (dynamic 330428951,
> ctxs 0, avg per ctx 0)
> [25718] 18/9/2011 -- 11:59:07 - (detect.c:3644) <Info>
> (SigAddressPrepareStage3) -- max sig id 9301, array size 1163
> [25718] 18/9/2011 -- 11:59:07 - (detect.c:3655) <Info>
> (SigAddressPrepareStage3) -- building signature grouping structure,
> stage 3: building destination address lists... complete
>
> I think 6 minutes is a pretty long time to compile signatures (stage
> 1), but I've seen that before.  Why does it take 28 minutes to build a
> source address list?  I'm using the standard ET ruleset.
> _______________________________________________
> Oisf-devel mailing list
> Oisf-devel at openinfosecfoundation.org
> http://lists.openinfosecfoundation.org/mailman/listinfo/oisf-devel
>

-- 
Peter Manev
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openinfosecfoundation.org/pipermail/oisf-devel/attachments/20110918/b768b639/attachment-0002.html>