On Fri, Oct 18, 2013 at 12:45 PM, Pavel Levshin <[email protected]>wrote:
> Hello
>
>
> We are trying to use mmnormalize to parse syslog from NAT device. This
> device makes around 150000 messages per second. Now, I’ve trying to make it
> working with rsyslog 7.5.5 (RHEL 6 x86_64, official RPMs). Then, I have
> two problems.
>
> First, mmnormalize is unable to handle the load. It appears to me that
> there is a big lock somewhere in the module, because it is unable to
> distribute CPU load between threads. Total CPU utilization by the module is
> around 100% despite of number of threads.
>
>
just commenting on the performance: there are two issues in regard to your
use case
First of all, the current mmnormalize does a lot of unnecessary work
converting between libee representation and rsyslog's internal json parser.
This could be greatly improved.
Secondly, as you noted, the action interface traditional permits only one
thread at a time to be inside the actual action. For "the usual cases",
this is of little problem, but there are cases where permiting multiple
entries would be very benefitial. mmnormalize is among them.
I would like to change both, but need a sponsor to do this quickly. On my
non-sponsored todo list, the second issue is with a somewhat higher
priority than the first one. I would hope I could work on it within the
next 6 to 9 month. Hopefully I will even be able to do some initial
analysis soon, which could speed up the process if it appears to be more
trivial than I currently think.
Rainer
> Threads=”3”
>
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
>
> 2482 root 20 0 635m 189m 1064 R 60.2 0.8 0:13.07 in:imudp
>
> 2486 root 20 0 635m 189m 1064 R 37.7 0.8 0:07.73 rs:action 1 que
>
> 2487 root 20 0 635m 189m 1064 S 36.7 0.8 0:07.66 rs:action 1 que
>
> 2485 root 20 0 635m 189m 1064 S 36.1 0.8 0:07.47 rs:action 1 que
>
> 2484 root 20 0 635m 189m 1064 R 27.5 0.8 0:05.44 rs:main Q:Reg
>
> Threads=”10”
>
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
>
> 2515 root 20 0 1218m 195m 1080 R 60.5 0.8 0:56.13 in:imudp
>
> 2516 root 20 0 1218m 195m 1080 R 27.8 0.8 0:24.41 rs:main Q:Reg
>
> 2519 root 20 0 1218m 195m 1080 R 11.6 0.8 0:09.97 rs:action 1 que
>
> 2523 root 20 0 1218m 195m 1080 S 11.6 0.8 0:10.42 rs:action 1 que
>
> 2520 root 20 0 1218m 195m 1080 S 11.2 0.8 0:10.40 rs:action 1 que
>
> 2525 root 20 0 1218m 195m 1080 S 11.2 0.8 0:10.25 rs:action 1 que
>
> 2518 root 20 0 1218m 195m 1080 S 10.9 0.8 0:10.20 rs:action 1 que
>
> 2522 root 20 0 1218m 195m 1080 S 10.9 0.8 0:09.99 rs:action 1 que
>
> 2524 root 20 0 1218m 195m 1080 S 10.9 0.8 0:10.03 rs:action 1 que
>
> 2526 root 20 0 1218m 195m 1080 S 10.9 0.8 0:10.19 rs:action 1 que
>
> 2517 root 20 0 1218m 195m 1080 S 10.6 0.8 0:10.05 rs:action 1 que
>
> 2521 root 20 0 1218m 195m 1080 S 10.6 0.8 0:10.32 rs:action 1 que
>
> Omstats:
>
> Fri Oct 18 14:13:22 2013: imuxsock: submitted=657 ratelimit.discarded=0
> ratelimit.numratelimiters=7
>
> Fri Oct 18 14:13:22 2013: action 1: processed=9385402 failed=0
>
> Fri Oct 18 14:13:22 2013: dynafile cache normFilename: requests=0 level0=0
> missed=0 evicted=0 maxused=0
>
> Fri Oct 18 14:13:22 2013: action 2: processed=0 failed=0
>
> Fri Oct 18 14:13:22 2013: action 3: processed=645 failed=0
>
> Fri Oct 18 14:13:22 2013: action 4: processed=3 failed=0
>
> Fri Oct 18 14:13:22 2013: action 5: processed=0 failed=0
>
> Fri Oct 18 14:13:22 2013: action 6: processed=9 failed=0
>
> Fri Oct 18 14:13:22 2013: action 7: processed=1 failed=0
>
> Fri Oct 18 14:13:22 2013: action 8: processed=0 failed=0
>
> Fri Oct 18 14:13:22 2013: action 9: processed=0 failed=0
>
> Fri Oct 18 14:13:22 2013: action 10: processed=0 failed=0
>
> Fri Oct 18 14:13:22 2013: imudp(*:514): submitted=9385432
>
> Fri Oct 18 14:13:22 2013: imudp(*:514): submitted=0
>
> Fri Oct 18 14:13:22 2013: resource-usage: utime=173476627 stime=42114597
> maxrss=200500 minflt=1094749 majflt=0 inblock=0 oublock=552 nvcsw=2367078
> nivcsw=1441
>
> Fri Oct 18 14:13:22 2013: action 1 queue: size=200000 enqueued=9385401
> full=4742604 discarded.full=4742604 discarded.nf=0 maxqsize=200000
>
> Fri Oct 18 14:13:22 2013: main Q: size=31 enqueued=9386090 full=0
> discarded.full=0 discarded.nf=0 maxqsize=1122
>
> Fri Oct 18 14:13:22 2013: imudp(w0): called.recvmmsg=10554433
> called.recvmsg=0 msgs.received=9385433
>
> 99,5% of messages has one format, like this (raw message):
>
> <150>2013-10-17 20:41:59 CGN-ATS-528{sset_SP_000}[**FWNAT]:
> ASP_SFW_CREATE_ACCEPT_FLOW 100.91.5.221:53129 [78.25.120.17:36231] ->
> 176.194.90.81:6881 (TCP)
>
> Configuration for the module follows:
>
> Ruleset(name="logd"){
>
> Action(
>
> queue.workerthreads="10"
>
> queue.type="LinkedList"
>
> queue.size="200000"
>
> queue.timeoutenqueue="0"
>
> type="mmnormalize"
>
> userawmsg="on"
>
> rulebase="/etc/rsyslog.d/**rules.rb"
>
> )
>
> if $!date != "" then {
>
> Action(
>
> type="omfile"
>
> DynaFile="normFilename"
>
> template="normTemplate"
>
> )
>
> }
>
> }
>
> Rulebase:
>
> prefix=<150>%date:word% %time:word% %cgn:char-to:{%{%sset:char-to:**
> }%}[FWNAT]:
>
> rule=: ASP_SFW_CREATE_ACCEPT_FLOW %ip1:ipv4%:%port1:number%
> [%ip2:ipv4%:%port2:number%] -> %ip3:ipv4%:%port3:number% (%proto:char-to:)%)
>
> Second, in 7.5.5, this does not work at all. In 7.4.4, mmnormalize
> produces expected output, though it cannot keep the load and has known
> memory leak.
>
>
> On the other hand, in 7.5.5 it produces rare records in the output file
> (say, 100 per minute). It looks like it cannot match other records, but
> this is weird, as they are all in the same format and happily match in
> lognormalize.
>
>
> Does anyone have this working?
>
> Thanks for reading this,
> Pavel
>
> ______________________________**_________________
> rsyslog mailing list
> http://lists.adiscon.net/**mailman/listinfo/rsyslog<http://lists.adiscon.net/mailman/listinfo/rsyslog>
> http://www.rsyslog.com/**professional-services/<http://www.rsyslog.com/professional-services/>
> What's up with rsyslog? Follow https://twitter.com/rgerhards
> NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad
> of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you
> DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of
sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE
THAT.
