it looks like the bulk of the cpu time is taken up in the queue management of
your first two actions.
By default, rsyslog works to minimize latency, but with a queue that has little
work to do, this can result in a lot of lock contention on the queue
the good news is that as there is more traffic, the congestion reduces, and so
throughput will keep going up without increasing the cpu utilization,
you can try to reduce the contention by setting the min batch size so that it
waits a bit longer before working to deliver messages (set it to something
small, 2-5 and see what happens)
queue.minDequeueBatchSize¶
type default mandatory obsolete legacy directive
integer 0 no none
Specifies the minimum batch size for dequeue operations. This setting is
especially useful with outputs like ElasticSearch or ClickHouse, where you want
to limit the number of HTTP requests. With this setting, the queue engine waits
up to queue.minDequeueBatchSize.timeout milliseconds when there are fewer
messages currently queued. Note that the minimum batch size cannot be larger
than the configured maximum batch size. If so, it is automatically adjusted to
match the maximum. So if in doubt, you need to specify both parameters.
queue.minDequeueBatchSize.timeout
type default mandatory obsolete legacy directive
integer 1000 no none
This parameter is only meaningful if use together with
queue.minDequeueBatchSize, otherwise it is ignored. It specifies the amount of
time (in milliseconds) rsyslogs waits for new messages so that the minimum batch
size can be reached. After this period, the batch is processed, even if it is
below minimum size. This capability exists to prevent having messages stalled in
an incomplete batch just because no new messages arrive. We would expect that it
usually makes little sense to set it to higher than 60.000 (60 seconds), but
this is permitted. Just be warned that this potentially delays log processing
for that long.
David Lang
On Sun, 4 Oct 2020, Kype Ahamed via rsyslog wrote:
Date: Sun, 4 Oct 2020 21:29:52 +0800
From: Kype Ahamed via rsyslog <[email protected]>
To: [email protected]
Cc: Kype Ahamed <[email protected]>
Subject: [rsyslog] CPU usage constantly above 80%
Hello,
I am using rsyslog mainly as a syslog relay, to forward messages from 1
source device to multiple destination devices.
Right now i am receiving about 50k messages per second, and i noticed CPU
usage is constantly above 80%
Are there any further tweaks that can be done to below config to reduce the
CPU usage?
-------------------------------------------------
rsyslog config file:
module(load="impstats"
interval="20"
severity="7"
log.syslog="off"
log.file="/var/log/impstats.log")
global(parser.escapecontrolcharactertab="off")
# Load Modules #
module(load="imudp" TimeRequery="5" BatchSize="64")
# rsyslog Templates #
template(name="testMachineHeader" type="string"
string="%TIMESTAMP:::date-rfc3164% testMachine %rawmsg:::drop-last-lf%\n")
template(name="rawTemplate" type="string"
string="%rawmsg:::drop-last-lf%\n")
# rsyslog Input Modules #
input(type="imudp"
port="10514"
ruleset="forwardToDestRule"
device="eth0"
)
# rsyslog RuleSets #
ruleset(name="forwardToDestRule"
queue.type="fixedArray"
queue.size="25000"
) {
if ($msg contains "interface=inbound" and $msg contains "source=10.1.1.1")
then {
action(type="omfwd"
Target="10.1.1.5"
Port="514"
Protocol="tcp"
Device="eth0"
queue.type="fixedArray"
queue.size="50000"
queue.dequeueBatchSize="1024"
template="testMachineHeader")
}
else{
action(type="omfwd"
Target="10.1.1.6"
Port="514"
Protocol="udp"
Device="eth0"
queue.type="fixedArray"
queue.size="50000"
action.resumeRetryCount="-1"
template="rawTemplate")
}
if ($msg contains "interface=outbound" and $msg contains "source=10.1.1.1")
then {
if ($msg contains "proto=17") then {
action(type="omfwd"
Target="10.1.1.7"
Port="514"
Protocol="udp"
Device="eth0"
queue.type="linkedlist"
queue.size="50000"
action.resumeRetryCount="-1"
template="rawTemplate")
}
}
}
-------------------------------------------------
Top -H output:
top - 08:53:26 up 1:55, 1 user, load average: 2.32, 1.50, 1.07
Threads: 112 total, 7 running, 105 sleeping, 0 stopped, 0 zombie
%Cpu(s): 23.4 us, 53.5 sy, 0.0 ni, 3.5 id, 0.4 wa, 0.0 hi, 19.1 si,
0.0 st
KiB Mem : 7972668 total, 7475888 free, 250088 used, 246692 buff/cache
KiB Swap: 4063228 total, 4063228 free, 0 used. 7449764 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2567 root 20 0 639540 16836 12416 R 32.4 0.2 1:11.53
rs:action 2 que
2566 root 20 0 639540 16836 12416 R 30.1 0.2 1:11.32
rs:action 1 que
2551 root 20 0 639540 16836 12416 R 14.1 0.2 0:30.68 in:imudp
2565 root 20 0 639540 16836 12416 R 11.1 0.2 0:31.94
rs:forwardToDes
600 root 20 0 100676 38508 38184 S 6.2 0.5 0:33.62
systemd-journal
-------------------------------------------------
impstats output:
Sun Oct 4 08:46:49 2020: global: origin=dynstats
Sun Oct 4 08:46:49 2020: imuxsock: origin=imuxsock submitted=0
ratelimit.discarded=0 ratelimit.numratelimiters=0
Sun Oct 4 08:46:49 2020: action 0: origin=core.action processed=0 failed=0
suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 1: origin=core.action processed=1341545
failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 2: origin=core.action processed=1341545
failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 3: origin=core.action processed=4022
failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 4: origin=core.action processed=1 failed=0
suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 5: origin=core.action processed=0 failed=0
suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 6: origin=core.action processed=0 failed=0
suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 7: origin=core.action processed=0 failed=0
suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 8: origin=core.action processed=0 failed=0
suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: action 9: origin=core.action processed=0 failed=0
suspended=0 suspended.duration=0 resumed=0
Sun Oct 4 08:46:49 2020: imudp(*:10514): origin=imudp submitted=1341849
Sun Oct 4 08:46:49 2020: imudp(*:10514): origin=imudp submitted=0
Sun Oct 4 08:46:49 2020: resource-usage: origin=impstats utime=9190927
stime=25608171 maxrss=12244 minflt=166970 majflt=0 inblock=0 oublock=4368
nvcsw=37503 nivcsw=339
Sun Oct 4 08:46:49 2020: action 0 queue: origin=core.queue size=0
enqueued=0 full=0 discarded.full=0 discarded.nf=0 maxqsize=0
Sun Oct 4 08:46:49 2020: action 1 queue: origin=core.queue size=0
enqueued=1341545 full=0 discarded.full=0 discarded.nf=0 maxqsize=5227
Sun Oct 4 08:46:49 2020: action 2 queue: origin=core.queue size=252
enqueued=1341545 full=0 discarded.full=0 discarded.nf=0 maxqsize=6051
Sun Oct 4 08:46:49 2020: forwardToDestRule: origin=core.queue size=304
enqueued=1341849 full=0 discarded.full=0 discarded.nf=0 maxqsize=1003
Sun Oct 4 08:46:49 2020: main Q: origin=core.queue size=0 enqueued=4023
full=0 discarded.full=0 discarded.nf=0 maxqsize=64
Sun Oct 4 08:46:49 2020: imudp(w0): origin=imudp called.recvmmsg=40859
called.recvmsg=0 msgs.received=1341849
-------------------------------------------------
Regards,
Scorsese P.
_______________________________________________
rsyslog mailing list
https://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.
_______________________________________________
rsyslog mailing list
https://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.
