I am sending my live server logs to kafka using rsyslog module. I am using mmnormalize module to parse my log file & My log files are generating 2400 records per seconds. Even It will go up to 10000 per seconds.
Rsyslog taking High CPU usage to parse 2400 records.
I will pick only field1, field3, field5, field17, field18, field19, field53 out of 65 fields. Since I need only 7 fields for my report purpose. Is there any way to simplify my parsing logic?
Also I have reduced little amount of CPU by changing my parsing rule like below. But still it is above than expected behaviour.
Hi Team,
I am sending my live server logs to kafka using rsyslog module. I am using mmnormalize module to parse my log file & My log files are generating 2400 records per seconds. Even It will go up to 10000 per seconds.
Rsyslog taking High CPU usage to parse 2400 records.
Below is my sample log and parsing rule.
Logs:
15:08:2018:08:11:54|15:08:2018:08:11:54|15:08:2018:08:11:54|221729780|MTReq-Out|010513615343009130026|9999999999999|4444444444444|DD-HFGFHF|8888888888888|0|0|827288272|272772772772|8|8|Forwarded|0|0|a98f00d1:37||TC-Continue|0|662525525525||0|||0||3333333333333333|2222222222222222|SD|0|0|0|1||158|||0|||2:0,6:0,7:0,9:0|0|||||||9155454454454||||||0||0||0||
Parsing Rule:
File Name: /etc/MTFW_CDR.rb
version=2 rule=@log:%field1:char-sep:|%|%field2:char-sep:|%|%field3:char-sep:|%|%field4:char-sep:|%|%field5:char-sep:|%|%field6:char-sep:|%|%field7:char-sep:|%|%field8:char-sep:|%|%field9:char-sep:|%|%field10:char-sep:|%|%field11:char-sep:|%|%field12:char-sep:|%|%field13:char-sep:|%|%field14:char-sep:|%|%field15:char-sep:|%|%field16:char-sep:|%|%field17:char-sep:|%|%field18:char-sep:|%|%field19:char-sep:|%|%field20:char-sep:|%|%field21:char-sep:|%|%field22:char-sep:|%|%field23:char-sep:|%|%field24:char-sep:|%|%field25:char-sep:|%|%field26:char-sep:|%|%field27:char-sep:|%|%field28:char-sep:|%|%field29:char-sep:|%|%field30:char-sep:|%|%field31:char-sep:|%|%field32:char-sep:|%|%field33:char-sep:|%|%field34:char-sep:|%|%field35:char-sep:|%|%field36:char-sep:|%|%field37:char-sep:|%|%field38:char-sep:|%|%field39:char-sep:|%|%field40:char-sep:|%|%field41:char-sep:|%|%field42:char-sep:|%|%field43:char-sep:|%|%field44:char-sep:|%|%field45:char-sep:|%|%field46:char-sep:|%|%field47:char-sep:|%|%field48:char-sep:|%|%field49:char-sep:|%|%field50:char-sep:|%|%field51:char-sep:|%|%field52:char-sep:|%|%field53:char-sep:|%|%field54:char-sep:|%|%field55:char-sep:|%|%field56:char-sep:|%|%field57:char-sep:|%|%field58:char-sep:|%|%field59:char-sep:|%|%field60:char-sep:|%|%field61:char-sep:|%|%field62:char-sep:|%|%field63:char-sep:|%|%field64:char-sep:|%|%field65:char-sep:rest%
I will pick only field1, field3, field5, field17, field18, field19, field53 out of 65 fields. Since I need only 7 fields for my report purpose. Is there any way to simplify my parsing logic?
Also I have reduced little amount of CPU by changing my parsing rule like below. But still it is above than expected behaviour.
rule=@mtfw_cdr:%field1:char-sep:|%|%field2:char-sep:|%|%field3:char-sep:|%|%field4:char-sep:|%|%field5:char-sep:|%|%field6:char-sep:|%|%field7:char-sep:|%|%field8:char-sep:|%|%field9:char-sep:|%|%field10:char-sep:|%|%field11:char-sep:|%|%field12:char-sep:|%|%field13:char-sep:|%|%field14:char-sep:|%|%field15:char-sep:|%|%field16:char-sep:|%|%field17:char-sep:|%|%field18:char-sep:|%|%field19:char-sep:|%|%field20:char-sep:|%|%field21:char-sep:|%|%field22:char-sep:|%|%field23:char-sep:|%|%field24:char-sep:|%|%field25:char-sep:|%|%field26:char-sep:|%|%field27:char-sep:|%|%field28:char-sep:|%|%field29:char-sep:|%|%field30:char-sep:|%|%field31:char-sep:|%|%field32:char-sep:|%|%field33:char-sep:|%|%field34:char-sep:|%|%field35:char-sep:|%|%field36:char-sep:|%|%field37:char-sep:|%|%field38:char-sep:|%|%field39:char-sep:|%|%field40:char-sep:|%|%field41:char-sep:|%|%field42:char-sep:|%|%field43:char-sep:|%|%field44:char-sep:|%|%field45:char-sep:|%|%field46:char-sep:|%|%field47:char-sep:|%|%field48:char-sep:|%|%field49:char-sep:|%|%field50:char-sep:|%|%field51:char-sep:|%|%field52:char-sep:|%|%field53:char-sep:|%|%field54:char-sep:\x25%
Rsyslog Rule:
module(load="imfile") module(load="mmnormalize") module(load="omkafka") module(load="impstats" interval="60" resetCounters="on" format="legacy")
template (name="MTFW_CDR" type="list") { constant(value="{\"ReportGeneratedTime\":\"") property(name="$!field1") constant(value=" +05:30") constant(value="\",\"Delivered Time\":\"") property(name="$!field3") constant(value=" +05:30") constant(value="\",\"Record Type\":\"") property(name="$!field5") constant(value="\",\"Delivery Status\":\"") property(name="$!field17") constant(value="\",\"Failure Reason\":\"") property(name="$!field18") constant(value="\",\"Failure Reason Type\":\"") property(name="$!field19") constant(value="\",\"Service Centre\":\"") property(name="$!field53") constant(value="\",\"vendor\":\"TELE\",\"location\":\"NOIDA\",\"IPAddress\":\"10.10.10.1\",\"product\":\"MTFW\"}") }
input(type="imfile" File="/home/prem/rsyslog/cdrs/SMSFW_CDR_Pune_MT*.log" Tag="cdr: " ruleset="MTFW_CDR")
ruleset(name="MTFW_CDR") { action(type="mmnormalize" rulebase="/etc/MTFW_CDR.rb") action( action.resumeRetryCount="-1" action.resumeInterval="5" action.reportSuspension="on" action.reportSuspensionContinuation="on" broker=["10.10.10.10:9092"] template="MTFW_CDR" type="omkafka" topic="mtfw_cdr" partitions.auto="on" errorFile="/var/log/kafka_error.log" confParam=[ "socket.timeout.ms=1000", "socket.keepalive.enable=true", "queue.buffering.max.messages=2000000", "queue.buffering.max.ms=1000", "compression.codec=gzip" ] queue.workerThreads="10" queue.dequeueBatchSize="100"
queue.buffering.max.messages="10000"
}
Below is my impstats data,
Aug 21 11:23:17 Gems10 rsyslogd-pstats: global: origin=dynstats Aug 21 11:23:17 Gems10 rsyslogd-pstats: imuxsock: origin=imuxsock submitted=3 ratelimit.discarded=0 ratelimit.numratelimiters=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 0: origin=core.action processed=3 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 1: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 2: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 3: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 4: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 5: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 6: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: omkafka: submitted=148800 maxoutqsize=9554 failures=0 topicdynacache.skipped=0 topicdynacache.miss=0 topicdynacache.evicted=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 7: origin=core.action processed=148800 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: action 8: origin=core.action processed=148800 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:23:17 Gems10 rsyslogd-pstats: resource-usage: origin=impstats utime=9531094 stime=96243 maxrss=26516 minflt=45917 majflt=0 inblock=0 oublock=0 nvcsw=2872 nivcsw=60 Aug 21 11:23:17 Gems10 rsyslogd-pstats: main Q: origin=core.queue size=13 enqueued=148816 full=0 discarded.full=0 discarded.nf=0 maxqsize=6176 Aug 21 11:24:17 Gems10 rsyslogd-pstats: global: origin=dynstats Aug 21 11:24:17 Gems10 rsyslogd-pstats: imuxsock: origin=imuxsock submitted=0 ratelimit.discarded=0 ratelimit.numratelimiters=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 0: origin=core.action processed=14 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 1: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 2: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 3: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 4: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 5: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 6: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: omkafka: submitted=144000 maxoutqsize=9554 failures=0 topicdynacache.skipped=0 topicdynacache.miss=0 topicdynacache.evicted=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 7: origin=core.action processed=144000 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: action 8: origin=core.action processed=144000 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:24:17 Gems10 rsyslogd-pstats: resource-usage: origin=impstats utime=18872399 stime=168335 maxrss=26516 minflt=60985 majflt=0 inblock=0 oublock=8 nvcsw=5242 nivcsw=92 Aug 21 11:24:17 Gems10 rsyslogd-pstats: main Q: origin=core.queue size=13 enqueued=144014 full=0 discarded.full=0 discarded.nf=0 maxqsize=6176 Aug 21 11:25:17 Gems10 rsyslogd-pstats: global: origin=dynstats Aug 21 11:25:17 Gems10 rsyslogd-pstats: imuxsock: origin=imuxsock submitted=0 ratelimit.discarded=0 ratelimit.numratelimiters=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 0: origin=core.action processed=14 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 1: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 2: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 3: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 4: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 5: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 6: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: omkafka: submitted=144000 maxoutqsize=9554 failures=0 topicdynacache.skipped=0 topicdynacache.miss=0 topicdynacache.evicted=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 7: origin=core.action processed=144000 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: action 8: origin=core.action processed=144000 failed=0 suspended=0 suspended.duration=0 resumed=0 Aug 21 11:25:17 Gems10 rsyslogd-pstats: resource-usage: origin=impstats utime=28014390 stime=223481 maxrss=26516 minflt=76394 majflt=0 inblock=0 oublock=24 nvcsw=7580 nivcsw=166 Aug 21 11:25:17 Gems10 rsyslogd-pstats: main Q: origin=core.queue size=13 enqueued=144014 full=0 discarded.full=0 discarded.nf=0 maxqsize=6176