[systemd-devel] journald forwarding to rsyslogd. Huge (350 times) performance degradation. What am I doing wrong???

[Vitaly Repin]

Hello,

I have noticed that sometimes log messages are dropped in one of my
systemd-based system (systemd 219).

Apps log through syslog (/dev/log). rsyslogd listens at
/run/systemd/journal/syslog

I decided to compare the logging performance (using loggen tool:
https://www.syslog-ng.com/technical-documents/doc/syslog-ng-open-source-edition/3.16/administration-guide/87
) in two cases:

1. If it logs to /dev/log
2. If it logs to /run/systemd/journal/syslog

All the setup was the same. I can share the script I used to test if needed
but the idea was pretty simple - for every tested logging rate, log for 5
minute. Then count number of lines in the log and compare it with the
number of lines sent by loggen tool.

I expected certain degradation as promised by rsyslog manual: ("It must be
noted, however, that the journal tends to drop messages when it becomes
busy instead of forwarding them to the system log socket. This is because
the journal uses an
async log socket interface for forwarding instead of the traditional
synchronous one").

However I was shocked by the results.

Max rate at which log messages are NOT dropped is 17250 msg/s for logging
to /run/systemd/journal/syslog.  And only 47 messages per second for
logging to /dev/log.

Example of the loggen cmdline:

./loggen --unix -D --interval 300 --rate 35 --size 512 /dev/log

journald.conf:

[Journal]
#
# Configuration in order to send logs to rsyslog
#
Storage=none
#Storage=auto
ForwardToSyslog=yes
MaxLevelSyslog=debug
#
# These configurations are if the storage is set to auto
# this is just configured in order to limit the log size
#
SystemMaxUse=400M
SystemKeepFree=200M
SystemMaxFileSize=20M
RuntimeMaxUse=1000M
RuntimeKeepFree=1000M
RuntimeMaxFileSize=100M
MaxRetentionSec=1month
MaxFileSec=1week

(I have checked with "journalctl -f" that logs are not stored in the binary
journal)

I was shocked by the results. My first idea was that there is something
with buffers not being flushed somewhere in the chain at the end of the
test.

But I can see that last messages in the log are the last messages sent by
loggen tool.  It looks unbelievably bad.

Do I measure something wrong? Or is there any known setting I have to apply
to journald to make forwarding more efficient?

Any ideas are appreciated.

Thank you in advance!
-- 
WBR & WBW, Vitaly
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20200920/15375d9b/attachment.htm>