2014-11-29 10:06 GMT+01:00 David Lang <[email protected]>: > but why should this cause the latency to increase based on the number of > simultanious writers?
I'd assume that's locking contention. After all, there seem to be 500 writes plus 1 reader (rsyslog) contenting on that socket. > that's what makes me think that rsyslog may not be acking the messages one > at a time, but instead is acking all of them that it's processing in one > batch. > > No, it just waits for the socket to become ready and than does single reads until no more messages are available. Have a look here: https://github.com/rsyslog/rsyslog/blob/master/plugins/imuxsock/imuxsock.c#L1379 The read loop is inside readSocket(). That's why I conclude this whole problem is totally outside of rsyslog. Rainer > 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. > _______________________________________________ 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.
