David Lang
On Mon, 11 Apr 2016, singh.janmejay wrote:
Date: Mon, 11 Apr 2016 23:04:48 +0530 From: singh.janmejay <[email protected]> Reply-To: rsyslog-users <[email protected]> To: rsyslog-users <[email protected]> Subject: Re: [rsyslog] dynastats problems with user defined variables? David, Did a few runs with those lines present / commented out with rsyslog-master. I see no difference in either on-cpu or off-cpu performance. The left-hand-side is with edge-relay and core-relay lines being active, and the right-side has them commented out. Here is the cpu profile: https://drive.google.com/open?id=0B_XhUZLNFT4dWDFOZlB6VW1hc0E The hypercall on top is cpu-idle call. This was on a c1.4large box on ec2. Both were on the same version of Rsyslog (built off master). I'll do another round of tests with the version I run on production (which is patched fork of 8.12, afair) to identify any large change in cpu profile. This is a much more simplified version of config though. I extracted valid (non garbled) json messages from debug log(got 9089 lines) and pumped them in 100 times using tcpflood. tcpflood call was timed, it took between 19.7 - 20.5 seconds for each run regardless of edge and core relay counters being incremented. It was ~ 45k / sec (but again, neither the load profile, not the machine is not exactly like yours), so its not apples to apples. On Fri, Apr 8, 2016 at 12:15 PM, singh.janmejay <[email protected]> wrote:It doesn't treat them any different. It takes the key and puts it in a hash-table and set an accumulator as its value. Then it'll look it up every time you ask it to increment the counter followed by actual increment. That is about it. The only way I can foresee the contents affecting its behavior is the hash-fn takes more CPU time when given a large string. But that should be on-cpu and not off-cpu time. Today im working on a getting an Rsyslog build running with config into which I inject messages from your debug-log (i'll extract messages and tcpflood them in) and try to understand why it behaves different between those lines commented out or not. If I fail to reproduce it in this simple setup, we'll have to track backtraces that are taking Rsyslog off-cpu in your environment. On Fri, Mar 25, 2016 at 12:57 AM, David Lang <[email protected]> wrote:doing a little more digging (and some accidental stuff), is it possible that it's running into grief if the contents of the variable are not a simple word (spaces or other funny characters in the value)? David Lang On Wed, 23 Mar 2016, singh.janmejay wrote:Date: Wed, 23 Mar 2016 01:07:49 +0530 From: singh.janmejay <[email protected]> Reply-To: rsyslog-users <[email protected]> To: rsyslog-users <[email protected]> Subject: Re: [rsyslog] dynastats problems with user defined variables? Yep, it looked like that. Its interesting though, its 100% off CPU (very unique). On Wed, Mar 23, 2016 at 1:02 AM, David Lang <[email protected]> wrote:Yes, the first one is with the user variables commented out, exactly what I pasted in from the grep. the second is enabling the dyn_inc for edge relays. David Lang On Wed, 23 Mar 2016, singh.janmejay wrote:Date: Wed, 23 Mar 2016 00:51:18 +0530 From: singh.janmejay <[email protected]> Reply-To: rsyslog-users <[email protected]> To: rsyslog-users <[email protected]> Subject: Re: [rsyslog] dynastats problems with user defined variables? You meant the first one was with "commented out" version right? (you said uncommenting edge_relay, so double-checking). On Wed, Mar 23, 2016 at 12:38 AM, David Lang <[email protected]> wrote:here is vmstat 1 running # vmstat 1 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 2 0 62280 2363804 584 27280376 0 1 21 596 0 1 46 3 51 0 0 1 0 62280 2349476 584 27280612 0 0 0 87042 979 891 4 0 95 0 0 1 0 62280 2330488 584 27280908 0 0 0 0 388 258 4 0 96 0 0 1 0 62280 2314744 584 27281148 0 0 0 0 396 255 4 0 96 0 0 1 0 62280 2297736 584 27281388 0 0 0 0 376 245 4 0 96 0 0 2 0 62280 2546260 584 27245272 0 0 0 4 639 568 6 1 94 0 0 2 0 62280 2464300 584 27245928 0 0 0 1716 936 1146 8 0 91 0 0 2 0 62280 2394452 584 27246444 0 0 0 8 687 333 8 0 92 0 0 here is vmstat 1 uncommenting edge_relay # vmstat 1 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 1 0 62280 3198672 584 26770624 0 1 21 596 0 1 46 3 51 0 0 0 0 62280 3198904 584 26770664 0 0 0 0 151 247 0 0 100 0 0 0 0 62280 3200332 584 26770664 0 0 0 0 128 233 0 0 100 0 0 0 0 62280 3202244 584 26770664 0 0 0 4 172 315 0 0 100 0 0 0 0 62280 3203132 584 26770664 0 0 0 0 132 218 0 0 100 0 0 0 0 62280 3203912 584 26770668 0 0 0 8 203 347 0 0 100 0 0 things just are not running with it uncommented. I'm going to send you my config directly, it is a very heavy config. David Lang On Wed, 23 Mar 2016, singh.janmejay wrote:On my cluster, each node (those 66 nodes) have 4 threads for ruleset (it does everything, lognorm based parsing, lookups using loopup table, re_extract, string concat, several if-else based conditions and queues up for egress using omkafka and I generally see 3 being utilized). This setup runs at ~37k msg/s (2.5M / 66 = 37k). 300k/Min is still 5k/s which should be doable on a single-thd (unless your ruleset is much heavier than mine). Im thinking for a equivalently complex ruleset 37k / 4 = 9k should be achievable. I'll try to reproduce this. Can you share out the exact commit-id you are working with? On Tue, Mar 22, 2016 at 8:38 PM, David Lang <[email protected]> wrote:On Tue, 22 Mar 2016, singh.janmejay wrote:On Tue, Mar 22, 2016 at 5:01 AM, David Lang <[email protected]> wrote:I added this to my configs # grep -B 1 -A 1 dyn_ /etc/rsyslog.conf # custom stats to track in rsyslog dyn_stats(name="msgs_per_host" resettable="on" maxCardinality="3000" unusedMetricLife="1200") dyn_stats(name="msgs_per_edge_relay" resettable="on" maxCardinality="3000" unusedMetricLife="1200") dyn_stats(name="msgs_per_core_relay" resettable="on" maxCardinality="3000" unusedMetricLife="1200") dyn_stats(name="msgs_per_program" resettable="on" maxCardinality="3000" unusedMetricLife="1200") dyn_stats(name="msgs_per_tag" resettable="on" maxCardinality="3000" unusedMetricLife="1200") -- /var/log/sources-messages;sources set $.inc = dyn_inc("msgs_per_host", $hostname); set $.inc = dyn_inc("msgs_per_program", $programname); # if $!trusted!edge!relay != "" then { # set $.inc = dyn_inc("msgs_per_edge_relay", $!trusted!edge!relay); # } # if $!trusted!core!relay != "" then { # set $.inc = dyn_inc("msgs_per_edge_relay", $!trusted!core!relay); # } -- } #set $.inc = dyn_inc("msgs_per_tag", $.custommessage); /var/log/messages-tags;manual if I uncomment any of the lines that refer to $! or $. variables, rsyslog basically stops processing messages (a few messages seem to be processed in spurts, bit a lot of processing never happens) any chance that this has problems with locking around user defined variables?Not sure, I run it in production (66 6-cpu(HT) haswell VMs handling an aggregate of ~2.5 M-msg / sec (~1.5kB each)) and haven't seen such jitters, but then I don't use 3 level deep keys either and in my case, the feature is backported to 8.12 branch), so still uses json-c (not libfastjson). I do use it with user-defined variables too, just not nested as deep. We don't treat variables differently after dereferencing them in the top-most layer handling rainerscript fn-calls, so $hostname and $!x!y!z, as far as any rainerscript fn invocation is considered, are the same (performance-wise) except for the top-level dereference (outside of fn-impl-body). Some more info may come handy in reproducing it: - What is the message throughput (in msg/s) and what is the avg msg size?with these commented out as above, ~50k messages/min normal, ~200K message/min if I'm replaying queued logs (box saturated, see the other thread where 8.17 final seems to have slowed down from ~300K messages/min that I was getting with a 8.16+ git)- Do you see messages being written to sources-messages file, while they don't get written to messages-tags file?Yes, but not all messages. I have an alarm that goes off if sources-messages isn't written to in two 35 second checks (70 seconds total), that alarm never fired. But there would be a burst of messages show up in sources-messages and then 20 or so seconds before another burst would show up.- Do you see a significant jump in voluntary context switches(say per 10 seconds or even per second) when you uncomment those lines? How big is the jump? - How does the observation change if you replace it with this kind of variable access pattern: set $.x = $!trusted!edge!relay; if $.x != "" then { set $.inc = dyn_inc("msgs_per_edge_relay", $.x); }will check.- Is this stock 8.17 build?stock config, but against git as of yesterday. I needed to get liblognorm 2.0 and the current libjsonfast- Is this x86-64 Linux? What distro (and version)?ubuntu trusty (14.04) 64 bit.Also, the documentation doesn't say why we are setting $.inc to the result of the command, what does $.inc contain after the command is run? from the documentation, it looks like it contains an error code (at least the way it's used is similar to error code returns in other languages), but I don't see what the errors are in the doc page.Yes, it is the error-code. It has value 0 when successful, an non-zero when it fails to increment (it may fail due to maxCardinality being hit or due to a contended for lock etc (it doesn't wait for the lock, it uses try-lock and doesn't increment the counter if it can't get a shared-lock over the bucket).While I do have multiple threads running on the main queue, the places I am calling this are on action queues with only one worker, so the only lock conflict should be when the data is reported.These are rsyslog error-codes. It does an error pass-thru. I'll add this to documentation (didn't know this was missed).Thanks. Sorry I didn't get a chance to run this pre-release, this is exactly why I try to use features like this pre-release to spot the things that the person developign them misses because they are too close to the problem. :-) David Lang _______________________________________________ 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.-- Regards, Janmejay http://codehunk.wordpress.com
_______________________________________________ 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.
