Re: [rsyslog] Calling syslog() is slow - it takes +100usec

David Lang Sat, 29 Nov 2014 01:07:06 -0800

but why should this cause the latency to increase based on the number ofsimultanious writers? that's what makes me think that rsyslog may not be ackingthe messages one at a time, but instead is acking all of them that it'sprocessing in one batch.


David Lang


On Sat, 29 Nov 2014, Rainer Gerhards wrote:

I think that's an issue with the syslog () api. It is synchronous, so
blocking is expected. I guess the rest of the problem is that linux puts
mutexes around the /dev/log writes (after all, writes are atomic).

Sent from phone, thus brief.
Am 28.11.2014 23:57 schrieb "David Lang" <[email protected]>:

Hmm, I wonder if the batch size is what you are seeing (where rsyslog
processes multiple messages at once).

We'll need to wait until Rainer can comment for sure, but you may want to
try setting the batch size very low (say 5) and see if that puts a cap on
the latency that you see.

We've done a lot of testing for throughput, both from a single process and
from multiple processes, but I don't remember every looking at per-process
latency before.

David Lang

On Fri, 28 Nov 2014, Mehrdad Pazooki wrote:

 I am using:


rsyslogd 8.4.2.ad1, compiled with:
   FEATURE_REGEXP:                Yes
   GSSAPI Kerberos 5 support:        No
   FEATURE_DEBUG (debug build, slow code):    No
   32bit Atomic operations supported:    Yes
   64bit Atomic operations supported:    Yes
   memory allocator:            system default
   Runtime Instrumentation (slow code):    No
   uuid support:                Yes
   Number of Bits in RainerScript integers: 32 (due to too-old json-c lib)

It is handling a very high volume but syslog() blocks and the blocking
time
is not constant, so as I add more processes that are making a syslog()
call
the blocking time increases by 10usec per process on my machine.




On Fri, Nov 28, 2014 at 4:50 PM, David Lang <[email protected]> wrote:

 what version of rsyslog are you running?


rsyslog should be able to keep up with a very high volume of logs being
delivered to /dev/log, but there are significant improvements between the
version of rsyslog that was shipped in 12.05 (which I think was 5.x) and
the current 8.x versions

David Lang


 On Fri, 28 Nov 2014, Mehrdad Pazooki wrote:

 Date: Fri, 28 Nov 2014 10:14:30 -0500

From: Mehrdad Pazooki <[email protected]>
Reply-To: rsyslog-users <[email protected]>
To: rsyslog-users <[email protected]>
Subject: Re: [rsyslog] Calling syslog() is slow - it takes +100usec

There is no systemd on this platform.

More details about the platform:

Description:    Ubuntu 12.04.1 LTS
Release:    12.04
Codename:    precise

Linux 3.13.0-39-generic #66-Ubuntu SMP

On Fri, Nov 28, 2014 at 7:14 AM, Mehrdad Pazooki <[email protected]>
wrote:

 It's running in Ubuntu (precise). I'll check it for systemd. I think

syslog call is blocking because of /dev/log . if I use UDP locally,
will
that bypass /Dev/log?


On Fri, Nov 28, 2014, 04:08 Rainer Gerhards <[email protected]>
wrote:

 which platform is this running on? Is systemd journal active?


Rainer

2014-11-27 22:37 GMT+01:00 Mehrdad Pazooki <[email protected]>:

 Hi,


I am calling syslog in c++ using syslog.h . the time it takes on each

 call


 is too long. I am comparing it with IPC Queue and there is almost


 100usec


 overhead when I call syslog() vs ipc.

I did some benchmarking, when I use a single process for hitting
syslog

 the


 performance is great it stays at avg 11usec/record for 1m records on

my
system. but if I run 10 of these processes the time will increase to

 about


 100usec/record.


Another problem is that memory usage remains really low ~0% so that

 tells


 me syslog() is somehow blocking and using cpu rather than do a set an

forget to the queue and process it later on. another issue is that
all
workers are not engage. I see 5 workers but only 3 are working.
The way I'm using it in prod is about 500 threads hit syslog(). I
need

 to


 keep the time it takes for a syslog() call to a constant of 10usec


 ideal to


 max 40usec.

Also, I am not doing openlog() before calling syslog()

This is my configuration:

#  /etc/rsyslog.conf    Configuration file for rsyslog.
#
#            For more information see
#            /usr/share/doc/rsyslog-doc/
html/rsyslog_conf.html
#
#  Default logging rules can be found in
/etc/rsyslog.d/50-default.conf


#################
#### MODULES ####
#################
$ModLoad imuxsock # provides support for local system logging
$ModLoad imklog   # provides kernel logging support (previously done
by
rklogd)
#$ModLoad immark  # provides --MARK-- message capability

# provides UDP syslog reception
#$ModLoad imudp
#$UDPServerRun 514

# provides TCP syslog reception
#$ModLoad imtcp
#$InputTCPServerRun 514


# For debug only
# module(load="impstats" interval="1" severity="8")

###########################
#### GLOBAL DIRECTIVES ####
###########################

#
# Use traditional timestamp format.
# To enable high precision timestamps, comment out the following
line.
#
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

# Filter duplicated messages
$RepeatedMsgReduction off

#
# Set the default permissions for all log files.
#
$FileOwner root
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022
$PrivDropToUser root
$PrivDropToGroup root

#
# Where to place spool files
#
$WorkDirectory /var/spool/rsyslog

$ActionResumeRetryCount         -1                    # infinite

 retries if


 host is down

$SystemLogRateLimitInterval     0
$SystemLogRateLimitBurst        0
$MaxMessageSize                    4k

main_queue(
    queue.Type="LinkedList"
    queue.Size="1000000"
    queue.workerThreads="8"
    queue.workerThreadMinimumMessages="10000"
    queue.SaveOnShutdown="on"
)



template(name="localone" type="string" string="%msg:2:$%\n") # ":2:$"

 -->


 tells rsyslog to ignore the leading char, b/c rsyslog adds a leading


 space


 to every message


if $syslogfacility-text == 'local1' then {
    action(
        type="omfile"
        template="localone"
        file="/var/log/local1.log"
        flushOnTXEnd="off"
        asyncWriting="on"
        ioBufferSize="64k"
        queue.type="LinkedList"
        queue.size="1000000"
        queue.dequeueBatchSize="4096"
        queue.workerThreads="8"
        queue.workerThreadMinimumMessages="10000"
        queue.SaveOnShutdown="on"
        action.ResumeRetryCount="-1"
    )
    stop
}

#if $syslogtag contains 'rsyslogd-pstats' then {
#     action(
#        type="omfile"
#        queue.type="LinkedList"
#        queue.discardmark="1000"
#        name="pstats"
#        file="/var/log/pstats.log"
#    )
#    stop
#}
_______________________________________________
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.

 _______________________________________________

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.


  _______________________________________________

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.

 _______________________________________________

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.

 _______________________________________________

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.

 _______________________________________________

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.

_______________________________________________
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.

_______________________________________________
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.

Re: [rsyslog] Calling syslog() is slow - it takes +100usec

Reply via email to